Add temporary debug logging around Tornado handler protocol.

This logging is kinda excessive since it adds like 4 log lines per
recipient, so I expect we'll end up reverting it once we've debugged
the proximal issue.

(imported from commit 5e6ab3e230f32b65ad9cf0d95f20ffbc0fe7397e)
This commit is contained in:
Tim Abbott
2013-11-07 15:14:58 -05:00
parent 3b41e79074
commit ba15333df9
2 changed files with 11 additions and 0 deletions

View File

@@ -65,6 +65,10 @@ class ClientDescriptor(object):
async_request_restart(self.current_handler._request) async_request_restart(self.current_handler._request)
self.event_queue.push(event) self.event_queue.push(event)
logging.info("DEBUG: Added %s event to queue %s: handler is %s" % (
event.get("type"),
self.event_queue.id,
self.current_handler is not None))
if self.current_handler is not None: if self.current_handler is not None:
try: try:
self.current_handler._request._extra_log_data = "[%s/1]" % (self.event_queue.id,) self.current_handler._request._extra_log_data = "[%s/1]" % (self.event_queue.id,)
@@ -73,7 +77,9 @@ class ClientDescriptor(object):
queue_id=self.event_queue.id), queue_id=self.event_queue.id),
self.current_handler._request, self.current_handler._request,
apply_markdown=self.apply_markdown) apply_markdown=self.apply_markdown)
logging.info("DEBUG: Successfully called back on queue %s" % (self.event_queue.id))
except socket.error: except socket.error:
logging.info("DEBUG: Got error adding event to queue %s" % (self.event_queue.id))
traceback.print_exc() traceback.print_exc()
self.disconnect_handler() self.disconnect_handler()
@@ -99,8 +105,11 @@ class ClientDescriptor(object):
ioloop = tornado.ioloop.IOLoop.instance() ioloop = tornado.ioloop.IOLoop.instance()
heartbeat_time = time.time() + HEARTBEAT_MIN_FREQ_SECS + random.randint(0, 10) heartbeat_time = time.time() + HEARTBEAT_MIN_FREQ_SECS + random.randint(0, 10)
self._timeout_handle = ioloop.add_timeout(heartbeat_time, timeout_callback) self._timeout_handle = ioloop.add_timeout(heartbeat_time, timeout_callback)
logging.info("DEBUG: connected handler for queue %s" % (self.event_queue.id,))
def disconnect_handler(self): def disconnect_handler(self):
if self.current_handler is not None:
logging.info("DEBUG: disconnected handler for queue %s" % (self.event_queue.id,))
self.current_handler = None self.current_handler = None
if self._timeout_handle is not None: if self._timeout_handle is not None:
ioloop = tornado.ioloop.IOLoop.instance() ioloop = tornado.ioloop.IOLoop.instance()

View File

@@ -13,6 +13,7 @@ from zerver.tornado_callbacks import process_notification
from zerver.lib.event_queue import allocate_client_descriptor, get_client_descriptor from zerver.lib.event_queue import allocate_client_descriptor, get_client_descriptor
import ujson import ujson
import logging
from zerver.lib.rest import rest_dispatch as _rest_dispatch from zerver.lib.rest import rest_dispatch as _rest_dispatch
rest_dispatch = csrf_exempt((lambda request, *args, **kwargs: _rest_dispatch(request, globals(), *args, **kwargs))) rest_dispatch = csrf_exempt((lambda request, *args, **kwargs: _rest_dispatch(request, globals(), *args, **kwargs)))
@@ -49,6 +50,7 @@ def get_events_backend(request, user_profile, handler = None,
queue_id = client.event_queue.id queue_id = client.event_queue.id
else: else:
return json_error("Missing 'queue_id' argument") return json_error("Missing 'queue_id' argument")
logging.info("DEBUG: created queue %s" % (queue_id,))
else: else:
if last_event_id is None: if last_event_id is None:
return json_error("Missing 'last_event_id' argument") return json_error("Missing 'last_event_id' argument")