def test_context_eventlet(request):
try:
import eventlet
except ImportError:
pytest.skip('eventlet must be installed')
request.addfinalizer(enable_eventlet_context())
def f1():
assert Context.logging.flat == {}
Context.logging.push({'f1': 1})
Context.track('gevent', 1.0)
assert Context.logging.flat == {'f1': 1}
assert Context.current().tracking['gevent'].count == 1
eventlet.sleep(0.2) # yield to let f2 run
assert Context.logging.flat == {'f1': 1}
assert Context.current().tracking['gevent'].count == 1
def f2():
assert Context.logging.flat == {}
Context.logging.push({'f2': 2})
Context.track('gevent', 1.0)
assert Context.current().tracking['gevent'].count == 1
assert Context.logging.flat == {'f2': 2}
pool = eventlet.GreenPool()
pool.spawn(f1)
pool.spawn(f2)
pool.waitall()
# Resetting Context
Context.clear()
Context.current().request_id = None
Context.current().tracking = {}
def test_context_gevent(request):
try:
import gevent
except ImportError:
pytest.skip('gevent must be installed')
request.addfinalizer(enable_gevent_context())
def f1():
assert Context.logging.flat == {}
Context.logging.push({'f1': 1})
Context.track('gevent', 1.0)
assert Context.logging.flat == {'f1': 1}
assert Context.current().tracking['gevent'].count == 1
gevent.sleep(0.2) # yield to let f2 run
assert Context.logging.flat == {'f1': 1}
assert Context.current().tracking['gevent'].count == 1
def f2():
assert Context.logging.flat == {}
Context.logging.push({'f2': 2})
Context.track('gevent', 1.0)
assert Context.current().tracking['gevent'].count == 1
assert Context.logging.flat == {'f2': 2}
g1 = gevent.spawn(f1)
g2 = gevent.spawn(f2)
gevent.joinall([g1, g2], timeout=2)
# Resetting Context
Context.clear()
Context.current().request_id = None
Context.current().tracking = {}
def f1():
assert Context.logging.flat == {}
Context.logging.push({'f1': 1})
Context.track('gevent', 1.0)
assert Context.logging.flat == {'f1': 1}
assert Context.current().tracking['gevent'].count == 1
eventlet.sleep(0.2) # yield to let f2 run
assert Context.logging.flat == {'f1': 1}
assert Context.current().tracking['gevent'].count == 1
def test_tracking():
Context.new()
Context.track('sql', 1.0)
Context.track('sql', 2.0)
Context.track('http', 3.0)
assert Context.current().tracking['sql'].count == 2
assert Context.current().tracking['sql'].time == 3.0
assert Context.current().tracking['http'].count == 1
assert Context.current().tracking['http'].time == 3.0
def worker():
Context.new()
Context.logging.push(a=2)
Context.track('test', 1.0)
e1.set()
e2.wait()
assert Context.logging.flat == {'a': 2}
Context.logging.pop()
e1.set()
assert Context.logging.flat == {}
assert Context.current().tracking['test'].count == 1
def test_null_context():
Context.request_id = 'test'
Context.set_debug()
Context.soft_timeout = 10
Context.set_relative_deadline(10)
Context.track('sql', 1.0)
assert Context.request_id is None
assert Context.debug is False
assert Context.soft_timeout == -1
assert Context.deadline_timeout() is None
assert Context.current().tracking == {}
with Context.logging(foo='bar'):
assert Context.logging.flat == {}
def test_context_api():
Context.new()
Context.logging.push(a=1)
Context.request_id = 'id'
Context.track('test', 1.0)
assert Context.current().logging.flat == {'a': 1}
assert Context.current().request_id == 'id'
assert Context.current().tracking['test'].count == 1
assert Context.current().tracking['test'].time == 1.0
Context.clear()
assert Context.current().logging.flat == {}
assert Context.current().request_id is None
assert Context.current().tracking == {}
def test_context_thread():
e1 = threading.Event()
e2 = threading.Event()
def worker():
Context.new()
Context.logging.push(a=2)
Context.track('test', 1.0)
e1.set()
e2.wait()
assert Context.logging.flat == {'a': 2}
Context.logging.pop()
e1.set()
assert Context.logging.flat == {}
assert Context.current().tracking['test'].count == 1
t = threading.Thread(target=worker)
Context.new()
Context.track('test', 1.0)
Context.logging.push(a=1)
assert Context.logging.flat == {'a': 1}
t.start()
e1.wait()
e1.clear()
assert Context.logging.flat == {'a': 1}
assert Context.current().tracking['test'].count == 1
e2.set()
e1.wait()
assert Context.logging.flat == {'a': 1}
t.join()
def f():
result['timeout'] = Context.current().deadline
result['soft_timeout'] = Context.soft_timeout
def f2():
assert Context.logging.flat == {}
Context.logging.push({'f2': 2})
Context.track('gevent', 1.0)
assert Context.current().tracking['gevent'].count == 1
assert Context.logging.flat == {'f2': 2}
def __call__(self, environ, start_response):
Context.new()
config = talisker.get_config()
# setup environment
environ['start_time'] = Context.current().start_time
if self.environ:
environ.update(self.environ)
# ensure request id
if config.wsgi_id_header not in environ:
environ[config.wsgi_id_header] = str(uuid.uuid4())
rid = environ[config.wsgi_id_header]
environ['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
Context.request_id = rid
Context.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:
try:
deadline = datetime.strptime(
header_deadline,
"%Y-%m-%dT%H:%M:%S.%fZ",
)
except ValueError:
pass
else:
# set deadline directly
# TODO: validate deadline is in future?
Context.set_absolute_deadline(datetime_to_timestamp(deadline))
set_deadline = True
if not set_deadline and config.request_timeout is not None:
Context.set_relative_deadline(config.request_timeout)
# create the response container
request = TaliskerWSGIRequest(environ, start_response, self.headers)
# track in-flight requests
if rid in REQUESTS:
logger.warning('duplicate request id received by gunicorn worker',
extra={'request_id': rid})
else:
REQUESTS[rid] = request
try:
response_iter = self.app(environ, request.start_response)
except Exception as e:
# store details for later
request.exc_info = sys.exc_info()
if isinstance(e, RequestTimeout):
request.timedout = True
# switch to generating an error response
response_iter = request.error(request.exc_info)
except SystemExit as e:
if e.code != 0:
request.exc_info = sys.exc_info()
request.finish_request()
raise
return request.wrap_response(response_iter)
def get_metadata(self):
"""Return an ordered dictionary of request metadata for logging."""
environ = self.environ
extra = OrderedDict()
if self.headers is None:
headers = {}
else:
headers = dict((k.lower(), v) for k, v in self.headers)
extra['method'] = environ.get('REQUEST_METHOD')
script = environ.get('SCRIPT_NAME', '')
path = environ.get('PATH_INFO', '')
extra['path'] = script + '/' + path.lstrip('/')
qs = environ.get('QUERY_STRING')
if qs:
extra['qs'] = environ.get('QUERY_STRING')
if self.status_code:
extra['status'] = self.status_code
if 'VIEW_NAME' in environ:
extra['view'] = environ['VIEW_NAME']
elif 'x-view-name' in headers:
extra['view'] = headers['x-view-name']
extra['duration_ms'] = round(self.duration * 1000, 3)
extra['ip'] = environ.get('REMOTE_ADDR', None)
extra['proto'] = environ.get('SERVER_PROTOCOL')
if self.content_length:
extra['length'] = self.content_length
if self.file_path is not None:
extra['filepath'] = self.file_path
request_length = environ.get('CONTENT_LENGTH')
if request_length:
try:
extra['request_length'] = int(request_length)
except ValueError:
pass
content_type = environ.get('CONTENT_TYPE')
if content_type:
extra['request_type'] = content_type
referrer = environ.get('HTTP_REFERER', None)
if referrer is not None:
extra['referrer'] = environ.get('HTTP_REFERER', None)
if 'HTTP_X_FORWARDED_FOR' in environ:
extra['forwarded'] = environ['HTTP_X_FORWARDED_FOR']
if 'HTTP_USER_AGENT' in environ:
extra['ua'] = environ['HTTP_USER_AGENT']
if self.timedout:
extra['timeout'] = True
if self.exc_info and self.exc_info[0]:
extra['exc_type'] = str(self.exc_info[0].__name__)
extra['trailer'] = ''.join(
traceback.format_exception(*self.exc_info))
tracking = Context.current().tracking
for name, tracker in sorted(tracking.items()):
extra[name + '_count'] = tracker.count
extra[name + '_time_ms'] = tracker.time
return extra