Pass request details as log record extra fields

[dolfinus]

Summary

I've running an application with uvicorn, and also using python-json-logger to output all production logs in JSON (to pass them to ELK as is, without complicated parsing config).

Here is an example logging config:

version: 1
disable_existing_loggers: false

formatters:
  json:
    (): pythonjsonlogger.jsonlogger.JsonFormatter
    fmt: '%(name)s %(lineno)d %(levelname)s %(message)s'
    timestamp: true

handlers:
  main:
    class: logging.StreamHandler
    formatter: json
    stream: ext://sys.stdout

loggers:
  '':
    handlers: [main]
    propagate: false
  uvicorn:
    handlers: [main]
    propagate: false
  uvicorn.access:
    handlers: [main]
    propagate: false

So instead of logs like these:

INFO:     Started server process [34753]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://0.0.0.0:8000 (Press CTRL+C to quit)
INFO:     127.0.0.1:60084 - "GET /docs HTTP/1.1" 200 OK
INFO:     127.0.0.1:60084 - "GET /openapi.json HTTP/1.1" 200 OK

I got these:

{"name": "uvicorn.error", "lineno": 76, "levelname": "INFO", "message": "Started server process [37546]", "color_message": "Started server process [\u001b[36m%d\u001b[0m]", "timestamp": "2023-11-16T09:38:39.691669+00:00"}
{"name": "uvicorn.error", "lineno": 46, "levelname": "INFO", "message": "Waiting for application startup.", "timestamp": "2023-11-16T09:38:39.691809+00:00"}
{"name": "uvicorn.error", "lineno": 60, "levelname": "INFO", "message": "Application startup complete.", "timestamp": "2023-11-16T09:38:39.692186+00:00"}
{"name": "uvicorn.error", "lineno": 218, "levelname": "INFO", "message": "Uvicorn running on http://0.0.0.0:8000 (Press CTRL+C to quit)", "color_message": "Uvicorn running on \u001b[1m%s://%s:%d\u001b[0m (Press CTRL+C to quit)", "timestamp": "2023-11-16T09:38:39.692461+00:00"}
{"name": "uvicorn.access", "lineno": 483, "levelname": "INFO", "message": "127.0.0.1:60270 - \"GET /docs HTTP/1.1\" 200", "client_addr": "127.0.0.1:60270", "method": "GET", "full_path": "/docs", "http_version": "1.1", "status": 200, "timestamp": "2023-11-16T09:38:47.859381+00:00"}
{"name": "uvicorn.access", "lineno": 483, "levelname": "INFO", "message": "127.0.0.1:60270 - \"GET /openapi.json HTTP/1.1\" 200", "client_addr": "127.0.0.1:60270", "method": "GET", "full_path": "/openapi.json", "http_version": "1.1", "status": 200, "timestamp": "2023-11-16T09:38:48.421080+00:00"}

Message contains lines like 127.0.0.1:60270 - \"GET /openapi.json HTTP/1.1\" 200, but I prefer to have separated fields client_address, method, full_path, status and so on.
uvicorn.access loger already has access to all of this info, but it is logged only in one text field message, which I don't want to parse.

Instead, I've changed the way access_log.info is called - arguments are passed both to message format and to extra, so they can be accessed by other log formatters from LogRecord object. The result is:

version: 1
disable_existing_loggers: false

formatters:
  json:
    (): pythonjsonlogger.jsonlogger.JsonFormatter
    fmt: '%(name)s %(lineno)d %(levelname)s %(message)s'
    timestamp: true
  access:
    (): pythonjsonlogger.jsonlogger.JsonFormatter
    fmt: '%(name)s %(lineno)d %(levelname)s %(client_addr)s %(method)s %(full_path)s %(http_version)s %(status)s'
    timestamp: true

handlers:
  main:
    class: logging.StreamHandler
    formatter: json
    stream: ext://sys.stdout
  access:
    class: logging.StreamHandler
    formatter: access
    stream: ext://sys.stdout

loggers:
  '':
    handlers: [main]
    propagate: false
  uvicorn:
    handlers: [main]
    propagate: false
  uvicorn.access:
    handlers: [access]
    propagate: false

{"name": "uvicorn.error", "lineno": 76, "levelname": "INFO", "message": "Started server process [37991]", "color_message": "Started server process [\u001b[36m%d\u001b[0m]", "timestamp": "2023-11-16T09:41:07.350819+00:00"}
{"name": "uvicorn.error", "lineno": 46, "levelname": "INFO", "message": "Waiting for application startup.", "timestamp": "2023-11-16T09:41:07.351085+00:00"}
{"name": "uvicorn.error", "lineno": 60, "levelname": "INFO", "message": "Application startup complete.", "timestamp": "2023-11-16T09:41:07.351890+00:00"}
{"name": "uvicorn.error", "lineno": 218, "levelname": "INFO", "message": "Uvicorn running on http://0.0.0.0:8000 (Press CTRL+C to quit)", "color_message": "Uvicorn running on \u001b[1m%s://%s:%d\u001b[0m (Press CTRL+C to quit)", "timestamp": "2023-11-16T09:41:07.352437+00:00"}
{"name": "uvicorn.access", "lineno": 483, "levelname": "INFO", "client_addr": "127.0.0.1:48356", "method": "GET", "full_path": "/docs", "http_version": "1.1", "status": 200, "timestamp": "2023-11-16T09:41:09.065982+00:00"}
{"name": "uvicorn.access", "lineno": 483, "levelname": "INFO", "client_addr": "127.0.0.1:48356", "method": "GET", "full_path": "/openapi.json", "http_version": "1.1", "status": 200, "timestamp": "2023-11-16T09:41:09.738589+00:00"}

Checklist

• I understand that this PR may be closed in case there was no previous discussion. (This doesn't apply to typos!)
• I've added a test for each change that was introduced, and I tried as much as possible to make a single atomic change.
• I've updated the documentation accordingly.

[dolfinus]

Same as #2154, just moved to another branch and rebased

[peddyspg]

Is this request still active?
Or any other solution to work with json-logs in a simple way?
Actually, I'm setting up a fastapi+sqlmodel python application running in gcloud. With JSON-Format is much simpler to filter.
Also all Logs <=ERROR schould go to STDOUT, otherwise to STDERROR.

[ComputasSnorriEngen]

Is there any chance this will be implemented any time soon? Exactly what I am missing to make log visualisations useful

[dolfinus]

@Kludex could you take a look, please?

[sanbor]

I was looking into this and found this open PR. Any chance this can be reviewed and merged?

[tino]

I'd like to see this implemented too!

[tino]

I would advice to undo this change. status_code is used throughout, and reverting it back probably makes it easier to accept this patch! (Also because it makes the diff smaller.)