After OAuthenticator successfully returned the user, kubespawner stuck at creating PVC

JupyterHub Zero to JupyterHub on Kubernetes
#1

Hello community,
I am using Jupyterhub helm chart version 2.0.0 (with some updates). Using Generic oauthenticator. Seeing an issue that after successful authentication, username is returned correctly and Kubespawner is trying to spawn a user pod. In this process, it gets stuck at creating PVC and finally gives up saying server failed to start. Here’s the log:

Looking for /usr/local/etc/jupyterhub/jupyterhub_config in /srv/jupyterhub
Loading /usr/local/etc/jupyterhub/secret/values.yaml
No config at /usr/local/etc/jupyterhub/existing-secret/values.yaml
[D 2022-12-01 17:24:44.771 JupyterHub application:858] Loaded config file: /usr/local/etc/jupyterhub/jupyterhub_config.py
[I 2022-12-01 17:24:44.832 JupyterHub app:2775] Running JupyterHub version 3.0.0
[I 2022-12-01 17:24:44.832 JupyterHub app:2805] Using Authenticator: oauthenticator.generic.GenericOAuthenticator-15.1.0
[I 2022-12-01 17:24:44.832 JupyterHub app:2805] Using Spawner: kubespawner.spawner.KubeSpawner-4.2.0
[I 2022-12-01 17:24:44.832 JupyterHub app:2805] Using Proxy: jupyterhub.proxy.ConfigurableHTTPProxy-3.0.0
…
…
[D 2022-12-01 17:25:34.847 JupyterHub roles:281] Assigning default role to User xxx_yyy
[I 2022-12-01 17:25:34.851 JupyterHub roles:238] Adding role user for User: xxx_yyy
[D 2022-12-01 17:25:34.865 JupyterHub roles:281] Assigning default role to User xxx_yyy
[D 2022-12-01 17:25:34.870 JupyterHub base:563] Setting cookie for xxx_yyy: jupyterhub-hub-login
[D 2022-12-01 17:25:34.870 JupyterHub base:559] Setting cookie jupyterhub-hub-login: {‘httponly’: True, ‘path’: ‘/hub/’}
[I 2022-12-01 17:25:34.871 JupyterHub base:810] User logged in: xxx_yyy
[I 2022-12-01 17:25:34.871 JupyterHub log:186] 302 GET /hub/oauth_callback?state=[secret]&code=[secret] → /hub/ (@::ffff:172.18.218.144) 1001.92ms
[D 2022-12-01 17:25:34.923 JupyterHub base:275] Recording first activity for <User(xxx_yyy 0/1 running)>
[D 2022-12-01 17:25:34.931 JupyterHub user:430] Creating <class ‘kubespawner.spawner.KubeSpawner’> for xxx_yyy:
[I 2022-12-01 17:25:34.936 JupyterHub log:186] 302 GET /hub/ → /hub/spawn (xxx_yyy@::ffff:172.18.218.144) 15.48ms
[D 2022-12-01 17:25:34.985 JupyterHub scopes:796] Checking access via scope servers
[D 2022-12-01 17:25:34.985 JupyterHub scopes:623] Argument-based access to /hub/spawn via servers
[D 2022-12-01 17:25:34.985 JupyterHub pages:213] Triggering spawn with default options for xxx_yyy
[D 2022-12-01 17:25:34.985 JupyterHub base:934] Initiating spawn for xxx_yyy
[D 2022-12-01 17:25:34.985 JupyterHub base:938] 0/64 concurrent spawns
[D 2022-12-01 17:25:34.985 JupyterHub base:943] 0 active servers
[I 2022-12-01 17:25:35.000 JupyterHub provider:651] Creating oauth client jupyterhub-user-xxx_yyy
[D 2022-12-01 17:25:35.019 JupyterHub user:743] Calling Spawner.start for xxx_yyy
[I 2022-12-01 17:25:35.020 JupyterHub spawner:2509] Attempting to create pvc claim-xxx-5fyyy, with timeout 3
[I 2022-12-01 17:25:35.022 JupyterHub log:186] 302 GET /hub/spawn → /hub/spawn-pending/xxx_yyy (xxx_yyy@::ffff:172.18.218.144) 38.92ms
[D 2022-12-01 17:25:35.079 JupyterHub scopes:796] Checking access via scope servers
[D 2022-12-01 17:25:35.079 JupyterHub scopes:623] Argument-based access to /hub/spawn-pending/xxx_yyy via servers
[I 2022-12-01 17:25:35.079 JupyterHub pages:394] xxx_yyy is pending spawn
[I 2022-12-01 17:25:35.083 JupyterHub log:186] 200 GET /hub/spawn-pending/xxx_yyy (xxx_yyy@::ffff:172.18.218.144) 6.20ms
[D 2022-12-01 17:25:35.146 JupyterHub log:186] 304 GET /hub/static/css/style.min.css?v=bff49b4a161afb17ee3b71927ce7d6c4e5b0e4b9ef6f18ca3e356a05f29e69776d3a76aee167060dd2ae2ee62d3cfdcf203b4b0090b1423f7d629ea7daa3f9da (@::ffff:172.18.218.144) 0.89ms
[D 2022-12-01 17:25:35.152 JupyterHub log:186] 304 GET /hub/static/components/requirejs/require.js?v=bd1aa102bdb0b27fbf712b32cfcd29b016c272acf3d864ee8469376eaddd032cadcf827ff17c05a8c8e20061418fe58cf79947049f5c0dff3b4f73fcc8cad8ec (@::ffff:172.18.218.144) 0.70ms
[D 2022-12-01 17:25:35.154 JupyterHub log:186] 304 GET /hub/static/components/jquery/dist/jquery.min.js?v=69528a4518bf43f615fb89a3a0a06c138c771fe0647a0a0cfde9b8e8d3650aa3539946000e305b78d79f371615ee0894a74571202b6a76b6ea53b89569e64d5c (@::ffff:172.18.218.144) 0.62ms
[D 2022-12-01 17:25:35.156 JupyterHub log:186] 304 GET /hub/static/components/bootstrap/dist/js/bootstrap.min.js?v=a014e9acc78d10a0a7a9fbaa29deac6ef17398542d9574b77b40bf446155d210fa43384757e3837da41b025998ebfab4b9b6f094033f9c226392b800df068bce (@::ffff:172.18.218.144) 0.67ms
[D 2022-12-01 17:25:35.204 JupyterHub log:186] 200 GET /hub/logo (@::ffff:172.18.218.144) 0.80ms
[D 2022-12-01 17:25:35.221 JupyterHub log:186] 304 GET /hub/static/components/font-awesome/fonts/fontawesome-webfont.woff2?v=4.7.0 (@::ffff:172.18.218.144) 0.68ms
[D 2022-12-01 17:25:35.227 JupyterHub scopes:796] Checking access via scope read:servers
[D 2022-12-01 17:25:35.227 JupyterHub scopes:610] Unrestricted access to /hub/api/users/xxx_yyy/server/progress via read:servers
[D 2022-12-01 17:25:35.229 JupyterHub spawner:2308] progress generator: jupyter-xxx-5fyyy
[D 2022-12-01 17:25:35.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.69ms
[D 2022-12-01 17:25:37.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.65ms
[I 2022-12-01 17:25:38.040 JupyterHub spawner:2509] Attempting to create pvc claim-xxx-5fyyy, with timeout 3
[D 2022-12-01 17:25:39.826 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.72ms
[I 2022-12-01 17:25:41.370 JupyterHub spawner:2509] Attempting to create pvc claim-xxx-5fyyy, with timeout 3
[D 2022-12-01 17:25:41.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.74ms
[D 2022-12-01 17:25:43.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.66ms
[I 2022-12-01 17:25:44.432 JupyterHub spawner:2509] Attempting to create pvc claim-xxx-5fyyy, with timeout 3
[D 2022-12-01 17:25:45.106 JupyterHub proxy:884] Proxy: Fetching GET http://proxy-api:8001/api/routes
[D 2022-12-01 17:25:45.110 JupyterHub proxy:395] Checking routes
[D 2022-12-01 17:25:45.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.66ms
[D 2022-12-01 17:25:47.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.66ms
[I 2022-12-01 17:25:47.993 JupyterHub spawner:2509] Attempting to create pvc claim-xxx-5fyyy, with timeout 3
[D 2022-12-01 17:25:49.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.66ms
[D 2022-12-01 17:25:51.826 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.70ms
[I 2022-12-01 17:25:52.390 JupyterHub spawner:2509] Attempting to create pvc claim-xxx-5fyyy, with timeout 3
[D 2022-12-01 17:25:53.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.68ms
[D 2022-12-01 17:25:55.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.68ms
[D 2022-12-01 17:25:57.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.65ms
[W 2022-12-01 17:25:58.774 JupyterHub web:1796] 403 GET /hub/metrics (172.18.219.176): Access to metrics requires scope ‘read:metrics’
[D 2022-12-01 17:25:58.775 JupyterHub base:1342] No template for 403
[W 2022-12-01 17:25:58.775 JupyterHub log:186] 403 GET /hub/metrics (@172.18.219.176) 1.38ms
[D 2022-12-01 17:25:59.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.67ms
[I 2022-12-01 17:26:00.394 JupyterHub spawner:2509] Attempting to create pvc claim-xxx-5fyyy, with timeout 3
[D 2022-12-01 17:26:01.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.66ms
[D 2022-12-01 17:26:03.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.69ms
[D 2022-12-01 17:26:05.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.67ms
[I 2022-12-01 17:26:07.405 JupyterHub spawner:2509] Attempting to create pvc claim-xxx-5fyyy, with timeout 3
[D 2022-12-01 17:26:07.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.66ms
[D 2022-12-01 17:26:09.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.68ms
[W 2022-12-01 17:26:10.406 JupyterHub user:824] xxx_yyy’s server failed to start in 900 seconds, giving up.

Common causes of this timeout, and debugging tips:

1. Everything is working, but it took too long.
   To fix: increase `Spawner.start_timeout` configuration
   to a number of seconds that is enough for spawners to finish starting.
2. The server didn't finish starting,
   or it crashed due to a configuration issue.
   Check the single-user server's logs for hints at what needs fixing.

[D 2022-12-01 17:26:10.406 JupyterHub user:930] Stopping xxx_yyy
[D 2022-12-01 17:26:11.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.64ms
[D 2022-12-01 17:26:13.825 JupyterHub log:186] 200 GET /hub/health (@172.18.217.225) 0.63ms

Please any help here?

#2

It sounds like Kubernetes is unable to create the PVC.

Can you show us your Z2JH configuration?

How did you setup K8s? Are dynamic volumes working for all other applications?

#3

Thank you ! The issue was https_proxy, http_proxy set for authentication. For spawner, I had to delete those env variables and k8s was able to create pvc and pods.