Upgrade to Pro — share decks privately, control downloads, hide ads and more …

Context Matters - more useful logging with Python

Context Matters - more useful logging with Python

Producing more useful logs with Python

2e3d2ffc00b7ff346be9275d2de35535?s=128

Fergal Walsh

May 26, 2019
Tweet

Transcript

  1. Context Matters Fergal Walsh fergal@hipolabs.com Producing more useful logs with

    Python
  2. Logging 101 import logging logger = logging.getLogger(__name__) logger.info(‘Hello PyConWeb’)

  3. Logging 101 import logging logger = logging.getLogger(__name__) handler = logging.StreamHandler()

    formatter = logging.Formatter('%(levelname)s %(name)s: %(message)s') handler.setFormatter(formatter) logger.addHandler(handler) logger.setLevel(logging.INFO) logger.info(‘Hello PyConWeb’) INFO slides: Hello PyConWeb
  4. logger.info(‘Hello PyConWeb’) INFO slides: Hello PyConWeb Adapter str Logger str

    Filter Filters LogRecord Filter Handlers LogRecord LogRecord Filter Filters Formatter str LogRecord
  5. Logs Screenshot

  6. Logging 101 import logging logger = logging.getLogger(__name__) handler = logging.StreamHandler()

    formatter = logging.Formatter('%(levelname)s %(asctime)s %(name)s:....%(message)s') handler.setFormatter(formatter) logger.addHandler(handler) logger.setLevel(logging.INFO) logger.info(‘Hello PyConWeb’) INFO 2019-05-26 15:05:05,468 slides:5 Hello PyConWeb
  7. • Which request are we responding to? ◦ What is

    the path? ◦ Which domain? ◦ Which user? ◦ What browser/client are they using? ◦ What is their IP? ◦ What did they ask us? • Which server are we? • Which version of the app is this? • How did we even get here? Context
  8. • Which request are we responding to? ◦ What is

    the path? request.path ◦ Which domain? request.host ◦ Which user? request.user ◦ What browser/client are they using? request.user_agent ◦ What is their IP? request.remote_addr ◦ What did they ask us? request.args • Which server are we? get_hostname() • Which version of the app is this? get_git_revision() • How did we even get here? traceback Context
  9. Context > extra formatter = logging.Formatter('%(domain)s %(path)s %(username)s … %(levelname)s

    %(asctime)s %(name)s:%(lineno)d: %(message)s') context = { 'path': request.path, 'domain': request.host, 'username': request.user.username, ... } logger.info('Hello PyConWeb', extra=context) INFO 2019-05-26 15:05:05,468 slides:11 Hello PyConWeb api.example.com /v1/hello/ brian00 … INFO 2019-05-26 15:05:05,468 slides:11 Hello PyConWeb
  10. Do we really need to pass the context every time?

    What about other libraries? requests, sqlalchemy, boto, etc We want all logs to be context enriched
  11. logger.info(‘Hello PyConWeb’) Logger Filter Filters Formatter Filter Handlers INFO 2019-05-26

    15:05:05,468 slides:5 Hello PyConWeb Adapter str str LogRecord LogRecord LogRecord str Filter Filters LogRecord Insert Context Here Insert Context Here Insert Context Here Insert Context Here Insert Context Here Insert Context Here Insert Context Here
  12. logger.info(‘Hello PyConWeb’) Logger Filter Filters Formatter Filter Handlers INFO 2019-05-26

    15:05:05,468 slides:5 Hello PyConWeb Adapter str str LogRecord LogRecord LogRecord str Insert Context Here LogRecordFactory Filter Filters LogRecord
  13. Context > Filter class ContextFilter(logging.Filter): def filter(self, record): context =

    get_context() # This should be from a ContextVar/threading.local record.username = context.username record.domain = context.domain record.path = context.path … return True handler.addFilter(ContextFilter())
  14. Context > Filter class ContextFilter(logging.Filter): def filter(self, record): context =

    get_context() # This should be from a ContextVar/threading.local record.username = context.username record.domain = context.domain record.path = context.path … return True handler.addFilter(ContextFilter()) formatter = logging.Formatter('%(domain)s %(path)s %(username)s … %(levelname)s %(asctime)s %(name)s:%(lineno)d: %(message)s') handler.setFormatter(formatter) logger.info(‘Hello PyConWeb’) api.example.com /v1/hello/ brian00 … INFO 2019-05-26 15:05:05,468 slides:11 Hello PyConWeb
  15. Context > LogRecordFactory old_factory = logging.getLogRecordFactory() def record_factory(*args, **kwargs): record

    = old_factory(*args, **kwargs) context = get_context() # This should be from a ContextVar/threading.local record.username = context.username record.domain = context.domain record.path = context.path … return record logging.setLogRecordFactory(record_factory)
  16. Context > LogRecordFactory old_factory = logging.getLogRecordFactory() def record_factory(*args, **kwargs): record

    = old_factory(*args, **kwargs) context = get_context() # This should be from a ContextVar/threading.local record.username = context.username record.domain = context.domain record.path = context.path … return record logging.setLogRecordFactory(record_factory) formatter = logging.Formatter('%(domain)s %(path)s %(username)s … %(levelname)s %(asctime)s %(name)s:%(lineno)d: %(message)s') handler.setFormatter(formatter) logger.info(‘Hello PyConWeb’) api.example.com /v1/hello/ brian00 … INFO 2019-05-26 15:05:05,468 slides:11 Hello PyConWeb
  17. LOGGING = { 'version': 1, 'disable_existing_loggers': True, 'formatters': { 'verbose':

    { 'format': '%(method)s %(domain)s %(path)s ...' }, }, 'filters': { 'context': { '()': 'demo.utils.ContextFilter', }, }, 'handlers': { 'console': { 'level': 'DEBUG', 'class': 'logging.StreamHandler', 'formatter': 'verbose', 'filters': ['context'], }, }, 'loggers': { '__main__': { 'handlers': ['console'], 'level': 'INFO', 'propagate': False, }, 'demo': { 'handlers': ['console'], 'level': 'INFO', 'propagate': False, }, 'urllib3': { 'handlers': ['console'], 'level': 'DEBUG', 'propagate': False, }, 'sqlalchemy.engine': { 'handlers': ['console'], 'level': 'INFO', 'propagate': False, }, }
  18. Formatting GET api.example.com /v1/hello/ ?arg1=value1 app Mozilla/5.0 (Macintosh; Intel Mac

    OS X 10_13_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36 154.142.78.32 brian00 INFO 2019-05-26 15:05:05,468 slides:11 Hello PyConWeb
  19. Formatting method=GET domain=api.example.com path=/v1/hello/ query=?arg1=value1 user-agent=Mozilla/5.0 (Macintosh; Intel Mac OS

    X 10_13_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36 154.142.78.32 username=brian00 level=INFO time=2019-05-26 15:05:05,468 logger=slides lineno=11 message=Hello PyConWeb
  20. Formatting > JsonFormatter class JsonFormatter(logging.Formatter): def format(self, record): if isinstance(record.msg,

    str): record.message = record.getMessage() else: record.message = record.msg log_record = dict(record.__dict__) return json.dumps(log_record) handler.setFormatter(JsonFormatter()) * Note: Not a complete implementation
  21. class JsonFormatter(logging.Formatter): def format(self, record): if isinstance(record.msg, str): record.message =

    record.getMessage() else: record.message = record.msg log_record = dict(record.__dict__) return json.dumps(log_record) handler.setFormatter(JsonFormatter()) logger.info(‘Hello PyConWeb’) Formatting > JsonFormatter { "name": "demo.app", "msg": "Hello PyConWeb", "args": [], "levelname": "INFO", "levelno": 20, "pathname": "/Users/fergal/workspace/demo/app.py", "filename": "app.py", "module": "app", "exc_info": "None", "exc_text": "None", "stack_info": "None", "lineno": 80, "funcName": "run", "created": 1558132129.1351192, "msecs": 135.11919975280762, "relativeCreated": 2884.1490745544434, "thread": 140735565054784, "threadName": "MainThread", "processName": "MainProcess", "process": 86643, "username": "brian00", "domain": "api.example.com", "path": "/v1/hello/", … "message": "Hello PyConWeb", "asctime": "2019-05-26 15:05:05,468" }
  22. LOGGING = { 'version': 1, 'disable_existing_loggers': True, 'formatters': { 'verbose':

    { 'format': '%(method)s %(domain)s %(path)s ...' }, }, 'filters': { 'context': { '()': 'demo.utils.ContextFilter', }, }, 'handlers': { 'console': { 'level': 'DEBUG', 'class': 'logging.StreamHandler', 'formatter': 'verbose', 'filters': ['context'], }, }, 'loggers': { '__main__': { 'handlers': ['console'], 'level': 'INFO', 'propagate': False, }, 'demo': { 'handlers': ['console'], 'level': 'INFO', 'propagate': False, }, 'urllib3': { 'handlers': ['console'], 'level': 'DEBUG', 'propagate': False, }, 'sqlalchemy.engine': { 'handlers': ['console'], 'level': 'INFO', 'propagate': False, }, }
  23. LOGGING = { 'version': 1, 'disable_existing_loggers': True, 'formatters': { 'json':

    { 'class': 'demo.utils.JsonFormatter', }, }, 'filters': { 'context': { '()': 'demo.utils.ContextFilter', }, }, 'handlers': { 'console': { 'level': 'DEBUG', 'class': 'logging.StreamHandler', 'formatter': 'json', 'filters': ['context'], }, }, 'loggers': { '__main__': { 'handlers': ['console'], 'level': 'INFO', 'propagate': False, }, 'demo': { 'handlers': ['console'], 'level': 'INFO', 'propagate': False, }, 'urllib3': { 'handlers': ['console'], 'level': 'DEBUG', 'propagate': False, }, 'sqlalchemy.engine': { 'handlers': ['console'], 'level': 'INFO', 'propagate': False, }, }
  24. { "name": "demo.app", "msg": "Hello PyConWeb", "args": [], "levelname": "INFO",

    "levelno": 20, "pathname": "/Users/fergal/workspace/demo/app.py", "filename": "app.py", "module": "app", "exc_info": "None", "exc_text": "None", "stack_info": "None", "lineno": 80, "funcName": "run", "created": 1558132129.1351192, "msecs": 135.11919975280762, "relativeCreated": 2884.1490745544434, "thread": 140735565054784, "threadName": "MainThread", "processName": "MainProcess", "process": 86643, "username": "brian00", "domain": "api.example.com", "path": "/v1/hello/", … "message": "Hello PyConWeb", "asctime": "2019-05-26 15:05:05,468" }
  25. Should we really just log to stdout? A twelve-factor app

    never concerns itself with routing or storage of its output stream. It should not attempt to write to or manage logfiles. Instead, each running process writes its event stream, unbuffered, to stdout. - 12factor.net/logs Yes! But.. what if we don’t?
  26. Writing > Handlers StreamHandler FileHandler RotatingFileHandler SocketHandler DatagramHandler SMTPHandler MemoryHandler

    HTTPHandler QueueHandler
  27. class RedisHandler(logging.Handler): def __init__(self, redis_url, key): super().__init__(self) self.redis = Redis.from_url(redis_url)

    self.key = key self.formatter = JsonFormatter() def emit(self, record): self.redis.lpush(self.key, self.format(record)) Writing > RedisHandler * Note: Not a complete implementation
  28. class PostgresHandler(logging.Handler): def __init__(self, postgres_url, table): super().__init__(self) self.pg = PostgresConnection(postgres_url)

    self.table = table self.formatter = JsonFormatter() def emit(self, record): row = { 'username': record.username, 'domain': record.domain, 'path': record.path, … 'time': datetime.datetime.fromtimestamp(record.created), 'level': record.levelno, 'name': record.name, 'message': record.getMessage(), 'log': self.format(record), # format full log record as json } self.pg.insert_row(self.table, row) Writing > PostgresHandler * Note: Not a complete implementation
  29. LOGGING = { 'version': 1, 'disable_existing_loggers': True, 'formatters': { 'verbose':

    { 'format': '%(request_id)s %(levelname)s ...' }, }, 'filters': { 'context': { '()': 'demo.utils.ContextFilter', }, }, 'handlers': { 'console': { 'level': 'DEBUG', 'class': 'logging.StreamHandler', 'formatter': 'verbose', 'filters': ['context'], }, 'postgres': { 'level': 'INFO', 'class': 'demo.utils.PostgresHandler', 'postgres_url': 'postgresql://localhost/demo', 'table': 'app_logs', 'filters': ['context'], }, }, 'loggers': { '__main__': { 'handlers': ['console'], 'level': 'INFO', 'propagate': False, }, 'demo': { 'handlers': ['console', 'postgres'], 'level': 'INFO', 'propagate': False, }, 'urllib3': { 'handlers': ['console', 'postgres'], 'level': 'DEBUG', 'propagate': False, }, 'sqlalchemy.engine': { 'handlers': ['console', 'postgres'], 'level': 'INFO', 'propagate': False, }, }
  30. class PostgresHandler(logging.Handler): def __init__(self, postgres_url, table): super().__init__(self) self.pg = PostgresConnection(postgres_url)

    self.table = table self.formatter = JsonFormatter() def emit(self, record): row = { 'username': record.username, 'domain': record.domain, 'path': record.path, … 'time': datetime.datetime.fromtimestamp(record.created), 'level': record.levelno, 'name': record.name, 'message': record.getMessage(), 'log': self.format(record), # format full log record as json } self.pg.insert_row(self.table, row) Writing > PostgresHandler * Note: Not a complete implementation
  31. class BufferingPostgresHandler(logging.BufferingHandler): def __init__(self, postgres_url, table, capacity): super().__init__(self, capacity) self.pg

    = PostgresConnection(postgres_url) self.table = table self.formatter = JsonFormatter() def flush(self): self.acquire() try: rows = [] for record in self.buffer: row = { 'username': record.username, 'domain': record.domain, 'path': record.path, … 'time': datetime.datetime.fromtimestamp(record.created), 'level': record.levelno, 'name': record.name, 'message': record.getMessage(), 'log': json.dumps(record.__dict__), } rows.append(row) self.pg.insert_rows(self.table, rows) self.buffer = [] finally: self.release() Writing > BufferingPostgresHandler
  32. LOGGING = { 'version': 1, 'disable_existing_loggers': True, 'formatters': { 'verbose':

    { 'format': '%(request_id)s %(levelname)s ...' }, }, 'filters': { 'context': { '()': 'demo.utils.ContextFilter', }, }, 'handlers': { 'console': { 'level': 'DEBUG', 'class': 'logging.StreamHandler', 'formatter': 'verbose', 'filters': ['context'], }, 'postgres': { 'level': 'INFO', 'class': 'demo.utils.BufferingPostgresHandler', 'postgres_url': 'postgresql://localhost/demo', 'table': 'app_logs', 'capacity': 10, 'filters': ['context'], }, }, 'loggers': { '__main__': { 'handlers': ['console'], 'level': 'INFO', 'propagate': False, }, 'demo': { 'handlers': ['console', 'postgres'], 'level': 'INFO', 'propagate': False, }, 'urllib3': { 'handlers': ['console', 'postgres'], 'level': 'DEBUG', 'propagate': False, }, 'sqlalchemy.engine': { 'handlers': ['console', 'postgres'], 'level': 'INFO', 'propagate': False, }, }
  33. Reading Logs Time User Domain Path Level Name Function Message

    15:20:05 brian00 api.example.com /v1/hello INFO demo.app hello Hello PyConWeb 15:20:04 basil api.example.com /v1/hello WARNING demo.utils get_message Something happened 15:20:04 brian00 api.example.com /v1/hello INFO demo.utils get_message Contacting api…. 15:20:03 manuel api.example.com /v1/foo INFO demo.app foo 12 Results... 15:20:03 basil api.example.com /v1/hello INFO demo.utils get_message Contacting api….
  34. Are we still missing some context?

  35. Reading Logs Time User Domain Path Level Name Function Message

    15:20:05 brian00 api.example.com /v1/hello INFO demo.app hello Hello PyConWeb 15:20:04 basil api.example.com /v1/hello WARNING demo.utils get_message Something happened 15:20:04 brian00 api.example.com /v1/hello INFO demo.utils get_message Contacting api…. 15:20:03 manuel api.example.com /v1/foo INFO demo.app foo 12 Results... 15:20:03 basil api.example.com /v1/hello INFO demo.utils get_message Contacting api…. Are these the same request?
  36. Reading Logs Time Request Id User Domain Path Level Name

    Function Message 15:20:05 52615044216 brian00 api.example.com /v1/hello INFO demo.app hello Hello PyConWeb 15:20:04 52615033207 basil api.example.com /v1/hello WARNING demo.utils get_message Something happened 15:20:04 52615044216 brian00 api.example.com /v1/hello INFO demo.utils get_message Contacting api…. 15:20:03 52615038721 manuel api.example.com /v1/foo INFO demo.app foo 12 Results... 15:20:03 52615033207 basil api.example.com /v1/hello INFO demo.utils get_message Contacting api…. Are these the same request? Yes!
  37. app_requests request_id text domain text path text method text username

    text user_agent text client_ip text app_log request_id text time timestamptz level int name text message text log jsonb
  38. Reading Logs Time Level Name Function Message 15:20:04 INFO demo.utils

    get_message Contacting api…. 15:20:05 INFO demo.app hello Hello PyConWeb Request Id 52615044216 Domain api.example.com Path /v1/hello Method GET Username brian00 User-Agent Chrome/74.0.3729.131
  39. Reading Logs Time Level Name Function Message 15:20:03 INFO demo.utils

    get_message Contacting api…. 15:20:04 WARNING demo.app hello Something happened Request Id 52615033207 Domain api.example.com Path /v1/hello Method GET Username basil User-Agent DemoApp/0.1 CFNetwork/978.0.7 Darwin/18.5.0
  40. Context > Filter class ContextFilter(logging.Filter): def filter(self, record): record.request_id =

    get_request_id() # This should be from a ContextVar/ threading.local return True handler.addFilter(ContextFilter())
  41. Formatting > JsonFormatter { "name": "demo.app", "msg": "Hello PyConWeb", "args":

    [], "levelname": "INFO", "levelno": 20, "pathname": "/Users/fergal/workspace/demo/app.py", "filename": "app.py", "module": "app", "exc_info": "None", "exc_text": "None", "stack_info": "None", "lineno": 80, "funcName": "run", "created": 1558132129.1351192, "msecs": 135.11919975280762, "relativeCreated": 2884.1490745544434, "thread": 140735565054784, "threadName": "MainThread", "processName": "MainProcess", "process": 86643, "request_id": "2019052615054684242", "message": "Hello PyConWeb", "asctime": "2019-05-26 15:05:05,468" }
  42. class PostgresHandler(logging.Handler): def __init__(self, postgres_url, table): super().__init__(self) self.pg = PostgresConnection(postgres_url)

    self.table = table self.formatter = JsonFormatter() def emit(self, record): row = { 'request_id': record.request_id, 'time': datetime.datetime.fromtimestamp(record.created), 'level': record.levelno, 'name': record.name, 'message': record.getMessage(), 'log': self.format(record), # format full log record as json } self.pg.insert_row(self.table, row) Writing > PostgresHandler
  43. @app.before_request def before_request_log(): g.request_id = generate_request_id() request_log = { 'request_id':

    g.request_id, 'method': request.method, 'domain': request.host, 'path': request.path, 'query_string': request.query_string.decode(), 'user_agent': str(request.user_agent), 'remote_ip': request.remote_addr, 'username': g.user.name, } pg.insert_row('app_requests', request_log) Request Logs - Flask
  44. @app.before_request def before_request_log(): g.request_id = generate_request_id() g.start_time = datetime.now() request_log

    = { 'request_id': g.request_id, 'method': request.method, 'domain': request.host, 'path': request.path, 'url': request.url, 'query_string': request.query_string.decode(), 'user_agent': str(request.user_agent), 'remote_ip': request.remote_addr, 'username': g.user.name, 'start_time': g.start_time, 'args': dict(request.args), 'request_body': _get_filtered_request_body_for_log(request), } pg.insert_row('app_requests', request_log) Request Logs - Flask
  45. @app.after_request def after_request_log(response): end_time = datetime.now() response_content = None if

    response.status_code >= 400: response_content = response.get_data(as_text=True) values = { 'status': response.status_code, 'response_content': response_content, 'end_time': end_time, 'duration': int((end_time - g.start_time).total_seconds() * 1000), } pg.update_row('app_requests', values, request_id=g.request_id) Request Logs - Flask
  46. App Requests Time Request Id User Method Path Level Status

    Duration 15:20:04 52615044216 brian00 GET /v1/hello INFO 200 701 15:20:03 52615038721 manuel POST /v1/foo INFO 200 227 15:20:03 52615033207 basil GET /v1/hello INFO 500 112 15:20:03 52615034562 aurthur GET /v1/search INFO 404 247 15:20:02 52615029475 the_animator GET /v1/search CRITICAL 500 60
  47. App Logs Time Elapsed Level Name Function Message 15:20:04 11ms

    INFO demo.utils get_message Contacting api…. 15:20:05 680ms INFO demo.app hello Hello PyConWeb Request Id 52615044216 Start Time 2019-05-26 15:04:01 Duration 701ms Status 200 Domain api.example.com Path /v1/hello Method GET Username brian00 User-Agent Chrome/74.0.3729.131
  48. None
  49. None
  50. None
  51. None
  52. But does it scale? Not really. But well enough.. for

    most of us.
  53. Caveats • Maybe you shouldn’t log every request IF: ◦

    You never go debugging individual requests ◦ You care more about statistics than individual requests • Maybe you shouldn’t log directly to a database IF: ◦ Your app doesn’t already use a database ◦ You have already (necessarily) optimised your app to minimise database access • You should cleanup your logs after some time ◦ To avoid wasting space ◦ To comply with user data retention policies/laws • All database writes for logging should be time limited and error handled so an error in logging doesn’t bring down the whole app
  54. Recommendations • Generate a request_id and add to all logs

    (even those generated by libraries) • Format logs as JSON • Write logs to a database • Write request-response metadata to database • Always keep the stderr handlers (StreamHandler) enabled, just in case • Write more log messages • Review the usefulness of your logs periodically
  55. Thanks! Questions? fergal@hipolabs.com @fergalwalsh

  56. Conclusions • Context makes logging more useful • Setting a

    request_id is particularly useful for web apps • logging is very flexible but confusing • Working with formatters, handlers and filters keeps things flexible • Writing logs to a database provides many advantages • More readable logs encourages writing more useful logs -> easier debugging