From b420f1d434b8bbd596392785f0186c143a6e81f1 Mon Sep 17 00:00:00 2001 From: M1nd3r Date: Mon, 28 Apr 2025 10:56:59 +0200 Subject: [PATCH] chore(core): add wire logging with interface [no changelog] --- core/embed/upymod/qstrdefsport.h | 2 + core/embed/upymod/qstrdefsport.h.mako | 2 +- core/src/trezor/wire/__init__.py | 11 ++-- core/src/trezor/wire/codec/codec_context.py | 20 ++++--- core/src/trezor/wire/message_handler.py | 15 +++-- core/src/trezor/wire/wire_log.py | 61 +++++++++++++++++++++ 6 files changed, 92 insertions(+), 19 deletions(-) create mode 100644 core/src/trezor/wire/wire_log.py diff --git a/core/embed/upymod/qstrdefsport.h b/core/embed/upymod/qstrdefsport.h index 00eac3a28a..d4bae6a00a 100644 --- a/core/embed/upymod/qstrdefsport.h +++ b/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 diff --git a/core/embed/upymod/qstrdefsport.h.mako b/core/embed/upymod/qstrdefsport.h.mako index 6deab0a706..1ba066c426 100644 --- a/core/embed/upymod/qstrdefsport.h.mako +++ b/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) diff --git a/core/src/trezor/wire/__init__.py b/core/src/trezor/wire/__init__.py index ae65539a59..c40ed32626 100644 --- a/core/src/trezor/wire/__init__.py +++ b/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) diff --git a/core/src/trezor/wire/codec/codec_context.py b/core/src/trezor/wire/codec/codec_context.py index 1d8f1dd54d..6d12a388ed 100644 --- a/core/src/trezor/wire/codec/codec_context.py +++ b/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.iface_num(), + self.iface, + "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.iface_num(), + self.iface, + "read: %s", expected_type.MESSAGE_NAME, ) @@ -76,8 +80,8 @@ class CodecContext(Context): if __debug__: log.debug( __name__, - "%d: write: %s", - self.iface.iface_num(), + self.iface, + "write: %s", msg.MESSAGE_NAME, ) diff --git a/core/src/trezor/wire/message_handler.py b/core/src/trezor/wire/message_handler.py index 13be61e8cc..25b1c8ec8f 100644 --- a/core/src/trezor/wire/message_handler.py +++ b/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.iface_num(), + ctx.iface, + "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: diff --git a/core/src/trezor/wire/wire_log.py b/core/src/trezor/wire/wire_log.py new file mode 100644 index 0000000000..9083ed1679 --- /dev/null +++ b/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]