smhk

mypy and verbose logging

tl;dr:

If you want to add a custom logging level to Python (e.g. verbose), and you want it to play nicely with mypy (e.g. to not report error: "Logger" has no attribute "verbose" every time you call logger.verbose()), there doesn’t seem to be a better way than appending # type: ignore to every call to logger.verbose():

init_verbose_logging()
logger = logging.getLogger(__name__)
logger.verbose("this is logged at verbose level")  # type: ignore

I’d love to find a better way to do this, so please reach out if you know a solution. I’ve done quite a lot of digging into this, but I’m new to mypy, so perhaps I’ve missed something. Regardless, read on for the story on how I came to this conclusion, and what the worse alternative solution is.

Python’s standard library logging module comes with five log levels:

  • CRITICAL
  • ERROR
  • WARNING
  • INFO
  • DEBUG

Each has a corresponding log method of the same name, but in lowercase, which is used to write to the log file at that log level. For example:

logger = logging.getLogger(__name__)
logger.debug("This is a DEBUG level message")
logger.critical("This is a CRITICAL level message")

It is fairly typical behaviour to add your own custom log level. For example, a VERBOSE or TRACE level log, which may sit one level lower than DEBUG. Althrough there are many answers on how to do this, they fall into a few categories.

The monkeypatch method §

The monkeypatch method involves adding a verbose method to the existing default logger class:

def verbose(self: Any, msg: str, *args: Any, **kwargs: Any) -> None:
    """Function which is monkeypatched into the logging module to add support
    for the "VERBOSE" log level.
    """
    if self.isEnabledFor(VERBOSE):
        self._log(VERBOSE, msg, args, **kwargs)


def init_verbose_logging() -> None:
    """Monkeypatches the logging module to add a `verbose` log method and a
    "VERBOSE" log level.
    """

    # Add custom log level
    logging.addLevelName(VERBOSE, "VERBOSE")

    # Monkeypatch logger to use our log level
    logging.Logger.verbose = verbose

The first problemw with this is the actual monkeypatching itself on the final line. This causes mypy to report error: "Type[Logger]" has no attribute "verbose" because we are trying to set an attribute outside of initialisation. Ideally, we would fix this by modifying the Logger class ourselves (such as when using a mixin with mypy). But unfortunately the Logger class exists in the Python standard library, which is outside of our reach.

We can append # type: ignore to this line, or we could rewrite it using setattr, e.g.:

setattr(logging.Logger, "verbose", verbose)

However, neither of those solutions help mypy understand that our logger class does have a verbose method. So any call to logger.verbose() still results in error: "Logger" has no attribute "verbose".

This means that every time we call logger.verbose(), we would have to append # type: ignore as a comment. For example:

logger.verbose("example")  # type: ignore

In a code base with lots of calls to logger.verbose(), this is not ideal.

The class method §

The class method involves using the logging.setLoggerClass to set the default logger class. This avoids the slightly dirty aspect of monkeypatching, but still makes use of the _log private method:

class VerboseLogger(logging.getLoggerClass()):
    def __init__(self, name: str, level: Union[int, Text]=logging.NOTSET) -> None:
        super().__init__(name, level)
        logging.addLevelName(VERBOSE, "VERBOSE")

    def verbose(self, msg: str, *args: Any, **kwargs: Any) -> None:
        if self.isEnabledFor(VERBOSE):
            self._log(VERBOSE, msg, args, **kwargs)


def init_verbose_logging() -> None:
    logging.setLoggerClass(VerboseLogger)

The class method has a couple of disadvantages.

The first disadvantage of the class method is that init_verbose_logging must be called before logging.getLogger is called, since it will not affect any Logger objects that already exist. For example:

logger = logging.getLogger(__name__)
init_verbose_logging()  # Uses class method
logger.verbose("this line will FAIL")

Whereas the monkeypatch method will affect the existing Logger object, and need only be called before logging.verbose is called. For example:

logger = logging.getLogger(__name__)
init_verbose_logging()  # Uses monkeypatch method
logger.verbose("this line will SUCCEED")

However, we can easily work around that by modifying our codebase to ensure that init_verbose_logging is called first thing.

The second disadvantage is more problematic. The use of logging.getLoggerClass() is not supported by mypy. It will report error: Unsupported dynamic base class "logging.getLoggerClass". We can ignore this specific warning by applying the # type: ignore comment to the class, e.g.:

class VerboseLogger(logging.getLoggerClass()):  # type: ignore
	# etc...

Alternatively, it may be safe to replace logging.getLoggerClass() with logging.Logger, assuming that no other code in your codebase also tries to replace the logger class.

