I am having an issue where the hub pod is unable to spawn user pods, and failing within 30 seconds with a timeout
error, even though the singleuser.startTimeout
is set to 30000. While trying to create the pod, I see the logs saying Attempting to create pod jupyter-user3, with timeout 3
, and then eventually fails after 30 seconds with user3's server failed to start in 30000 seconds, giving up.
, even though it hasn’t been 30000 seconds in total.
Is there a way to increase the timeout 3
which it uses while “attempting to create the pod” ?
My cluster has a lot of resources, so pod creation, etc. takes up to a minute or two on times.
I see the following in the hub logs
[D 2023-04-25 17:28:31.789 JupyterHub user:430] Creating <class 'kubespawner.spawner.KubeSpawner'> for user3:
[D 2023-04-25 17:28:31.792 JupyterHub pages:213] Triggering spawn with default options for user3
[D 2023-04-25 17:28:31.792 JupyterHub base:934] Initiating spawn for user3
[D 2023-04-25 17:28:31.792 JupyterHub base:938] 0/64 concurrent spawns
[D 2023-04-25 17:28:31.792 JupyterHub base:943] 0 active servers
[I 2023-04-25 17:28:31.803 JupyterHub provider:651] Creating oauth client jupyterhub-user-user3
[D 2023-04-25 17:28:31.821 JupyterHub user:743] Calling Spawner.start for user3
[I 2023-04-25 17:28:31.822 JupyterHub spawner:2509] Attempting to create pvc claim-user3, with timeout 3
[I 2023-04-25 17:28:31.823 JupyterHub log:186] 302 GET /hub/spawn/user3 -> /hub/spawn-pending/user3 (user3@100.64.31.165) 36.76ms
[D 2023-04-25 17:28:31.844 JupyterHub scopes:796] Checking access via scope servers
[D 2023-04-25 17:28:31.844 JupyterHub scopes:623] Argument-based access to /hub/spawn-pending/user3 via servers
[I 2023-04-25 17:28:31.844 JupyterHub pages:394] user3 is pending spawn
[D 2023-04-25 17:28:31.845 JupyterHub log:186] 304 GET /hub/spawn-pending/user3 (user3@100.64.31.165) 3.24ms
[I 2023-04-25 17:28:31.846 JupyterHub spawner:2525] PVC claim-user3 already exists, so did not create new pvc.
[I 2023-04-25 17:28:31.851 JupyterHub spawner:2469] Attempting to create pod jupyter-user3, with timeout 3
[D 2023-04-25 17:28:31.858 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.55ms
[D 2023-04-25 17:28:31.928 JupyterHub scopes:796] Checking access via scope read:servers
[D 2023-04-25 17:28:31.928 JupyterHub scopes:623] Argument-based access to /hub/api/users/user3/server/progress via read:servers
[D 2023-04-25 17:28:31.929 JupyterHub spawner:2308] progress generator: jupyter-user3
[D 2023-04-25 17:28:32.901 JupyterHub reflector:362] pods watcher timeout
[D 2023-04-25 17:28:32.902 JupyterHub reflector:281] Connecting pods watcher
[D 2023-04-25 17:28:33.541 JupyterHub reflector:362] events watcher timeout
[D 2023-04-25 17:28:33.541 JupyterHub reflector:281] Connecting events watcher
[D 2023-04-25 17:28:33.859 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.94ms
[D 2023-04-25 17:28:33.859 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.92ms
[I 2023-04-25 17:28:34.983 JupyterHub spawner:2469] Attempting to create pod jupyter-user3, with timeout 3
[D 2023-04-25 17:28:35.858 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.65ms
[D 2023-04-25 17:28:37.858 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.61ms
[I 2023-04-25 17:28:38.181 JupyterHub spawner:2469] Attempting to create pod jupyter-user3, with timeout 3
[D 2023-04-25 17:28:39.858 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.72ms
[I 2023-04-25 17:28:41.730 JupyterHub spawner:2469] Attempting to create pod jupyter-user3, with timeout 3
[D 2023-04-25 17:28:41.859 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.69ms
[D 2023-04-25 17:28:42.913 JupyterHub reflector:362] pods watcher timeout
[D 2023-04-25 17:28:42.913 JupyterHub reflector:281] Connecting pods watcher
[D 2023-04-25 17:28:43.566 JupyterHub reflector:362] events watcher timeout
[D 2023-04-25 17:28:43.566 JupyterHub reflector:281] Connecting events watcher
[D 2023-04-25 17:28:43.859 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.92ms
[D 2023-04-25 17:28:43.859 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.81ms
[D 2023-04-25 17:28:45.859 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.66ms
[I 2023-04-25 17:28:46.027 JupyterHub spawner:2469] Attempting to create pod jupyter-user3, with timeout 3
[D 2023-04-25 17:28:47.858 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.70ms
[D 2023-04-25 17:28:49.858 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.63ms
[I 2023-04-25 17:28:51.422 JupyterHub spawner:2469] Attempting to create pod jupyter-user3, with timeout 3
[D 2023-04-25 17:28:51.858 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.67ms
[D 2023-04-25 17:28:52.922 JupyterHub reflector:362] pods watcher timeout
[D 2023-04-25 17:28:52.923 JupyterHub reflector:281] Connecting pods watcher
[D 2023-04-25 17:28:53.587 JupyterHub reflector:362] events watcher timeout
[D 2023-04-25 17:28:53.588 JupyterHub reflector:281] Connecting events watcher
[D 2023-04-25 17:28:53.859 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.94ms
[D 2023-04-25 17:28:53.859 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.89ms
[D 2023-04-25 17:28:55.858 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.69ms
[D 2023-04-25 17:28:57.858 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.63ms
[I 2023-04-25 17:28:57.899 JupyterHub spawner:2469] Attempting to create pod jupyter-user3, with timeout 3
[D 2023-04-25 17:28:59.858 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.63ms
[D 2023-04-25 17:29:01.858 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.67ms
[I 2023-04-25 17:29:02.208 JupyterHub spawner:2469] Attempting to create pod jupyter-user3, with timeout 3
[D 2023-04-25 17:29:02.934 JupyterHub reflector:362] pods watcher timeout
[D 2023-04-25 17:29:02.934 JupyterHub reflector:281] Connecting pods watcher
[D 2023-04-25 17:29:03.613 JupyterHub reflector:362] events watcher timeout
[D 2023-04-25 17:29:03.614 JupyterHub reflector:281] Connecting events watcher
[D 2023-04-25 17:29:03.858 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.81ms
[D 2023-04-25 17:29:03.858 JupyterHub log:186] 200 GET /hub/health (@100.64.24.192) 0.82ms
[W 2023-04-25 17:29:05.211 JupyterHub user:824] user3's server failed to start in 30000 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 2023-04-25 17:29:05.211 JupyterHub user:930] Stopping user3
[D 2023-04-25 17:29:05.216 JupyterHub user:950] Deleting oauth client jupyterhub-user-user3
[D 2023-04-25 17:29:05.224 JupyterHub user:953] Finished stopping user3
[W 2023-04-25 17:29:05.233 JupyterHub base:1030] 3 consecutive spawns failed. Hub will exit if failure count reaches 5 before succeeding
[E 2023-04-25 17:29:05.233 JupyterHub gen:630] Exception in Future <Task finished name='Task-1601' coro=<BaseHandler.spawn_single_user.<locals>.finish_user_spawn() done, defined at /usr/local/lib/python3.9/site-packages/jupyterhub/handlers/base.py:954> exception=TimeoutError('Could not create pod dev-jupyterhub/jupyter-user3')> after timeout
Traceback (most recent call last):
File "/usr/local/lib/python3.9/site-packages/tornado/gen.py", line 625, in error_callback
future.result()
File "/usr/local/lib/python3.9/site-packages/jupyterhub/handlers/base.py", line 961, in finish_user_spawn
await spawn_future
File "/usr/local/lib/python3.9/site-packages/jupyterhub/user.py", line 850, in spawn
raise e
File "/usr/local/lib/python3.9/site-packages/jupyterhub/user.py", line 747, in spawn
url = await gen.with_timeout(timedelta(seconds=spawner.start_timeout), f)
File "/usr/local/lib/python3.9/site-packages/kubespawner/spawner.py", line 2663, in _start
await exponential_backoff(
File "/usr/local/lib/python3.9/site-packages/jupyterhub/utils.py", line 236, in exponential_backoff
raise asyncio.TimeoutError(fail_message)
asyncio.exceptions.TimeoutError: Could not create pod dev-jupyterhub/jupyter-user3
https://discourse.jupyter.org/t/jupyterhub-deployed-on-kubernetes-cannot-spawn-users/17511
[I 2023-04-25 17:29:05.234 JupyterHub log:186] 200 GET /hub/api/users/user3/server/progress (user3@100.64.31.165) 33307.70ms
[D 2023-04-25 17:29:05.325 JupyterHub proxy:884] Proxy: Fetching GET http://proxy-api:8001/api/routes
[D 2023-04-25 17:29:05.327 JupyterHub proxy:395] Checking routes
[I 2023-04-25 17:29:05.495 JupyterHub log:186] 200 GET /hub/api/ (jupyterhub-idle-culler@127.0.0.1) 7.92ms
[D 2023-04-25 17:29:05.498 JupyterHub scopes:796] Checking access via scope list:users
Kubernetes Version: 1.23
Helm Chart Version: 2.0.0