chore(core): add wire logging with interface

[no changelog]

core/embed/upymod/qstrdefsport.h

@@ -737,6 +737,8 @@ Q(trezor.enums.DebugButton)
 Q(trezor.enums.DebugPhysicalButton)
 Q(trezor.enums.DebugSwipeDirection)
 Q(trezor.enums.DebugWaitType)
+Q(trezor.wire.wire_log)
+Q(wire_log)
 #endif
 
 // generate full alphabet

core/embed/upymod/qstrdefsport.h.mako

@@ -33,7 +33,7 @@ ALTCOINS = (
 
 ALTCOINS_RE = re.compile("|".join(ALTCOINS), flags=re.IGNORECASE)
 THP_RE = re.compile(r"\.thp", flags=re.IGNORECASE)
-DEBUG_RE = re.compile("debug|prof", flags=re.IGNORECASE)
+DEBUG_RE = re.compile("debug|prof|wire_log", flags=re.IGNORECASE)
 
 pyfiles = chain.from_iterable(sorted(SRCDIR.glob(p)) for p in PATTERNS)
 

core/src/trezor/wire/__init__.py

@@ -25,7 +25,7 @@ reads the message's header. When the message type is known the first handler is
 
 from typing import TYPE_CHECKING
 
-from trezor import log, loop, protobuf, utils
+from trezor import loop, protobuf, utils
 
 from . import message_handler, protocol_common
 from .codec.codec_context import CodecContext
@@ -36,6 +36,9 @@ from .message_handler import failure
 # other packages.
 from .errors import *  # isort:skip # noqa: F401,F403
 
+if __debug__:
+    from . import wire_log as log
+
 if TYPE_CHECKING:
     from trezorio import WireInterface
     from typing import Any, Callable, Coroutine, TypeVar
@@ -86,7 +89,7 @@ async def handle_session(iface: WireInterface) -> None:
                     msg = await ctx.read_from_wire()
                 except protocol_common.WireError as exc:
                     if __debug__:
-                        log.exception(__name__, exc)
+                        log.exception(__name__, iface, exc)
                     await ctx.write(failure(exc))
                     continue
 
@@ -109,7 +112,7 @@ async def handle_session(iface: WireInterface) -> None:
                 # Log and ignore. The session handler can only exit explicitly in the
                 # following finally block.
                 if __debug__:
-                    log.exception(__name__, exc)
+                    log.exception(__name__, iface, exc)
             finally:
                 # Unload modules imported by the workflow. Should not raise.
                 utils.unimport_end(modules)
@@ -123,4 +126,4 @@ async def handle_session(iface: WireInterface) -> None:
             # Log and try again. The session handler can only exit explicitly via
             # loop.clear() above.
             if __debug__:
-                log.exception(__name__, exc)
+                log.exception(__name__, iface, exc)

core/src/trezor/wire/codec/codec_context.py

@@ -2,16 +2,20 @@ from typing import TYPE_CHECKING, Awaitable, Container
 
 from storage import cache_codec
 from storage.cache_common import DataCache, InvalidSessionError
-from trezor import log, protobuf
+from trezor import protobuf
 from trezor.wire.codec import codec_v1
 from trezor.wire.context import UnexpectedMessageException
 from trezor.wire.message_handler import wrap_protobuf_load
 from trezor.wire.protocol_common import Context, Message
 
+if __debug__:
+    from .. import wire_log as log
+
+
 if TYPE_CHECKING:
     from typing import TypeVar
 
-    from trezor.wire import BufferProvider, WireInterface
+    from .. import BufferProvider, WireInterface
 
     LoadedMessageType = TypeVar("LoadedMessageType", bound=protobuf.MessageType)
 
@@ -45,8 +49,8 @@ class CodecContext(Context):
         if __debug__:
             log.debug(
                 __name__,
-                "%d: expect: %s",
+                self.iface,
-                self.iface.iface_num(),
+                "expect: %s",
                 expected_type.MESSAGE_NAME if expected_type else expected_types,
             )
 
@@ -64,8 +68,8 @@ class CodecContext(Context):
         if __debug__:
             log.debug(
                 __name__,
-                "%d: read: %s",
+                self.iface,
-                self.iface.iface_num(),
+                "read: %s",
                 expected_type.MESSAGE_NAME,
             )
 
@@ -76,8 +80,8 @@ class CodecContext(Context):
         if __debug__:
             log.debug(
                 __name__,
-                "%d: write: %s",
+                self.iface,
-                self.iface.iface_num(),
+                "write: %s",
                 msg.MESSAGE_NAME,
             )
 

core/src/trezor/wire/message_handler.py

@@ -8,6 +8,9 @@ from trezor.wire.context import UnexpectedMessageException, with_context
 from trezor.wire.errors import ActionCancelled, DataError, Error, UnexpectedMessage
 from trezor.wire.protocol_common import Context, Message
 
+if __debug__:
+    from . import wire_log
+
 if TYPE_CHECKING:
     from typing import Any, Callable, Container
 
@@ -65,10 +68,10 @@ async def handle_single_message(ctx: Context, msg: Message) -> bool:
             msg_type = protobuf.type_for_wire(msg.type).MESSAGE_NAME
         except Exception:
             msg_type = f"{msg.type} - unknown message type"
-        log.debug(
+        wire_log.info(
             __name__,
-            "%d receive: <%s>",
+            ctx.iface,
-            ctx.iface.iface_num(),
+            "received message: %s",
             msg_type,
         )
 
@@ -149,11 +152,11 @@ async def handle_single_message(ctx: Context, msg: Message) -> bool:
         # - something canceled the workflow from the outside
         if __debug__:
             if isinstance(exc, ActionCancelled):
-                log.debug(__name__, "cancelled: %s", exc.message)
+                wire_log.debug(__name__, ctx.iface, "cancelled: %s", exc.message)
             elif isinstance(exc, loop.TaskClosed):
-                log.debug(__name__, "cancelled: loop task was closed")
+                wire_log.debug(__name__, ctx.iface, "cancelled: loop task was closed")
             else:
-                log.exception(__name__, exc)
+                wire_log.exception(__name__, ctx.iface, exc)
         res_msg = failure(exc)
 
     if res_msg is not None:

core/src/trezor/wire/wire_log.py

@@ -0,0 +1,61 @@
+import sys
+from typing import TYPE_CHECKING
+
+from trezor import log
+
+if TYPE_CHECKING:
+    from trezorio import WireInterface
+    from typing import Any, ParamSpec, Protocol
+
+    P = ParamSpec("P")
+
+    class LogFunction(Protocol):
+        def __call__(self, name: str, msg: str, *args: Any) -> None: ...
+
+    class LogIfaceFunction(Protocol):
+        def __call__(
+            self, name: str, iface: WireInterface | None, msg: str, *args: Any
+        ) -> None: ...
+
+
+def _wrap_log(log_func: LogFunction) -> LogIfaceFunction:
+    def wrapper(
+        name: str,
+        iface: WireInterface | None,
+        msg: str,
+        *args: P.args,
+        **kwargs: P.kwargs,
+    ) -> None:
+        if iface is None:
+            return log_func(name, msg, *args, **kwargs)
+
+        iface_str = f"\x1b[93m[{iface.__class__.__name__}]\x1b[0m"
+
+        return log_func(name, f"{iface_str} {msg}", *args, **kwargs)
+
+    return wrapper
+
+
+debug = _wrap_log(log.debug)
+info = _wrap_log(log.info)
+warning = _wrap_log(log.warning)
+error = _wrap_log(log.error)
+
+
+def exception(name: str, iface: WireInterface | None, exc: BaseException) -> None:
+    # we are using `__class__.__name__` to avoid importing ui module
+    # we also need to instruct typechecker to ignore the missing argument
+    # in ui.Result exception
+    if exc.__class__.__name__ == "Result":
+        debug(
+            name,
+            iface,
+            "ui.Result: %s",
+            exc.value,  # type: ignore [Cannot access attribute "value" for class "BaseException"]
+        )
+    elif exc.__class__.__name__ == "Cancelled":
+        debug(name, iface, "ui.Cancelled")
+    else:
+        error(name, iface, "exception:")
+        # since mypy 0.770 we cannot override sys, so print_exception is unknown
+        sys.print_exception(exc)  # type: ignore ["print_exception" is not a known attribute of module]