Each browser tab gets a separate JavaScript WebSocket client. It is also possible to see the connections with lsof
.
When the jupyterhub
and configurable-http-proxy
are running, lsof
should show these two listening connections.
$ lsof -p $(ps aux | grep "[c]onfigurable-http-proxy" | awk '{print $2}')
...
node 26484 kinow 20u IPv6 507887 0t0 TCP *:8000 (LISTEN)
node 26484 kinow 21u IPv4 507888 0t0 TCP localhost:8001 (LISTEN)
When you open a tab in the browser, you will connect to the configurable-htt-proxy
on port 80
. The proxy will have a connection to the Tornado application. The Tornado application is given a random port number.
$ netstat -tlnp
...
tcp6 0 0 :::48561 :::* LISTEN 5168/python
tcp6 0 0 :::8000 :::* LISTEN 26484/node
You can match the pid
5168 from netstat
output with what you get in the lsof
output, and confirm that's the JupyterHub spawned UI Server on port 48561.
$ lsof -p $(ps aux | grep "[c]onfigurable-http-proxy" | awk '{print $2}')
...
node 26484 kinow 22u IPv6 5362770 0t0 TCP localhost:8000->localhost:45456 (ESTABLISHED)
node 26484 kinow 23u IPv4 5362772 0t0 TCP localhost:58418->localhost:48561 (ESTABLISHED)
Here's the output with two tabs opened:
$ lsof -p $(ps aux | grep "[c]onfigurable-http-proxy" | awk '{print $2}')
...
node 26484 kinow 20u IPv6 507887 0t0 TCP *:8000 (LISTEN)
node 26484 kinow 21u IPv4 507888 0t0 TCP localhost:8001 (LISTEN)
node 26484 kinow 22u IPv6 5328558 0t0 TCP localhost:8000->localhost:44206 (ESTABLISHED)
node 26484 kinow 23u IPv4 5328560 0t0 TCP localhost:57168->localhost:48561 (ESTABLISHED)
node 26484 kinow 24u IPv6 5330280 0t0 TCP localhost:8000->localhost:44136 (ESTABLISHED)
node 26484 kinow 25u IPv4 5330282 0t0 TCP localhost:57098->localhost:48561 (ESTABLISHED)
Edit jupyterhub_config.py
adding the following lines:
c.JupyterHub.log_level = 'DEBUG'
c.Spawner.debug = True
c.LocalProcessSpawner.debug = True
c.ConfigurableHTTPProxy.debug = True
This should increase the log levels. You can also start jupyterhub
with jupyterhub --debug
(redundant, however).
With extra logging, it is also possible to see the WebSocket connections in the log.
10:25:08.786 [ConfigProxy] debug: PROXY WEB /user/kinow/ to http://127.0.0.1:48561
10:25:10.158 [ConfigProxy] debug: PROXY WEB /user/kinow//userprofile to http://127.0.0.1:48561
10:25:10.405 [ConfigProxy] debug: PROXY WS /user/kinow/subscriptions to http://127.0.0.1:48561
Logs from today's investigation:
For some reason, after the first connection, all subsequent connections have a chance to fail. When that happens, the Tornado Subscription Server has a Connection Context that is invalid (both these objects/entities are from GraphQL-WS).
Each WebSocket connection is handled individually by a new instance of a
TornadoSubscriptionHandler
(child oftornado.websocket.WebSocketHandler
). But all the handlers share a GraphQL-WS Susbcription Server.When using multiple tabs pointing to the same UI Server, we have already noticed that the chances of hitting the bug are higher. So it could indicate that this state shared by both handlers could be a lead.