async def sub():
# should be same context as r1
assert Context.logging.flat == {'a': 1}
Context.logging.push(a=2)
Context.track('test', 1.0)
assert Context.logging.flat == {'a': 2}
assert Context.current.tracking['test'].count == 2
async def r2():
# should be a separate context from r1
Context.new()
Context.logging.push(a=3)
Context.track('test', 1.0)
assert Context.logging.flat == {'a': 3}
assert Context.current().tracking['test'].count == 1
async def r1():
Context.logging.push(a=1)
Context.track('test', 1.0)
assert Context.logging.flat == {'a': 1}
assert Context.current.tracking['test'].count == 1
await sub()
# changes made by sub should be visible
assert Context.logging.flat == {'a': 2}
assert Context.current.tracking['test'].count == 2
def record_request(request, response=None, exc=None):
metadata = collect_metadata(request, response)
if response:
Context.track('http', metadata['duration_ms'])
if exc:
metadata.update(get_errno_fields(exc))
talisker.sentry.record_breadcrumb(
type='http',
category='requests',
data=metadata,
)
labels = {
'host': metadata['host'],
'view': metadata.get('view', 'unknown'),
}
ctx = Context.current
metric_api_name = getattr(ctx, 'metric_api_name', None)
metric_host_name = getattr(ctx, 'metric_host_name', None)
if metric_api_name is not None:
labels['view'] = metric_api_name
if metric_host_name is not None:
labels['host'] = metric_host_name
labels['host'] = labels['host'].replace('.', '-')
RequestsMetric.count.inc(**labels)
if response is None:
# likely connection errors
logger.exception('http request failure', extra=metadata)
labels['type'] = 'connection'
labels['status'] = metadata.get('errno', 'unknown')
RequestsMetric.errors.inc(**labels)
else:
logger.info('http request', extra=metadata)
labels['status'] = metadata['status_code']
RequestsMetric.latency.observe(metadata['duration_ms'], **labels)
if metadata['status_code'] >= 500:
labels['type'] = 'http'
RequestsMetric.errors.inc(**labels)
def test_wsgi_request_log(run_wsgi, context):
env = {
'PATH_INFO': '/foo',
'QUERY_STRING': 'bar=baz',
'HTTP_X_FORWARDED_FOR': '203.0.113.195, 150.172.238.178',
'CONTENT_LENGTH': '100',
'CONTENT_TYPE': 'application/json',
'HTTP_REFERER': 'referrer',
'HTTP_USER_AGENT': 'ua',
'REQUEST_ID': 'rid',
}
Context.track('sql', 1.0)
Context.track('http', 2.0)
Context.track('logging', 3.0)
run_wsgi(env, headers=[('X-View-Name', 'view')])
# check for explicit order preservation
log = context.logs.find(msg='GET /foo?')
assert log is not None
assert list(log.extra.items()) == [
('method', 'GET'),
('path', '/foo'),
('qs', 'bar=baz'),
('status', 200),
('view', 'view'),
('duration_ms', 1000.0),
('ip', '127.0.0.1'),
('proto', 'HTTP/1.0'),
('length', 1000),
('request_length', 100),
('request_type', 'application/json'),
('referrer', 'referrer'),
('forwarded', '203.0.113.195, 150.172.238.178'),
('ua', 'ua'),
('http_count', 1),
('http_time_ms', 2.0),
('logging_count', 1),
('logging_time_ms', 3.0),
('sql_count', 1),
('sql_time_ms', 1.0),
]
assert context.statsd[0] == 'wsgi.requests.view.GET.200:1|c'
assert context.statsd[1] == 'wsgi.latency.view.GET.200:1000.000000|ms'