Context Matters Fergal Walsh [email protected] Producing more useful logs with Python 

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

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 

logger.info(‘Hello PyConWeb’) INFO slides: Hello PyConWeb Adapter str Logger str Filter Filters LogRecord Filter Handlers LogRecord LogRecord Filter Filters Formatter str LogRecord 

Logs Screenshot 

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 

● 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 

● 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 

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 

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 

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 

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 

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

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 

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) 

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 

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

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 

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 

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 

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

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

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

{ "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" } 

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? 

Writing > Handlers StreamHandler FileHandler RotatingFileHandler SocketHandler DatagramHandler SMTPHandler MemoryHandler HTTPHandler QueueHandler 

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 

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 

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

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 

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 

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

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 we still missing some context? 

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? 

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! 

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 

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 

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 

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

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

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 

@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 

@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 

@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 

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 

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 

No content

No content

No content

No content

But does it scale? Not really. But well enough.. for most of us. 

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 

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 

Thanks! Questions? [email protected] @fergalwalsh 

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