synapse-product/synapse/util/logcontext.py

379 lines
12 KiB
Python
Raw Normal View History

2016-01-06 23:26:29 -05:00
# Copyright 2014-2016 OpenMarket Ltd
2015-01-06 08:21:39 -05:00
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
# http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
from twisted.internet import defer
2014-10-29 21:21:33 -04:00
import threading
import logging
logger = logging.getLogger(__name__)
try:
import resource
# Python doesn't ship with a definition of RUSAGE_THREAD but it's defined
# to be 1 on linux so we hard code it.
RUSAGE_THREAD = 1
# If the system doesn't support RUSAGE_THREAD then this should throw an
# exception.
resource.getrusage(RUSAGE_THREAD)
2015-12-04 06:34:05 -05:00
def get_thread_resource_usage():
return resource.getrusage(RUSAGE_THREAD)
except:
# If the system doesn't support resource.getrusage(RUSAGE_THREAD) then we
# won't track resource usage by returning None.
def get_thread_resource_usage():
return None
2014-10-30 06:13:46 -04:00
2014-10-29 21:21:33 -04:00
class LoggingContext(object):
2014-10-30 06:13:46 -04:00
"""Additional context for log formatting. Contexts are scoped within a
2016-02-10 06:29:21 -05:00
"with" block.
2014-10-30 06:13:46 -04:00
Args:
name (str): Name for the context for debugging.
"""
__slots__ = [
2016-02-10 06:25:19 -05:00
"previous_context", "name", "usage_start", "usage_end", "main_thread",
2016-02-04 05:22:44 -05:00
"__dict__", "tag", "alive",
]
2014-10-29 21:21:33 -04:00
thread_local = threading.local()
class Sentinel(object):
2014-10-30 06:13:46 -04:00
"""Sentinel to represent the root context"""
2014-10-29 21:21:33 -04:00
__slots__ = []
2014-10-30 06:13:46 -04:00
def __str__(self):
return "sentinel"
2014-10-29 21:21:33 -04:00
def copy_to(self, record):
pass
def start(self):
pass
def stop(self):
pass
def add_database_transaction(self, duration_ms):
pass
2016-02-03 08:51:25 -05:00
def __nonzero__(self):
return False
2014-10-29 21:21:33 -04:00
sentinel = Sentinel()
def __init__(self, name=None):
2016-02-10 06:25:19 -05:00
self.previous_context = LoggingContext.current_context()
2014-10-29 21:21:33 -04:00
self.name = name
self.ru_stime = 0.
self.ru_utime = 0.
self.db_txn_count = 0
self.db_txn_duration = 0.
self.usage_start = None
self.main_thread = threading.current_thread()
2016-02-03 08:51:25 -05:00
self.tag = ""
2016-02-04 05:22:44 -05:00
self.alive = True
2014-10-29 21:21:33 -04:00
def __str__(self):
2014-10-30 06:13:46 -04:00
return "%s@%x" % (self.name, id(self))
2014-10-29 21:21:33 -04:00
@classmethod
def current_context(cls):
2014-10-30 06:13:46 -04:00
"""Get the current logging context from thread local storage"""
2014-10-29 21:21:33 -04:00
return getattr(cls.thread_local, "current_context", cls.sentinel)
@classmethod
def set_current_context(cls, context):
"""Set the current logging context in thread local storage
Args:
context(LoggingContext): The context to activate.
Returns:
The context that was previously active
"""
current = cls.current_context()
2016-02-04 05:22:44 -05:00
if current is not context:
current.stop()
cls.thread_local.current_context = context
context.start()
return current
2014-10-29 21:21:33 -04:00
def __enter__(self):
2014-10-30 06:13:46 -04:00
"""Enters this logging context into thread local storage"""
2016-02-10 06:23:32 -05:00
old_context = self.set_current_context(self)
2016-02-10 06:25:19 -05:00
if self.previous_context != old_context:
2016-02-10 06:23:32 -05:00
logger.warn(
2016-02-10 06:25:19 -05:00
"Expected previous context %r, found %r",
self.previous_context, old_context
2016-02-10 06:23:32 -05:00
)
2016-02-04 05:22:44 -05:00
self.alive = True
2014-10-29 21:21:33 -04:00
return self
def __exit__(self, type, value, traceback):
2014-10-30 06:13:46 -04:00
"""Restore the logging context in thread local storage to the state it
was before this context was entered.
Returns:
None to avoid suppressing any exeptions that were thrown.
"""
2016-02-10 06:25:19 -05:00
current = self.set_current_context(self.previous_context)
if current is not self:
if current is self.sentinel:
logger.debug("Expected logging context %s has been lost", self)
else:
logger.warn(
"Current logging context %s is not expected context %s",
current,
self
)
2016-02-10 06:25:19 -05:00
self.previous_context = None
2016-02-04 05:22:44 -05:00
self.alive = False
2014-10-29 21:21:33 -04:00
def copy_to(self, record):
2016-02-10 06:25:19 -05:00
"""Copy fields from this context to the record"""
2014-10-29 21:21:33 -04:00
for key, value in self.__dict__.items():
setattr(record, key, value)
record.ru_utime, record.ru_stime = self.get_resource_usage()
def start(self):
if threading.current_thread() is not self.main_thread:
return
if self.usage_start and self.usage_end:
self.ru_utime += self.usage_end.ru_utime - self.usage_start.ru_utime
self.ru_stime += self.usage_end.ru_stime - self.usage_start.ru_stime
self.usage_start = None
self.usage_end = None
if not self.usage_start:
self.usage_start = get_thread_resource_usage()
def stop(self):
if threading.current_thread() is not self.main_thread:
return
if self.usage_start:
2015-12-04 06:34:05 -05:00
self.usage_end = get_thread_resource_usage()
def get_resource_usage(self):
ru_utime = self.ru_utime
ru_stime = self.ru_stime
if self.usage_start and threading.current_thread() is self.main_thread:
current = get_thread_resource_usage()
ru_utime += current.ru_utime - self.usage_start.ru_utime
ru_stime += current.ru_stime - self.usage_start.ru_stime
return ru_utime, ru_stime
def add_database_transaction(self, duration_ms):
self.db_txn_count += 1
self.db_txn_duration += duration_ms / 1000.
2014-10-29 21:21:33 -04:00
class LoggingContextFilter(logging.Filter):
2014-10-30 06:13:46 -04:00
"""Logging filter that adds values from the current logging context to each
record.
Args:
**defaults: Default values to avoid formatters complaining about
missing fields
"""
2014-10-29 21:21:33 -04:00
def __init__(self, **defaults):
self.defaults = defaults
def filter(self, record):
2014-10-30 06:13:46 -04:00
"""Add each fields from the logging contexts to the record.
Returns:
True to include the record in the log output.
"""
2014-10-29 21:21:33 -04:00
context = LoggingContext.current_context()
for key, value in self.defaults.items():
setattr(record, key, value)
context.copy_to(record)
return True
class PreserveLoggingContext(object):
2014-10-30 06:13:46 -04:00
"""Captures the current logging context and restores it when the scope is
exited. Used to restore the context after a function using
@defer.inlineCallbacks is resumed by a callback from the reactor."""
2016-02-04 05:22:44 -05:00
__slots__ = ["current_context", "new_context", "has_parent"]
def __init__(self, new_context=LoggingContext.sentinel):
self.new_context = new_context
2014-10-30 06:13:46 -04:00
2014-10-29 21:21:33 -04:00
def __enter__(self):
2014-10-30 06:13:46 -04:00
"""Captures the current logging context"""
self.current_context = LoggingContext.set_current_context(
self.new_context
)
2014-10-29 21:21:33 -04:00
2016-02-04 05:22:44 -05:00
if self.current_context:
2016-02-10 06:25:19 -05:00
self.has_parent = self.current_context.previous_context is not None
2016-02-04 05:22:44 -05:00
if not self.current_context.alive:
2016-02-09 04:20:06 -05:00
logger.debug(
2016-02-04 05:22:44 -05:00
"Entering dead context: %s",
self.current_context,
)
2014-10-29 21:21:33 -04:00
def __exit__(self, type, value, traceback):
2014-10-30 06:13:46 -04:00
"""Restores the current logging context"""
2016-02-04 05:22:44 -05:00
context = LoggingContext.set_current_context(self.current_context)
if context != self.new_context:
2016-02-09 04:20:06 -05:00
logger.debug(
2016-02-04 05:22:44 -05:00
"Unexpected logging context: %s is not %s",
context, self.new_context,
)
2015-05-08 14:53:34 -04:00
if self.current_context is not LoggingContext.sentinel:
2016-02-04 05:22:44 -05:00
if not self.current_context.alive:
2016-02-09 04:20:06 -05:00
logger.debug(
2015-05-08 14:53:34 -04:00
"Restoring dead context: %s",
self.current_context,
)
2015-06-19 06:45:55 -04:00
class _PreservingContextDeferred(defer.Deferred):
"""A deferred that ensures that all callbacks and errbacks are called with
the given logging context.
"""
def __init__(self, context):
self._log_context = context
defer.Deferred.__init__(self)
def addCallbacks(self, callback, errback=None,
callbackArgs=None, callbackKeywords=None,
errbackArgs=None, errbackKeywords=None):
callback = self._wrap_callback(callback)
errback = self._wrap_callback(errback)
return defer.Deferred.addCallbacks(
self, callback,
errback=errback,
callbackArgs=callbackArgs,
callbackKeywords=callbackKeywords,
errbackArgs=errbackArgs,
errbackKeywords=errbackKeywords,
)
def _wrap_callback(self, f):
def g(res, *args, **kwargs):
with PreserveLoggingContext(self._log_context):
2015-06-19 06:45:55 -04:00
res = f(res, *args, **kwargs)
return res
return g
def preserve_context_over_fn(fn, *args, **kwargs):
2015-05-08 11:52:49 -04:00
"""Takes a function and invokes it with the given arguments, but removes
and restores the current logging context while doing so.
If the result is a deferred, call preserve_context_over_deferred before
returning it.
"""
with PreserveLoggingContext():
2015-05-08 11:52:49 -04:00
res = fn(*args, **kwargs)
2015-05-08 11:52:49 -04:00
if isinstance(res, defer.Deferred):
return preserve_context_over_deferred(res)
else:
return res
def preserve_context_over_deferred(deferred):
2015-05-08 11:52:49 -04:00
"""Given a deferred wrap it such that any callbacks added later to it will
be invoked with the current context.
"""
current_context = LoggingContext.current_context()
2015-06-19 06:45:55 -04:00
d = _PreservingContextDeferred(current_context)
deferred.chainDeferred(d)
return d
2016-02-04 05:22:44 -05:00
def preserve_fn(f):
"""Ensures that function is called with correct context and that context is
restored after return. Useful for wrapping functions that return a deferred
which you don't yield on.
"""
current = LoggingContext.current_context()
def g(*args, **kwargs):
with PreserveLoggingContext(current):
return f(*args, **kwargs)
return g
# modules to ignore in `logcontext_tracer`
_to_ignore = [
"synapse.util.logcontext",
"synapse.http.server",
"synapse.storage._base",
"synapse.util.async",
]
def logcontext_tracer(frame, event, arg):
"""A tracer that logs whenever a logcontext "unexpectedly" changes within
a function. Probably inaccurate.
Use by calling `sys.settrace(logcontext_tracer)` in the main thread.
"""
if event == 'call':
name = frame.f_globals["__name__"]
if name.startswith("synapse"):
if name == "synapse.util.logcontext":
if frame.f_code.co_name in ["__enter__", "__exit__"]:
tracer = frame.f_back.f_trace
if tracer:
tracer.just_changed = True
tracer = frame.f_trace
if tracer:
return tracer
if not any(name.startswith(ig) for ig in _to_ignore):
return LineTracer()
class LineTracer(object):
__slots__ = ["context", "just_changed"]
def __init__(self):
self.context = LoggingContext.current_context()
self.just_changed = False
def __call__(self, frame, event, arg):
if event in 'line':
if self.just_changed:
self.context = LoggingContext.current_context()
self.just_changed = False
else:
c = LoggingContext.current_context()
if c != self.context:
logger.info(
"Context changed! %s -> %s, %s, %s",
self.context, c,
frame.f_code.co_filename, frame.f_lineno
)
self.context = c
return self