More verbose logs

synapse/__init__.py

@@ -27,4 +27,4 @@ try:
 except ImportError:
     pass
 
-__version__ = "0.99.2"
+__version__ = "0.99.2.post1"

synapse/handlers/appservice.py

@@ -61,12 +61,15 @@ class ApplicationServicesHandler(object):
         Args:
             current_id(int): The current maximum ID.
         """
+        logger.info("call notify_interested_services")
         services = self.store.get_app_services()
         if not services or not self.notify_appservices:
+            logger.info("ret not services or not self.notify_appservices")
             return
 
         self.current_max = max(self.current_max, current_id)
         if self.is_processing:
+            logger.info("ret self.is_processing")
             return
 
         with Measure(self.clock, "notify_interested_services"):
@@ -79,6 +82,7 @@ class ApplicationServicesHandler(object):
                     )
 
                     if not events:
+                        logger.info("ret not events")
                         break
 
                     events_by_room = {}

synapse/handlers/message.py

@@ -782,6 +782,7 @@ class EventCreationHandler(object):
 
         def _notify():
             try:
+                logger.info("call _notify")
                 self.notifier.on_new_room_event(
                     event, event_stream_id, max_stream_id,
                     extra_users=extra_users

synapse/notifier.py

@@ -222,6 +222,7 @@ class Notifier(object):
         until all previous events have been persisted before notifying
         the client streams.
         """
+        logger.info("call on_new_room_event")
         self.pending_new_room_events.append((
             room_stream_id, event, extra_users
         ))
@@ -236,6 +237,7 @@ class Notifier(object):
             max_room_stream_id(int): The highest stream_id below which all
                 events have been persisted.
         """
+        logger.info("call _notify_pending_new_room_events")
         pending = self.pending_new_room_events
         self.pending_new_room_events = []
         for room_stream_id, event, extra_users in pending:
@@ -249,6 +251,7 @@ class Notifier(object):
     def _on_new_room_event(self, event, room_stream_id, extra_users=[]):
         """Notify any user streams that are interested in this room event"""
         # poke any interested application service.
+        logger.info("call _on_new_room_event")
         run_as_background_process(
             "notify_app_services",
             self._notify_app_services, room_stream_id,
@@ -268,6 +271,7 @@ class Notifier(object):
 
     @defer.inlineCallbacks
     def _notify_app_services(self, room_stream_id):
+        logger.info("call _notify_app_services")
         try:
             yield self.appservice_handler.notify_interested_services(room_stream_id)
         except Exception:

synapse/storage/appservice.py

@@ -340,6 +340,8 @@ class ApplicationServiceTransactionWorkerStore(ApplicationServiceWorkerStore,
     def get_new_events_for_appservice(self, current_id, limit):
         """Get all new evnets"""
 
+        logger.info("call get_new_events_for_appservice(%s, %s)", current_id, limit)
+
         def get_new_events_for_appservice_txn(txn):
             sql = (
                 "SELECT e.stream_ordering, e.event_id"
@@ -365,8 +367,12 @@ class ApplicationServiceTransactionWorkerStore(ApplicationServiceWorkerStore,
             "get_new_events_for_appservice", get_new_events_for_appservice_txn,
         )
 
+        logger.info("call get_new_events_for_appservice len(event_ids): %s = %s", len(event_ids), event_ids)
+
         events = yield self._get_events(event_ids)
 
+        logger.info("call get_new_events_for_appservice len(event_ids) = %s", len(events))
+
         defer.returnValue((upper_bound, events))