diff --git a/synapse/handlers/events.py b/synapse/handlers/events.py
index e08231406d..f814e7165b 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,13 +92,15 @@ 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
)
del self._stop_timer_per_user[auth_user]
+ logger.debug("Scheduling _later: for %s", auth_user)
self._stop_timer_per_user[auth_user] = (
- self.clock.call_later(5, _later)
+ self.clock.call_later(600, _later)
)
diff --git a/synapse/handlers/presence.py b/synapse/handlers/presence.py
index bef1508892..414a5b7bd5 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
@@ -141,6 +143,10 @@ class PresenceHandler(BaseHandler):
@defer.inlineCallbacks
def is_presence_visible(self, observer_user, observed_user):
+ defer.returnValue(True)
+ # return
+ # FIXME (erikj): This code path absolutely kills the database.
+
assert(observed_user.is_mine)
if observer_user == observed_user:
@@ -184,7 +190,12 @@ class PresenceHandler(BaseHandler):
defer.returnValue(state)
@defer.inlineCallbacks
+ @trace_function
def set_state(self, target_user, auth_user, state):
+ # return
+ # TODO (erikj): Turn this back on. Why did we end up sending EDUs
+ # everywhere?
+
if not target_user.is_mine:
raise SynapseError(400, "User is not hosted on this Home Server")
@@ -237,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})
@@ -374,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)
@@ -455,6 +469,7 @@ class PresenceHandler(BaseHandler):
content={"poll": [u.to_string() for u in to_poll]}
)
+ @trace_function
def stop_polling_presence(self, user, target_user=None):
logger.debug("Stop polling for presence from %s", user)
@@ -494,6 +509,7 @@ class PresenceHandler(BaseHandler):
if not self._local_pushmap[localpart]:
del self._local_pushmap[localpart]
+ @trace_function
def _stop_polling_remote(self, user, domain, remoteusers):
to_unpoll = set()
@@ -514,6 +530,7 @@ class PresenceHandler(BaseHandler):
)
@defer.inlineCallbacks
+ @trace_function
def push_presence(self, user, statuscache):
assert(user.is_mine)
@@ -556,6 +573,7 @@ class PresenceHandler(BaseHandler):
)
@defer.inlineCallbacks
+ @trace_function
def _send_presence_to_distribution(self, srcuser, localusers=set(),
remotedomains=set(), statuscache=None):
diff --git a/synapse/notifier.py b/synapse/notifier.py
index 3d3fcdabdb..d222644cb6 100644
--- a/synapse/notifier.py
+++ b/synapse/notifier.py
@@ -15,7 +15,7 @@
from twisted.internet import defer, reactor
-from synapse.util.logutils import log_function
+from synapse.util.logutils import log_function, trace_function
import logging
@@ -119,6 +119,7 @@ class Notifier(object):
)
@defer.inlineCallbacks
+ @trace_function
def on_new_user_event(self, users=[], rooms=[]):
""" Used to inform listeners that something has happend
presence/user event wise.
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 021649071b..b94a749786 100644
--- a/synapse/util/logutils.py
+++ b/synapse/util/logutils.py
@@ -18,6 +18,8 @@ from inspect import getcallargs
from functools import wraps
import logging
+import inspect
+import traceback
def log_function(f):
@@ -65,4 +67,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
|
