Description
I ran into an issue where the JupyterLab becomes completely blocked from opening any documents when a user's cookie expires. Even after being re-authenticated and refreshing the page, I am unable to open any documents. The only thing that unblocks this scenario is to restart the server.
To help debug the issue a bit, I'll give a summary of what I saw in the logs (sorry for the ugly JSON, it's what I have running 😅 ) with timestamps.
The user cookie expires.
{
"message": "Clearing invalid/expired login cookie jupyter-session-token",
"levelname": "WARNING",
"name": "ServerApp",
"asctime": "2024-04-12 17:41:34,303",
"module": "identity",
"funcName": "_get_user",
"pathname": "/opt/conda/envs/user-env/lib/python3.9/site-packages/jupyter_server/auth/identity.py",
"lineno": 259
}
Due to expiration, the JupyterLab lost connection to the server and I think this caused the document to self clean.
{
"message": "Cleaning room: json:notebook:3312ce81-fed7-44c4-a227-a21f002ad2a6",
"levelname": "INFO",
"name": "ServerApp",
"asctime": "2024-04-12 17:39:07,037",
"module": "handlers",
"funcName": "on_close",
"pathname": "/opt/conda/envs/user-env/lib/python3.9/site-packages/jupyter_collaboration/handlers.py",
"lineno": 297
}
{
"message": "Cleaning room: json:notebook:3312ce81-fed7-44c4-a227-a21f002ad2a6",
"levelname": "INFO",
"name": "ServerApp",
"asctime": "2024-04-12 17:43:15,180",
"module": "handlers",
"funcName": "on_close",
"pathname": "/opt/conda/envs/user-env/lib/python3.9/site-packages/jupyter_collaboration/handlers.py",
"lineno": 297
}
The client is still trying to poll the server using an expired token, so a bunch of 403s appear. I'll include the first one here
{
"message": "403 GET /api/collaboration/room/json:notebook:3312ce81-fed7-44c4-a227-a21f002ad2a6?sessionId=3dd37d38-6ec5-4c10-bb63-4a75d074e05b 5.46ms referer=None",
"levelname": "WARNING",
"name": "ServerApp",
"asctime": "2024-04-12 17:43:17,645",
"module": "log",
"funcName": "log_request",
"pathname": "/opt/conda/envs/user-env/lib/python3.9/site-packages/jupyter_server/log.py",
"lineno": 98
}
and the last one here to show time-stamp differences. About 1 minute passed with polling happening every ~3 seconds.
{
"message": "403 GET /api/collaboration/room/json:notebook:3312ce81-fed7-44c4-a227-a21f002ad2a6?sessionId=3dd37d38-6ec5-4c10-bb63-4a75d074e05b 1.40ms referer=None",
"levelname": "WARNING",
"name": "ServerApp",
"asctime": "2024-04-12 17:44:15,735",
"module": "log",
"funcName": "log_request",
"pathname": "/opt/conda/envs/user-env/lib/python3.9/site-packages/jupyter_server/log.py",
"lineno": 98
}
After polling for a minute, the y document self deleted itself.
{
"message": "Deleting Y document from memory: json:notebook:3312ce81-fed7-44c4-a227-a21f002ad2a6",
"levelname": "INFO",
"name": "ServerApp",
"asctime": "2024-04-12 17:44:15,986",
"module": "handlers",
"funcName": "_clean_room",
"pathname": "/opt/conda/envs/user-env/lib/python3.9/site-packages/jupyter_collaboration/handlers.py",
"lineno": 342
}
{
"message": "Room json:notebook:3312ce81-fed7-44c4-a227-a21f002ad2a6 deleted",
"levelname": "INFO",
"name": "ServerApp",
"asctime": "2024-04-12 17:44:15,986",
"module": "handlers",
"funcName": "_clean_room",
"pathname": "/opt/conda/envs/user-env/lib/python3.9/site-packages/jupyter_collaboration/handlers.py",
"lineno": 347
}
{
"message": "Deleting file Untitled1.ipynb",
"levelname": "INFO",
"name": "ServerApp",
"asctime": "2024-04-12 17:44:15,986",
"module": "handlers",
"funcName": "_clean_room",
"pathname": "/opt/conda/envs/user-env/lib/python3.9/site-packages/jupyter_collaboration/handlers.py",
"lineno": 354
}
The server has deleted the room, but the (unauthenticated) client still thinks it's there, so it sends the old (deleted) ID to the server. There is definitely a bug here already... this endpoint should be authenticated but it doesn't appear to be.
{
"message": "Uncaught exception GET /api/collaboration/room/json:notebook:3312ce81-fed7-44c4-a227-a21f002ad2a6?sessionId=3dd37d38-6ec5-4c10-bb63-4a75d074e05b, method='GET', uri='/api/collaboration/room/json:notebook:3312ce81-fed7-44c4-a227-a21f002ad2a6?sessionId=3dd37d38-6ec5-4c10-bb63-4a75d074e05b'",
"levelname": "ERROR",
"name": "ServerApp",
"asctime": "2024-04-12 17:44:18,428",
"module": "web",
"funcName": "log_exception",
"pathname": "/opt/conda/envs/user-env/lib/python3.9/site-packages/tornado/web.py",
"lineno": 1875,
"exc_info": "Traceback (most recent call last):\n File \"/opt/conda/envs/user-env/lib/python3.9/site-packages/tornado/web.py\", line 1769, in _execute\n result = await result # type: ignore\n File \"/opt/conda/envs/user-env/lib/python3.9/site-packages/jupyter_collaboration/handlers.py\", line 112, in prepare\n await self._websocket_server.start_room(self.room)\n File \"/opt/conda/envs/user-env/lib/python3.9/site-packages/pycrdt_websocket/websocket_server.py\", line 88, in start_room\n await self._task_group.start(room.start)\n File \"/opt/conda/envs/user-env/lib/python3.9/site-packages/anyio/_backends/_asyncio.py\", line 800, in start\n task = self._spawn(func, args, name, future)\n File \"/opt/conda/envs/user-env/lib/python3.9/site-packages/anyio/_backends/_asyncio.py\", line 752, in _spawn\n raise RuntimeError(\nRuntimeError: This task group is not active; no new tasks can be started."
}
{
"message": "500 GET /api/collaboration/room/json:notebook:3312ce81-fed7-44c4-a227-a21f002ad2a6?sessionId=3dd37d38-6ec5-4c10-bb63-4a75d074e05b 1.32ms referer=None",
"levelname": "ERROR",
"name": "ServerApp",
"asctime": "2024-04-12 17:44:18,428",
"module": "log",
"funcName": "log_request",
"pathname": "/opt/conda/envs/user-env/lib/python3.9/site-packages/jupyter_server/log.py",
"lineno": 98
}
The final UX is that the document never opens. Just a spinning wheel shows.