def test_make_record_context_extra():
Context.new()
logger = logs.StructuredLogger('test')
logs.logging_context.push(a=1)
record = logger.makeRecord(*record_args())
assert record.__dict__['a'] == 1
assert record._structured == {'a': 1}
def test_logging_context_ctx():
Context.new()
with logs.logging_context(a=1):
assert logs.logging_context.flat == {'a': 1}
with logs.logging_context(a=2):
assert logs.logging_context.flat == {'a': 2}
assert logs.logging_context.flat == {'a': 1}
def test_make_record_global_extra():
Context.new()
logger = logs.StructuredLogger('test')
logs.set_global_extra({'a': 1})
record = logger.makeRecord(*record_args())
assert record.__dict__['a'] == 1
assert record._structured == {'a': 1}
def test_celery_basic(celery_signals):
from tests.celery_app import basic_task, error_task, propagate_task
cmd = ['talisker.celery', 'worker', '-q', '-A', 'tests.celery_app']
with ServerProcess(cmd) as pr:
pr.wait_for_output(' ready.', timeout=30)
Context.new()
result = basic_task.delay()
error_result = error_task.delay()
with request_id('myid'):
propagate = propagate_task.delay()
output = result.wait(timeout=3)
with pytest.raises(Exception):
error_result.wait(timeout=3)
propagate.wait(timeout=3)
assert output == 'basic'
pr.log.assert_log(
msg='basic task',
extra={'task_name': 'tests.celery_app.basic_task'},
)
pr.log.assert_log(
msg='propagate_task',
extra={'request_id': 'myid'},
)
def test_context_thread():
e1 = threading.Event()
e2 = threading.Event()
def worker():
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.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 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 test_make_record_context_renamed():
Context.new()
logger = logs.StructuredLogger('test')
logs.set_global_extra({'a': 1})
logs.logging_context.push(a=2)
record = logger.makeRecord(*record_args())
assert record._structured == {'a': 1, 'a_': 2}
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_logging_context_push():
Context.new()
logs.logging_context.push(a=1)
assert logs.logging_context.flat == {'a': 1}
logs.logging_context.push(a=2)
assert logs.logging_context.flat == {'a': 2}
logs.logging_context.pop()
assert logs.logging_context.flat == {'a': 1}
logs.logging_context.pop()
assert logs.logging_context.flat == {}
def worker():
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_make_record_all_extra():
Context.new()
logger = logs.StructuredLogger('test')
logs.set_global_extra({'a': 1})
logs.logging_context.push(b=2)
record = logger.makeRecord(*record_args(), extra={'c': 3})
assert record.__dict__['a'] == 1
assert record.__dict__['b'] == 2
assert record.__dict__['c'] == 3
assert record._structured == {'a': 1, 'b': 2, 'c': 3}
def test_make_record_ordering():
Context.new()
logger = logs.StructuredLogger('test')
logs.set_global_extra({'global': 1})
logs.logging_context.push(context=2)
extra = OrderedDict()
extra['user1'] = 3
extra['user2'] = 4
record = logger.makeRecord(*record_args(), extra=extra)
assert list(
record._structured.keys()) == ['user1', 'user2', 'context', 'global']
def test_context_api():
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_request_timeout():
Context.new()
result = {}
@request_timeout(timeout=1000, soft_timeout=500)
def f():
result['timeout'] = Context.current().deadline
result['soft_timeout'] = Context.soft_timeout
f()
assert result['timeout'] == time.time() + 1.0
assert result['soft_timeout'] == 500
def task_prerun(sender, task_id, task, **kwargs):
Context.new()
rid = get_header(task.request, REQUEST_ID)
if rid is not None:
Context.request_id = rid
start_time = get_header(task.request, ENQUEUE_START)
if start_time is not None:
ms = (time.time() - start_time) * 1000
CeleryMetric.queue_latency.observe(ms, job=sender.name)
if hasattr(task, 'talisker_timestamp') and task.request.is_eager:
# eager task, but retry has happened immeadiately, so send metrics
send_run_metric(sender.name, task.talisker_timestamp)
task_retry(sender)
task.talisker_timestamp = time.time()
talisker.logs.logging_context.push(task_id=task_id, task_name=task.name)
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 task_prerun(sender, task_id, task, **kwargs):
Context.new()
rid = get_header(task.request, REQUEST_ID)
if rid is not None:
Context.request_id = rid
start_time = get_header(task.request, ENQUEUE_START)
if start_time is not None:
ms = (time.time() - start_time) * 1000
CeleryMetric.queue_latency.observe(ms, job=sender.name)
if hasattr(task, 'talisker_timestamp') and task.request.is_eager:
# If there is a retry, celery behavior is to send signals in the
# following order:
# task-pre -> retry -> task-post
# (retry 1): task-pre -> (retry again, if needed) -> task-post
# in task-post, task latency is stored (via a call to
# `send_run_metric`.)
# So for a task with 2 retries, this looks something like:
# pre -> retry -> post -> pre -> retry -> post -> pre (max retries
# reached, so no more retry) -> post
# In celery 4.x:
# When the task is called eagerly, because the call is synchronous
# the call stack ends up looking something like:
# pre -> pre -> pre -> post -> post -> post
# In celery 5.x, the behavior has been fixed and works similarly
# in both eager and non-eager mode
# To emulate non-eager behavior in eager mode for celery 4.x, we check
# if the request is eager (task.request.is_eager) and it's a retry
# (task.talisker_timestamp is already set). If so, we manually track
# the calls to retry and task-post here.
task_retry(sender)
send_run_metric(sender.name, task.talisker_timestamp)
task.talisker_timestamp = time.time()
talisker.logs.logging_context.push(task_id=task_id, task_name=task.name)
def test_gunicorn_worker_exit(wsgi_env, context):
wsgi_env['start_time'] = time.time()
wsgi_env['REQUEST_ID'] = 'ID'
Context.new()
Context.request_id = 'ID'
request = talisker.wsgi.TaliskerWSGIRequest(wsgi_env, None, [])
talisker.wsgi.REQUESTS['ID'] = request
class worker:
pid = 100
gunicorn.gunicorn_worker_exit(None, worker())
context.assert_log(
name='talisker.wsgi',
msg='GET /',
extra={
'request_id': 'ID',
'timeout': True,
},
)
assert len(context.sentry) == 1
def test_tracking():
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 start(self):
self.old_statsd = talisker.statsd.get_client.raw_update(
self.statsd_client)
talisker.logs.add_talisker_handler(logging.NOTSET, self.handler)
self.sentry_context.start()
Context.new()
def clear_context():
"""Helper to clear any thread local contexts."""
import talisker.sentry
Context.clear()
talisker.sentry.clear()
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.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:
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.current.deadline = datetime_to_timestamp(deadline)
set_deadline = True
if not set_deadline and config.request_timeout is not None:
Context.current.set_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 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, extra=None, **kwargs):
with Context.logging(extra, **kwargs):
yield
def test_set_logging_context():
Context.new()
logs.set_logging_context(a=1)
assert logs.logging_context.flat == {'a': 1}
def test_extra_logging():
Context.new()
with logs.extra_logging({'a': 1}):
assert logs.logging_context.flat == {'a': 1}
def test_make_record_no_extra():
Context.new()
logger = logs.StructuredLogger('test')
record = logger.makeRecord(*record_args())
assert record._structured == {}
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
