debugging websocket connections

- add debug statement at the very beginning of a web socket request
- add debug statement in open, indicating that the connection has been accepted
- add timeout, so failed or slow kernel_info doesn't cause the request to never get a response
- don't send kernel_info_request before authenticating the request

The last one required some icky coroutine shenanigans,
because of our subclass structure, but it should work fine.

IPython/html/base/zmqhandlers.py

@@ -13,9 +13,7 @@ except ImportError:
     from urlparse import urlparse # Py 2
 
 import tornado
-from tornado import ioloop
-from tornado import web
-from tornado import websocket
+from tornado import gen, ioloop, web, websocket
 
 from IPython.kernel.zmq.session import Session
 from IPython.utils.jsonutil import date_default, extract_dates
@@ -197,7 +195,12 @@ class AuthenticatedZMQStreamHandler(ZMQStreamHandler, IPythonHandler):
         """
         pass
     
-    def get(self, *args, **kwargs):
+    def pre_get(self):
+        """Run before finishing the GET request
+        
+        Extend this method to add logic that should fire before
+        the websocket finishes completing.
+        """
         # Check to see that origin matches host directly, including ports
         # Tornado 4 already does CORS checking
         if tornado.version_info[0] < 4:
@@ -213,15 +216,22 @@ class AuthenticatedZMQStreamHandler(ZMQStreamHandler, IPythonHandler):
             self.session.session = cast_unicode(self.get_argument('session_id'))
         else:
             self.log.warn("No session ID specified")
+    
+    @gen.coroutine
+    def get(self, *args, **kwargs):
+        # pre_get can be a coroutine in subclasses
+        yield gen.maybe_future(self.pre_get())
         # FIXME: only do super get on tornado ≥ 4
         # tornado 3 has no get, will raise 405
         if tornado.version_info >= (4,):
-            return super(AuthenticatedZMQStreamHandler, self).get(*args, **kwargs)
+            super(AuthenticatedZMQStreamHandler, self).get(*args, **kwargs)
     
     def initialize(self):
+        self.log.debug("Initializing websocket connection %s", self.request.path)
         self.session = Session(config=self.config)
     
     def open(self, *args, **kwargs):
+        self.log.debug("Opening websocket %s", self.request.path)
         if tornado.version_info < (4,):
             try:
                 self.get(*self.open_args, **self.open_kwargs)

IPython/html/services/kernels/handlers.py

@@ -7,6 +7,7 @@ import json
 import logging
 from tornado import gen, web
 from tornado.concurrent import Future
+from tornado.ioloop import IOLoop
 
 from IPython.utils.jsonutil import date_default
 from IPython.utils.py3compat import cast_unicode
@@ -85,6 +86,10 @@ class KernelActionHandler(IPythonHandler):
 
 class ZMQChannelHandler(AuthenticatedZMQStreamHandler):
     
+    @property
+    def kernel_info_timeout(self):
+        return self.settings.get('kernel_info_timeout', 10)
+    
     def __repr__(self):
         return "%s(%s)" % (self.__class__.__name__, getattr(self, 'kernel_id', 'uninitialized'))
     
@@ -150,7 +155,8 @@ class ZMQChannelHandler(AuthenticatedZMQStreamHandler):
         if protocol_version != kernel_protocol_version:
             self.session.adapt_version = int(protocol_version.split('.')[0])
             self.log.info("Kernel %s speaks protocol %s", self.kernel_id, protocol_version)
-        self._kernel_info_future.set_result(info)
+        if not self._kernel_info_future.done():
+            self._kernel_info_future.set_result(info)
     
     def initialize(self):
         super(ZMQChannelHandler, self).initialize()
@@ -159,11 +165,30 @@ class ZMQChannelHandler(AuthenticatedZMQStreamHandler):
         self.kernel_info_channel = None
         self._kernel_info_future = Future()
     
+    @gen.coroutine
+    def pre_get(self):
+        # authenticate first
+        super(ZMQChannelHandler, self).pre_get()
+        # then request kernel info, waiting up to a certain time before giving up.
+        # We don't want to wait forever, because browsers don't take it well when
+        # servers never respond to websocket connection requests.
+        future = self.request_kernel_info()
+        
+        def give_up():
+            """Don't wait forever for the kernel to reply"""
+            if future.done():
+                return
+            self.log.warn("Timeout waiting for kernel_info reply from %s", self.kernel_id)
+            future.set_result(None)
+        loop = IOLoop.current()
+        loop.add_timeout(loop.time() + self.kernel_info_timeout, give_up)
+        # actually wait for it
+        yield future
+    
     @gen.coroutine
     def get(self, kernel_id):
         self.kernel_id = cast_unicode(kernel_id, 'ascii')
-        yield self.request_kernel_info()
-        super(ZMQChannelHandler, self).get(kernel_id)
+        yield super(ZMQChannelHandler, self).get(kernel_id=kernel_id)
     
     def open(self, kernel_id):
         super(ZMQChannelHandler, self).open()