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']