Support X-Debug header that sends sentry report.

As a precaution, the header is only respected from a trusted ip
address. This provides a secure way to to targeted diagnostic debugging.

This change also reintroduced the X-Sentry-Id header, as I figured out
how to include that when possible. It's not possible to do so for soft
timeouts, as we don't know until after the request is sent. Nor for
errors that occur after headers have been sent.

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(addr_str)
+        return ip.is_loopback or any(
+            ip in network for network in self.networks
+        )
+
 
 def parse_config_file(filename):
     module = {

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

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,21 +81,27 @@ 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_IP')
+        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(
                 ip_str,
                 force_unicode(request.remote_addr),
                 request.headers.get('x-forwarded-for'))
             return Response(msg, status='403 Forbidden')
+
     return wrapper
 
 

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: