Allow DEBUG2-logging in sub-protocols + nitpick debug messages + various

LICENSE

@@ -1,6 +1,6 @@
 The MIT License (MIT)
 
-Copyright 2017-2018 Ethereum Foundation
+Copyright 2017-2019 Ethereum Foundation
 
 Permission is hereby granted, free of charge, to any person obtaining a copy
 of this software and associated documentation files (the "Software"), to deal

p2p/discovery.py

@@ -45,6 +45,7 @@
     remove_0x_prefix,
     text_if_str,
     to_bytes,
+    to_hex,
     to_list,
     to_tuple,
     int_to_big_endian,
@@ -357,7 +358,9 @@ def _exclude_if_asked(nodes: Iterable[kademlia.Node]) -> List[kademlia.Node]:
             closest = kademlia.sort_by_distance(closest, node_id)[:kademlia.k_bucket_size]
             nodes_to_ask = _exclude_if_asked(closest)
 
-        self.logger.debug("lookup finished for %s: %s", node_id, closest)
+        self.logger.debug(
+            "lookup finished for target %s; closest neighbours: %s", to_hex(node_id), closest
+        )
         return tuple(closest)
 
     async def lookup_random(self) -> Tuple[kademlia.Node, ...]:

p2p/peer.py

@@ -578,7 +578,7 @@ def _disconnect(self, reason: DisconnectReason) -> None:
             raise ValueError(
                 f"Reason must be an item of DisconnectReason, got {reason}"
             )
-        self.logger.debug("Disconnecting from remote peer; reason: %s", reason.name)
+        self.logger.debug("Disconnecting from remote peer %s; reason: %s", self.remote, reason.name)
         self.base_protocol.send_disconnect(reason.value)
         self.close()
 

p2p/protocol.py

@@ -144,20 +144,27 @@ class BaseRequest(ABC, Generic[TRequestPayload]):
 
 class Protocol:
     peer: 'BasePeer'
-    logger = logging.getLogger("p2p.protocol.Protocol")
     name: str = None
     version: int = None
     cmd_length: int = None
     # List of Command classes that this protocol supports.
     _commands: List[Type[Command]] = []
 
+    _logger: logging.Logger = None
+
     def __init__(self, peer: 'BasePeer', cmd_id_offset: int) -> None:
         self.peer = peer
         self.cmd_id_offset = cmd_id_offset
         self.commands = [cmd_class(cmd_id_offset) for cmd_class in self._commands]
         self.cmd_by_type = {cmd_class: cmd_class(cmd_id_offset) for cmd_class in self._commands}
         self.cmd_by_id = dict((cmd.cmd_id, cmd) for cmd in self.commands)
 
+    @property
+    def logger(self) -> logging.Logger:
+        if self._logger is None:
+            self._logger = logging.getLogger(f"p2p.protocol.{type(self).__name__}")
+        return self._logger
+
     def send(self, header: bytes, body: bytes) -> None:
         self.peer.send(header, body)
 

trinity/cli_parser.py

@@ -58,6 +58,18 @@ def __call__(self,
 }
 
 
