diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py
index 6394bc27d1..4e74f4d14c 100755
--- a/synapse/app/homeserver.py
+++ b/synapse/app/homeserver.py
@@ -33,6 +33,7 @@ from synapse.api.urls import (
)
from synapse.config.homeserver import HomeServerConfig
from synapse.crypto import context_factory
+from synapse.util.logcontext import LoggingContext
from daemonize import Daemonize
import twisted.manhole.telnet
@@ -240,7 +241,7 @@ def setup():
daemon = Daemonize(
app="synapse-homeserver",
pid=config.pid_file,
- action=reactor.run,
+ action=run,
auto_close_fds=False,
verbose=True,
logger=logger,
@@ -250,6 +251,13 @@ def setup():
else:
reactor.run()
+def run():
+ with LoggingContext("run") as context:
+ reactor.run()
+
+def main():
+ with LoggingContext("main") as context:
+ setup()
if __name__ == '__main__':
- setup()
+ main()
diff --git a/synapse/config/logger.py b/synapse/config/logger.py
index 56cd095433..2a59bf9d15 100644
--- a/synapse/config/logger.py
+++ b/synapse/config/logger.py
@@ -14,7 +14,7 @@
# limitations under the License.
from ._base import Config
-
+from synapse.util.logcontext import LoggingContextFilter
from twisted.python.log import PythonLoggingObserver
import logging
import logging.config
@@ -45,7 +45,8 @@ class LoggingConfig(Config):
def setup_logging(self):
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:
@@ -54,12 +55,20 @@ class LoggingConfig(Config):
level = logging.DEBUG
# 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()
+ print handler
+ handler.setFormatter(formatter)
+
+ handler.addFilter(LoggingContextFilter(request=""))
- logging.basicConfig(
- level=level,
- filename=self.log_file,
- format=log_format
- )
+ logger.addHandler(handler)
+ logger.info("Test")
else:
logging.config.fileConfig(self.log_config)
diff --git a/synapse/crypto/keyclient.py b/synapse/crypto/keyclient.py
index 7cfec5148e..33fa9ca837 100644
--- a/synapse/crypto/keyclient.py
+++ b/synapse/crypto/keyclient.py
@@ -18,6 +18,7 @@ from twisted.web.http import HTTPClient
from twisted.internet.protocol import Factory
from twisted.internet import defer, reactor
from synapse.http.endpoint import matrix_endpoint
+from synapse.util.logcontext import PreserveLoggingContext
import json
import logging
@@ -36,10 +37,11 @@ def fetch_server_key(server_name, ssl_context_factory):
for i in range(5):
try:
- protocol = yield endpoint.connect(factory)
- server_response, server_certificate = yield protocol.remote_key
- defer.returnValue((server_response, server_certificate))
- return
+ with PreserveLoggingContext():
+ protocol = yield endpoint.connect(factory)
+ server_response, server_certificate = yield protocol.remote_key
+ defer.returnValue((server_response, server_certificate))
+ return
except Exception as e:
logger.exception(e)
raise IOError("Cannot get key for %s" % server_name)
diff --git a/synapse/http/client.py b/synapse/http/client.py
index 46c90dbb76..8bda42364b 100644
--- a/synapse/http/client.py
+++ b/synapse/http/client.py
@@ -16,11 +16,14 @@
from twisted.internet import defer, reactor
from twisted.internet.error import DNSLookupError
-from twisted.web.client import _AgentBase, _URI, readBody, FileBodyProducer, PartialDownloadError
+from twisted.web.client import (
+ _AgentBase, _URI, readBody, FileBodyProducer, PartialDownloadError
+)
from twisted.web.http_headers import Headers
from synapse.http.endpoint import matrix_endpoint
from synapse.util.async import sleep
+from synapse.util.logcontext import PreserveLoggingContext
from syutil.jsonutil import encode_canonical_json
@@ -106,16 +109,17 @@ class BaseHttpClient(object):
producer = body_callback(method, url_bytes, headers_dict)
try:
- response = yield self.agent.request(
- destination,
- endpoint,
- method,
- path_bytes,
- param_bytes,
- query_bytes,
- Headers(headers_dict),
- producer
- )
+ with PreserveLoggingContext():
+ response = yield self.agent.request(
+ destination,
+ endpoint,
+ method,
+ path_bytes,
+ param_bytes,
+ query_bytes,
+ Headers(headers_dict),
+ producer
+ )
logger.debug("Got response to %s", method)
break
diff --git a/synapse/http/server.py b/synapse/http/server.py
index 8d419c02dd..ed1f1170cb 100644
--- a/synapse/http/server.py
+++ b/synapse/http/server.py
@@ -20,6 +20,7 @@ from syutil.jsonutil import (
from synapse.api.errors import (
cs_exception, SynapseError, CodeMessageException
)
+from synapse.util.logcontext import LoggingContext
from twisted.internet import defer, reactor
from twisted.web import server, resource
@@ -88,9 +89,19 @@ class JsonResource(HttpServer, resource.Resource):
def render(self, 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
+ _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
def _async_render(self, request):
""" This get's called by twisted every time someone sends us a request.
diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py
index 65a86e9056..2faa63904e 100644
--- a/synapse/storage/_base.py
+++ b/synapse/storage/_base.py
@@ -19,6 +19,7 @@ from twisted.internet import defer
from synapse.api.errors import StoreError
from synapse.api.events.utils import prune_event
from synapse.util.logutils import log_function
+from synapse.util.logcontext import PreserveLoggingContext, LoggingContext
import collections
import copy
@@ -74,12 +75,19 @@ class SQLBaseStore(object):
self.event_factory = hs.get_event_factory()
self._clock = hs.get_clock()
+ @defer.inlineCallbacks
def runInteraction(self, func, *args, **kwargs):
"""Wraps the .runInteraction() method on the underlying db_pool."""
+ current_context = LoggingContext.current_context()
def inner_func(txn, *args, **kwargs):
- return func(LoggingTransaction(txn), *args, **kwargs)
-
- return self._db_pool.runInteraction(inner_func, *args, **kwargs)
+ with LoggingContext("runInteraction") as context:
+ current_context.copy_to(context)
+ return func(LoggingTransaction(txn), *args, **kwargs)
+ with PreserveLoggingContext():
+ result = yield self._db_pool.runInteraction(
+ inner_func, *args, **kwargs
+ )
+ defer.returnValue(result)
def cursor_to_dict(self, cursor):
"""Converts a SQL cursor into an list of dicts.
@@ -146,7 +154,7 @@ class SQLBaseStore(object):
)
logger.debug(
- "[SQL] %s Args=%s Func=%s",
+ "[SQL] %s Args=%s",
sql, values.values(),
)
diff --git a/synapse/util/async.py b/synapse/util/async.py
index 647ea6142c..3d3fbe182c 100644
--- a/synapse/util/async.py
+++ b/synapse/util/async.py
@@ -16,8 +16,11 @@
from twisted.internet import defer, reactor
+from .logcontext import PreserveLoggingContext
+@defer.inlineCallbacks
def sleep(seconds):
d = defer.Deferred()
reactor.callLater(seconds, d.callback, seconds)
- return d
+ with PreserveLoggingContext():
+ yield d
diff --git a/synapse/util/logcontext.py b/synapse/util/logcontext.py
new file mode 100644
index 0000000000..46a2855a15
--- /dev/null
+++ b/synapse/util/logcontext.py
@@ -0,0 +1,85 @@
+from functools import wraps
+
+import threading
+import logging
+
+class LoggingContext(object):
+ __slots__ = ["parent_context", "name", "__dict__"]
+
+ thread_local = threading.local()
+
+ class Sentinel(object):
+ __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):
+ return getattr(cls.thread_local, "current_context", cls.sentinel)
+
+ def __enter__(self):
+ 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):
+ 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):
+ return getattr(self.parent_context, name)
+
+ def copy_to(self, 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)
+
+ @classmethod
+ def wrap_callback(cls, callback):
+ context = cls.current_context()
+ @wraps(callback)
+ def wrapped(*args, **kargs):
+ cls.thread_local.current_context = context
+ return callback(*args, **kargs)
+ return wrapped
+
+
+class LoggingContextFilter(logging.Filter):
+ def __init__(self, **defaults):
+ self.defaults = defaults
+
+ def filter(self, record):
+ context = LoggingContext.current_context()
+ for key, value in self.defaults.items():
+ setattr(record, key, value)
+ context.copy_to(record)
+ return True
+
+
+class PreserveLoggingContext(object):
+ __slots__ = ["current_context"]
+ def __enter__(self):
+ self.current_context = LoggingContext.current_context()
+
+ def __exit__(self, type, value, traceback):
+ LoggingContext.thread_local.current_context = self.current_context
+
+
diff --git a/synapse/util/logutils.py b/synapse/util/logutils.py
index fadf0bd510..903a6cf1b3 100644
--- a/synapse/util/logutils.py
+++ b/synapse/util/logutils.py
@@ -75,6 +75,7 @@ def trace_function(f):
linenum = f.func_code.co_firstlineno
pathname = f.func_code.co_filename
+ @wraps(f)
def wrapped(*args, **kwargs):
name = f.__module__
logger = logging.getLogger(name)
|
