Documents won't open after a user's session expires and renews.

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.

jupyterlab / jupyter-collaboration

Documents won't open after a user's session expires and renews. #290