[WIP] gateway: Use structlog for structured logging #18
Conversation
Makes it possible to filter logs for a particular door or request, and to monitor processing times for HTTP requests and MQTT messages
|
|
||
| key_order = ['door', 'method', 'path', 'user', 'request_id', 'topic', 'payload'] | ||
|
|
||
| # FIXME: add timestamping |
There was a problem hiding this comment.
Timestamping is added by journald/docker so it might not be needed.
| ) | ||
|
|
||
|
|
||
| log_path = os.environ.get('DLOCK_LOG_PATH', 'logs') |
There was a problem hiding this comment.
Is the log file rotated with this?
There was a problem hiding this comment.
No but there is a handler in the standard library which has rotation. Can switch to that
| ## Logging helpers | ||
| def log_request(sender, **extra): | ||
| r, g = flask.request, flask.g | ||
|
|
||
| # add info | ||
| g.request_id = r.headers.get('X-Request-Id', str(uuid.uuid4())) | ||
| g.request_start_time = time.time() | ||
|
|
||
| log_params = request_log_params() | ||
| log_params.update(dict( | ||
| )) | ||
|
|
||
| log.info('http-request-start', **log_params) | ||
|
|
||
| def log_response(sender, response, **extra): | ||
| r, g = flask.request, flask.g | ||
|
|
||
| g.request_end_time = time.time() | ||
| duration = 1000.0 * (flask.g.request_end_time - flask.g.request_start_time) | ||
|
|
||
| log_params = request_log_params() | ||
| log_params.update(dict( | ||
| status_code=response.status_code, | ||
| duration_ms=duration, | ||
| )) | ||
|
|
||
| log.info('http-request-end', **log_params) |
There was a problem hiding this comment.
If these could push at least the request path to a thread local dict that would be useful. makes it easier to correlate stuff. https://www.structlog.org/en/stable/thread-local.html
If it could add a "request_id" field which is just an uuid we can trace all logging from a specific request which is also nice.
There was a problem hiding this comment.
request path and request_id is included, see the request_log_param() helper. Though not all logged events have it yet. Will try to use the threadlocal mechanism instead of doing it explicitly, to get it everywhere
Makes it possible to filter logs for a particular door or request,
and to monitor processing times for HTTP requests and MQTT messages
For now the log events are quite centered around the HTTP and MQTT loops.
Would be possible to add more "application logic specific" events, if desired.
Feedback on what more information is desirable to log is welcomed.
Right now
key=valuerendering is for the output. It is possible to change this to JSON, at least for the file log.