From b8b52ca09d76e14854535df9a93b25096fcbd36a Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 28 Aug 2014 14:58:51 +0100 Subject: [PATCH 1/8] Add logging to try and figure out what is going on with the presence stuff --- synapse/handlers/events.py | 3 ++ synapse/handlers/presence.py | 11 ++++++-- synapse/streams/config.py | 2 +- 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 ( "" - ) % (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 From e0ba81344c9f063ed4d9546ce316818b703866a9 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 28 Aug 2014 15:30:42 +0100 Subject: [PATCH 2/8] Add more logging. Up the event stream timer to 10s --- synapse/handlers/events.py | 3 ++- synapse/handlers/presence.py | 2 ++ 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/synapse/handlers/events.py b/synapse/handlers/events.py index 23bc0b6e28..f2df2175b6 100644 --- a/synapse/handlers/events.py +++ b/synapse/handlers/events.py @@ -98,8 +98,9 @@ class EventStreamHandler(BaseHandler): ) 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(10, _later) ) diff --git a/synapse/handlers/presence.py b/synapse/handlers/presence.py index 1be3845691..7741ed3171 100644 --- a/synapse/handlers/presence.py +++ b/synapse/handlers/presence.py @@ -517,6 +517,7 @@ class PresenceHandler(BaseHandler): ) @defer.inlineCallbacks + @trace_function def push_presence(self, user, statuscache): assert(user.is_mine) @@ -559,6 +560,7 @@ class PresenceHandler(BaseHandler): ) @defer.inlineCallbacks + @trace_function def _send_presence_to_distribution(self, srcuser, localusers=set(), remotedomains=set(), statuscache=None): From eb3094ed315fbf3ee1886eef3d6339f2ea259ba7 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 28 Aug 2014 15:58:38 +0100 Subject: [PATCH 3/8] And more logging. --- synapse/handlers/presence.py | 1 + synapse/notifier.py | 3 ++- 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/synapse/handlers/presence.py b/synapse/handlers/presence.py index 7741ed3171..a125ea6c10 100644 --- a/synapse/handlers/presence.py +++ b/synapse/handlers/presence.py @@ -503,6 +503,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): for u in remoteusers: self._remote_recvmap[u].remove(user) 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. From a8d318cf8276811222e1df187c5efeadb848f9ee Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 28 Aug 2014 16:44:09 +0100 Subject: [PATCH 4/8] Up timeout to 10 minutes --- synapse/handlers/events.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/handlers/events.py b/synapse/handlers/events.py index f2df2175b6..f814e7165b 100644 --- a/synapse/handlers/events.py +++ b/synapse/handlers/events.py @@ -100,7 +100,7 @@ class EventStreamHandler(BaseHandler): logger.debug("Scheduling _later: for %s", auth_user) self._stop_timer_per_user[auth_user] = ( - self.clock.call_later(10, _later) + self.clock.call_later(600, _later) ) From 1b7686329e96f1bde2a14cc35c98c2761e224c6e Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 28 Aug 2014 17:43:15 +0100 Subject: [PATCH 5/8] Don't query the rooms members table so much by using the new notifier api that allows you to specify room_ids to notify. --- synapse/handlers/events.py | 2 +- synapse/handlers/presence.py | 106 +++++++++++++++-------------------- 2 files changed, 46 insertions(+), 62 deletions(-) diff --git a/synapse/handlers/events.py b/synapse/handlers/events.py index f814e7165b..980a169b25 100644 --- a/synapse/handlers/events.py +++ b/synapse/handlers/events.py @@ -100,7 +100,7 @@ class EventStreamHandler(BaseHandler): logger.debug("Scheduling _later: for %s", auth_user) self._stop_timer_per_user[auth_user] = ( - self.clock.call_later(600, _later) + self.clock.call_later(30, _later) ) diff --git a/synapse/handlers/presence.py b/synapse/handlers/presence.py index 414a5b7bd5..677c1b2d81 100644 --- a/synapse/handlers/presence.py +++ b/synapse/handlers/presence.py @@ -260,24 +260,29 @@ class PresenceHandler(BaseHandler): @defer.inlineCallbacks def user_joined_room(self, user, room_id): - localusers = set() - remotedomains = set() - - rm_handler = self.homeserver.get_handlers().room_member_handler - yield rm_handler.fetch_room_distributions_into(room_id, - localusers=localusers, remotedomains=remotedomains, - ignore_user=user) + statuscache = self._get_or_make_usercache(user) if user.is_mine: - yield self._send_presence_to_distribution(srcuser=user, - localusers=localusers, remotedomains=remotedomains, - statuscache=self._get_or_offline_usercache(user), + remote_domains = set( + (yield self.store.get_joined_hosts_for_room(room_id)) ) - for srcuser in localusers: - yield self._send_presence(srcuser=srcuser, destuser=user, - statuscache=self._get_or_offline_usercache(srcuser), - ) + if not remote_domains: + defer.returnValue(None) + + deferreds = [] + for domain in remote_domains: + logger.debug(" | push to remote domain %s", domain) + deferreds.append(self._push_presence_remote(user, domain, + state=statuscache.get_state()) + ) + + + self.push_update_to_clients_2( + observed_user=user, + room_ids=[room_id], + statuscache=self._get_or_offline_usercache(user), + ) @defer.inlineCallbacks def send_invite(self, observer_user, observed_user): @@ -546,53 +551,28 @@ class PresenceHandler(BaseHandler): rm_handler = self.homeserver.get_handlers().room_member_handler room_ids = yield rm_handler.get_rooms_for_user(user) + remote_domains = set() for room_id in room_ids: - yield rm_handler.fetch_room_distributions_into( - room_id, localusers=localusers, remotedomains=remotedomains, - ignore_user=user, + remote_domains.update( + (yield self.store.get_joined_hosts_for_room(room_id)) ) if not localusers and not remotedomains: defer.returnValue(None) - yield self._send_presence_to_distribution(user, - localusers=localusers, remotedomains=remotedomains, - statuscache=statuscache - ) - - def _send_presence(self, srcuser, destuser, statuscache): - if destuser.is_mine: - self.push_update_to_clients( - observer_user=destuser, - observed_user=srcuser, - statuscache=statuscache) - return defer.succeed(None) - else: - return self._push_presence_remote(srcuser, destuser.domain, - state=statuscache.get_state() - ) - - @defer.inlineCallbacks - @trace_function - def _send_presence_to_distribution(self, srcuser, localusers=set(), - remotedomains=set(), statuscache=None): - - for u in localusers: - logger.debug(" | push to local user %s", u) - self.push_update_to_clients( - observer_user=u, - observed_user=srcuser, - statuscache=statuscache, - ) - deferreds = [] for domain in remotedomains: logger.debug(" | push to remote domain %s", domain) - deferreds.append(self._push_presence_remote(srcuser, domain, + deferreds.append(self._push_presence_remote(user, domain, state=statuscache.get_state()) ) - yield defer.DeferredList(deferreds) + self.push_update_to_clients_2( + observed_user=user, + users_to_push=localusers, + room_ids=room_ids, + statuscache=statuscache, + ) @defer.inlineCallbacks def _push_presence_remote(self, user, destination, state=None): @@ -633,12 +613,7 @@ class PresenceHandler(BaseHandler): rm_handler = self.homeserver.get_handlers().room_member_handler room_ids = yield rm_handler.get_rooms_for_user(user) - for room_id in room_ids: - yield rm_handler.fetch_room_distributions_into( - room_id, localusers=observers, ignore_user=user - ) - - if not observers: + if not observers and not room_ids: break state = dict(push) @@ -654,12 +629,12 @@ class PresenceHandler(BaseHandler): self._user_cachemap_latest_serial += 1 statuscache.update(state, serial=self._user_cachemap_latest_serial) - for observer_user in observers: - self.push_update_to_clients( - observer_user=observer_user, - observed_user=user, - statuscache=statuscache, - ) + self.push_update_to_clients_2( + observed_user=user, + users_to_push=observers, + room_ids=room_ids, + statuscache=statuscache, + ) if state["state"] == PresenceState.OFFLINE: del self._user_cachemap[user] @@ -701,6 +676,15 @@ class PresenceHandler(BaseHandler): [observer_user], ) + def push_update_to_clients_2(self, observed_user, users_to_push=[], + room_ids=[], statuscache=None): + statuscache.make_event(user=observed_user, clock=self.clock) + + self.notifier.on_new_user_event( + users_to_push, + room_ids, + ) + class UserPresenceCache(object): """Store an observed user's state and status message. From aaf4fd98eea39728a4e3311ac0001fc7a1390b18 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 28 Aug 2014 18:43:03 +0100 Subject: [PATCH 6/8] Only poll remote users if they are in our presence list, rather than in a common room --- synapse/handlers/presence.py | 119 +++++++++++++++++++---------------- 1 file changed, 66 insertions(+), 53 deletions(-) diff --git a/synapse/handlers/presence.py b/synapse/handlers/presence.py index 677c1b2d81..223ddfc650 100644 --- a/synapse/handlers/presence.py +++ b/synapse/handlers/presence.py @@ -263,26 +263,17 @@ class PresenceHandler(BaseHandler): statuscache = self._get_or_make_usercache(user) if user.is_mine: - remote_domains = set( - (yield self.store.get_joined_hosts_for_room(room_id)) + self.push_update_to_local_and_remote( + observed_user=user, + room_ids=[room_id], + statuscache=self._get_or_offline_usercache(user), + ) + else: + self.push_update_to_clients_2( + observed_user=user, + room_ids=[room_id], + statuscache=self._get_or_offline_usercache(user), ) - - if not remote_domains: - defer.returnValue(None) - - deferreds = [] - for domain in remote_domains: - logger.debug(" | push to remote domain %s", domain) - deferreds.append(self._push_presence_remote(user, domain, - state=statuscache.get_state()) - ) - - - self.push_update_to_clients_2( - observed_user=user, - room_ids=[room_id], - statuscache=self._get_or_offline_usercache(user), - ) @defer.inlineCallbacks def send_invite(self, observer_user, observed_user): @@ -398,6 +389,7 @@ class PresenceHandler(BaseHandler): if target_user: target_users = set([target_user]) + room_ids = [] else: presence = yield self.store.get_presence_list( user.localpart, accepted=True @@ -411,23 +403,24 @@ class PresenceHandler(BaseHandler): rm_handler = self.homeserver.get_handlers().room_member_handler room_ids = yield rm_handler.get_rooms_for_user(user) - for room_id in room_ids: - for member in (yield rm_handler.get_room_members(room_id)): - target_users.add(member) - if state is None: state = yield self.store.get_presence_state(user.localpart) - localusers, remoteusers = partitionbool( - target_users, - lambda u: u.is_mine + _, remote_domains = yield self.push_update_to_local_and_remote( + observed_user=user, + users_to_push=target_users, + room_ids=room_ids, + statuscache=self._get_or_make_usercache(user), ) - for target_user in localusers: - self._start_polling_local(user, target_user) + for target_user in target_users: + if target_user.is_mine: + self._start_polling_local(user, target_user) deferreds = [] - remoteusers_by_domain = partition(remoteusers, lambda u: u.domain) + remote_users = [u for u in target_users if not u.is_mine] + remoteusers_by_domain = partition(remote_users, lambda u: u.domain) + # Only poll for people in our get_presence_list for domain in remoteusers_by_domain: remoteusers = remoteusers_by_domain[domain] @@ -449,12 +442,6 @@ class PresenceHandler(BaseHandler): self._local_pushmap[target_localpart].add(user) - self.push_update_to_clients( - observer_user=user, - observed_user=target_user, - statuscache=self._get_or_offline_usercache(target_user), - ) - def _start_polling_remote(self, user, domain, remoteusers): to_poll = set() @@ -551,21 +538,15 @@ class PresenceHandler(BaseHandler): rm_handler = self.homeserver.get_handlers().room_member_handler room_ids = yield rm_handler.get_rooms_for_user(user) - remote_domains = set() - for room_id in room_ids: - remote_domains.update( - (yield self.store.get_joined_hosts_for_room(room_id)) - ) - - if not localusers and not remotedomains: + if not localusers and not room_ids: defer.returnValue(None) - deferreds = [] - for domain in remotedomains: - logger.debug(" | push to remote domain %s", domain) - deferreds.append(self._push_presence_remote(user, domain, - state=statuscache.get_state()) - ) + yield self.push_update_to_local_and_remote( + observed_user=user, + users_to_push=localusers, + room_ids=room_ids, + statuscache=statuscache, + ) self.push_update_to_clients_2( observed_user=user, @@ -668,14 +649,46 @@ class PresenceHandler(BaseHandler): yield defer.DeferredList(deferreds) - def push_update_to_clients(self, observer_user, observed_user, - statuscache): - statuscache.make_event(user=observed_user, clock=self.clock) + @defer.inlineCallbacks + def push_update_to_local_and_remote(self, observed_user, + users_to_push=[], room_ids=[], + statuscache=None): - self.notifier.on_new_user_event( - [observer_user], + localusers, remoteusers = partitionbool( + users_to_push, + lambda u: u.is_mine ) + localusers = set(localusers) + + self.push_update_to_clients_2( + observed_user, + users_to_push=localusers, + room_ids=room_ids, + statuscache=statuscache, + ) + + remote_domains = set([r.domain for r in remoteusers]) + for room_id in room_ids: + remote_domains.update( + (yield self.store.get_joined_hosts_for_room(room_id)) + ) + + remote_domains.discard(self.hs.hostname) + + deferreds = [] + for domain in remote_domains: + logger.debug(" | push to remote domain %s", domain) + deferreds.append( + self._push_presence_remote( + observed_user, domain, state=statuscache.get_state() + ) + ) + + yield defer.DeferredList(deferreds) + + defer.returnValue((localusers, remote_domains)) + def push_update_to_clients_2(self, observed_user, users_to_push=[], room_ids=[], statuscache=None): statuscache.make_event(user=observed_user, clock=self.clock) From 8113eb7c791890869fb8818da3be8e7ad8e37ea8 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 28 Aug 2014 18:45:00 +0100 Subject: [PATCH 7/8] Turn of trace_function logging --- synapse/handlers/presence.py | 16 ++++++++-------- synapse/notifier.py | 4 ++-- 2 files changed, 10 insertions(+), 10 deletions(-) diff --git a/synapse/handlers/presence.py b/synapse/handlers/presence.py index 223ddfc650..174a92d81b 100644 --- a/synapse/handlers/presence.py +++ b/synapse/handlers/presence.py @@ -18,7 +18,7 @@ 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 synapse.util.logutils import log_function from ._base import BaseHandler @@ -190,7 +190,7 @@ class PresenceHandler(BaseHandler): defer.returnValue(state) @defer.inlineCallbacks - @trace_function + @log_function def set_state(self, target_user, auth_user, state): # return # TODO (erikj): Turn this back on. Why did we end up sending EDUs @@ -248,12 +248,12 @@ class PresenceHandler(BaseHandler): self.push_presence(user, statuscache=statuscache) - @trace_function + @log_function def started_user_eventstream(self, user): # TODO(paul): Use "last online" state self.set_state(user, user, {"state": PresenceState.ONLINE}) - @trace_function + @log_function def stopped_user_eventstream(self, user): # TODO(paul): Save current state as "last online" state self.set_state(user, user, {"state": PresenceState.OFFLINE}) @@ -383,7 +383,7 @@ class PresenceHandler(BaseHandler): defer.returnValue(presence) @defer.inlineCallbacks - @trace_function + @log_function def start_polling_presence(self, user, target_user=None, state=None): logger.debug("Start polling for presence from %s", user) @@ -461,7 +461,7 @@ class PresenceHandler(BaseHandler): content={"poll": [u.to_string() for u in to_poll]} ) - @trace_function + @log_function def stop_polling_presence(self, user, target_user=None): logger.debug("Stop polling for presence from %s", user) @@ -501,7 +501,7 @@ class PresenceHandler(BaseHandler): if not self._local_pushmap[localpart]: del self._local_pushmap[localpart] - @trace_function + @log_function def _stop_polling_remote(self, user, domain, remoteusers): to_unpoll = set() @@ -522,7 +522,7 @@ class PresenceHandler(BaseHandler): ) @defer.inlineCallbacks - @trace_function + @log_function def push_presence(self, user, statuscache): assert(user.is_mine) diff --git a/synapse/notifier.py b/synapse/notifier.py index d222644cb6..b6d5ec4820 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, trace_function +from synapse.util.logutils import log_function import logging @@ -119,7 +119,7 @@ class Notifier(object): ) @defer.inlineCallbacks - @trace_function + @log_function def on_new_user_event(self, users=[], rooms=[]): """ Used to inform listeners that something has happend presence/user event wise. From 5dd38d579b45be26c27b1a109a1d413c3b0425a2 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Fri, 29 Aug 2014 12:08:33 +0100 Subject: [PATCH 8/8] Fix a couple of bugs in presence handler related to pushing updatesto the correct user. Fix presence tests. --- synapse/federation/replication.py | 2 + synapse/handlers/presence.py | 59 ++++++++---- tests/handlers/test_presence.py | 138 ++++++++++++++++++---------- tests/handlers/test_presencelike.py | 54 ++++++++--- tests/utils.py | 37 ++++++-- 5 files changed, 200 insertions(+), 90 deletions(-) diff --git a/synapse/federation/replication.py b/synapse/federation/replication.py index 7868575a2e..cadf574b3b 100644 --- a/synapse/federation/replication.py +++ b/synapse/federation/replication.py @@ -543,6 +543,8 @@ class _TransactionQueue(object): def eb(failure): if not deferred.called: deferred.errback(failure) + else: + logger.exception("Failed to send edu", failure) self._attempt_new_transaction(destination).addErrback(eb) return deferred diff --git a/synapse/handlers/presence.py b/synapse/handlers/presence.py index 174a92d81b..7731de85c0 100644 --- a/synapse/handlers/presence.py +++ b/synapse/handlers/presence.py @@ -260,7 +260,6 @@ class PresenceHandler(BaseHandler): @defer.inlineCallbacks def user_joined_room(self, user, room_id): - statuscache = self._get_or_make_usercache(user) if user.is_mine: self.push_update_to_local_and_remote( @@ -268,13 +267,25 @@ class PresenceHandler(BaseHandler): room_ids=[room_id], statuscache=self._get_or_offline_usercache(user), ) + else: - self.push_update_to_clients_2( + self.push_update_to_clients( observed_user=user, room_ids=[room_id], statuscache=self._get_or_offline_usercache(user), ) + # We also want to tell them about current presence of people. + rm_handler = self.homeserver.get_handlers().room_member_handler + curr_users = yield rm_handler.get_room_members(room_id) + + for local_user in [c for c in curr_users if c.is_mine]: + self.push_update_to_local_and_remote( + observed_user=local_user, + users_to_push=[user], + statuscache=self._get_or_offline_usercache(local_user), + ) + @defer.inlineCallbacks def send_invite(self, observer_user, observed_user): if not observer_user.is_mine: @@ -405,8 +416,13 @@ class PresenceHandler(BaseHandler): if state is None: state = yield self.store.get_presence_state(user.localpart) + else: +# statuscache = self._get_or_make_usercache(user) +# self._user_cachemap_latest_serial += 1 +# statuscache.update(state, self._user_cachemap_latest_serial) + pass - _, remote_domains = yield self.push_update_to_local_and_remote( + yield self.push_update_to_local_and_remote( observed_user=user, users_to_push=target_users, room_ids=room_ids, @@ -417,6 +433,14 @@ class PresenceHandler(BaseHandler): if target_user.is_mine: self._start_polling_local(user, target_user) + # We want to tell the person that just came online + # presence state of people they are interested in? + self.push_update_to_clients( + observed_user=target_user, + users_to_push=[user], + statuscache=self._get_or_offline_usercache(target_user), + ) + deferreds = [] remote_users = [u for u in target_users if not u.is_mine] remoteusers_by_domain = partition(remote_users, lambda u: u.domain) @@ -544,13 +568,7 @@ class PresenceHandler(BaseHandler): yield self.push_update_to_local_and_remote( observed_user=user, users_to_push=localusers, - room_ids=room_ids, - statuscache=statuscache, - ) - - self.push_update_to_clients_2( - observed_user=user, - users_to_push=localusers, + remote_domains=remotedomains, room_ids=room_ids, statuscache=statuscache, ) @@ -570,12 +588,17 @@ class PresenceHandler(BaseHandler): self.clock.time_msec() - state.pop("mtime") ) + user_state = { + "user_id": user.to_string(), + } + user_state.update(**state) + yield self.federation.send_edu( destination=destination, edu_type="m.presence", content={ "push": [ - dict(user_id=user.to_string(), **state), + user_state, ], } ) @@ -610,7 +633,7 @@ class PresenceHandler(BaseHandler): self._user_cachemap_latest_serial += 1 statuscache.update(state, serial=self._user_cachemap_latest_serial) - self.push_update_to_clients_2( + self.push_update_to_clients( observed_user=user, users_to_push=observers, room_ids=room_ids, @@ -652,6 +675,7 @@ class PresenceHandler(BaseHandler): @defer.inlineCallbacks def push_update_to_local_and_remote(self, observed_user, users_to_push=[], room_ids=[], + remote_domains=[], statuscache=None): localusers, remoteusers = partitionbool( @@ -661,14 +685,15 @@ class PresenceHandler(BaseHandler): localusers = set(localusers) - self.push_update_to_clients_2( - observed_user, + self.push_update_to_clients( + observed_user=observed_user, users_to_push=localusers, room_ids=room_ids, statuscache=statuscache, ) - remote_domains = set([r.domain for r in remoteusers]) + remote_domains = set(remote_domains) + remote_domains |= set([r.domain for r in remoteusers]) for room_id in room_ids: remote_domains.update( (yield self.store.get_joined_hosts_for_room(room_id)) @@ -689,10 +714,8 @@ class PresenceHandler(BaseHandler): defer.returnValue((localusers, remote_domains)) - def push_update_to_clients_2(self, observed_user, users_to_push=[], + def push_update_to_clients(self, observed_user, users_to_push=[], room_ids=[], statuscache=None): - statuscache.make_event(user=observed_user, clock=self.clock) - self.notifier.on_new_user_event( users_to_push, room_ids, diff --git a/tests/handlers/test_presence.py b/tests/handlers/test_presence.py index 8d094fd1f9..fcd7a784cd 100644 --- a/tests/handlers/test_presence.py +++ b/tests/handlers/test_presence.py @@ -193,6 +193,8 @@ class PresenceStateTestCase(unittest.TestCase): SynapseError ) + test_get_disallowed_state.skip = "Presence permissions are disabled" + @defer.inlineCallbacks def test_set_my_state(self): mocked_set = self.datastore.set_presence_state @@ -497,6 +499,7 @@ class PresencePushTestCase(unittest.TestCase): db_pool=None, datastore=Mock(spec=[ "set_presence_state", + "get_joined_hosts_for_room", # Bits that Federation needs "prep_send_transaction", @@ -511,8 +514,12 @@ class PresencePushTestCase(unittest.TestCase): ) hs.handlers = JustPresenceHandlers(hs) + def update(*args,**kwargs): + # print "mock_update_client: Args=%s, kwargs=%s" %(args, kwargs,) + return defer.succeed(None) + self.mock_update_client = Mock() - self.mock_update_client.return_value = defer.succeed(None) + self.mock_update_client.side_effect = update self.datastore = hs.get_datastore() @@ -546,6 +553,14 @@ class PresencePushTestCase(unittest.TestCase): return defer.succeed([]) self.room_member_handler.get_room_members = get_room_members + def get_room_hosts(room_id): + if room_id == "a-room": + hosts = set([u.domain for u in self.room_members]) + return defer.succeed(hosts) + else: + return defer.succeed([]) + self.datastore.get_joined_hosts_for_room = get_room_hosts + @defer.inlineCallbacks def fetch_room_distributions_into(room_id, localusers=None, remotedomains=None, ignore_user=None): @@ -611,18 +626,10 @@ class PresencePushTestCase(unittest.TestCase): {"state": ONLINE}) self.mock_update_client.assert_has_calls([ - call(observer_user=self.u_apple, + call(users_to_push=set([self.u_apple, self.u_banana, self.u_clementine]), + room_ids=["a-room"], observed_user=self.u_apple, statuscache=ANY), # self-reflection - call(observer_user=self.u_banana, - observed_user=self.u_apple, - statuscache=ANY), - call(observer_user=self.u_clementine, - observed_user=self.u_apple, - statuscache=ANY), - call(observer_user=self.u_elderberry, - observed_user=self.u_apple, - statuscache=ANY), ], any_order=True) self.mock_update_client.reset_mock() @@ -651,7 +658,8 @@ class PresencePushTestCase(unittest.TestCase): ], presence) self.mock_update_client.assert_has_calls([ - call(observer_user=self.u_banana, + call(users_to_push=set([self.u_banana]), + room_ids=[], observed_user=self.u_banana, statuscache=ANY), # self-reflection ]) # and no others... @@ -659,21 +667,21 @@ class PresencePushTestCase(unittest.TestCase): @defer.inlineCallbacks def test_push_remote(self): put_json = self.mock_http_client.put_json - put_json.expect_call_and_return( - call("remote", - path=ANY, # Can't guarantee which txn ID will be which - data=_expect_edu("remote", "m.presence", - content={ - "push": [ - {"user_id": "@apple:test", - "state": "online", - "mtime_age": 0}, - ], - } - ) - ), - defer.succeed((200, "OK")) - ) +# put_json.expect_call_and_return( +# call("remote", +# path=ANY, # Can't guarantee which txn ID will be which +# data=_expect_edu("remote", "m.presence", +# content={ +# "push": [ +# {"user_id": "@apple:test", +# "state": "online", +# "mtime_age": 0}, +# ], +# } +# ) +# ), +# defer.succeed((200, "OK")) +# ) put_json.expect_call_and_return( call("farm", path=ANY, # Can't guarantee which txn ID will be which @@ -681,7 +689,7 @@ class PresencePushTestCase(unittest.TestCase): content={ "push": [ {"user_id": "@apple:test", - "state": "online", + "state": u"online", "mtime_age": 0}, ], } @@ -730,10 +738,8 @@ class PresencePushTestCase(unittest.TestCase): ) self.mock_update_client.assert_has_calls([ - call(observer_user=self.u_apple, - observed_user=self.u_potato, - statuscache=ANY), - call(observer_user=self.u_banana, + call(users_to_push=set([self.u_apple]), + room_ids=["a-room"], observed_user=self.u_potato, statuscache=ANY), ], any_order=True) @@ -753,19 +759,17 @@ class PresencePushTestCase(unittest.TestCase): ) self.mock_update_client.assert_has_calls([ - # Apple and Elderberry see each other - call(observer_user=self.u_apple, + call(room_ids=["a-room"], observed_user=self.u_elderberry, + users_to_push=set(), statuscache=ANY), - call(observer_user=self.u_elderberry, + call(users_to_push=set([self.u_elderberry]), observed_user=self.u_apple, + room_ids=[], statuscache=ANY), - # Banana and Elderberry see each other - call(observer_user=self.u_banana, - observed_user=self.u_elderberry, - statuscache=ANY), - call(observer_user=self.u_elderberry, + call(users_to_push=set([self.u_elderberry]), observed_user=self.u_banana, + room_ids=[], statuscache=ANY), ], any_order=True) @@ -887,7 +891,12 @@ class PresencePollingTestCase(unittest.TestCase): self.datastore.get_received_txn_response = get_received_txn_response self.mock_update_client = Mock() - self.mock_update_client.return_value = defer.succeed(None) + + def update(*args,**kwargs): + # print "mock_update_client: Args=%s, kwargs=%s" %(args, kwargs,) + return defer.succeed(None) + + self.mock_update_client.side_effect = update self.handler = hs.get_handlers().presence_handler self.handler.push_update_to_clients = self.mock_update_client @@ -951,10 +960,10 @@ class PresencePollingTestCase(unittest.TestCase): # apple should see both banana and clementine currently offline self.mock_update_client.assert_has_calls([ - call(observer_user=self.u_apple, + call(users_to_push=[self.u_apple], observed_user=self.u_banana, statuscache=ANY), - call(observer_user=self.u_apple, + call(users_to_push=[self.u_apple], observed_user=self.u_clementine, statuscache=ANY), ], any_order=True) @@ -974,10 +983,11 @@ class PresencePollingTestCase(unittest.TestCase): # apple and banana should now both see each other online self.mock_update_client.assert_has_calls([ - call(observer_user=self.u_apple, + call(users_to_push=set([self.u_apple]), observed_user=self.u_banana, + room_ids=[], statuscache=ANY), - call(observer_user=self.u_banana, + call(users_to_push=[self.u_banana], observed_user=self.u_apple, statuscache=ANY), ], any_order=True) @@ -994,8 +1004,9 @@ class PresencePollingTestCase(unittest.TestCase): # banana should now be told apple is offline self.mock_update_client.assert_has_calls([ - call(observer_user=self.u_banana, + call(users_to_push=set([self.u_banana, self.u_apple]), observed_user=self.u_apple, + room_ids=[], statuscache=ANY), ], any_order=True) @@ -1008,7 +1019,7 @@ class PresencePollingTestCase(unittest.TestCase): put_json = self.mock_http_client.put_json put_json.expect_call_and_return( call("remote", - path="/matrix/federation/v1/send/1000000/", + path=ANY, data=_expect_edu("remote", "m.presence", content={ "poll": [ "@potato:remote" ], @@ -1018,6 +1029,18 @@ class PresencePollingTestCase(unittest.TestCase): defer.succeed((200, "OK")) ) + put_json.expect_call_and_return( + call("remote", + path=ANY, + data=_expect_edu("remote", "m.presence", + content={ + "push": [ {"user_id": "@clementine:test" }], + }, + ), + ), + defer.succeed((200, "OK")) + ) + # clementine goes online yield self.handler.set_state( target_user=self.u_clementine, auth_user=self.u_clementine, @@ -1032,15 +1055,28 @@ class PresencePollingTestCase(unittest.TestCase): self.assertTrue(self.u_clementine in self.handler._remote_recvmap[self.u_potato]) + + put_json.expect_call_and_return( + call("remote", + path=ANY, + data=_expect_edu("remote", "m.presence", + content={ + "push": [ {"user_id": "@fig:test" }], + }, + ), + ), + defer.succeed((200, "OK")) + ) + # fig goes online; shouldn't send a second poll yield self.handler.set_state( target_user=self.u_fig, auth_user=self.u_fig, state={"state": ONLINE} ) - reactor.iterate(delay=0) + # reactor.iterate(delay=0) - put_json.assert_had_no_calls() + yield put_json.await_calls() # fig goes offline yield self.handler.set_state( @@ -1054,7 +1090,7 @@ class PresencePollingTestCase(unittest.TestCase): put_json.expect_call_and_return( call("remote", - path="/matrix/federation/v1/send/1000001/", + path=ANY, data=_expect_edu("remote", "m.presence", content={ "unpoll": [ "@potato:remote" ], @@ -1069,7 +1105,7 @@ class PresencePollingTestCase(unittest.TestCase): target_user=self.u_clementine, auth_user=self.u_clementine, state={"state": OFFLINE}) - put_json.await_calls() + yield put_json.await_calls() self.assertFalse(self.u_potato in self.handler._remote_recvmap, msg="expected potato not to be in _remote_recvmap" diff --git a/tests/handlers/test_presencelike.py b/tests/handlers/test_presencelike.py index da06a06647..e81d7ce101 100644 --- a/tests/handlers/test_presencelike.py +++ b/tests/handlers/test_presencelike.py @@ -81,7 +81,11 @@ class PresenceProfilelikeDataTestCase(unittest.TestCase): self.replication = hs.get_replication_layer() self.replication.send_edu = Mock() - self.replication.send_edu.return_value = defer.succeed((200, "OK")) + + def send_edu(*args, **kwargs): + # print "send_edu: %s, %s" % (args, kwargs) + return defer.succeed((200, "OK")) + self.replication.send_edu.side_effect = send_edu def get_profile_displayname(user_localpart): return defer.succeed("Frank") @@ -95,11 +99,12 @@ class PresenceProfilelikeDataTestCase(unittest.TestCase): return defer.succeed("http://foo") self.datastore.get_profile_avatar_url = get_profile_avatar_url + self.presence_list = [ + {"observed_user_id": "@banana:test"}, + {"observed_user_id": "@clementine:test"}, + ] def get_presence_list(user_localpart, accepted=None): - return defer.succeed([ - {"observed_user_id": "@banana:test"}, - {"observed_user_id": "@clementine:test"}, - ]) + return defer.succeed(self.presence_list) self.datastore.get_presence_list = get_presence_list def do_users_share_a_room(userlist): @@ -109,7 +114,10 @@ class PresenceProfilelikeDataTestCase(unittest.TestCase): self.handlers = hs.get_handlers() self.mock_update_client = Mock() - self.mock_update_client.return_value = defer.succeed(None) + def update(*args, **kwargs): + # print "mock_update_client: %s, %s" %(args, kwargs) + return defer.succeed(None) + self.mock_update_client.side_effect = update self.handlers.presence_handler.push_update_to_clients = ( self.mock_update_client) @@ -130,6 +138,11 @@ class PresenceProfilelikeDataTestCase(unittest.TestCase): @defer.inlineCallbacks def test_set_my_state(self): + self.presence_list = [ + {"observed_user_id": "@banana:test"}, + {"observed_user_id": "@clementine:test"}, + ] + mocked_set = self.datastore.set_presence_state mocked_set.return_value = defer.succeed({"state": OFFLINE}) @@ -142,6 +155,11 @@ class PresenceProfilelikeDataTestCase(unittest.TestCase): @defer.inlineCallbacks def test_push_local(self): + self.presence_list = [ + {"observed_user_id": "@banana:test"}, + {"observed_user_id": "@clementine:test"}, + ] + self.datastore.set_presence_state.return_value = defer.succeed( {"state": ONLINE}) @@ -173,12 +191,10 @@ class PresenceProfilelikeDataTestCase(unittest.TestCase): presence) self.mock_update_client.assert_has_calls([ - call(observer_user=self.u_apple, + call(users_to_push=set([self.u_apple, self.u_banana, self.u_clementine]), + room_ids=[], observed_user=self.u_apple, statuscache=ANY), # self-reflection - call(observer_user=self.u_banana, - observed_user=self.u_apple, - statuscache=ANY), ], any_order=True) statuscache = self.mock_update_client.call_args[1]["statuscache"] @@ -198,12 +214,10 @@ class PresenceProfilelikeDataTestCase(unittest.TestCase): self.u_apple, "I am an Apple") self.mock_update_client.assert_has_calls([ - call(observer_user=self.u_apple, + call(users_to_push=set([self.u_apple, self.u_banana, self.u_clementine]), + room_ids=[], observed_user=self.u_apple, statuscache=ANY), # self-reflection - call(observer_user=self.u_banana, - observed_user=self.u_apple, - statuscache=ANY), ], any_order=True) statuscache = self.mock_update_client.call_args[1]["statuscache"] @@ -217,6 +231,10 @@ class PresenceProfilelikeDataTestCase(unittest.TestCase): @defer.inlineCallbacks def test_push_remote(self): + self.presence_list = [ + {"observed_user_id": "@potato:remote"}, + ] + self.datastore.set_presence_state.return_value = defer.succeed( {"state": ONLINE}) @@ -247,6 +265,11 @@ class PresenceProfilelikeDataTestCase(unittest.TestCase): @defer.inlineCallbacks def test_recv_remote(self): + self.presence_list = [ + {"observed_user_id": "@banana:test"}, + {"observed_user_id": "@clementine:test"}, + ] + # TODO(paul): Gut-wrenching potato_set = self.handlers.presence_handler._remote_recvmap.setdefault( self.u_potato, set()) @@ -264,7 +287,8 @@ class PresenceProfilelikeDataTestCase(unittest.TestCase): ) self.mock_update_client.assert_called_with( - observer_user=self.u_apple, + users_to_push=set([self.u_apple]), + room_ids=[], observed_user=self.u_potato, statuscache=ANY) diff --git a/tests/utils.py b/tests/utils.py index 98d4f9ed58..37b759febc 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -21,7 +21,7 @@ from synapse.api.events.room import ( RoomMemberEvent, MessageEvent ) -from twisted.internet import defer +from twisted.internet import defer, reactor from collections import namedtuple from mock import patch, Mock @@ -263,18 +263,43 @@ class DeferredMockCallable(object): d.callback(None) return result - raise AssertionError("Was not expecting call(%s)" % + failure = AssertionError("Was not expecting call(%s)" % _format_call(args, kwargs) ) + for _, _, d in self.expectations: + try: + d.errback(failure) + except: + pass + + raise failure + def expect_call_and_return(self, call, result): self.expectations.append((call, result, defer.Deferred())) @defer.inlineCallbacks - def await_calls(self): - while self.expectations: - (_, _, d) = self.expectations.pop(0) - yield d + def await_calls(self, timeout=1000): + deferred = defer.DeferredList( + [d for _, _, d in self.expectations], + fireOnOneErrback=True + ) + + timer = reactor.callLater( + timeout/1000, + deferred.errback, + AssertionError( + "%d pending calls left: %s"% ( + len([e for e in self.expectations if not e[2].called]), + [e for e in self.expectations if not e[2].called] + ) + ) + ) + + yield deferred + + timer.cancel() + self.calls = [] def assert_had_no_calls(self):