Merge pull request #13 from matrix-org/request_logging

Request logging
This commit is contained in:
Erik Johnston 2014-11-14 11:46:07 +00:00
commit b8eca1ffbf
10 changed files with 244 additions and 48 deletions

View File

@ -33,6 +33,7 @@ from synapse.api.urls import (
) )
from synapse.config.homeserver import HomeServerConfig from synapse.config.homeserver import HomeServerConfig
from synapse.crypto import context_factory from synapse.crypto import context_factory
from synapse.util.logcontext import LoggingContext
from daemonize import Daemonize from daemonize import Daemonize
import twisted.manhole.telnet import twisted.manhole.telnet
@ -246,7 +247,7 @@ def setup():
daemon = Daemonize( daemon = Daemonize(
app="synapse-homeserver", app="synapse-homeserver",
pid=config.pid_file, pid=config.pid_file,
action=reactor.run, action=run,
auto_close_fds=False, auto_close_fds=False,
verbose=True, verbose=True,
logger=logger, logger=logger,
@ -256,6 +257,13 @@ def setup():
else: else:
reactor.run() reactor.run()
def run():
with LoggingContext("run"):
reactor.run()
def main():
with LoggingContext("main"):
setup()
if __name__ == '__main__': if __name__ == '__main__':
setup() main()

View File

@ -14,7 +14,7 @@
# limitations under the License. # limitations under the License.
from ._base import Config from ._base import Config
from synapse.util.logcontext import LoggingContextFilter
from twisted.python.log import PythonLoggingObserver from twisted.python.log import PythonLoggingObserver
import logging import logging
import logging.config import logging.config
@ -46,7 +46,8 @@ class LoggingConfig(Config):
def setup_logging(self): def setup_logging(self):
log_format = ( log_format = (
'%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(message)s' "%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s"
" - %(message)s"
) )
if self.log_config is None: if self.log_config is None:
@ -55,12 +56,19 @@ class LoggingConfig(Config):
level = logging.DEBUG level = logging.DEBUG
# FIXME: we need a logging.WARN for a -q quiet option # FIXME: we need a logging.WARN for a -q quiet option
logger = logging.getLogger('')
logger.setLevel(level)
formatter = logging.Formatter(log_format)
if self.log_file:
handler = logging.FileHandler(self.log_file)
else:
handler = logging.StreamHandler()
handler.setFormatter(formatter)
logging.basicConfig( handler.addFilter(LoggingContextFilter(request=""))
level=level,
filename=self.log_file, logger.addHandler(handler)
format=log_format logger.info("Test")
)
else: else:
logging.config.fileConfig(self.log_config) logging.config.fileConfig(self.log_config)

View File

@ -18,6 +18,7 @@ from twisted.web.http import HTTPClient
from twisted.internet.protocol import Factory from twisted.internet.protocol import Factory
from twisted.internet import defer, reactor from twisted.internet import defer, reactor
from synapse.http.endpoint import matrix_endpoint from synapse.http.endpoint import matrix_endpoint
from synapse.util.logcontext import PreserveLoggingContext
import json import json
import logging import logging
@ -36,6 +37,7 @@ def fetch_server_key(server_name, ssl_context_factory):
for i in range(5): for i in range(5):
try: try:
with PreserveLoggingContext():
protocol = yield endpoint.connect(factory) protocol = yield endpoint.connect(factory)
server_response, server_certificate = yield protocol.remote_key server_response, server_certificate = yield protocol.remote_key
defer.returnValue((server_response, server_certificate)) defer.returnValue((server_response, server_certificate))

View File

@ -23,6 +23,7 @@ from twisted.web.http_headers import Headers
from synapse.http.endpoint import matrix_endpoint from synapse.http.endpoint import matrix_endpoint
from synapse.util.async import sleep from synapse.util.async import sleep
from synapse.util.logcontext import PreserveLoggingContext
from syutil.jsonutil import encode_canonical_json from syutil.jsonutil import encode_canonical_json
@ -108,6 +109,7 @@ class BaseHttpClient(object):
producer = body_callback(method, url_bytes, headers_dict) producer = body_callback(method, url_bytes, headers_dict)
try: try:
with PreserveLoggingContext():
response = yield self.agent.request( response = yield self.agent.request(
destination, destination,
endpoint, endpoint,

View File

@ -20,6 +20,7 @@ from syutil.jsonutil import (
from synapse.api.errors import ( from synapse.api.errors import (
cs_exception, SynapseError, CodeMessageException cs_exception, SynapseError, CodeMessageException
) )
from synapse.util.logcontext import LoggingContext
from twisted.internet import defer, reactor from twisted.internet import defer, reactor
from twisted.web import server, resource from twisted.web import server, resource
@ -88,9 +89,19 @@ class JsonResource(HttpServer, resource.Resource):
def render(self, request): def render(self, request):
""" This get's called by twisted every time someone sends us a request. """ This get's called by twisted every time someone sends us a request.
""" """
self._async_render(request) self._async_render_with_logging_context(request)
return server.NOT_DONE_YET return server.NOT_DONE_YET
_request_id = 0
@defer.inlineCallbacks
def _async_render_with_logging_context(self, request):
request_id = "%s-%s" % (request.method, JsonResource._request_id)
JsonResource._request_id += 1
with LoggingContext(request_id) as request_context:
request_context.request = request_id
yield self._async_render(request)
@defer.inlineCallbacks @defer.inlineCallbacks
def _async_render(self, request): def _async_render(self, request):
""" This get's called by twisted every time someone sends us a request. """ This get's called by twisted every time someone sends us a request.

View File

@ -17,8 +17,11 @@ import logging
from synapse.api.errors import StoreError from synapse.api.errors import StoreError
from synapse.api.events.utils import prune_event from synapse.api.events.utils import prune_event
from synapse.util.logutils import log_function from synapse.util.logutils import log_function
from synapse.util.logcontext import PreserveLoggingContext, LoggingContext
from syutil.base64util import encode_base64 from syutil.base64util import encode_base64
from twisted.internet import defer
import collections import collections
import copy import copy
import json import json
@ -84,9 +87,13 @@ class SQLBaseStore(object):
self.event_factory = hs.get_event_factory() self.event_factory = hs.get_event_factory()
self._clock = hs.get_clock() self._clock = hs.get_clock()
@defer.inlineCallbacks
def runInteraction(self, desc, func, *args, **kwargs): def runInteraction(self, desc, func, *args, **kwargs):
"""Wraps the .runInteraction() method on the underlying db_pool.""" """Wraps the .runInteraction() method on the underlying db_pool."""
current_context = LoggingContext.current_context()
def inner_func(txn, *args, **kwargs): def inner_func(txn, *args, **kwargs):
with LoggingContext("runInteraction") as context:
current_context.copy_to(context)
start = time.clock() * 1000 start = time.clock() * 1000
txn_id = SQLBaseStore._TXN_ID txn_id = SQLBaseStore._TXN_ID
@ -109,7 +116,11 @@ class SQLBaseStore(object):
name, end - start name, end - start
) )
return self._db_pool.runInteraction(inner_func, *args, **kwargs) with PreserveLoggingContext():
result = yield self._db_pool.runInteraction(
inner_func, *args, **kwargs
)
defer.returnValue(result)
def cursor_to_dict(self, cursor): def cursor_to_dict(self, cursor):
"""Converts a SQL cursor into an list of dicts. """Converts a SQL cursor into an list of dicts.
@ -177,7 +188,7 @@ class SQLBaseStore(object):
) )
logger.debug( logger.debug(
"[SQL] %s Args=%s Func=%s", "[SQL] %s Args=%s",
sql, values.values(), sql, values.values(),
) )

View File

@ -16,12 +16,14 @@
from twisted.internet import defer, reactor from twisted.internet import defer, reactor
from .logcontext import PreserveLoggingContext
@defer.inlineCallbacks
def sleep(seconds): def sleep(seconds):
d = defer.Deferred() d = defer.Deferred()
reactor.callLater(seconds, d.callback, seconds) reactor.callLater(seconds, d.callback, seconds)
return d with PreserveLoggingContext():
yield d
def run_on_reactor(): def run_on_reactor():
""" This will cause the rest of the function to be invoked upon the next """ This will cause the rest of the function to be invoked upon the next

108
synapse/util/logcontext.py Normal file
View File

@ -0,0 +1,108 @@
import threading
import logging
class LoggingContext(object):
"""Additional context for log formatting. Contexts are scoped within a
"with" block. Contexts inherit the state of their parent contexts.
Args:
name (str): Name for the context for debugging.
"""
__slots__ = ["parent_context", "name", "__dict__"]
thread_local = threading.local()
class Sentinel(object):
"""Sentinel to represent the root context"""
__slots__ = []
def copy_to(self, record):
pass
sentinel = Sentinel()
def __init__(self, name=None):
self.parent_context = None
self.name = name
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)
def __enter__(self):
"""Enters this logging context into thread local storage"""
if self.parent_context is not None:
raise Exception("Attempt to enter logging context multiple times")
self.parent_context = self.current_context()
self.thread_local.current_context = self
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.
"""
if self.thread_local.current_context is not self:
logging.error(
"Current logging context %s is not the expected context %s",
self.thread_local.current_context,
self
)
self.thread_local.current_context = self.parent_context
self.parent_context = None
def __getattr__(self, name):
"""Delegate member lookup to parent context"""
return getattr(self.parent_context, name)
def copy_to(self, record):
"""Copy fields from this context and its parents to the record"""
if self.parent_context is not None:
self.parent_context.copy_to(record)
for key, value in self.__dict__.items():
setattr(record, key, value)
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"]
def __enter__(self):
"""Captures the current logging context"""
self.current_context = LoggingContext.current_context()
def __exit__(self, type, value, traceback):
"""Restores the current logging context"""
LoggingContext.thread_local.current_context = self.current_context

View File

@ -75,6 +75,7 @@ def trace_function(f):
linenum = f.func_code.co_firstlineno linenum = f.func_code.co_firstlineno
pathname = f.func_code.co_filename pathname = f.func_code.co_filename
@wraps(f)
def wrapped(*args, **kwargs): def wrapped(*args, **kwargs):
name = f.__module__ name = f.__module__
logger = logging.getLogger(name) logger = logging.getLogger(name)

View File

@ -0,0 +1,43 @@
from twisted.internet import defer
from twisted.internet import reactor
from .. import unittest
from synapse.util.async import sleep
from synapse.util.logcontext import LoggingContext
class LoggingContextTestCase(unittest.TestCase):
def _check_test_key(self, value):
self.assertEquals(
LoggingContext.current_context().test_key, value
)
def test_with_context(self):
with LoggingContext() as context_one:
context_one.test_key = "test"
self._check_test_key("test")
def test_chaining(self):
with LoggingContext() as context_one:
context_one.test_key = "one"
with LoggingContext() as context_two:
self._check_test_key("one")
context_two.test_key = "two"
self._check_test_key("two")
self._check_test_key("one")
@defer.inlineCallbacks
def test_sleep(self):
@defer.inlineCallbacks
def competing_callback():
with LoggingContext() as competing_context:
competing_context.test_key = "competing"
yield sleep(0)
self._check_test_key("competing")
reactor.callLater(0, competing_callback)
with LoggingContext() as context_one:
context_one.test_key = "one"
yield sleep(0)
self._check_test_key("one")