123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378 |
- # Copyright 2014-2016 OpenMarket Ltd
- #
- # 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
- 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)
- 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
- class LoggingContext(object):
- """Additional context for log formatting. Contexts are scoped within a
- "with" block.
- Args:
- name (str): Name for the context for debugging.
- """
- __slots__ = [
- "previous_context", "name", "usage_start", "usage_end", "main_thread",
- "__dict__", "tag", "alive",
- ]
- thread_local = threading.local()
- class Sentinel(object):
- """Sentinel to represent the root context"""
- __slots__ = []
- def __str__(self):
- return "sentinel"
- def copy_to(self, record):
- pass
- def start(self):
- pass
- def stop(self):
- pass
- def add_database_transaction(self, duration_ms):
- pass
- def __nonzero__(self):
- return False
- sentinel = Sentinel()
- def __init__(self, name=None):
- self.previous_context = LoggingContext.current_context()
- 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()
- self.tag = ""
- self.alive = True
- def __str__(self):
- return "%s@%x" % (self.name, id(self))
- @classmethod
- def current_context(cls):
- """Get the current logging context from thread local storage"""
- 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()
- if current is not context:
- current.stop()
- cls.thread_local.current_context = context
- context.start()
- return current
- def __enter__(self):
- """Enters this logging context into thread local storage"""
- old_context = self.set_current_context(self)
- if self.previous_context != old_context:
- logger.warn(
- "Expected previous context %r, found %r",
- self.previous_context, old_context
- )
- self.alive = True
- return self
- def __exit__(self, type, value, traceback):
- """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.
- """
- 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
- )
- self.previous_context = None
- self.alive = False
- def copy_to(self, record):
- """Copy fields from this context to the record"""
- 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:
- 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.
- class LoggingContextFilter(logging.Filter):
- """Logging filter that adds values from the current logging context to each
- record.
- Args:
- **defaults: Default values to avoid formatters complaining about
- missing fields
- """
- def __init__(self, **defaults):
- self.defaults = defaults
- def filter(self, record):
- """Add each fields from the logging contexts to the record.
- Returns:
- True to include the record in the log output.
- """
- context = LoggingContext.current_context()
- for key, value in self.defaults.items():
- setattr(record, key, value)
- context.copy_to(record)
- return True
- class PreserveLoggingContext(object):
- """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."""
- __slots__ = ["current_context", "new_context", "has_parent"]
- def __init__(self, new_context=LoggingContext.sentinel):
- self.new_context = new_context
- def __enter__(self):
- """Captures the current logging context"""
- self.current_context = LoggingContext.set_current_context(
- self.new_context
- )
- if self.current_context:
- self.has_parent = self.current_context.previous_context is not None
- if not self.current_context.alive:
- logger.debug(
- "Entering dead context: %s",
- self.current_context,
- )
- def __exit__(self, type, value, traceback):
- """Restores the current logging context"""
- context = LoggingContext.set_current_context(self.current_context)
- if context != self.new_context:
- logger.debug(
- "Unexpected logging context: %s is not %s",
- context, self.new_context,
- )
- if self.current_context is not LoggingContext.sentinel:
- if not self.current_context.alive:
- logger.debug(
- "Restoring dead context: %s",
- self.current_context,
- )
- 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):
- res = f(res, *args, **kwargs)
- return res
- return g
- def preserve_context_over_fn(fn, *args, **kwargs):
- """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():
- res = fn(*args, **kwargs)
- if isinstance(res, defer.Deferred):
- return preserve_context_over_deferred(res)
- else:
- return res
- def preserve_context_over_deferred(deferred):
- """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()
- d = _PreservingContextDeferred(current_context)
- deferred.chainDeferred(d)
- return d
- 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
|