From ccb926af530e7d48a9acaf9af5cb74e881aad2fd Mon Sep 17 00:00:00 2001
From: Jan Pochyla <jpochyla@gmail.com>
Date: Mon, 2 Sep 2019 12:48:49 +0200
Subject: [PATCH] core: improve log messages in workflow and wire

---
 core/src/trezor/wire/__init__.py |  9 +++++++++
 core/src/trezor/wire/codec_v1.py |  3 +++
 core/src/trezor/workflow.py      | 23 +++++++++++++++++++++--
 3 files changed, 33 insertions(+), 2 deletions(-)

diff --git a/core/src/trezor/wire/__init__.py b/core/src/trezor/wire/__init__.py
index 99b442dc23..2221c7f06c 100644
--- a/core/src/trezor/wire/__init__.py
+++ b/core/src/trezor/wire/__init__.py
@@ -251,6 +251,15 @@ async def handle_session(iface: WireInterface, session_id: int) -> None:
                 # header is eventually received, after a couple of tries.
                 req_reader = ctx.make_reader()
                 await req_reader.aopen()
+
+                if __debug__:
+                    log.debug(
+                        __name__,
+                        "%s:%x receive: %s",
+                        iface.iface_num(),
+                        session_id,
+                        req_reader.type,
+                    )
             else:
                 # We have a reader left over from earlier.  We should process
                 # this message instead of waiting for new one.
diff --git a/core/src/trezor/wire/codec_v1.py b/core/src/trezor/wire/codec_v1.py
index bcc8891426..8a92a5acab 100644
--- a/core/src/trezor/wire/codec_v1.py
+++ b/core/src/trezor/wire/codec_v1.py
@@ -31,6 +31,9 @@ class Reader:
         self.ofs = 0
         self.data = bytes()
 
+    def __repr__(self) -> str:
+        return "<Reader type: %s>" % self.type
+
     async def aopen(self) -> None:
         """
         Start reading a message by waiting for initial message report.  Because
diff --git a/core/src/trezor/workflow.py b/core/src/trezor/workflow.py
index 9d5f615aef..a0c90edf6e 100644
--- a/core/src/trezor/workflow.py
+++ b/core/src/trezor/workflow.py
@@ -1,4 +1,4 @@
-from trezor import loop
+from trezor import log, loop
 
 if False:
     from typing import Callable, Optional, Set
@@ -34,6 +34,8 @@ def on_start(workflow: loop.Task) -> None:
 def on_close(workflow: loop.Task) -> None:
     """Call when a workflow task has finished running."""
     # Remove task from the running set.
+    if __debug__:
+        log.debug(__name__, "close: %s", workflow)
     tasks.remove(workflow)
     if not tasks and default_constructor:
         # If no workflows are running, we should create a new default workflow
@@ -54,15 +56,21 @@ def start_default(constructor: Callable[[], loop.Task]) -> None:
     if not default_task:
         default_constructor = constructor
         default_task = constructor()
-
+        if __debug__:
+            log.debug(__name__, "start default")
         # Schedule the default task.  Because the task can complete on its own,
         # we need to reset the `default_task` global in a finalizer.
         loop.schedule(default_task, None, None, _finalize_default)
+    else:
+        if __debug__:
+            log.debug(__name__, "default already started")
 
 
 def close_default() -> None:
     """Explicitly close the default workflow task."""
     if default_task:
+        if __debug__:
+            log.debug(__name__, "close default")
         # We let the `_finalize_default` reset the global.
         loop.close(default_task)
 
@@ -71,4 +79,15 @@ def _finalize_default(task, value) -> None:
     global default_task
 
     if default_task is task:
+        if __debug__:
+            log.debug(__name__, "default closed")
         default_task = None
+    else:
+        if __debug__:
+            log.warning(
+                __name__,
+                "default task does not match: task=%s, default_task=%s",
+                task,
+                default_task,
+            )
+