At this point we encounter the exact same problem we had with the monkeypatch method, in that every call to logger.verbose() must have # type: ignore afterwards, which is not ideal.

Solution §

So what is the solution?

I have found one solution, but I will say up front, it is not great.

For your own Python code, you can include the type hint annotations that mypy needs inline. However, if you are using third-party code which does not have type annotations, you would be in a pickle if it were not for stubs. Stubs allow the type hinting to be defined in separate .pyi files. These can be included inside the Python module that requires the type hinting, or in a separate Python module with the -stubs suffix. This latter point is especially important, because it means that without modifying the third-party library itself, you can define the type hinting for it.

For example, if there exists a foobar library without type hinting, a foobar-stubs package can be created which has the type hinting defined for the public interface.

Since the Python standard library does not have type hinting throughout, the typeshed package (which is included inside mypy) was developed to provide these stubs. This lets you use all of the Python standard library with mypy out-of-the-box.

If we look inside the typeshed definition for the Python standard library logging module, we can see in __init__.pyi that only the five log levels mentioned at the start of this post are defined:

    elif sys.version_info >= (3,):
        def debug(self, msg: Any, *args: Any, exc_info: _ExcInfoType = ...,
                  stack_info: bool = ..., extra: Optional[Dict[str, Any]] = ...,
                  **kwargs: Any) -> None: ...
        def info(self, msg: Any, *args: Any, exc_info: _ExcInfoType = ...,
                 stack_info: bool = ..., extra: Optional[Dict[str, Any]] = ...,
                 **kwargs: Any) -> None: ...
        def warning(self, msg: Any, *args: Any, exc_info: _ExcInfoType = ...,
                    stack_info: bool = ..., extra: Optional[Dict[str, Any]] = ...,
                    **kwargs: Any) -> None: ...
        def warn(self, msg: Any, *args: Any, exc_info: _ExcInfoType = ...,
                 stack_info: bool = ..., extra: Optional[Dict[str, Any]] = ...,
                 **kwargs: Any) -> None: ...
        def error(self, msg: Any, *args: Any, exc_info: _ExcInfoType = ...,
                  stack_info: bool = ..., extra: Optional[Dict[str, Any]] = ...,
                  **kwargs: Any) -> None: ...
        def critical(self, msg: Any, *args: Any, exc_info: _ExcInfoType = ...,
                     stack_info: bool = ..., extra: Optional[Dict[str, Any]] = ...,
                     **kwargs: Any) -> None: ...

Going one step further, there is also the concept of partial stubs. As the name implies, these are stubs that only provide a type hinting definition for part of the public interface of the Python module.

Note that the type checker resolution order will check for partial stubs before it falls back to typeshed. This means it is possible to override the typeshed type hinting!

Perhaps you can see where this is going?

We can write a partial stub to define the verbose method, which will fix the error: "Logger" has no attribute "verbose". This should be as easy finding a way to override the __init__.pyi file to include:

        def verbose(self, msg: Any, *args: Any, exc_info: _ExcInfoType = ...,
                  stack_info: bool = ..., extra: Optional[Dict[str, Any]] = ...,
                  **kwargs: Any) -> None: ...

Where this solution falls short is that partial stubs operate on a per-file basis, and according to the BDFL, there is no intention to support partial stubs at the function level.

So the “solution”, which I am not keen to present, is to create a Python package called logging-stubs. I followed the mypy example partial stubs package, and created this:

logging-stubs
	setup.py
	logging-stubs
		__init__.pyi
		py.typed

The file contents are as follows:

setup.py
import setuptools

setuptools.setup(
    name='logging-stubs',
    author='yourself',
    version='0.1',
    zip_safe=False,
    package_data={'logging-stubs': ['__init__.pyi', 'py.typed']},
    packages=['logging-stubs'],
)

In accordance with PEP-0561, this indicates the package is a partial stub.

py.typed
partial

The following __init__.pyi file is a copy of the latest logging/__init__.pyi file from typeshed, but with the verbose method added into the Logger class (in two places). It’s served as a separate file due to its size:

Inside this logging-stubs package, run python setup.py bdist_wheel to build the Python wheel, then add it as a test dependency to your code.

Needless to say (again), this is not a good solution. It is very brittle, because we would miss out on any updates the typeshed project make to the standard library logging support. Looking at the history for this file, we can see it has been fairly updated over the years, even over the past few months.

To come full circle, I regret to conclude that the best solution I could find for adding a verbose log level that plays nicely with mypy is to sprinkle a little # type: ignore after every logging.verbose() call.

P.S. While I ran out of time to write about it, I did explore the idea of finding a way to suppress all the errors caused by logger.verbose() by modifying the mypy configuration, but was unsuccessful. Perhaps though this is worth exploring further?