+def log_level_formatted_string() -> str:
+    numeric_levels = [k for k in LOG_LEVEL_CHOICES.keys() if k.isdigit()]
+    literal_levels = [k for k in LOG_LEVEL_CHOICES.keys() if not k.isdigit()]
+
+    return (
+        "LEVEL must be one of: "
+        f"\n  {'/'.join(numeric_levels)} (numeric); "
+        f"\n  {'/'.join(literal_levels).lower()} (lowercase); "
+        f"\n  {'/'.join(literal_levels).upper()} (uppercase)."
+    )
+
+
 class ValidateAndStoreLogLevel(argparse.Action):
     def __call__(self,
                  parser: argparse.ArgumentParser,
@@ -81,22 +93,18 @@ def __call__(self,
                     self,
                     f"Invalid logging config: '{value}'.  Log level may be specified "
                     "as a global logging level using the syntax `--log-level "
-                    "<LEVEL-NAME>` or for to specify the logging level for an "
+                    "<LEVEL>`; or, to specify the logging level for an "
                     "individual logger, '--log-level "
-                    "<LOGGER-NAME>:<LEVEL-NAME>'"
+                    "<LOGGER-NAME>=<LEVEL>'" + '\n' +
+                    log_level_formatted_string()
                 )
 
             try:
                 log_level = LOG_LEVEL_CHOICES[raw_log_level.upper()]
             except KeyError:
-                raise argparse.ArgumentError(
-                    self,
-                    (
-                        f"Invalid logging level.  Got '{raw_log_level}'.  Must be one of\n"
-                        " - 5/10/20/30/40 (numeric logging levels)\n"
-                        " - trace/debug/info/warn/warning/error/critical (lowercase)\n"
-                        " - TRACE/DEBUG/INFO/WARN/WARNING/ERROR/CRITICAL (uppercase)\n"
-                    )
+                raise argparse.ArgumentError(self, (
+                    f"Invalid logging level.  Got '{raw_log_level}'.",
+                    log_level_formatted_string())
                 )
 
         if getattr(namespace, self.dest) is None:
@@ -170,11 +178,7 @@ def __call__(self,
     dest="log_levels",
     metavar="LEVEL",
     help=(
-        "Configure the logging level. The `LEVEL` may be provide as any of: "
-        "TRACE/DEBUG/INFO/WARN/WARNING/ERROR/CRITICAL, "
-        "5/10/20/30/40/50, or to specify "
-        "the logging level for a specific logger, `--log-level "
-        "LOGGER_NAME=LEVEL`.  Default: INFO"
+        "Configure the logging level. " + log_level_formatted_string()
     ),
 )
 logging_parser.add_argument(

trinity/protocol/bcc/proto.py

@@ -1,5 +1,3 @@
-import logging
-
 from p2p.protocol import Protocol
 
 from eth.beacon.types.blocks import BaseBeaconBlock
@@ -22,16 +20,18 @@
     Union,
 )
 
+from trinity._utils.logging import HasExtendedDebugLogger
+
 if TYPE_CHECKING:
     from .peer import BCCPeer  # noqa: F401
 
 
-class BCCProtocol(Protocol):
+# HasExtendedDebugLogger must come before Protocol so there's self.logger.debug2()
+class BCCProtocol(HasExtendedDebugLogger, Protocol):
     name = "bcc"
     version = 0
     _commands = [Status, GetBeaconBlocks, BeaconBlocks, AttestationRecords]
     cmd_length = 4
-    logger = logging.getLogger("p2p.bcc.BCCProtocol")
 
     peer: "BCCPeer"
 
@@ -43,7 +43,7 @@ def send_handshake(self, genesis_hash: Hash32, best_hash: Hash32) -> None:
             "best_hash": best_hash,
         }
         cmd = Status(self.cmd_id_offset)
-        self.logger.debug("Sending BCC/Status msg: %s", resp)
+        self.logger.debug2("Sending BCC/Status msg: %s", resp)
         self.send(*cmd.encode(resp))
 
     def send_get_blocks(self,

trinity/protocol/eth/proto.py

@@ -1,4 +1,3 @@
-import logging
 from typing import (
     List,
     Tuple,
@@ -37,19 +36,21 @@
     Transactions,
 )
 
+from trinity._utils.logging import HasExtendedDebugLogger
+
 if TYPE_CHECKING:
     from .peer import ETHPeer  # noqa: F401
 
 
-class ETHProtocol(Protocol):
+# HasExtendedDebugLogger must come before Protocol so there's self.logger.debug2()
+class ETHProtocol(HasExtendedDebugLogger, Protocol):
     name = 'eth'
     version = 63
     _commands = [
         Status, NewBlockHashes, Transactions, GetBlockHeaders, BlockHeaders,
         GetBlockBodies, BlockBodies, NewBlock, GetNodeData, NodeData,
         GetReceipts, Receipts]
     cmd_length = 17
-    logger = logging.getLogger("p2p.eth.ETHProtocol")
 
     peer: 'ETHPeer'
 
@@ -62,7 +63,7 @@ def send_handshake(self, chain_info: ChainInfo) -> None:
             'genesis_hash': chain_info.genesis_hash,
         }
         cmd = Status(self.cmd_id_offset)
-        self.logger.debug("Sending ETH/Status msg: %s", resp)
+        self.logger.debug2("Sending ETH/Status msg: %s", resp)
         self.send(*cmd.encode(resp))
 
     #

trinity/protocol/eth/servers.py

@@ -18,6 +18,10 @@
     Hash32,
 )
 
+from eth_utils import (
+    to_hex,
+)
+
 from p2p import protocol
 from p2p.peer import BasePeer
 from p2p.protocol import (
@@ -75,7 +79,9 @@ async def handle_get_block_bodies(self, peer: ETHPeer, block_hashes: Sequence[Ha
             try:
                 header = await self.wait(self.db.coro_get_block_header_by_hash(block_hash))
             except HeaderNotFound:
-                self.logger.debug("%s asked for block we don't have: %s", peer, block_hash)
+                self.logger.debug(
+                    "%s asked for a block we don't have: %s", peer, to_hex(block_hash)
+                )
                 continue
             transactions = await self.wait(
                 self.db.coro_get_block_transactions(header, BaseTransactionFields))
@@ -95,7 +101,8 @@ async def handle_get_receipts(self, peer: ETHPeer, block_hashes: Sequence[Hash32
                 header = await self.wait(self.db.coro_get_block_header_by_hash(block_hash))
             except HeaderNotFound:
                 self.logger.debug(
-                    "%s asked receipts for block we don't have: %s", peer, block_hash)
+                    "%s asked receipts for a block we don't have: %s", peer, to_hex(block_hash)
+                )
                 continue
             block_receipts = await self.wait(self.db.coro_get_receipts(header, Receipt))
             receipts.append(block_receipts)
@@ -112,7 +119,9 @@ async def handle_get_node_data(self, peer: ETHPeer, node_hashes: Sequence[Hash32
             try:
                 node = await self.wait(self.db.coro_get(node_hash))
             except KeyError:
-                self.logger.debug("%s asked for a trie node we don't have: %s", peer, node_hash)
+                self.logger.debug(
+                    "%s asked for a trie node we don't have: %s", peer, to_hex(node_hash)
+                )
                 continue
             nodes.append(node)
         self.logger.debug2("Replying to %s with %d trie nodes", peer, len(nodes))

trinity/sync/common/chain.py

@@ -131,7 +131,7 @@ async def next_header_batch(self) -> AsyncIterator[Tuple[BlockHeader, ...]]:
                         continue
                 else:
                     headers = all_headers
-                self.logger.debug2('sync received new headers', headers)
+                self.logger.debug2('sync received new headers: %s', headers)
             except OperationCancelled:
                 self.logger.info("Sync with %s completed", peer)
                 break

trinity/sync/common/headers.py

@@ -417,7 +417,7 @@ async def _fetch_headers_from(
                 reverse=False,
             ))
 
-            self.logger.debug2('sync received new headers', headers)
+            self.logger.debug2('sync received new headers: %s', headers)
         except OperationCancelled:
             self.logger.info("Skeleteon sync with %s cancelled", peer)
             return tuple()