gunicorn access log format

Question

I'm planning to run flask through gunicorn at kubernetes. To get the logging right, I want to output all my logs in json.

Currently I'm testing with minikube and https://github.com/inovex/kubernetes-logging to have fluentd collecting the logs.

I managed to get the errorlogs (tracebacks) properly formated thanks to: JSON formatted logging with Flask and gunicorn

I'm still struggling with the access log format. I specified the following gunicorn access log format:

access_log_format = '{"remote_ip":"%(h)s","request_id":"%({X-Request-Id}i)s","response_code":"%(s)s","request_method":"%(m)s","request_path":"%(U)s","request_querystring":"%(q)s","request_timetaken":"%(D)s","response_length":"%(B)s"}'

And the resulting log is json formated. But the message part (format based on access_log_format) now contains escaped double quotes, and will not be parsed by fluentd / ELK into it's individual fields

{"tags": [], "timestamp": "2017-12-07T11:50:20.362559Z", "level": "INFO", "host": "ubuntu", "path": "/usr/local/lib/python2.7/dist-packages/gunicorn/glogging.py", "message": "{\"remote_ip\":\"127.0.0.1\",\"request_id\":\"-\",\"response_code\":\"200\",\"request_method\":\"GET\",\"request_path\":\"/v1/records\",\"request_querystring\":\"\",\"request_timetaken\":\"19040\",\"response_length\":\"20\"}", "logger": "gunicorn.access"}

Thanks Jpw

Answer 1

I was searching for something that would be useful in a logging config file. Also, i am not a fan of manually constructing json formats by hand.
Solution: All of of gunicorn's logging arguments are available in the record's args. So let's grab the fields from there and let pythonjsonlogger do the rest of the work for us.

Formatter Class

from pythonjsonlogger.jsonlogger import JsonFormatter, merge_record_extra


class GunicornLogFormatter(JsonFormatter): 
    def add_fields(self, log_record, record, message_dict):
        """
        This method allows us to inject gunicorn's args as fields for the formatter
        """
        super(GunicornLogFormatter, self).add_fields(log_record, record, message_dict)
        for field in self._required_fields:
            if field in self.rename_fields:
                log_record[self.rename_fields[field]] = record.args.get(field)
            else:
                log_record[field] = record.args.get(field)

Sample Logging Config File

version: 1
disable_existing_loggers: False
formatters:
  gunicorn_json:
    (): GunicornLogFormatter
    format: '%(h)s %(r)s %({x-request-id}i)s'
    datefmt: '%Y-%m-%dT%H:%M:%S%z'
    rename_fields:
      levelname: level
      '{x-request-id}i': request_id
      r: request

handlers:
  json-gunicorn-console:
    class: logging.StreamHandler
    level: INFO
    formatter: gunicorn_json
    stream: ext://sys.stdout

loggers:
  gunicorn.access:
    level: INFO
    handlers:
      - json-gunicorn-console

Sample Logs

{"h": "127.0.0.1", "request": "GET /login?next=/ HTTP/1.1", "request_id": null}
{"h": "127.0.0.1", "request": "GET /static/css/style.css HTTP/1.1", "request_id": null}
{"h": "127.0.0.1", "request": "GET /some/random/path HTTP/1.1", "request_id": null}
{"h": "127.0.0.1", "request": "GET /some/random/path HTTP/1.1", "request_id": "123123123123123123"}