Notebook connection failed (using sudospawner)

Hello! I’m having a problem with JupyterHub. When i open a notebook a message pops up:
“Connection failed: A connection to the notebook server could not be established. The notebook will continue trying to reconnect. Check your network connection or notebook server configuration.”

The system is Debian 10 with most packages (including “jupyter”) installed from the Debian repositories, but “jupyterhub” and “sudospawner” installed from pip as they were not available in Debian.

JupyterHub’s systemd service file looks like:

[Unit]
Description=Jupyterhub
After=network-online.target

[Service]
User=jupyterhub
RuntimeDirectory=jupyterhub
Environment=PATH=/usr/local/bin:/usr/bin
ExecStart=/usr/local/bin/jupyterhub --config=/usr/local/etc/jupyterhub/config.py
WorkingDirectory=/usr/local/etc/jupyterhub

[Install]
WantedBy=multi-user.target

And the /usr/local/etc/jupyterhub/config.py file has this (comments removed for brevity):

c.JupyterHub.base_url = '/jupyterhub'
c.JupyterHub.extra_log_file = '/var/log/jupyterhub.log'
c.JupyterHub.pid_file = '/var/run/jupyterhub/jupyterhub.pid'
c.JupyterHub.spawner_class = 'sudospawner.SudoSpawner'
c.Spawner.default_url = '/tree/home/{username}'
c.Spawner.notebook_dir = '/'

I’m not sure what to check next. I’ll paste the journald logs for the session below. In the session i logged in, open a notebook, and see the error popup. I left the browser alone for a bit to make sure nothing else would get logged, but this was it:

