python/trezorctl: dump raw protobuf bytes with -vv (fixes #117)

python/src/trezorlib/cli/trezorctl.py

@@ -147,9 +147,10 @@ class UnderscoreAgnosticGroup(click.Group):
         return cmd
 
 
-def enable_logging():
-    log.enable_debug_output()
-    log.OMITTED_MESSAGES.add(proto.Features)
+def configure_logging(verbose: int):
+    if verbose:
+        log.enable_debug_output(verbose)
+        log.OMITTED_MESSAGES.add(proto.Features)
 
 
 @click.command(cls=UnderscoreAgnosticGroup, context_settings={"max_content_width": 400})
@@ -159,14 +160,13 @@ def enable_logging():
     help="Select device by specific path.",
     default=os.environ.get("TREZOR_PATH"),
 )
-@click.option("-v", "--verbose", is_flag=True, help="Show communication messages.")
+@click.option("-v", "--verbose", count=True, help="Show communication messages.")
 @click.option(
     "-j", "--json", "is_json", is_flag=True, help="Print result as JSON object"
 )
 @click.pass_context
 def cli(ctx, path, verbose, is_json):
-    if verbose:
-        enable_logging()
+    configure_logging(verbose)
 
     def get_device():
         try:

python/src/trezorlib/log.py

@@ -21,6 +21,9 @@ from . import protobuf
 
 OMITTED_MESSAGES = set()  # type: Set[Type[protobuf.MessageType]]
 
+DUMP_BYTES = 5
+
+logging.addLevelName(DUMP_BYTES, "BYTES")
 
 class PrettyProtobufFormatter(logging.Formatter):
     def format(self, record: logging.LogRecord) -> str:
@@ -39,13 +42,18 @@ class PrettyProtobufFormatter(logging.Formatter):
         return message
 
 
-def enable_debug_output(handler: Optional[logging.Handler] = None):
+def enable_debug_output(verbosity: int = 1, handler: Optional[logging.Handler] = None):
     if handler is None:
         handler = logging.StreamHandler()
 
     formatter = PrettyProtobufFormatter()
     handler.setFormatter(formatter)
 
+    if verbosity > 0:
+        level = logging.DEBUG
+    if verbosity > 1:
+        level = DUMP_BYTES
+
     logger = logging.getLogger("trezorlib")
-    logger.setLevel(logging.DEBUG)
+    logger.setLevel(level)
     logger.addHandler(handler)

python/src/trezorlib/transport/bridge.py

@@ -23,6 +23,7 @@ import requests
 
 from .. import mapping, protobuf
 from . import Transport, TransportException
+from ..log import DUMP_BYTES
 
 LOG = logging.getLogger(__name__)
 
@@ -159,6 +160,7 @@ class BridgeTransport(Transport):
         buffer = BytesIO()
         protobuf.dump_message(buffer, msg)
         ser = buffer.getvalue()
+        LOG.log(DUMP_BYTES, "sending bytes: {}".format(ser.hex()))
         header = struct.pack(">HL", mapping.get_type(msg), len(ser))
 
         self.handle.write_buf(header + ser)
@@ -167,7 +169,9 @@ class BridgeTransport(Transport):
         data = self.handle.read_buf()
         headerlen = struct.calcsize(">HL")
         msg_type, datalen = struct.unpack(">HL", data[:headerlen])
-        buffer = BytesIO(data[headerlen : headerlen + datalen])
+        ser = data[headerlen : headerlen + datalen]
+        LOG.log(DUMP_BYTES, "received bytes: {}".format(ser.hex()))
+        buffer = BytesIO(ser)
         msg = protobuf.load_message(buffer, mapping.get_class(msg_type))
         LOG.debug(
             "received message: {}".format(msg.__class__.__name__),

python/src/trezorlib/transport/protocol.py

@@ -24,6 +24,7 @@ from typing_extensions import Protocol as StructuralType
 
 from .. import mapping, protobuf
 from . import Transport
+from ..log import DUMP_BYTES
 
 REPLEN = 64
 
@@ -141,6 +142,7 @@ class ProtocolV1(Protocol):
         data = BytesIO()
         protobuf.dump_message(data, msg)
         ser = data.getvalue()
+        LOG.log(DUMP_BYTES, "sending bytes: {}".format(ser.hex()))
         header = struct.pack(">HL", mapping.get_type(msg), len(ser))
         buffer = bytearray(b"##" + header + ser)
 
@@ -162,7 +164,9 @@ class ProtocolV1(Protocol):
             buffer.extend(self.read_next())
 
         # Strip padding
-        data = BytesIO(buffer[:datalen])
+        ser = buffer[:datalen]
+        data = BytesIO(ser)
+        LOG.log(DUMP_BYTES, "received bytes: {}".format(ser.hex()))
 
         # Parse to protobuf
         msg = protobuf.load_message(data, mapping.get_class(msg_type))