Python Loggers

Programming
Comments

This is a memo about my current standard way of logging in Python, especially when multiple modules are involved.

In the main application (app.py):

import logging

import test_module


if __name__ == "__main__":
    logger = logging.getLogger()
else:
    logger = logging.getLogger(__name__)
    logger.addHandler(logging.NullHandler())


def function_in_app():
    logger.info("This is log from a function in app.py")
    return


def main():
    logger.setLevel(logging.INFO)
    formatter = logging.Formatter('%(asctime)s %(name)s %(levelname)s %(message)s')
    consolehandler = logging.StreamHandler()
    consolehandler.setFormatter(formatter)
    logger.addHandler(consolehandler)
    logger.info("App has been started standalone")
    function_in_app()
    test_module.function_in_test_module()
    return


if __name__ == "__main__":
    main()

When app.py is started it gets the root logger in line 7. In main() it sets the logging configurations: logging level, formatter and handler. Here the handler is just outputting to stderr. (Other typical handlers are shown in the end of this post.)

Note that if app.py is not run directly but it is imported in some other file, it does not get the root logger but it creates a logger with its own name (“app”) and adds a NullHandler. See https://docs.python.org/3/howto/logging.html#configuring-logging-for-a-library for more reasoning for it (in short: it prevents warnings and higher to be logged to stderr if not specifically configured).

test_module.py is a module that is imported in app.py:

import logging


logger = logging.getLogger(__name__)
logger.addHandler(logging.NullHandler())


def function_in_test_module():
    logger.info("This is log from a function in test_module.py")
    return

test_module.py is not planned to be run standalone, so it will always just create a logger with its own name and use NullHandler.

This is the result when running app.py:

PS C:\Users\Markku\Desktop\python-temps> python app.py
2020-09-20 18:47:32,887 root INFO App has been started standalone
2020-09-20 18:47:32,895 root INFO This is log from a function in app.py
2020-09-20 18:47:32,897 test_module INFO This is log from a function in test_module.py
PS C:\Users\Markku\Desktop\python-temps>

Let’s see what happens when test_module is imported and used but no root logger has been configured:

PS C:\Users\Markku\Desktop\python-temps> python
Python 3.8.3 (tags/v3.8.3:6f8c832, May 13 2020, 22:20:19) [MSC v.1925 32 bit (Intel)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> import test_module
>>> test_module.function_in_test_module()
>>>

That’s right, there is no logging output. This is intentional so that if the user of the module has not configured any logging the module does not try to guess any correct logging formats or destinations.

But if the module user configures logging:

>>> import logging
>>> logger = logging.getLogger()
>>> logger.setLevel(logging.INFO)
>>> formatter = logging.Formatter('%(asctime)s %(name)s %(levelname)s %(message)s')
>>> consolehandler = logging.StreamHandler()
>>> consolehandler.setFormatter(formatter)
>>> logger.addHandler(consolehandler)
>>> test_module.function_in_test_module()
2020-09-20 18:57:43,374 test_module INFO This is log from a function in test_module.py
>>>

Then the module logging works as well, using the configured root logger.

The same is valid if app.py is imported and used:

>>> import app
>>> app.function_in_app()
2020-09-20 19:02:32,027 app INFO This is log from a function in app.py
>>>

The logging works regardless of NullHandler because the root logger has been set.

If I want to log to a file as well (using the same formatter that was used earlier), I can do this:

try:
    filehandler = logging.FileHandler(args.log_file)
except OSError as e:
    logger.error("Error opening the log file: %s", str(e))
    sys.exit(2)
filehandler.setFormatter(formatter)
logger.addHandler(filehandler)

The log file name is typically got by argument parsing.

Or if I want to log to the local syslog daemon on Linux:

import logging.handlers
syslogformatter = logging.Formatter("%(name)s %(levelname)s %(message)s")
sysloghandler = logging.handlers.SysLogHandler(address="/dev/log")
sysloghandler.setFormatter(syslogformatter)
logger.addHandler(sysloghandler)

And by the way, sometimes I want the console logger to just log short timestamps, not the full date+time+msec fields:

consoleformatter = logging.Formatter("%(asctime)s %(levelname)s %(message)s", datefmt="%H:%M:%S")
consolehandler.setFormatter(formatter)
logger.addHandler(consolehandler)

For file and syslog logging I usually use the default full date+time+msec format as shown in the outputs above.

Extra hint if you are using Azure core Python library: If you are using INFO level logging, your logs will be filled with these every time you do for example Azure storage queue polling:

2020-09-21 11:17:17,886 azure.core.pipeline.policies.http_logging_policy INFO: Request URL: 'https://youraccountname.queue.core.windows.net/yourqueuename/messages?numofmessages=REDACTED&visibilitytimeout=REDACTED'
2020-09-21 11:17:17,887 azure.core.pipeline.policies.http_logging_policy INFO: Request method: 'GET'
2020-09-21 11:17:17,887 azure.core.pipeline.policies.http_logging_policy INFO: Request headers:
2020-09-21 11:17:17,888 azure.core.pipeline.policies.http_logging_policy INFO: 'Accept': 'application/xml'
2020-09-21 11:17:17,888 azure.core.pipeline.policies.http_logging_policy INFO: 'x-ms-version': 'REDACTED'
2020-09-21 11:17:17,888 azure.core.pipeline.policies.http_logging_policy INFO: 'x-ms-date': 'REDACTED'
2020-09-21 11:17:17,889 azure.core.pipeline.policies.http_logging_policy INFO: 'x-ms-client-request-id': 'dd19cec4-fbe2-11ea-b1a8-xxxxxxxxxxx'
2020-09-21 11:17:17,889 azure.core.pipeline.policies.http_logging_policy INFO: 'User-Agent': 'azsdk-python-storage-queue/12.1.1 Python/3.6.9 (Linux-5.4.0-1025-azure-x86_64-with-Ubuntu-18.04-bionic)'
2020-09-21 11:17:17,889 azure.core.pipeline.policies.http_logging_policy INFO: 'Authorization': 'REDACTED'
2020-09-21 11:17:17,899 azure.core.pipeline.policies.http_logging_policy INFO: Response status: 200
2020-09-21 11:17:17,899 azure.core.pipeline.policies.http_logging_policy INFO: Response headers:
2020-09-21 11:17:17,899 azure.core.pipeline.policies.http_logging_policy INFO: 'Cache-Control': 'no-cache'
2020-09-21 11:17:17,900 azure.core.pipeline.policies.http_logging_policy INFO: 'Transfer-Encoding': 'chunked'
2020-09-21 11:17:17,900 azure.core.pipeline.policies.http_logging_policy INFO: 'Content-Type': 'application/xml'
2020-09-21 11:17:17,900 azure.core.pipeline.policies.http_logging_policy INFO: 'Server': 'Windows-Azure-Queue/1.0 Microsoft-HTTPAPI/2.0'
2020-09-21 11:17:17,901 azure.core.pipeline.policies.http_logging_policy INFO: 'x-ms-request-id': '03dde641-3003-0018-5def-xxxxxxxxxxxx'
2020-09-21 11:17:17,901 azure.core.pipeline.policies.http_logging_policy INFO: 'x-ms-version': 'REDACTED'
2020-09-21 11:17:17,901 azure.core.pipeline.policies.http_logging_policy INFO: 'Date': 'Mon, 21 Sep 2020 08:17:17 GMT'

You get rid of these messages by increasing the level of that logger:

logging.getLogger("azure.core.pipeline.policies.http_logging_policy") .setLevel(logging.WARNING)
# Note the long line was split here for technical reasons

Leave a Reply