Apr 29 09:43:45 lnx-csapps2-prod.drake.edu python3[5058]: pam_unix(login:auth): authentication failure; logname= uid=997 euid=997 tty= ruser= rhost=  user=ramaley
Apr 29 09:43:45 lnx-csapps2-prod.drake.edu python3[5058]: pam_sss(login:auth): authentication success; logname= uid=997 euid=997 tty= ruser= rhost= user=ramaley
Apr 29 09:43:45 lnx-csapps2-prod.drake.edu python3[5058]: pam_group(login:setcred): unable to set the group membership for user: Operation not permitted
Apr 29 09:43:45 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:45.949 JupyterHub base:762] User logged in: ramaley
Apr 29 09:43:45 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:45.951 JupyterHub log:189] 302 POST /jupyterhub/hub/login?next= -> /jupyterhub/hub/spawn (ramaley@::ffff:127.0.0.1) 62.98ms
Apr 29 09:43:46 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:46.042 JupyterHub provider:574] Creating oauth client jupyterhub-user-ramaley
Apr 29 09:43:46 lnx-csapps2-prod.drake.edu python3[5058]: pam_loginuid(login:session): Error writing /proc/self/loginuid: Operation not permitted
Apr 29 09:43:46 lnx-csapps2-prod.drake.edu python3[5058]: pam_loginuid(login:session): set_loginuid failed
Apr 29 09:43:46 lnx-csapps2-prod.drake.edu python3[5058]: pam_limits(login:session): Could not set limit for 'nofile' to soft=1024, hard=1048576: Operation not permitted; uid=997,euid=997
Apr 29 09:43:46 lnx-csapps2-prod.drake.edu python3[5058]: pam_limits(login:session): Could not set limit for 'memlock' to soft=67108864, hard=67108864: Operation not permitted; uid=997,euid=997
Apr 29 09:43:46 lnx-csapps2-prod.drake.edu python3[5058]: pam_lastlog(login:session): unable to open /var/log/lastlog: Permission denied
Apr 29 09:43:46 lnx-csapps2-prod.drake.edu python3[5058]: pam_keyinit(login:session): Unable to change GID to 10000 temporarily
Apr 29 09:43:46 lnx-csapps2-prod.drake.edu python3[5058]: pam_unix(login:session): session opened for user ramaley by (uid=997)
Apr 29 09:43:46 lnx-csapps2-prod.drake.edu python3[5058]: pam_systemd(login:session): Failed to create session: Access denied
Apr 29 09:43:46 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [W 2021-04-29 09:43:46.113 JupyterHub auth:1079] Failed to open PAM session for ramaley: [PAM Error 14] Cannot make/remove an entry for the specified session
Apr 29 09:43:46 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [W 2021-04-29 09:43:46.114 JupyterHub auth:1080] Disabling PAM sessions from now on.
Apr 29 09:43:46 lnx-csapps2-prod.drake.edu sudo[5098]: jupyterhub : problem with defaults entries ; TTY=unknown ; PWD=/usr/local/etc/jupyterhub ; USER=ramaley ;
Apr 29 09:43:46 lnx-csapps2-prod.drake.edu sudo[5098]: jupyterhub : TTY=unknown ; PWD=/usr/local/etc/jupyterhub ; USER=ramaley ; COMMAND=/usr/local/bin/sudospawner
Apr 29 09:43:46 lnx-csapps2-prod.drake.edu sudo[5098]: pam_unix(sudo:session): session opened for user ramaley by (uid=0)
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 210429 09:43:46 mediator:89] Spawning /usr/local/bin/jupyterhub-singleuser --port=48417 --notebook-dir=/ --SingleUserNotebookApp.default_url=/tree/home/ramaley
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:46.996 SingleUserNotebookApp mixins:567] Starting jupyterhub-singleuser server version 1.4.0
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:46.999 JupyterHub log:189] 200 GET /jupyterhub/hub/api (@127.0.0.1) 1.31ms
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.000 SingleUserNotebookApp notebookapp:1774] Serving notebooks from local directory: /
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.000 SingleUserNotebookApp notebookapp:1774] The Jupyter Notebook is running at:
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.000 SingleUserNotebookApp notebookapp:1774] http://127.0.0.1:48417/jupyterhub/user/ramaley/
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.000 SingleUserNotebookApp notebookapp:1775] Use Control-C to stop this server and shut down all kernels (twice to skip confirmation).
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.003 SingleUserNotebookApp mixins:548] Updating Hub with activity every 300 seconds
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.038 JupyterHub log:189] 200 POST /jupyterhub/hub/api/users/ramaley/activity (ramaley@127.0.0.1) 33.79ms
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.039 JupyterHub log:189] 302 GET /jupyterhub/hub/spawn -> /jupyterhub/hub/spawn-pending/ramaley (ramaley@::ffff:127.0.0.1) 1042.08ms
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.075 JupyterHub pages:402] ramaley is pending spawn
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.094 JupyterHub log:189] 200 GET /jupyterhub/hub/spawn-pending/ramaley (ramaley@::ffff:127.0.0.1) 22.76ms
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu sudo[5098]: pam_unix(sudo:session): session closed for user ramaley
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.521 JupyterHub base:910] User ramaley took 1.501 seconds to start
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.521 JupyterHub proxy:282] Adding user ramaley to proxy /jupyterhub/user/ramaley/ => http://127.0.0.1:48417
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: 09:43:47.523 [ConfigProxy] info: Adding route /jupyterhub/user/ramaley -> http://127.0.0.1:48417
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: 09:43:47.523 [ConfigProxy] info: Route added /jupyterhub/user/ramaley -> http://127.0.0.1:48417
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: 09:43:47.523 [ConfigProxy] info: 201 POST /api/routes/jupyterhub/user/ramaley
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.521 SingleUserNotebookApp log:189] 302 GET /jupyterhub/user/ramaley/ -> /jupyterhub/user/ramaley/tree/home/ramaley? (@127.0.0.1) 0.45ms
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.524 JupyterHub users:671] Server ramaley is ready
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.524 JupyterHub log:189] 200 GET /jupyterhub/hub/api/users/ramaley/server/progress (ramaley@::ffff:127.0.0.1) 107.78ms
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.599 JupyterHub log:189] 302 GET /jupyterhub/hub/spawn-pending/ramaley -> /jupyterhub/user/ramaley/ (ramaley@::ffff:127.0.0.1) 2.97ms
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.631 SingleUserNotebookApp log:189] 302 GET /jupyterhub/user/ramaley/ -> /jupyterhub/user/ramaley/tree/home/ramaley? (@::ffff:127.0.0.1) 0.50ms
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.658 SingleUserNotebookApp log:189] 302 GET /jupyterhub/user/ramaley/tree/home/ramaley? -> /jupyterhub/hub/api/oauth2/authorize?client_id=jupyterhub-user-ramaley&redirect_uri=%2Fjupyterhub%2Fuser%2Framaley%2Foauth_callback&response_type=code&state=[secret] (@::ffff:127.0.0.1) 1.45ms
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.707 JupyterHub log:189] 302 GET /jupyterhub/hub/api/oauth2/authorize?client_id=jupyterhub-user-ramaley&redirect_uri=%2Fjupyterhub%2Fuser%2Framaley%2Foauth_callback&response_type=code&state=[secret] -> /jupyterhub/user/ramaley/oauth_callback?code=[secret]&state=[secret] (ramaley@::ffff:127.0.0.1) 17.76ms
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.782 JupyterHub log:189] 200 POST /jupyterhub/hub/api/oauth2/token (ramaley@127.0.0.1) 31.20ms
Apr 29 09:43:47 lnx-csapps2-prod.drake.edu jupyterhub[5058]: [I 2021-04-29 09:43:47.802 JupyterHub log:189] 200 GET /jupyterhub/hub/api/authorizations/token/[secret] (ramaley@127.0.0.1) 17.00ms

Any ideas what i should look at or adjust to get it working?

Does that mean the main notebook interface loads but you only see an error with the notebook? If you open your browser’s javascript console do you see any warnings or errors?

I had not checked the javascript console. Thank you for that pointer! That was enough for me to dig in and fix it.

I found errors like this in the browser console:

Firefox can’t establish a connection to the server at wss://analytics2.drake.edu/jupyterhub/user/ramaley/api/kernels/22a64f22-06ac-4658-9653-94f3dd77da4a/channels?session_id=bb58e0a2fae44010906fbbc40a5f5cfe. kernel.js:461

We’re using an Apache proxy in front of JupyterHub. I checked Apache’s logs and found equivalent messages:

[Mon May 03 15:52:56.880631 2021] [proxy:warn] [pid 764:tid 139819615241984] [client 10.110.0.110:0] AH01144: No protocol handler was valid for the URL /jupyterhub/user/ramaley/api/kernels/22a64f22-06ac-4658-9653-94f3dd77da4a/channels (scheme 'ws'). If you are using a DSO version of mod_proxy, make sure the proxy submodules are included in the configuration using LoadModule.

It turns out we did not have proxy_wstunnel_module loaded. When migrating the server from RHEL 7 to Debian 10, the presence of that module was overlooked. Once i enabled the module, notebooks started working.

Thanks again for pointing me in the right direction.

1 Like