Add extended debug logging utils #158

pipermerriam · 2019-05-10T17:21:51Z

What was wrong?

We have a few libraries that need to log with more granularity than the default logging module provides. We also regularly want loggers attached to our classes and we end up re-inventing mechanisms to make this DRY across different codebases.

How was it fixed?

Added the following utilities to eth-utils to make this easier.

HasLogger: inherit from this class and a logger is available on both the class and instances of the class at the logger property
HasExtendedDebugLogger: Same as HasLogger but exposes an ExtendedDebugLogger
ExtendedDebugLogger: Subclass of logging.Logger that has a debug2(...) logging method for logging at the DEBUG2 level
setup_DEBUG2_logging: Installs the DEBUG2 log level into the standard library logging module at the numeric level of 8 with the string name 'DEBUG2'.

This improves on existing mechanisms by:

using a metaclass so that the logger is available at the class level and shared across all instances as a class level attribute.
uses the __qualname__ for the logger name from PEP3155 which seems to be exactly what we want.
still allows you to specify a logger property manually and respects that.
HasExtendedDebugLogger no longer relies on the user having called setup_DEBUG2_logging to work. Calling the setup function is merely a nicety now that lets the logging module know the correct human readable name to use as well as making logging.DEBUG2 an importable property.

Cute Animal Picture

pipermerriam · 2019-05-10T17:34:58Z

eth_utils/logging.py

+    pass
+
+
+class _BaseHasExtendedDebugLogger(HasLogger[ExtendedDebugLogger]):  # type: ignore


Noting this API of doing HasLogger[LoggerClass] to create a new one that uses the new logger class is intentionally not documented so that we aren't committed to supporting this API.

pipermerriam · 2019-05-10T17:36:08Z

eth_utils/logging.py

+    # This class exists to a allow us to define the type of the logger.  Once
+    # python3.5 is deprecated this can be removed in favor of a simple type
+    # annotation on the main class.
+    logger = ExtendedDebugLogger("")  # type: ExtendedDebugLogger


I tried a whole bunch of things to try and do this cleanly but this was the one way I could make it work without ugly side effects.

Tried programatically populating __annotations__

Tried using a typing.Generic

Looked into mypy plugins

Looked into writing stub files.

carver · 2019-05-13T17:55:16Z

Hah, @lithp was also working on getting the logger available at the class level.

Edit: oh, I see you already pinged him. Maybe you knew that.

carver

Cool, so two primary things:

Performance: no idea what the impact of adding a metaclass to the mix is. Maybe not good? Would we just not use this logger for py-evm and trinity?
Getting it working on the class level almost certainly requires some magic. Brian took a look, and had another option. So it would be worth comparing the two incantations side by side for readability.

carver · 2019-05-13T17:58:09Z

docs/utilities.rst

+    ...     pass
+    ...
+    >>> hasattr(MyClass, 'logger')
+    True


If you like, we could highlight the benefit here:

>>> MyClass.logger.debug('Can log from the class')

carver · 2019-05-13T18:01:23Z

docs/utilities.rst

+^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
+
+Same as the ``HasLogger`` class except the logger it exposes is an instance of
+``ExtendedDebugLogger``


I think that if you don't run setup then this all still works, right? I guess it would be nice to specifically address that.

class NoisyClass(HasExtendedDebugLogger): pass NoisyClass.logger.debug2('What if I add a debug2 log without running setup_DEBUG2_logging?')

carver · 2019-05-13T18:10:01Z

eth_utils/logging.py

+            # replace it.
+            return super().__new__(mcls, name, bases, namespace)
+        if "__qualname__" not in namespace:
+            raise AttributeError("Missing __qualname__")


I've never really dived into meta classes. It all seems pretty magical to me still. Brian did another implementation that was also magical. Maybe he still has it floating around. I'm not sure which one was better. Also performance matters on some use cases, like py-evm/trinity. I don't know this code well enough to understand the performance impact.

My understanding is that there should be no performance hit and this should more performant than the @property based approach since metaclass code runs at class creation time which is module loading time. Assuming I am correct, there should be zero runtime overhead as everything should happen at module loading time.

Just scrounged through my reflog to find my solution:

class classproperty(Generic[TResult]): def __init__(self, func: Callable[[Type[Any]], TResult]) -> None: self.func = func def __get__(self, instance: Any, owner: Type[Any]) -> TResult: return self.func(owner) def get_logger(cls: Type['BasePlugin']) -> logging.Logger: return logging.getLogger(f'trinity.extensibility.plugin#{cls.__name__}') class BasePlugin(ABC): logger = classproperty(get_logger) ....

Where get_logger was pulled out to make mypy happy but could also be in-line with a # type: ignore

Never thought I'd say this but I expect that the metaclass is not only faster but also less magical.

carver · 2019-05-13T18:13:22Z

tox.ini

@@ -35,6 +35,6 @@ extras=lint
 commands=
    flake8 {toxinidir}/eth_utils setup.py
    mypy --follow-imports=silent --ignore-missing-imports --disallow-incomplete-defs --warn-unused-ignore -p eth_utils
-    mypy --follow-imports=silent --ignore-missing-imports --disallow-incomplete-defs tests/mypy_typing_of_functional_utils.py
+    mypy --follow-imports=silent --ignore-missing-imports --disallow-incomplete-defs tests/type-checks/


