Context Matters - more useful logging with Python

Producing more useful logs with Python

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
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