Add logging to try and figure out what is going on with the presence stuff

paul/schema_breaking_changes
Erik Johnston 2014-08-28 14:58:51 +01:00
parent b485d622cc
commit b8b52ca09d
4 changed files with 66 additions and 3 deletions

View File

@ -16,6 +16,7 @@
from twisted.internet import defer from twisted.internet import defer
from synapse.api.events import SynapseEvent from synapse.api.events import SynapseEvent
from synapse.util.logutils import log_function
from ._base import BaseHandler from ._base import BaseHandler
@ -44,6 +45,7 @@ class EventStreamHandler(BaseHandler):
self.notifier = hs.get_notifier() self.notifier = hs.get_notifier()
@defer.inlineCallbacks @defer.inlineCallbacks
@log_function
def get_stream(self, auth_user_id, pagin_config, timeout=0): def get_stream(self, auth_user_id, pagin_config, timeout=0):
auth_user = self.hs.parse_userid(auth_user_id) 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 # 10 seconds of grace to allow the client to reconnect again
# before we think they're gone # before we think they're gone
def _later(): def _later():
logger.debug("_later stopped_user_eventstream %s", auth_user)
self.distributor.fire( self.distributor.fire(
"stopped_user_eventstream", auth_user "stopped_user_eventstream", auth_user
) )

View File

@ -18,6 +18,8 @@ from twisted.internet import defer
from synapse.api.errors import SynapseError, AuthError from synapse.api.errors import SynapseError, AuthError
from synapse.api.constants import PresenceState from synapse.api.constants import PresenceState
from synapse.util.logutils import trace_function, log_function
from ._base import BaseHandler from ._base import BaseHandler
import logging import logging
@ -142,7 +144,7 @@ class PresenceHandler(BaseHandler):
@defer.inlineCallbacks @defer.inlineCallbacks
def is_presence_visible(self, observer_user, observed_user): def is_presence_visible(self, observer_user, observed_user):
defer.returnValue(True) defer.returnValue(True)
return # return
# FIXME (erikj): This code path absolutely kills the database. # FIXME (erikj): This code path absolutely kills the database.
assert(observed_user.is_mine) assert(observed_user.is_mine)
@ -188,8 +190,9 @@ class PresenceHandler(BaseHandler):
defer.returnValue(state) defer.returnValue(state)
@defer.inlineCallbacks @defer.inlineCallbacks
@trace_function
def set_state(self, target_user, auth_user, state): def set_state(self, target_user, auth_user, state):
return # return
# TODO (erikj): Turn this back on. Why did we end up sending EDUs # TODO (erikj): Turn this back on. Why did we end up sending EDUs
# everywhere? # everywhere?
@ -245,10 +248,12 @@ class PresenceHandler(BaseHandler):
self.push_presence(user, statuscache=statuscache) self.push_presence(user, statuscache=statuscache)
@trace_function
def started_user_eventstream(self, user): def started_user_eventstream(self, user):
# TODO(paul): Use "last online" state # TODO(paul): Use "last online" state
self.set_state(user, user, {"state": PresenceState.ONLINE}) self.set_state(user, user, {"state": PresenceState.ONLINE})
@trace_function
def stopped_user_eventstream(self, user): def stopped_user_eventstream(self, user):
# TODO(paul): Save current state as "last online" state # TODO(paul): Save current state as "last online" state
self.set_state(user, user, {"state": PresenceState.OFFLINE}) self.set_state(user, user, {"state": PresenceState.OFFLINE})
@ -382,6 +387,7 @@ class PresenceHandler(BaseHandler):
defer.returnValue(presence) defer.returnValue(presence)
@defer.inlineCallbacks @defer.inlineCallbacks
@trace_function
def start_polling_presence(self, user, target_user=None, state=None): def start_polling_presence(self, user, target_user=None, state=None):
logger.debug("Start polling for presence from %s", user) 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]} content={"poll": [u.to_string() for u in remoteusers]}
) )
@trace_function
def stop_polling_presence(self, user, target_user=None): def stop_polling_presence(self, user, target_user=None):
logger.debug("Stop polling for presence from %s", user) logger.debug("Stop polling for presence from %s", user)

View File

@ -81,4 +81,4 @@ class PaginationConfig(object):
return ( return (
"<PaginationConfig from_tok=%s, to_tok=%s, " "<PaginationConfig from_tok=%s, to_tok=%s, "
"direction=%s, limit=%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)

View File

@ -17,6 +17,8 @@
from inspect import getcallargs from inspect import getcallargs
import logging import logging
import inspect
import traceback
def log_function(f): def log_function(f):
@ -63,4 +65,55 @@ def log_function(f):
return f(*args, **kwargs) 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 return wrapped