blog

git clone https://git.ce9e.org/blog.git

commit
e45a5340a9e73ed1d8cb1ae16721596ae3660fc1
parent
daeba706811b307dd7d5f86a81bf8280a3a357e7
Author
Tobias Bengfort <tobias.bengfort@posteo.de>
Date
2023-10-13 19:29
post: logging

Diffstat

A _content/posts/2023-10-13-logging/index.md 199 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
A _content/posts/2023-10-13-logging/index.yml 3 +++

2 files changed, 202 insertions, 0 deletions


diff --git a/_content/posts/2023-10-13-logging/index.md b/_content/posts/2023-10-13-logging/index.md

@@ -0,0 +1,199 @@
   -1     1 Python's [logging](https://docs.python.org/3/library/logging.html) library is a
   -1     2 mixed bag. The code was clearly written in a pre-python3 and pre-pep8 era, so
   -1     3 it has a lot of sharp edges. It also feels like there is much more complexity
   -1     4 than would be needed for such a simple task. But this library also offers a lot
   -1     5 of flexibility for advanced users as well as shortcuts for simple use cases. So
   -1     6 let's take a look.
   -1     7 
   -1     8 # Creating log records
   -1     9 
   -1    10 Typically you would create log records like this:
   -1    11 
   -1    12 ```python
   -1    13 import logging
   -1    14 
   -1    15 logger = logging.getLogger(__name__)
   -1    16 
   -1    17 def myfunc():
   -1    18     logger.error('something went wrong')
   -1    19 ```
   -1    20 
   -1    21 First you create a logger instance with the name of the current module (e.g.
   -1    22 `'myproject.utils'`). Loggers form a hierarchy that is derived from their
   -1    23 names. For example, the logger `'myproject.utils'` would propagate to
   -1    24 `'myproject'`. The root logger is available as `logging.root`. You do not have
   -1    25 to use the module name, but it is a good default.
   -1    26 
   -1    27 Once you have a logger you can create log records. There is a method for each
   -1    28 log level (`debug()`, `info()`, `warn()`, `error()`, and `critical()`). Each of
   -1    29 these will also extract some information from the call stack, e.g. the path and
   -1    30 line of the place where it was triggered. There is also `exception()` which is
   -1    31 the same as `error()` but will also capture the stack trace.
   -1    32 
   -1    33 For very simple cases, you can skip the logger and use shortcut functions
   -1    34 instead, e.g. `logging.error()`. These will use the root logger. If handlers
   -1    35 have not yet been configured (see next section), these shortcuts will also
   -1    36 make sure that log records are written to stderr.
   -1    37 
   -1    38 # Configuring handlers
   -1    39 
   -1    40 By default, log records don't go anywhere. To make them do something useful,
   -1    41 you have to configure handlers.
   -1    42 
   -1    43 `logging` provides many useful handlers such as `StreamHandler` to write to
   -1    44 stderr or `SMTPHandler` to send mails. Many more handlers are available from
   -1    45 third party packages.
   -1    46 
   -1    47 Handlers have some options. First, you may want to filter which log records are
   -1    48 even considered for a given handler. You can set a minimum level or add a
   -1    49 custom `Filter` object for more complex conditions. After that, you need to
   -1    50 convert the log record to a string. The default format is
   -1    51 `%(levelname)s:%(name)s:%(message)s`. But you can customize it using a
   -1    52 `Formatter` object.
   -1    53 
   -1    54 Unfortunately, there are multiple different options to configure handlers.
   -1    55 Let's first create the necessary objects manually:
   -1    56 
   -1    57 ```python
   -1    58 import logging
   -1    59 from logging.handlers import SMTPHandler
   -1    60 
   -1    61 formatter = logging.Formatter(
   -1    62     '%(asctime)s %(levelname)-8s %(name)s %(message)s'
   -1    63 )
   -1    64 
   -1    65 streamhandler = logging.StreamHandler()
   -1    66 streamhandler.level = logging._checkLevel(logging.INFO)
   -1    67 streamhandler.formatter = formatter
   -1    68 logging.root.addHandler(streamhandler)
   -1    69 
   -1    70 smtphandler = SMTPHandler(
   -1    71     'localhost',
   -1    72     'me@localhost',
   -1    73     'you@localhost',
   -1    74     'new log message',
   -1    75 )
   -1    76 smtphandler.level = logging._checkLevel(logging.ERROR)
   -1    77 smtphandler.formatter = formatter
   -1    78 logging.root.addHandler(smtphandler)
   -1    79 ```
   -1    80 
   -1    81 The second option is to use the shortcut function `basicConfig()` which has all
   -1    82 kinds of defaults. A simple call to `basicConfig()` will configure a stream
   -1    83 handler. You can do more with it, but it breaks down pretty quickly. For the
   -1    84 example above, `basicConfig()` doesn't really have any benefits.
   -1    85 
   -1    86 The third option is to use a dictionary:
   -1    87 
   -1    88 ```python
   -1    89 import logging.config
   -1    90 
   -1    91 logging.config.dictConfig({
   -1    92     'version': 1,
   -1    93     'formatters': {
   -1    94         'default': {
   -1    95             'format': '%(asctime)s %(levelname)-8s %(name)s %(message)s'
   -1    96         },
   -1    97     },
   -1    98     'handlers': {
   -1    99         'console': {
   -1   100             'class': 'logging.StreamHandler',
   -1   101             'level': 'INFO',
   -1   102             'formatter': 'default',
   -1   103         },
   -1   104         'mail': {
   -1   105             'class': 'logging.handlers.SMTPHandler',
   -1   106             'mailhost': 'localhost',
   -1   107             'fromaddr': 'me@localhost',
   -1   108             'toaddrs': 'you@localhost',
   -1   109             'subject': 'new log message',
   -1   110             'level': 'ERROR',
   -1   111             'formatter': 'default',
   -1   112         },
   -1   113     },
   -1   114     'root': {
   -1   115         'handlers': ['console', 'mail'],
   -1   116     },
   -1   117 })
   -1   118 ```
   -1   119 
   -1   120 The main benefit of this version is that you can encode this dictionary as a
   -1   121 JSON string, so it can be used with all kinds of setups.
   -1   122 
   -1   123 The final option is to use `logging.config.listen()` to start a TCP server that
   -1   124 can receive configuration in JSON format. I am not sure why you would want to
   -1   125 do that and I find it rather strange that this is included in the standard
   -1   126 library.
   -1   127 
   -1   128 # Attaching handlers to specific loggers
   -1   129 
   -1   130 In most cases you will want to attach your handlers to the root logger and then
   -1   131 filter records there. But you can also attach handlers to different loggers.
   -1   132 Consider this example:
   -1   133 
   -1   134 ```
   -1   135 logging.config.dictConfig({
   -1   136     'version': 1,
   -1   137     'handlers': {
   -1   138         'console': {
   -1   139             'class': 'logging.StreamHandler',
   -1   140         },
   -1   141         'audit-file': {
   -1   142             'class': 'logging.FileHandler',
   -1   143             'filename': 'audit.log',
   -1   144         },
   -1   145     },
   -1   146     'loggers': {
   -1   147         'audit': {
   -1   148             'handlers': ['audit-file'],
   -1   149             'propagate': False,
   -1   150         },
   -1   151     },
   -1   152     'root': {
   -1   153         'handlers': ['console'],
   -1   154     },
   -1   155 })
   -1   156 ```
   -1   157 
   -1   158 This way, log records from the "audit" namespace will be logged to a file
   -1   159 instead of stderr.
   -1   160 
   -1   161 # Recommendations
   -1   162 
   -1   163 `logging` has lots of flexibility, so much so that it is sometimes hard to know
   -1   164 how to do simple things. So here are some recommendations:
   -1   165 
   -1   166 -   Attach handlers to the root logger.
   -1   167 -   Use `basicConfig()` (without arguments) if you just want to log to stderr.
   -1   168 -   For anything more involved, use `dictConfig()`. It gives you full control
   -1   169     and since the dict can be encoded as JSON it can be used in any setup.
   -1   170 -   It is theoretically possible to set a minimum level for both loggers and
   -1   171     handlers. I can't think of any case where a minimum level on a logger is
   -1   172     useful, so you should stick to using it on handlers.
   -1   173 
   -1   174 # Wishful thinking
   -1   175 
   -1   176 With that said, there are some things in `logging` that I wish were different:
   -1   177 
   -1   178 -   All handlers should accept `level` and `formatter` as keyword arguments.
   -1   179     The current way to construct them is just awkward.
   -1   180 -   The default format should include the time. A log message without the time
   -1   181     is pretty much useless. Sometimes your logging pipeline will attach a time
   -1   182     automatically (e.g. journald). But for all other cases you basically have
   -1   183     to configure a custom formatter.
   -1   184 -   Python has accumulated a bunch of string formatting syntaxes, and
   -1   185     consequently `logging` offers different formatting styles (%, {, and $).
   -1   186     This is just silly. Everyone should just use the default style.
   -1   187 -   `logging.config.listen()` has no place in the standard library and should
   -1   188     be removed.
   -1   189 -   This is a bigger thing, but I am just not sold on the whole hierarchy idea.
   -1   190     It adds a lot of complexity without a tangible benefit because you could
   -1   191     achieve the same thing with filters.
   -1   192 
   -1   193 # Conclusion
   -1   194 
   -1   195 The right logging configuration is crucial. If your logs get lost you cannot
   -1   196 debug issues. And if you do not get notified about errors, you might not even
   -1   197 realize what is going on. I personally have wasted too much time with complex
   -1   198 logging configurations. So it was high time to take a deeper look into this. I
   -1   199 hope my recommendations will prove to be helpful.

diff --git a/_content/posts/2023-10-13-logging/index.yml b/_content/posts/2023-10-13-logging/index.yml

@@ -0,0 +1,3 @@
   -1     1 title: Another look at python's logging library
   -1     2 date: 2023-10-13
   -1     3 tags: [code]