pipermerriam · 2019-05-13T19:45:59Z

@carver

Performance: no idea what the impact of adding a metaclass to the mix is. Maybe not good? Would we just not use this logger for py-evm and trinity?

Mirrored from my other comment. This was actually written to address the performance part since metaclass code runs at module loading time, effectively front-loading the work so that it's already done by the time you actually work with any of the classes.

While metaclasses are magic, this I don't feel this is dark magic. I've tried to write reasonably exhaustive tests to ensure that it works as expected in all of the inheritance scenarios we may encounter, though now that I'm saying this, I realize I need to write a test that ensures this behaves nicely with classes that also inherit from typing.Generic.

pipermerriam · 2019-05-14T17:37:43Z

Did not find a clean way to make this work nicely with typing.Generic so I added a .. warning to the docs indicating that if you need a typing.Generic you'll need to assign your logger manually.

pipermerriam · 2019-05-14T19:02:49Z

@carver are you 👍 to merge this? @lithp do you have any feedback on it this approach?

carver · 2019-05-14T19:04:40Z

Hm, I think it causes problems if you run tox locally and expect it to pick up your changes.

carver · 2019-05-14T19:06:57Z

I think the right thing to do is to drop the pyproject.toml until we're actually using it to build the project.

carver · 2019-05-14T19:07:35Z

may pass --no-use-pep517 to opt out of pyproject.toml-style processing appears to be a runner-up solution

pipermerriam · 2019-05-14T19:12:13Z

Dropped pyproject.toml and used comment mechanism to keep black from formatting eth_utils/units.py

lithp · 2019-05-15T02:03:20Z

eth_utils/logging.py

+
+    def __new__(mcls, name, bases, namespace):
+        if "logger" in namespace:
+            # If a logger was explicitely declared we shouldn't do anything to


s/explicitely/explicitly/

lithp · 2019-05-15T02:05:36Z

eth_utils/logging.py

+        logging.setLoggerClass(original_logger_cls)
+
+
+class HasLoggerMeta(ABCMeta):


Why does this derive from ABCMeta?

Because..... I don't know. removing.

lithp · 2019-05-15T02:07:13Z

Didn't look through this thoroughly but this approach seems reasonable! 👍

pipermerriam force-pushed the piper/extended-debug-logging branch 2 times, most recently from 7896cf3 to b20c437 Compare May 10, 2019 17:28

pipermerriam mentioned this pull request May 10, 2019

Bring in HasExtendedDebugLogger into this codebase ethereum/py-evm#1750

Closed

pipermerriam requested review from lithp and carver May 10, 2019 17:28

pipermerriam force-pushed the piper/extended-debug-logging branch from b20c437 to 1c82ed0 Compare May 10, 2019 17:33

pipermerriam commented May 10, 2019

View reviewed changes

Add extended debug logging utils

cf0c207

pipermerriam force-pushed the piper/extended-debug-logging branch from 1c82ed0 to cf0c207 Compare May 10, 2019 18:33

carver approved these changes May 13, 2019

View reviewed changes

pipermerriam force-pushed the piper/extended-debug-logging branch from 9073987 to ab256b1 Compare May 14, 2019 19:01

update docs

8994534

pipermerriam force-pushed the piper/extended-debug-logging branch from ab256b1 to 8994534 Compare May 14, 2019 19:09

lithp reviewed May 15, 2019

View reviewed changes

PR review

a1831ac

pipermerriam merged commit f15d431 into ethereum:master May 16, 2019

pipermerriam deleted the piper/extended-debug-logging branch May 16, 2019 03:56

pipermerriam mentioned this pull request Aug 5, 2019

fixup extended debug logging utils #165

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add extended debug logging utils #158

Add extended debug logging utils #158

pipermerriam commented May 10, 2019

pipermerriam May 10, 2019

pipermerriam May 10, 2019

carver commented May 13, 2019 •

edited

Loading

carver left a comment •

edited

Loading

carver May 13, 2019

carver May 13, 2019

carver May 13, 2019

pipermerriam May 13, 2019

lithp May 15, 2019

carver May 13, 2019

pipermerriam commented May 13, 2019

pipermerriam commented May 14, 2019

pipermerriam commented May 14, 2019

carver commented May 14, 2019

carver commented May 14, 2019

carver commented May 14, 2019

pipermerriam commented May 14, 2019

lithp May 15, 2019

lithp May 15, 2019

pipermerriam May 15, 2019

lithp commented May 15, 2019

		pass


		class _BaseHasExtendedDebugLogger(HasLogger[ExtendedDebugLogger]): # type: ignore

		logging.setLoggerClass(original_logger_cls)


		class HasLoggerMeta(ABCMeta):

Add extended debug logging utils #158

Add extended debug logging utils #158

Conversation

pipermerriam commented May 10, 2019

What was wrong?

How was it fixed?

Cute Animal Picture

Choose a reason for hiding this comment

Choose a reason for hiding this comment

carver commented May 13, 2019 • edited Loading

carver left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pipermerriam commented May 13, 2019

pipermerriam commented May 14, 2019

pipermerriam commented May 14, 2019

carver commented May 14, 2019

carver commented May 14, 2019

carver commented May 14, 2019

pipermerriam commented May 14, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lithp commented May 15, 2019

carver commented May 13, 2019 •

edited

Loading

carver left a comment •

edited

Loading