Improve logging output

junkie/_junkie.py

@@ -7,6 +7,7 @@
 
 import junkie
 
+LOGGER = logging.getLogger(junkie.__name__)
 BUILTINS = {item for item in vars(builtins).values() if isinstance(item, type)}
 
 
@@ -21,19 +22,17 @@ def __init__(self, instances_and_factories: Mapping[str, Any] = None):
         self._instances_by_name = None
         self._instances_by_name_stack = [{}]
 
-        self.logger = logging.getLogger(junkie.__name__)
-
     @contextmanager
     def inject(self, *names_and_factories: Union[str, Callable]) -> Union[Any, Tuple[Any]]:
+        LOGGER.debug("inject(%s)", Junkie._LogParams(*names_and_factories))
+
         with ExitStack() as self._exit_stack:
             self._instances_by_name = self._instances_by_name_stack[-1].copy()
             self._instances_by_name_stack.append(self._instances_by_name)
 
             if len(names_and_factories) == 1:
-                self.logger.debug("inject(%r)", names_and_factories[0])
                 yield self._build_instance(names_and_factories[0])
             else:
-                self.logger.debug("inject(%r)", names_and_factories)
                 yield self._build_tuple(*names_and_factories)
 
             self._instances_by_name_stack.pop()
@@ -80,12 +79,13 @@ def _build_by_factory_function(self, factory_function: Callable, instance_name:
 
         parameters, args, kwargs = self._build_parameters(factory_function)
 
-        self.logger.debug("%s = %s(%s)", instance_name, factory_function.__name__, list(parameters.keys()))
+        log_params = Junkie._LogParams(*parameters.keys(), *args, **kwargs)
+        LOGGER.debug("%s = %s(%s)", instance_name or "_", factory_function.__name__, log_params)
         instance = factory_function(*parameters.values(), *args, **kwargs)
 
         if hasattr(instance, "__enter__"):
-            self.logger.debug("%s.__enter__()", instance_name)
-            self._exit_stack.push(lambda *exception_details: self.logger.debug("%s.__exit__()", instance_name))
+            LOGGER.debug("%s.__enter__()", instance_name or "_")
+            self._exit_stack.push(lambda *exception_details: LOGGER.debug("%s.__exit__()", instance_name or "_"))
 
             instance = self._exit_stack.enter_context(instance)
 
@@ -124,3 +124,13 @@ def _build_parameters(self, factory_function: Callable) -> (OrderedDict, tuple,
                 )
 
         return parameters, args, kwargs
+
+    class _LogParams:
+        def __init__(self, *args, **kwargs):
+            self.args = args
+            self.kwargs = kwargs
+
+        def __str__(self):
+            arg_params = list(map(str, self.args))
+            kwarg_params = list(map(str, [f"{key}={repr(value)}" for key, value in self.kwargs.items()]))
+            return ", ".join(arg_params + kwarg_params)

test/test_junkie.py

@@ -6,7 +6,6 @@
 from contextlib import contextmanager
 from unittest import skipIf
 
-import junkie
 from junkie import Junkie, JunkieError
 
 
@@ -253,43 +252,45 @@ def test_logging(self):
         self.maxDiff = None
 
         class Class:
-            def __init__(self, database_context, message_service, text):
+            def __init__(self, database_context, message_service, *args):
                 self.database_context = database_context
                 self.message_service = message_service
-                self.text = text
+                self.args = args
 
         @contextmanager
-        def create_database(connection_string):
-            yield "DB: " + connection_string
+        def create_database(connection_string, **kwargs):
+            yield "DB: " + connection_string + str(kwargs)
 
         @contextmanager
         def create_message_service():
             yield "message-service"
 
         context = {
-            "text": "abc",
             "connection_string": lambda: "URL",
             "database_context": create_database,
             "message_service": create_message_service,
             "class": Class,
+            "args": ["app_name"],
+            "kwargs": {"engine": "sqlite"},
         }
 
         with self.assertLogs(level="DEBUG") as logging_context:
-            with Junkie(context).inject("class"):
+            with Junkie(context).inject("class", Class):
                 logging.getLogger(__name__).info("execute context block")
 
-        self.assertEqual([
-            "DEBUG:{}:inject('class')".format(junkie.__name__),
-            "DEBUG:{}:connection_string = <lambda>([])".format(junkie.__name__),
-            "DEBUG:{}:database_context = create_database(['connection_string'])".format(junkie.__name__),
-            "DEBUG:{}:database_context.__enter__()".format(junkie.__name__),
-            "DEBUG:{}:message_service = create_message_service([])".format(junkie.__name__),
-            "DEBUG:{}:message_service.__enter__()".format(junkie.__name__),
-            "DEBUG:{}:class = Class(['database_context', 'message_service', 'text'])".format(junkie.__name__),
-            "INFO:{}:execute context block".format(__name__),
-            "DEBUG:{}:message_service.__exit__()".format(junkie.__name__),
-            "DEBUG:{}:database_context.__exit__()".format(junkie.__name__),
-        ], logging_context.output)
+        self.assertEqual((
+            "DEBUG:inject(class, <class 'test.test_junkie.JunkieTest.test_logging.<locals>.Class'>)\n"
+            "DEBUG:connection_string = <lambda>()\n"
+            "DEBUG:database_context = create_database(connection_string, engine='sqlite')\n"
+            "DEBUG:database_context.__enter__()\n"
+            "DEBUG:message_service = create_message_service()\n"
+            "DEBUG:message_service.__enter__()\n"
+            "DEBUG:class = Class(database_context, message_service, app_name)\n"
+            "DEBUG:_ = Class(database_context, message_service, app_name)\n"
+            "INFO:test.test_junkie:execute context block\n"
+            "DEBUG:message_service.__exit__()\n"
+            "DEBUG:database_context.__exit__()"
+        ), "\n".join(logging_context.output).replace(":junkie:", ":"))
 
     def test_auto_inject(self):
         class A: