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
def test_adapter_raises_when_context_deadline_exceeded():
Context.new()
Context.set_relative_deadline(0)
session = requests.Session()
adapter = talisker.requests.TaliskerAdapter()
session.mount('http://name', adapter)
with pytest.raises(talisker.DeadlineExceeded):
session.get('http://name/foo')
def test_adapter_respects_context_timeout(send_kwargs):
Context.new()
Context.set_relative_deadline(500)
session = requests.Session()
adapter = talisker.requests.TaliskerAdapter()
session.mount('http://name', adapter)
session.get('http://name/foo')
assert send_kwargs['timeout'] == (0.5, 0.5)
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 send(self, request, *args, **kwargs):
# ensure both connect and read timeouts set
request._original_url = request.url
retry = self.__retry
connect, read = self.connect_timeout, self.read_timeout
timeout = kwargs.pop('timeout', None)
if timeout:
# timeout can be one of:
# - number
# - Retry
# - (number, Retry)
# - (number, number)
# - (number, number, Retry)
if isinstance(timeout, (int, float)):
read = self.connect_timeout
elif isinstance(timeout, Retry):
retry = timeout
else:
try:
if isinstance(timeout[-1], urllib3.Retry):
retry = timeout[-1]
timeout = timeout[:-1]
size = len(timeout)
assert size in (1, 2)
if size == 1:
read = timeout[0]
elif size == 2:
connect, read = timeout
except Exception:
raise ValueError(
'timeout must be a float/int, None, urllib3.Retry, '
'or a tuple of either two float/ints, '
'or two float/ints and a urllib3.Retry'
)
# enforce any context deadline
ctx_timeout = Context.deadline_timeout()
if ctx_timeout is not None:
connect = min(connect, ctx_timeout)
read = min(read, ctx_timeout)
# ensure urllib3 timeout
kwargs['timeout'] = (connect, read)
# load balance the url
self.select_backend(request)
# if no retry, just pass straight to base class
if retry is None:
return super().send(
request,
*args,
**self.modify_send_kwargs_for_request(request, kwargs)
)
request._retry = retry.new()
request._start = time.time()
request._read_timeout = read
return self._send(request, *args, **kwargs)
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_context_asyncio():
if sys.version_info < (3, 7):
if sys.version_info < (3, 5, 3):
pytest.skip('aiocontextvars does not work in python {}'.format(
sys.version))
elif not pkg_is_installed('aiocontextvars'):
pytest.skip('aiocontextvars not installed')
async def r1():
Context.new()
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
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
# ensure we have no context
loop = asyncio.get_event_loop()
Context.clear()
t1 = loop.create_task(r1())
t2 = loop.create_task(r2())
loop.run_until_complete(asyncio.gather(t1, t2))
def test_metric_hook_user_name(context, get_breadcrumbs):
r = mock_response(view='view')
Context.current().metric_api_name = 'api'
Context.current().metric_host_name = 'service'
talisker.requests.metrics_response_hook(r)
assert context.statsd[0] == 'requests.count.service.api:1|c'
assert context.statsd[1] == (
'requests.latency.service.api.200:1000.000000|ms')
breadcrumbs = get_breadcrumbs()
if breadcrumbs is not None:
assert breadcrumbs[0]['type'] == 'http'
assert breadcrumbs[0]['category'] == 'requests'
assert breadcrumbs[0]['data']['url'] == 'http://example.com/'
assert breadcrumbs[0]['data']['host'] == 'example.com'
assert breadcrumbs[0]['data']['view'] == 'view'
assert breadcrumbs[0]['data']['method'] == 'GET'
assert breadcrumbs[0]['data']['status_code'] == 200
assert breadcrumbs[0]['data']['duration_ms'] == 1000.0
def test_configured_session(context, get_breadcrumbs):
deadline = time.time() + 10
expected_deadline = datetime.utcfromtimestamp(deadline).isoformat() + 'Z'
Context.set_debug()
Context.set_absolute_deadline(deadline)
session = requests.Session()
talisker.requests.configure(session)
responses.add(
responses.GET,
'http://localhost/foo/bar',
body='OK',
headers={'X-View-Name': 'view'},
)
with talisker.testing.request_id('XXX'):
session.get('http://localhost/foo/bar')
for header_name in responses.calls[0].request.headers:
assert isinstance(header_name, native_str)
headers = responses.calls[0].request.headers
assert headers['X-Request-Id'] == 'XXX'
assert headers['X-Request-Deadline'] == expected_deadline
assert headers['X-Debug'] == '1'
assert context.statsd[0] == 'requests.count.localhost.view:1|c'
assert context.statsd[1].startswith(
'requests.latency.localhost.view.200:')
breadcrumbs = get_breadcrumbs()
if breadcrumbs is not None:
assert breadcrumbs[0]['type'] == 'http'
assert breadcrumbs[0]['category'] == 'requests'
assert breadcrumbs[0]['data']['url'] == 'http://localhost/foo/bar'
assert breadcrumbs[0]['data']['host'] == 'localhost'
assert breadcrumbs[0]['data']['view'] == 'view'
assert breadcrumbs[0]['data']['method'] == 'GET'
assert breadcrumbs[0]['data']['status_code'] == 200
assert 'duration_ms' in breadcrumbs[0]['data']
def request(method, url, **kwargs):
ctx = Context.current()
try:
ctx.metric_api_name = kwargs.pop('metric_api_name', None)
ctx.metric_host_name = kwargs.pop('metric_host_name', None)
return func(method, url, **kwargs)
finally:
# some requests errors can cause the context to be lost, and we
# should never fail due to this.
try:
del ctx.metric_api_name
del ctx.metric_host_name
except Exception:
pass
def send(request, **kwargs):
rid = Context.request_id
if rid and config.id_header not in request.headers:
request.headers[config.id_header] = rid
ctx_deadline = Context.current().deadline
if ctx_deadline:
deadline = datetime.utcfromtimestamp(ctx_deadline)
formatted = deadline.isoformat() + 'Z'
request.headers[config.deadline_header] = formatted
if Context.debug:
request.headers[DEBUG_HEADER] = '1'
try:
return func(request, **kwargs)
except Exception as e:
record_request(request, None, e)
raise
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'
def app(environ, _start_response):
contexts.append(Context.current())
_start_response('200 OK', [('Content-Type', 'text/plain')])
return [b'OK']
