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

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?

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?

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.