Python logging quirk: watch out when calling dictConfig()

Today, when I urgently needed to debug some weird, 3rd-party library behavior, I’ve discovered another treasure in vast fields of Python quirks, this time related to its built-in logging configuration API.

The first and quickest thing a typical developer does when in need to gather more details on some reproducible behavior, is to enable more logs, of course. To give some context, my service utilizes Python built-in logging, configured by external JSON file, which in turn is being mounted using volume directive into the service container. The method I call to actually configure the logging is logging.config.dictConfig, taking as parameter parsed JSON/YAML in form of Dict. Here’s partial logging config that resembles mine, with non-crucial parts removed:

{
  "version": 1,
  "formatters": {...},
  "handlers": {
    "console": {...}
  },
  "root": {
    "handlers": ["console"],
    "level": "WARNING"
  },
  "loggers": {
    "LOGGER_NAME": {
      "handlers": ["console"],
      "level": "INFO",
      "propagate": false
    }
  }
}

My services instantiates logger named LOGGER_NAME, with logging level set to INFO, which does not propagate to root logger; and the root logger itself, handling all 3rd party loggers, outputting level WARNING and higher, as usually I don’t need their internal specifics. This setup works well, as I don’t have to update the configuration each time I change or add 3rd party library, and the config itself might be centralized for all the services in the future.

So enabling debug logs would be as easy as editing that JSON file and changing WARNING to DEBUG in root logger and re-running tests. To my surprise, despite this simple change, 3rd party library logs were still missing. After circa 2 hours(!) of furious debugging, I’ve found the cause: mighty disable_existing_loggers parameter.

The parameter is buried deep down in Python documentation, as last documented schema parameter in the section. It isn’t a parameter of dictConfig method (as it is in logging.config.fileConfig), nor it is mentioned in method docstring. It isn’t used in any example configuration snippet in Python documentation, there’s no warning notice for it in docs etc.

My problem with that parameter is its default, quirky value: it’s True. As a result, calling dictConfig to configure all the service logging, disables logging for all instantiated Loggers instances not mentioned in the config. Yup, you read that correctly: it doesn’t re-configure existing loggers - despite logging module being thread-safe in Python by design - doesn’t re-create them with new configuration, just sets their logging level to NOTSET.

Now add the fact that Python’s import order is as described: first goes Python’s built-ins, then 3rd party libraries, and then internal code. As you can see, importing 3rd party libraries takes places before my import, so those libraries can - and often do - instantiate their loggers using code in top-level __init__ files, effectively preceding my setup logging code.

And that was exactly my case - imported 3rd party libraries instantiated their loggers before my service called logging setup, which in turn disabled those loggers permanently, due to default parameter value.

The fix is simple: just set the parameter to desired value in JSON configuration. But the time wasted on debugging is, well, wasted. For those who just glance over post to see the answer, below you can see fixed configuration:

 {
   "version": 1,
   "formatters": {...},
   "handlers": {
     "console": {...}
   },
   "root": {
     "handlers": ["console"],
     "level": "WARNING"
   },
   "loggers": {
     "LOGGER_NAME": {
       "handlers": ["console"],
       "level": "INFO",
       "propagate": false
     }
   },
  "disable_existing_loggers": false
 }