Effortless logging: A deep dive into Python logging module

Logs are our best friend, especially on those late nights when we try to troubleshoot a problem in production that was written by a co-worker who is on vacation. Logs are the main way to know what is happening with an application at runtime, but we don’t realize how important they are until we actually need them. Unfortunately, they are usually an under-estimated part of the development process.

This talk aims to transmit the need for the logging module, briefly explains how to use it and how it is built, and dives into all the complexity that is hidden to us. This will help attendees not just understand all the magic that allows us to inspect our applications at runtime, but also to avoid mistakes and adapt the module to our needs for more esoteric scenarios.

The talk is structured to simplify the understanding of the logging module. Many people have read the documentation, but still struggle to fully understand what is happening under the hood. This talk aims to eliminate that barrier by presenting it in an easier-to-digest manner.

https://us.pycon.org/2018/schedule/presentation/104/

Transcript

1. © 2018 Bloomberg Finance L.P. All rights reserved. PyCon 2018 May 13, 2018 Mario Corchero Python Infrastructure @ Bloomberg @mariocj89 A deep dive into the logging module Effortless Logging:
2. © 2018 Bloomberg Finance L.P. All rights reserved. Agenda • Why logging matters • How logging works • How to use it • How to configure it • Sailing to the guts of logging • Sample use cases • Q&A
3. © 2018 Bloomberg Finance L.P. All rights reserved. Why logging matters
4. © 2018 Bloomberg Finance L.P. All rights reserved. Versatility & Configurability Why logging matters
5. © 2018 Bloomberg Finance L.P. All rights reserved. How logging works
6. © 2018 Bloomberg Finance L.P. All rights reserved. Logger How logging works
7. © 2018 Bloomberg Finance L.P. All rights reserved. Logger Logger logger.info(“Hello %s”, name) Emitted to string/file How logging works
8. © 2018 Bloomberg Finance L.P. All rights reserved. Record How logging works
9. © 2018 Bloomberg Finance L.P. All rights reserved. Handler How logging works
10. © 2018 Bloomberg Finance L.P. All rights reserved. Handler Logger logger.info(“Hello %s”, name) Handler Log Record How logging works
11. © 2018 Bloomberg Finance L.P. All rights reserved. Formatter How logging works
12. © 2018 Bloomberg Finance L.P. All rights reserved. Formatter Logger logger.info(“Hello %s”, name) Handler emit(Log Record) Formatter format(Log record) string How logging works
13. © 2018 Bloomberg Finance L.P. All rights reserved. Filter How logging works
14. © 2018 Bloomberg Finance L.P. All rights reserved. Filter Logger logger.info(“Hello %s”, name) Handler emit(Log Record) Formatter format(Log record) string Filter Filter How logging works
15. © 2018 Bloomberg Finance L.P. All rights reserved. The hierarchy logger = logging.getLogger(”parent.child”) How logging works
16. © 2018 Bloomberg Finance L.P. All rights reserved. The hierarchy Logger logger.info(“Hello %s”, name) Handler emit(Log Record) Formatter format(Log record) string Filter Filter propagate? emit Parent Handlers How logging works
17. © 2018 Bloomberg Finance L.P. All rights reserved. The actual flow How logging works
18. © 2018 Bloomberg Finance L.P. All rights reserved. Logger logger.info(“Hello %s”, name) Handler emit(Log Record) Formatter format(Log record) string Filter Filter propagate? emit Parent Handlers category enabled? category How logging works The actual flow
19. © 2018 Bloomberg Finance L.P. All rights reserved. How logging works The actual flow
20. © 2018 Bloomberg Finance L.P. All rights reserved. How to use it
21. © 2018 Bloomberg Finance L.P. All rights reserved. How to use it import logging def sample_function(secret_parameter): logger = logging.getLogger(__name__) logger.debug (”Going to perform magic with '%s’”, secret_parameter) ... try: result = do_magic(secret_parameter) except IndexError: logger.exception("OMG it happened again, someone please tell Laszlo") except : logger.info("Unexpected exception", exc_info=True) raise else: logger.info("Magic with '%s' resulted in '%s'", secret_parameter, result, stack_info=True)
22. © 2018 Bloomberg Finance L.P. All rights reserved. Common misuses How to use it
23. © 2018 Bloomberg Finance L.P. All rights reserved. Common misuses logger.debug("Hello {}".format(name)) logger.debug("Hello %s", name)) How to use it
24. © 2018 Bloomberg Finance L.P. All rights reserved. Common misuses except Exception as error: logging.info("A terrible error happened: %s", error) except Exception: logging.info("A terrible error happened", exc_info=True) How to use it
25. © 2018 Bloomberg Finance L.P. All rights reserved. Common misuses Logging.getLogger("project_name") Logging.getLogger(__name__) How to use it
26. © 2018 Bloomberg Finance L.P. All rights reserved. How to configure it
27. © 2018 Bloomberg Finance L.P. All rights reserved. basicConfig import logging logging.basicConfig(level='INFO') filename filemode format datefmt level stream How to configure it
28. © 2018 Bloomberg Finance L.P. All rights reserved. dictConfig config = { # logging.config.dictConfig(config) 'disable_existing_loggers': False, 'version': 1, 'formatters': { 'short': { 'format': '%(asctime)s %(levelname)s %(name)s: %(message)s’ }, }, 'handlers': { 'console': { 'level': 'INFO', 'formatter': 'short', 'class': 'logging.StreamHandler', }, }, 'loggers': { '': { 'handlers': ['console'], 'level': 'INFO', }, 'plugins’: { 'level’: ‘ERROR', } }, } How to configure it
29. © 2018 Bloomberg Finance L.P. All rights reserved. Demo! import logging logging.basicConfig(level='INFO') logger = logging.getLogger(’logname') logger.info('Hello %s', 'EuroPython')
30. © 2018 Bloomberg Finance L.P. All rights reserved. Calling info
31. © 2018 Bloomberg Finance L.P. All rights reserved. Logger.info
32. Logger._log
33. © 2018 Bloomberg Finance L.P. All rights reserved. Logger.handle
34. Logger.callHandlers
35. Handler.handle
37. © 2018 Bloomberg Finance L.P. All rights reserved. Sample recipes
38. © 2018 Bloomberg Finance L.P. All rights reserved. Multiple handlers 'loggers': { 'request': { 'handlers': ['request_logs'], 'level’: ‘DEBUG', 'propagate': False, }, '': { 'handlers': ['info_log_file', 'error_log_file', 'debug_log_file', 'mail_admins'], 'level': 'DEBUG', }, } Recipes
39. © 2018 Bloomberg Finance L.P. All rights reserved. Logging JSON import logging import logging.config import json ATTR_TO_JSON = ['created', 'filename', 'funcName', 'levelname', 'lineno', 'module', 'msecs', 'msg', 'name', 'pathname', 'process', 'processName', 'relativeCreated', 'thread', 'threadName'] class JsonFormatter: def format(self, record): obj = {attr: getattr(record, attr) for attr in ATTR_TO_JSON} return json.dumps(obj, indent=4) handler = logging.StreamHandler() handler.formatter = JsonFormatter() logger = logging.getLogger(__name__) logger.addHandler(handler) logger.error("Hello") Recipes
40. © 2018 Bloomberg Finance L.P. All rights reserved. Using filters to add context import logging import logging.config GLOBAL_SCARY_STUFF = 1 class ContextFilter(logging.Filter): def filter(self, record): global GLOBAL_SCARY_STUFF GLOBAL_SCARY_STUFF += 1 record.crazy_global_data = GLOBAL_SCARY_STUFF return True handler = logging.StreamHandler() handler.formatter = logging.Formatter("%(crazy_global_data)s %(message)s") handler.addFilter(ContextFilter()) logger = logging.getLogger(__name__) logger.addHandler(handler) logging.getLogger(__name__).error("Hi1") logging.getLogger(__name__).error("Hi2") Recipes
41. © 2018 Bloomberg Finance L.P. All rights reserved. Buffering import logging import logging.handlers class SmartBufferHandler(logging.handlers.MemoryHandler): … init ... def emit(self, record): if len(self.buffer) == self.capacity - 1: self.buffer.pop(0) super().emit(record) handler = SmartBufferHandler(buffered=2, target=logging.StreamHandler(), flushLevel=ERROR) logger = logging.getLogger(__name__) logger.setLevel("INFO") logger.addHandler(handler) logging.getLogger(__name__).error("Hello1") logging.getLogger(__name__).info("Hello2") logging.getLogger(__name__).info("Hello3") logging.getLogger(__name__).error("Hello4") Recipes
42. © 2018 Bloomberg Finance L.P. All rights reserved. Non blocking handling of records que = queue.Queue(-1) # no limit on size queue_handler = QueueHandler(que) handler = logging.StreamHandler() listener = QueueListener(que, handler) root = logging.getLogger() root.addHandler(queue_handler) listener.start() root.warning('Look out!') listener.stop() Recipes
43. © 2018 Bloomberg Finance L.P. All rights reserved. Console output class MaxLevelFilter: def __init__(self, max_level=None): self.max_level = max_level def filter(self, record): return record.levelno <= self.max_level import sys logger = logging.getLogger() logger.setLevel(logging.DEBUG) stdout = logging.StreamHandler(sys.stdout) stdout.setLevel("DEBUG") stdout.addFilter(MaxLevelFilter("INFO")) stderr = logging.StreamHandler(sys.stderr) stderr.setLevel(logging.WARNING) logger.addHandler(stdout) logger.addHandler(stderr) logger.info('INFO') # to stdout only logger.error('ERROR') # to stderr Recipes
44. © 2018 Bloomberg Finance L.P. All rights reserved. Lazy evaluation import logging def expensive_call(): print("This was really expensive") return "Hi” class LazyLog: def __init__(self, func, *args, **kwargs): self.func = func self.args = args self.kwargs = kwargs def __str__(self): return self.func(*self.args, **self.kwargs) or None logging.basicConfig(level="INFO") logging.debug(LazyLog(expensive_call)) logging.info(LazyLog(expensive_call)) Recipes
45. © 2018 Bloomberg Finance L.P. All rights reserved. Quiz time! kahoot.it
46. © 2018 Bloomberg Finance L.P. All rights reserved. Links Some useful links about the talk • https://opensource.com/article/17/9/python-logging • https://docs.python.org/3.6/howto/logging.html • https://docs.python.org/3/howto/logging-cookbook.html • https://github.com/python/cpython/blob/master/Lib/logging/__init__.py
47. © 2018 Bloomberg Finance L.P. All rights reserved. Questions