def test_gunicorn_logger_set_formatters_on_gunicorn_logs():
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
error = logger._get_gunicorn_handler(logger.error_log)
assert isinstance(error.formatter, logs.StructuredFormatter)
access = logger._get_gunicorn_handler(logger.access_log)
assert isinstance(access.formatter, logs.StructuredFormatter)
def test_gunicorn_logger_get_extra_str_status(environ):
response, environ, delta, expected = access_extra_args(environ, '/')
cfg = Config()
logger = gunicorn.GunicornLogger(cfg)
response.status = '200 OK'
msg, extra = logger.get_extra(response, None, environ, delta)
assert extra['status'] == '200'
def test_gunicorn_logger_get_extra(environ):
response, environ, delta, expected = access_extra_args(
environ, '/foo?bar=baz')
cfg = Config()
logger = gunicorn.GunicornLogger(cfg)
msg, extra = logger.get_extra(response, None, environ, delta, 200)
assert msg == 'GET /foo?'
assert extra == expected
def test_gunicorn_logger_logging(level, statsd_metrics, log):
cfg = Config()
logger = gunicorn.GunicornLogger(cfg)
getattr(logger, level)(level)
expected = 'ERROR' if level == 'exception' else level.upper()
assert log[0].levelname == expected
assert log[0].getMessage() == level
assert 'gunicorn.log.{}:1|c'.format(level) in statsd_metrics[0]
def test_gunicorn_logger_access(environ, log):
response, environ, delta, expected = access_extra_args(environ, '/')
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
logger.access(response, None, environ, delta)
log[0]._structured == expected
def test_gunicorn_logger_access_qs(environ, context):
response, environ, delta, expected = access_extra_args(
environ, '/url?foo=bar')
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
context.logs[:] = []
logger.access(response, None, environ, delta)
assert context.logs.exists(msg='GET /url?', extra=expected)
def test_gunicorn_logger_access_forwarded(environ, context):
response, environ, delta, expected = access_extra_args(environ, '/')
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
context.logs[:] = []
logger.access(response, None, environ, delta)
assert context.logs.exists(msg='GET /', extra=expected)
assert context.statsd[0] == 'gunicorn.count.view.GET.200:1|c'
assert context.statsd[1].startswith('gunicorn.latency.view.GET.200:')
def test_gunicorn_logger_access_qs(environ, log):
response, environ, delta, expected = access_extra_args(
environ, '/url?foo=bar')
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
log[:] = []
logger.access(response, None, environ, delta)
assert log[0]._structured == expected
assert log[0].msg == 'GET /url?'
def test_gunicorn_logger_status_url(environ, log, statsd_metrics):
response, environ, delta, expected = access_extra_args(
environ, '/_status/ping')
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
statsd.get_client() # force the statsd creationg log message
log[:] = []
logger.access(response, None, environ, delta)
assert len(log) == 0
assert len(statsd_metrics) == 0
def test_gunicorn_logger_status_url_enabled(environ, context, monkeypatch):
response, environ, delta, expected = access_extra_args(
environ, '/_status/ping')
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
statsd.get_client() # force the statsd creationg log message
context.logs[:] = []
monkeypatch.setitem(os.environ, 'TALISKER_LOGSTATUS', 'true')
logger.access(response, None, environ, delta)
assert len(context.logs) == 1
assert len(context.statsd) == 0
def test_gunicorn_logger_access_forwarded(environ, log, statsd_metrics):
response, environ, delta, expected = access_extra_args(environ, '/')
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
log[:] = []
logger.access(response, None, environ, delta)
assert log[0]._structured == expected
assert log[0].msg == 'GET /'
assert statsd_metrics[0] == 'gunicorn.count.view.GET.200:1|c'
assert statsd_metrics[1].startswith('gunicorn.latency.view.GET.200:')
def test_gunicorn_logger_access_with_request_id(environ, context):
rid = 'request-id'
response, environ, delta, expected = access_extra_args(environ, '/')
expected['request_id'] = rid
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
context.logs[:] = []
with request_id.context(rid):
logger.access(response, None, environ, delta)
assert context.logs.exists(extra=expected)
def test_gunicorn_logger_access_with_request_id(environ, log):
rid = 'request-id'
response, environ, delta, expected = access_extra_args(environ, '/')
expected['request_id'] = rid
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
log[:] = []
with request_id.context(rid):
logger.access(response, None, environ, delta)
assert log[0]._structured == expected
def test_gunicorn_logger_access_with_request_content(environ, log):
response, environ, delta, expected = access_extra_args(environ, '/')
environ['CONTENT_TYPE'] = 'type'
environ['CONTENT_LENGTH'] = '10'
expected['request_type'] = 'type'
expected['request_length'] = 10
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
log[:] = []
logger.access(response, None, environ, delta)
assert log[0]._structured == expected
def test_gunicorn_logger_access_with_request_id(environ, log):
rid = 'request-id'
response, environ, delta, expected = access_extra_args(
environ, '/')
response.headers.append(('X-Request-Id', rid))
expected['request_id'] = rid
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
log[:] = []
logger.access(response, None, environ, delta)
assert log[0]._structured == expected
def test_gunicorn_logger_access_no_forwarded(environ, context):
response, environ, delta, expected = access_extra_args(environ, '/')
environ.pop('HTTP_X_FORWARDED_FOR')
response.headers = [('X-View-Name', 'view')]
expected.pop('forwarded')
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
context.logs[:] = []
logger.access(response, None, environ, delta)
assert context.logs.exists(msg='GET /', extra=expected)
assert context.statsd[0] == 'gunicorn.count.view.GET.200:1|c'
assert context.statsd[1].startswith('gunicorn.latency.view.GET.200:')
def test_gunicorn_logger_access_500(environ, context):
response, environ, delta, expected = access_extra_args(environ, '/')
response.status_code = 500
response.status = '500 Server Error'
expected['status'] = 500
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
context.logs[:] = []
logger.access(response, None, environ, delta)
assert context.logs.exists(msg='GET /', extra=expected)
assert context.statsd[0] == 'gunicorn.count.view.GET.500:1|c'
assert context.statsd[1] == 'gunicorn.errors.view.GET.500:1|c'
assert context.statsd[2].startswith('gunicorn.latency.view.GET.500:')
def test_gunicorn_logger_access_no_forwarded(environ, log, statsd_metrics):
response, environ, delta, expected = access_extra_args(environ, '/')
environ.pop('HTTP_X_FORWARDED_FOR')
response.headers = [('X-View-Name', 'view')]
expected.pop('forwarded')
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
log[:] = []
logger.access(response, None, environ, delta)
assert log[0]._structured == expected
assert log[0].msg == 'GET /'
assert statsd_metrics[0] == 'gunicorn.count.view.GET.200:1|c'
assert statsd_metrics[1].startswith('gunicorn.latency.view.GET.200:')
def test_gunicorn_get_response_status():
cfg = Config()
logger = gunicorn.GunicornLogger(cfg)
class Response1:
status_code = 200
assert logger.get_response_status(Response1()) == 200
class Response2:
status = '200 OK'
assert logger.get_response_status(Response2()) == 200
class Response3:
status = 200
assert logger.get_response_status(Response3()) == 200
def test_gunicorn_logger_access(environ, log, statsd_metrics):
response, environ, delta, expected = access_extra_args(
environ, '/')
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
log[:] = []
logger.access(response, None, environ, delta)
assert log[0]._structured == expected
assert log[0].msg == 'GET /'
assert 'gunicorn.request.duration:' in statsd_metrics[0]
assert 'gunicorn.requests:1|c' in statsd_metrics[1]
assert 'gunicorn.request.status.200:1|c' in statsd_metrics[2]
def test_gunicorn_logger_access_500(environ, log, statsd_metrics):
response, environ, delta, expected = access_extra_args(environ, '/')
response.status_code = 500
response.status = '500 Server Error'
expected['status'] = 500
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
log[:] = []
logger.access(response, None, environ, delta)
assert log[0]._structured == expected
assert log[0].msg == 'GET /'
assert statsd_metrics[0] == 'gunicorn.count.view.GET.500:1|c'
assert statsd_metrics[1] == 'gunicorn.errors.view.GET.500:1|c'
assert statsd_metrics[2].startswith('gunicorn.latency.view.GET.500:')
def test_gunicorn_logger_get_extra(environ):
track_request_metric('sql', 1.0)
track_request_metric('http', 2.0)
track_request_metric('log', 3.0)
response, environ, delta, expected = access_extra_args(
environ, '/foo?bar=baz')
expected['sql_count'] = 1
expected['sql_time_ms'] = 1.0
expected['http_count'] = 1
expected['http_time_ms'] = 2.0
expected['log_count'] = 1
expected['log_time_ms'] = 3.0
cfg = Config()
logger = gunicorn.GunicornLogger(cfg)
msg, extra = logger.get_extra(response, None, environ, delta, 200)
assert msg == 'GET /foo?'
assert extra == expected
def test_gunicorn_logger_propagate_error_log():
cfg = Config()
logger = gunicorn.GunicornLogger(cfg)
assert logger.error_log.propagate is True
assert len(logger.error_log.handlers) == 0
def test_gunicorn_logger_no_handler_for_stderr_access_log():
cfg = Config()
cfg.set('accesslog', '-')
logger = gunicorn.GunicornLogger(cfg)
assert logger.access_log.propagate is True
assert logger._get_gunicorn_handler(logger.access_log) is None
def test_gunicorn_logger_now():
logger = gunicorn.GunicornLogger(Config())
ts = logger.now()
assert ts == '[02/Jan/2016:03:04:05.678 +0000]'
