Access log format not working as documented

[fiunchinho]

I'd like to output my access log using JSON, but some of the access log fields seem to be not working.

For example, the following configuration in the gunicorn_config.py file

bind = '0.0.0.0:5000'
loglevel = 'info'
accesslog = '-'
errorlog = '-'
access_log_format = '{"request": "%(r)s", "http_status_code": "%(s)s", "http_request_url": "%(U)s", "http_query_string": "%(q)s", "http_verb": "%(m)s", "http_version": "%(H)s"}'

I get the following output

{
  "stack_info": null,
  "level": "INFO",
  "timestamp": "2018-02-18T16:20:13.153947Z",
  "path": "/usr/local/lib/python3.5/site-packages/gunicorn/glogging.py",
  "message": "{\"request\": \"POST /format HTTP/1.1\", \"http_status_code\": \"200\", \"http_request_url\": \"-\", \"http_query_string\": \"-\", \"http_verb\": \"-\", \"http_version\": \"-\"}",
  "host": "87eab0ccce6a",
  "logger": "gunicorn.access",
  "tags": []
}

Notice how some fields like the method or the protocol are missing from the log line, even though the information seems to be accesible from other places. The method should be POST, not '-'. Same for the URL (should be /format).

Is this a bug?

[tilgovi]

Is that the final logging output or have you "tapped" the logging methods somewhere to inspect their arguments?

[fiunchinho]

Not sure if I understand the question. That's the output taken directly from the console

[tilgovi]

Are you using some JSON log formatter, then? How do you configure it?

I ask because you pasted a dictionary and not a single log message in the normal text format. I want to know whether you've configured logging some way you haven't shown, or whether you were printing/debugging local variables rather than the actual log output.

[tilgovi]

If that isn't clear, I'll say a little more.

You are passing access_log_format but the block you pasted shows other fields surrounding a message field that contains a message with the format specified by access_log_format. Where are you getting this output and how are you creating it?

[fiunchinho]

This is my logging config

[loggers]
keys=root, gunicorn.error, gunicorn.access

[handlers]
keys=console

[formatters]
keys=json

[logger_root]
level=INFO
handlers=console

[logger_gunicorn.error]
level=ERROR
handlers=console
propagate=0
qualname=gunicorn.error

[logger_gunicorn.access]
level=INFO
handlers=console
propagate=0
qualname=gunicorn.access

[handler_console]
class=StreamHandler
formatter=json
args=(sys.stdout, )

[formatter_json]
class=jsonlogging.JSONFormatter

And I start my application with
gunicorn --log-config feed/gunicorn_logging.conf -c feed/gunicorn_config.py --chdir /code/feed application:app

[fiunchinho]

Any hints?

[benoitc]

PATH_INFO should be at least. Can you paste the configuration of your web server. Ay way to reproduce it?

[fiunchinho]

Updating the version of flask and gunicorn fixed the issue.

[jakebolam]

Just ran into the same issue, updating flask and gunicorn fixed the issue.

[waketzheng]

Ran into similar issue with worker class uvicorn.workers.UvicornWorker and fix it as this: encode/uvicorn#527 (comment)