From 807db9b190eb5f10c364da5bef563bafea768377 Mon Sep 17 00:00:00 2001
From: Kier Davis <kierdavis@gmail.com>
Date: Tue, 6 Aug 2019 01:44:31 +0100
Subject: [PATCH] Add DEBUG-level logging of all Interface method calls

This uses some funky introspection whenever a Backend is registered to:
* get all of the interfaces it implements
* get all of the abstract methods of these interfaces (component-backend interactions)
* install a wrapper around each method
* use the call signature of the method to get a mapping of the arguments to the call with both names and values
* log the method name, arguments and return value...
* ...to the logger named by the module that the interface is defined in!

This code contains copious amounts of black magic. Perhaps manually
adding log messages to every interface method would have been a more
obvious if less efficient solution.
---
 j5/backends/backend.py | 36 ++++++++++++++++++++++++++++++++++++
 1 file changed, 36 insertions(+)

diff --git a/j5/backends/backend.py b/j5/backends/backend.py
index 2a130ba9..dfb7f046 100644
--- a/j5/backends/backend.py
+++ b/j5/backends/backend.py
@@ -1,6 +1,9 @@
 """The base classes for backends."""
 
+import inspect
+import logging
 from abc import ABCMeta, abstractmethod
+from functools import wraps
 from typing import TYPE_CHECKING, Dict, Optional, Set, Type
 
 if TYPE_CHECKING:  # pragma: nocover
@@ -17,6 +20,38 @@ class CommunicationError(Exception):
     """
 
 
+def _wrap_method_with_logging(
+    backend_class: Type['Backend'],
+    method_name: str,
+    logger: logging.Logger,
+) -> None:
+    old_method = getattr(backend_class, method_name)
+    signature = inspect.signature(old_method)
+    @wraps(old_method)
+    def new_method(*args, **kwargs):  # type: ignore
+        retval = old_method(*args, **kwargs)
+        arg_map = signature.bind(*args, **kwargs).arguments
+        args_str = ", ".join(
+            f"{name}={value!r}"
+            for name, value in arg_map.items()
+            if name != "self"
+        )
+        retval_str = (f" -> {retval!r}" if retval is not None else "")
+        message = f"{method_name}({args_str}){retval_str}"
+        logger.debug(message)
+        return retval
+    setattr(backend_class, method_name, new_method)
+
+
+def _wrap_methods_with_logging(backend_class: Type['Backend']) -> None:
+    component_classes = backend_class.board.supported_components()  # type: ignore
+    for component_class in component_classes:
+        logger = logging.getLogger(component_class.__module__)
+        interface_class = component_class.interface_class()
+        for method_name in interface_class.__abstractmethods__:
+            _wrap_method_with_logging(backend_class, method_name, logger)
+
+
 class BackendMeta(ABCMeta):
     """
     The metaclass for a backend.
@@ -43,6 +78,7 @@ def __new__(mcs, name, bases, namespace, **kwargs):  # type:ignore
                 mcs._check_component_interfaces(cls)
 
                 cls.environment.register_backend(cls.board, cls)
+                _wrap_methods_with_logging(cls)
                 return cls
 
         # The following line should never run, as _check_compatibility should fail first.