New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

gunicorn.error doesn't have the timezone set for timestamps #1626

Open
SEJeff opened this Issue Oct 17, 2017 · 1 comment

Comments

Projects
None yet
2 participants
@SEJeff

SEJeff commented Oct 17, 2017

Given a logging.conf such as:

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

[handlers]
keys=console,console_access

[formatters]
keys=generic,access_log

[logger_root]
level=INFO
handlers=console

# HTTP access logs
[logger_gunicorn.access]
level=INFO
handlers=console_access
propagate=0
qualname=gunicorn.access

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

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

[handler_console_access]
class=StreamHandler
formatter=access_log
args=(sys.stdout,)

[formatter_generic]
# type:error to more easily search for just error messages
format=time:%(asctime)s message:%(message)s type:error
datefmt=[%d/%b/%Y:%H:%M:%S %z]
class=logging.Formatter

[formatter_access_log]
# type:access_log to more easily search for the access logs
format=%(message)s  type:access_log

And a config with these ltsv () separated values for the access log:

access_log_format = 'time:%(t)s host:%(h)s  forwardedfor:%({X-Forwarded-For}i)s req:"%(r)s" status:%(s)s    size:%(b)s  referer:"%(f)s" ua:"%(a)s"  reqtime:%(L)s   user:%(u)s  host:%({Host}i)s'

The timestamps show different timezones depending on the logger:

time:[17/Oct/2017:08:01:19 +0000]	message:Starting gunicorn 19.7.1	type:error
time:[17/Oct/2017:08:01:19 +0000]	message:Arbiter booted	type:error
time:[17/Oct/2017:08:01:19 +0000]	message:Listening at: http://0.0.0.0:8000 (67867)	type:error
time:[17/Oct/2017:08:01:19 +0000]	message:Using worker: sync	type:error
time:[17/Oct/2017:08:01:19 +0000]	message:Server is ready. Spawning workers	type:error
time:[17/Oct/2017:08:01:19 +0000]	message:Booting worker with pid: 67872	type:error
time:[17/Oct/2017:08:01:19 +0000]	message:Worker spawned (pid: 67872)	type:error
time:[17/Oct/2017:08:01:19 +0000]	message:1 workers	type:error
time:[17/Oct/2017:08:01:20 +0000]	message:GET /version/	type:error
time:[17/Oct/2017:08:01:20 -0500]	host:1.2.3.4	forwardedfor:1.2.3.5	req:"GET /version/ HTTP/1.1"	status:200	size:42	referer:"https://yomom.fool"	ua:"curl/7.29.0"	reqtime:0.002553	user:-	host:localhost:8000	type:access_log

I'm running gunicorn this way:

gunicorn --config blah_config.py --log-config logging.conf blah:app

It seems wrong that the gunicorn.error logs have no timezone set and the gunicorn.access logs have the correct timezone set on the datetime.

@wimglenn

This comment has been minimized.

Show comment
Hide comment
@wimglenn

wimglenn Nov 9, 2017

This is a configuration issue:

datefmt=[%d/%b/%Y:%H:%M:%S %z]

%z (lowercase z) is unsupported on Python 2. Whether it works or not is platform dependent, but it's buggy/undocumented and can't be relied on (see also the footnote at the bottom of the linked page).

Your options are:

  • Experiment with using the deprecated '%Z' instead (upper Z)
  • Use Python 3 where %z works normally
  • Don't log in local time, configure to enforce logging in UTC

wimglenn commented Nov 9, 2017

This is a configuration issue:

datefmt=[%d/%b/%Y:%H:%M:%S %z]

%z (lowercase z) is unsupported on Python 2. Whether it works or not is platform dependent, but it's buggy/undocumented and can't be relied on (see also the footnote at the bottom of the linked page).

Your options are:

  • Experiment with using the deprecated '%Z' instead (upper Z)
  • Use Python 3 where %z works normally
  • Don't log in local time, configure to enforce logging in UTC
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment