diff options
| -rw-r--r-- | synapse/handlers/events.py | 3 | ||||
| -rw-r--r-- | synapse/handlers/presence.py | 11 | ||||
| -rw-r--r-- | synapse/streams/config.py | 2 | ||||
| -rw-r--r-- | synapse/util/logutils.py | 53 |
4 files changed, 66 insertions, 3 deletions
diff --git a/synapse/handlers/events.py b/synapse/handlers/events.py index e08231406d..23bc0b6e28 100644 --- a/synapse/handlers/events.py +++ b/synapse/handlers/events.py @@ -16,6 +16,7 @@ from twisted.internet import defer from synapse.api.events import SynapseEvent +from synapse.util.logutils import log_function from ._base import BaseHandler @@ -44,6 +45,7 @@ class EventStreamHandler(BaseHandler): self.notifier = hs.get_notifier() @defer.inlineCallbacks + @log_function def get_stream(self, auth_user_id, pagin_config, timeout=0): auth_user = self.hs.parse_userid(auth_user_id) @@ -90,6 +92,7 @@ class EventStreamHandler(BaseHandler): # 10 seconds of grace to allow the client to reconnect again # before we think they're gone def _later(): + logger.debug("_later stopped_user_eventstream %s", auth_user) self.distributor.fire( "stopped_user_eventstream", auth_user ) diff --git a/synapse/handlers/presence.py b/synapse/handlers/presence.py index c479908f61..1be3845691 100644 --- a/synapse/handlers/presence.py +++ b/synapse/handlers/presence.py @@ -18,6 +18,8 @@ from twisted.internet import defer from synapse.api.errors import SynapseError, AuthError from synapse.api.constants import PresenceState +from synapse.util.logutils import trace_function, log_function + from ._base import BaseHandler import logging @@ -142,7 +144,7 @@ class PresenceHandler(BaseHandler): @defer.inlineCallbacks def is_presence_visible(self, observer_user, observed_user): defer.returnValue(True) - return + # return # FIXME (erikj): This code path absolutely kills the database. assert(observed_user.is_mine) @@ -188,8 +190,9 @@ class PresenceHandler(BaseHandler): defer.returnValue(state) @defer.inlineCallbacks + @trace_function def set_state(self, target_user, auth_user, state): - return + # return # TODO (erikj): Turn this back on. Why did we end up sending EDUs # everywhere? @@ -245,10 +248,12 @@ class PresenceHandler(BaseHandler): self.push_presence(user, statuscache=statuscache) + @trace_function def started_user_eventstream(self, user): # TODO(paul): Use "last online" state self.set_state(user, user, {"state": PresenceState.ONLINE}) + @trace_function def stopped_user_eventstream(self, user): # TODO(paul): Save current state as "last online" state self.set_state(user, user, {"state": PresenceState.OFFLINE}) @@ -382,6 +387,7 @@ class PresenceHandler(BaseHandler): defer.returnValue(presence) @defer.inlineCallbacks + @trace_function def start_polling_presence(self, user, target_user=None, state=None): logger.debug("Start polling for presence from %s", user) @@ -457,6 +463,7 @@ class PresenceHandler(BaseHandler): content={"poll": [u.to_string() for u in remoteusers]} ) + @trace_function def stop_polling_presence(self, user, target_user=None): logger.debug("Stop polling for presence from %s", user) diff --git a/synapse/streams/config.py b/synapse/streams/config.py index 2434844d80..01bab568ff 100644 --- a/synapse/streams/config.py +++ b/synapse/streams/config.py @@ -81,4 +81,4 @@ class PaginationConfig(object): return ( "<PaginationConfig from_tok=%s, to_tok=%s, " "direction=%s, limit=%s>" - ) % (self.from_tok, self.to_tok, self.direction, self.limit) + ) % (self.from_token, self.to_token, self.direction, self.limit) diff --git a/synapse/util/logutils.py b/synapse/util/logutils.py index 9270a1790b..86a41ddc8e 100644 --- a/synapse/util/logutils.py +++ b/synapse/util/logutils.py @@ -17,6 +17,8 @@ from inspect import getcallargs import logging +import inspect +import traceback def log_function(f): @@ -63,4 +65,55 @@ def log_function(f): return f(*args, **kwargs) + wrapped.__name__ = func_name + return wrapped + + +def trace_function(f): + func_name = f.__name__ + linenum = f.func_code.co_firstlineno + pathname = f.func_code.co_filename + + def wrapped(*args, **kwargs): + name = f.__module__ + logger = logging.getLogger(name) + level = logging.DEBUG + + s = inspect.currentframe().f_back + + to_print = [ + "\t%s:%s %s. Args: args=%s, kwargs=%s" % ( + pathname, linenum, func_name, args, kwargs + ) + ] + while s: + if True or s.f_globals["__name__"].startswith("synapse"): + filename, lineno, function, _, _ = inspect.getframeinfo(s) + args_string = inspect.formatargvalues(*inspect.getargvalues(s)) + + to_print.append( + "\t%s:%d %s. Args: %s" % ( + filename, lineno, function, args_string + ) + ) + + s = s.f_back + + msg = "\nTraceback for %s:\n" % (func_name,) + "\n".join(to_print) + + record = logging.LogRecord( + name=name, + level=level, + pathname=pathname, + lineno=lineno, + msg=msg, + args=None, + exc_info=None + ) + + logger.handle(record) + + return f(*args, **kwargs) + + wrapped.__name__ = func_name return wrapped |