diff --git a/talisker/config.py b/talisker/config.py index 919090b2..cec62013 100644 --- a/talisker/config.py +++ b/talisker/config.py @@ -33,7 +33,7 @@ import collections from future.utils import text_to_native_str -from ipaddress import ip_network +from ipaddress import ip_network, ip_address import os import subprocess import sys @@ -390,6 +390,14 @@ def deadline_header(self, raw_name): def wsgi_id_header(self): return 'HTTP_' + self.id_header.upper().replace('-', '_') + def is_trusted_addr(self, addr_str): + if not addr_str: + return False + ip = ip_address(force_unicode(addr_str)) + return ip.is_loopback or any( + ip in network for network in self.networks + ) + def parse_config_file(filename): module = { diff --git a/talisker/context.py b/talisker/context.py index b8918c72..01dbe5c2 100644 --- a/talisker/context.py +++ b/talisker/context.py @@ -151,6 +151,7 @@ def __init__(self, context_id): self.tracking = defaultdict(Tracker) self.soft_timeout = -1 self.deadline = None + self.debug = False def set_deadline(self, timeout): """Set the absolute request deadline.""" @@ -221,6 +222,13 @@ def request_id(self): def request_id(self, _id): self.current.request_id = _id + @property + def debug(self): + return self.current.debug + + def set_debug(self): + self.current.debug = True + def deadline_timeout(self): if self.current.deadline is None: return None diff --git a/talisker/endpoints.py b/talisker/endpoints.py index 164ca676..46f18ecc 100644 --- a/talisker/endpoints.py +++ b/talisker/endpoints.py @@ -32,7 +32,6 @@ import collections from datetime import datetime import functools -from ipaddress import ip_address import logging import os import sys @@ -82,14 +81,19 @@ def private(f): @functools.wraps(f) def wrapper(self, request): config = talisker.get_config() - if not request.access_route: - # this means something probably bugged in werkzeug, but let's fail - # gracefully - return Response('no client ip provided', status='403 Forbidden') - - ip_str = force_unicode(request.access_route[-1]) - ip = ip_address(ip_str) - if ip.is_loopback or any(ip in network for network in config.networks): + # talisker middleware provides this + ip_str = request.environ.get('CLIENT_ADDR') + if ip_str is None: + # fallback to werkzeug's handling + ip_str = force_unicode(request.access_route[-1]) + + if ip_str is None: + return Response( + 'no client ip provided', + status='403 Forbidden', + ) + + if config.is_trusted_addr(ip_str): return f(self, request) else: msg = PRIVATE_BODY_RESPONSE_TEMPLATE.format( @@ -97,6 +101,7 @@ def wrapper(self, request): force_unicode(request.remote_addr), request.headers.get('x-forwarded-for')) return Response(msg, status='403 Forbidden') + return wrapper diff --git a/talisker/testing.py b/talisker/testing.py index b85e335b..1d5aa181 100644 --- a/talisker/testing.py +++ b/talisker/testing.py @@ -222,7 +222,9 @@ def _parse_line(self, lines): date, tod, level, name, msg = parsed[:5] extra = dict((v.split('=', 1)) for v in parsed[5:]) except ValueError: - raise ValueError("failed to parse logfmt:\n" + '\n'.join(lines)) + raise AssertionError( + "failed to parse logfmt:\n" + '\n'.join(lines) + ) # create a minimal LogRecord to search against record = logging.LogRecord( diff --git a/talisker/wsgi.py b/talisker/wsgi.py index 047d3ae4..f25b058e 100644 --- a/talisker/wsgi.py +++ b/talisker/wsgi.py @@ -174,6 +174,8 @@ def __init__(self, environ, start_response, added_headers=None): + + # request metadata self.environ = environ self.original_start_response = start_response self.added_headers = added_headers @@ -215,6 +217,10 @@ def start_response(self, status, headers, exc_info=None): self.environ['REQUEST_ID'], ) + # are we going to be sending a sentry report? If so, include header + if self.exc_info or Context.debug: + set_wsgi_header(headers, 'X-Sentry-Id', self.environ['SENTRY_ID']) + self.status = status status_code, _, _ = status.partition(' ') self.status_code = int(status_code) @@ -382,17 +388,23 @@ def finish_request(self, timeout=False): # We want to send a sentry report if: # a) an error or timeout occured # b) soft timeout - # c) manual debugging (TODO) + # c) manual debugging if talisker.sentry.enabled: soft_timeout = Context.current.soft_timeout try: if self.exc_info: self.send_sentry(metadata) + elif Context.debug: + self.send_sentry( + metadata, + msg='Debug: {}'.format(metadata['path']), + level='debug', + ) elif soft_timeout > 0 and response_latency > soft_timeout: self.send_sentry( metadata, - msg='start_response latency exceeded soft timeout', + msg='Soft Timeout: {}'.format(metadata['path']), level='warning', extra={ 'start_response_latency': response_latency, @@ -500,8 +512,12 @@ def metrics(self, extra): elif self.status_code and self.status_code >= 500: WSGIMetric.errors.inc(**labels) - def send_sentry(self, metadata, msg=None, **kwargs): + def send_sentry(self, metadata, msg=None, data=None, **kwargs): from raven.utils.wsgi import get_current_url, get_environ, get_headers + if data is None: + data = {} + if 'SENTRY_ID' in self.environ: + data['event_id'] = self.environ['SENTRY_ID'] # sentry displays these specific fields in a different way http_context = { 'url': get_current_url(self.environ), @@ -516,6 +532,7 @@ def send_sentry(self, metadata, msg=None, **kwargs): http_context, exc_info=self.exc_info, msg=msg, + data=data, **kwargs ) @@ -538,9 +555,11 @@ def __init__(self, app, environ=None, headers=None): self.environ = environ self.headers = headers + # ensure new workers have an initialised sentry_context + talisker.sentry.new_context() + def __call__(self, environ, start_response): Context.new() - talisker.sentry.new_context() config = talisker.get_config() # setup environment @@ -552,11 +571,40 @@ def __call__(self, environ, start_response): environ[config.wsgi_id_header] = str(uuid.uuid4()) rid = environ[config.wsgi_id_header] environ['REQUEST_ID'] = rid - Context.request_id = rid + # needs to be different from request id, as request can be passed on to + # upstream services + environ['SENTRY_ID'] = uuid.uuid4().hex - # populate default values + Context.request_id = rid Context.current.soft_timeout = config.soft_request_timeout + # calculate ip route + route = None + try: + forwarded = environ.get('HTTP_X_FORWARDED_FOR') + if forwarded: + route = [a.strip() for a in forwarded.split(',')] + elif "REMOTE_ADDR" in environ: + route = [environ["REMOTE_ADDR"]] + except Exception as e: + logger.exception(e) + else: + if route is not None: + environ['ACCESS_ROUTE'] = route + environ['CLIENT_ADDR'] = route[-1] + + if 'HTTP_X_DEBUG' in environ: + if config.is_trusted_addr(environ.get('CLIENT_ADDR')): + Context.set_debug() + else: + logger.warning( + 'X-Debug header set but not trusted IP address', + extra={ + "access_route": ','.join(environ.get('ACCESS_ROUTE')), + "x_debug": environ['HTTP_X_DEBUG'], + } + ) + set_deadline = False header_deadline = environ.get('HTTP_X_REQUEST_DEADLINE') if header_deadline: diff --git a/tests/test_wsgi.py b/tests/test_wsgi.py index ed147ad4..418c43ad 100644 --- a/tests/test_wsgi.py +++ b/tests/test_wsgi.py @@ -42,6 +42,8 @@ from talisker.util import datetime_to_timestamp import talisker.sentry +from tests.conftest import require_module + @pytest.fixture def start_response(): @@ -82,11 +84,28 @@ def run(env=None, status='200 OK', headers=None, body=None, duration=1): response = list(iter) iter.close() - return start_response.headers, response + return dict(start_response.headers), response return run +@pytest.fixture +def sentry_id(monkeypatch): + + class MockId: + hex = 'SENTRY_ID' + + def get(): + return MockId + + def set(id): + MockId.hex = id + + monkeypatch.setattr(wsgi.uuid, 'uuid4', get) + + return set + + def test_error_response_handler(wsgi_env, config): config['DEVEL'] = 0 wsgi_env['REQUEST_ID'] = 'REQUESTID' @@ -158,6 +177,7 @@ def test_wsgi_request_start_response(wsgi_env, start_response): assert start_response.exc_info is request.exc_info is None +@require_module('raven') def test_wsgi_request_soft_timeout_default(run_wsgi, context): run_wsgi() assert context.sentry == [] @@ -168,7 +188,7 @@ def test_wsgi_request_soft_explicit(run_wsgi, context): talisker.Context.current.soft_timeout = 100 run_wsgi(duration=2) msg = context.sentry[0] - assert msg['message'] == 'start_response latency exceeded soft timeout' + assert msg['message'] == 'Soft Timeout: /' assert msg['level'] == 'warning' assert msg['extra']['start_response_latency'] == 2000 assert msg['extra']['soft_timeout'] == 100 @@ -224,6 +244,7 @@ def test_wsgi_request_wrap_file(run_wsgi, context, tmpdir): def test_wsgi_request_wrap_error_in_iterator(exc_type, run_wsgi, context): env = { 'REQUEST_ID': 'REQUESTID', + 'SENTRY_ID': 'SENTRY_ID', 'HTTP_ACCEPT': 'application/json', } @@ -238,6 +259,7 @@ def __next__(self): output = b''.join(body) error = json.loads(output.decode('utf8')) + assert headers['X-Sentry-Id'] == 'SENTRY_ID' assert error['title'] == 'Server Error: ' + exc_type.__name__ extra = dict([ @@ -256,7 +278,11 @@ def __next__(self): context.assert_log(msg='GET /', extra=extra) if talisker.sentry.enabled: - assert len(context.sentry) == 1 + msg = context.sentry[0] + assert msg['event_id'] == 'SENTRY_ID' + assert msg['message'] == '{}: {}'.format( + exc_type.__name__, 'error' + ) def test_wsgi_request_wrap_error_headers_sent(run_wsgi, context): @@ -278,7 +304,7 @@ def iterator(): output = b''.join(body) assert output == b'' - assert headers == [] + assert headers == {} def test_wsgi_request_log(run_wsgi, context): @@ -459,7 +485,7 @@ def app(environ, _start_response): wsgi.RequestTimeout, ]) def test_middleware_error_before_start_response( - exc_type, wsgi_env, start_response, context): + exc_type, wsgi_env, start_response, context, sentry_id, monkeypatch): def app(environ, _start_response): raise exc_type('error') @@ -477,10 +503,11 @@ def app(environ, _start_response): assert wsgi_env['ENV'] == 'VALUE' assert wsgi_env['REQUEST_ID'] == 'ID' assert start_response.exc_info[0] is exc_type - assert start_response.headers[:3] == [ + assert start_response.headers[:4] == [ ('Content-Type', 'application/json'), ('Some-Header', 'value'), ('X-Request-Id', 'ID'), + ('X-Sentry-Id', 'SENTRY_ID'), ] extra = { @@ -498,7 +525,11 @@ def app(environ, _start_response): ) if talisker.sentry.enabled: - assert len(context.sentry) == 1 + msg = context.sentry[0] + assert msg['event_id'] == 'SENTRY_ID' + assert msg['message'] == '{}: {}'.format( + exc_type.__name__, 'error' + ) @pytest.mark.parametrize('exc_type', [ @@ -506,7 +537,7 @@ def app(environ, _start_response): wsgi.RequestTimeout, ]) def test_middleware_error_after_start_response( - exc_type, wsgi_env, start_response, context): + exc_type, wsgi_env, start_response, sentry_id, context): def app(wsgi_env, _start_response): _start_response('200 OK', [('Content-Type', 'application/json')]) @@ -525,10 +556,11 @@ def app(wsgi_env, _start_response): assert wsgi_env['ENV'] == 'VALUE' assert wsgi_env['REQUEST_ID'] == 'ID' assert start_response.status == '500 Internal Server Error' - assert start_response.headers[:3] == [ + assert start_response.headers[:4] == [ ('Content-Type', 'application/json'), ('Some-Header', 'value'), ('X-Request-Id', 'ID'), + ('X-Sentry-Id', 'SENTRY_ID') ] extra = { @@ -546,7 +578,11 @@ def app(wsgi_env, _start_response): ) if talisker.sentry.enabled: - assert len(context.sentry) == 1 + msg = context.sentry[0] + assert msg['event_id'] == 'SENTRY_ID' + assert msg['message'] == '{}: {}'.format( + exc_type.__name__, 'error' + ) def test_middleware_preserves_file_wrapper( @@ -643,6 +679,52 @@ def app(environ, start_response): assert output == b'' +def test_middleware_debug(wsgi_env, start_response, context): + + def app(environ, _start_response): + _start_response('200 OK', [('Content-Type', 'text/plain')]) + return [b'OK'] + + wsgi_env['HTTP_X_DEBUG'] = '1' + mw = wsgi.TaliskerMiddleware(app, {}, {}) + output = b''.join(mw(wsgi_env, start_response)) + + assert output == b'OK' + assert start_response.status == '200 OK' + + if talisker.sentry.enabled: + msg = context.sentry[0] + assert msg['message'] == 'Debug: /' + assert msg['level'] == 'debug' + + +def test_middleware_debug_invalid_ip(wsgi_env, start_response, context): + + def app(environ, _start_response): + _start_response('200 OK', [('Content-Type', 'text/plain')]) + return [b'OK'] + + wsgi_env['HTTP_X_DEBUG'] = '1' + wsgi_env['REMOTE_ADDR'] = '1.2.3.4' + mw = wsgi.TaliskerMiddleware(app, {}, {}) + output = b''.join(mw(wsgi_env, start_response)) + + assert output == b'OK' + assert start_response.status == '200 OK' + + if talisker.sentry.enabled: + assert len(context.sentry) == 0 + + context.assert_log( + level='warning', + msg='X-Debug header set but not trusted IP address', + extra={ + 'access_route': '1.2.3.4', + 'x_debug': '1', + }, + ) + + def test_wrap(): def app(environ, start_response): diff --git a/tests/wsgi_app.py b/tests/wsgi_app.py index c12ad242..501efee6 100644 --- a/tests/wsgi_app.py +++ b/tests/wsgi_app.py @@ -45,7 +45,6 @@ def application(environ, start_response): logger.warning('warning') logger.error('error') logger.critical('critical') - time.sleep(10) return [output.encode('utf8')]