Jupyterhub helm chart 3.1.0+k8s 1.27.6: User pods not spawning got TimeoutError

JupyterHub Zero to JupyterHub on Kubernetes
, ,
1

Context

k8s: v1.27.6
helm: v3.13.0
jupyterhub helm chart: 3.1.0

# configs.yaml
proxy:
  service:
    type: NodePort
ingress:
  enabled: true
  annotations:
    kubernetes.io/ingress.class: nginx
    nginx.ingress.kubernetes.io/proxy-body-size: 512m
    cert-manager.io/cluster-issuer: letsencrypt-prod
  hosts:
    - xxxxxxxxxxxxxxxxxxxxxxxx
  tls:
    - hosts:
      - xxxxxxxxxxxxxxxxxxxxxxxx
      secretName: codebook-tls

singleuser:
  startTimeout: 300

debug:
  enabled: true

Deployment seems to work fine:

NAME                             READY   STATUS    RESTARTS   AGE
continuous-image-puller-2v74w    1/1     Running   0          8m59s
continuous-image-puller-c9zvb    1/1     Running   0          8m59s
continuous-image-puller-rrlcm    1/1     Running   0          8m59s
hub-674b844668-qlghj             1/1     Running   0          8m59s
proxy-846b4778b6-xj4jc           1/1     Running   0          8m59s
user-scheduler-c849bb8dd-8bb7w   1/1     Running   0          8m59s
user-scheduler-c849bb8dd-nh5cg   1/1     Running   0          8m59s

Issue

When login with user test through the default DummyAuthenticator, the user pod wasn’t created at all, and got a TimeoutError at the end:

[D 2023-10-18 18:58:33.343 JupyterHub application:905] 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 2023-10-18 18:58:33.835 JupyterHub application:926] Loaded config file: /usr/local/etc/jupyterhub/jupyterhub_config.py
[I 2023-10-18 18:58:33.869 JupyterHub app:2859] Running JupyterHub version 4.0.2
[I 2023-10-18 18:58:33.869 JupyterHub app:2889] Using Authenticator: jupyterhub.auth.DummyAuthenticator-4.0.2
[I 2023-10-18 18:58:33.869 JupyterHub app:2889] Using Spawner: kubespawner.spawner.KubeSpawner-6.1.0
[I 2023-10-18 18:58:33.869 JupyterHub app:2889] Using Proxy: jupyterhub.proxy.ConfigurableHTTPProxy-4.0.2
[D 2023-10-18 18:58:33.876 JupyterHub app:1833] Connecting to db: sqlite:///jupyterhub.sqlite
[D 2023-10-18 18:58:33.900 JupyterHub orm:984] Stamping empty database with alembic revision 0eee8c825d24
[I 2023-10-18 18:58:33.902 alembic.runtime.migration migration:213] Context impl SQLiteImpl.
[I 2023-10-18 18:58:33.902 alembic.runtime.migration migration:216] Will assume non-transactional DDL.
[I 2023-10-18 18:58:33.915 alembic.runtime.migration migration:619] Running stamp_revision  -> 0eee8c825d24
[D 2023-10-18 18:58:33.916 alembic.runtime.migration migration:827] new branch insert 0eee8c825d24
[D 2023-10-18 18:58:33.929 JupyterHub orm:984] Stamping empty database with alembic revision 0eee8c825d24
[I 2023-10-18 18:58:33.931 alembic.runtime.migration migration:213] Context impl SQLiteImpl.
[I 2023-10-18 18:58:33.931 alembic.runtime.migration migration:216] Will assume non-transactional DDL.
[D 2023-10-18 18:58:34.093 JupyterHub app:2104] Loading roles into database
[I 2023-10-18 18:58:34.126 JupyterHub roles:172] Role jupyterhub-idle-culler added to database
[I 2023-10-18 18:58:34.131 JupyterHub app:1984] Not using allowed_users. Any authenticated user will be allowed.
[D 2023-10-18 18:58:34.157 JupyterHub app:2343] Purging expired APITokens
[D 2023-10-18 18:58:34.160 JupyterHub app:2343] Purging expired OAuthCodes
[D 2023-10-18 18:58:34.164 JupyterHub app:2179] Loading role assignments from config
[D 2023-10-18 18:58:34.188 JupyterHub app:2502] Initializing spawners
[D 2023-10-18 18:58:34.190 JupyterHub app:2633] Loaded users:
    
[I 2023-10-18 18:58:34.191 JupyterHub app:2928] Initialized 0 spawners in 0.003 seconds
[I 2023-10-18 18:58:34.200 JupyterHub metrics:278] Found 0 active users in the last ActiveUserPeriods.twenty_four_hours
[I 2023-10-18 18:58:34.201 JupyterHub metrics:278] Found 0 active users in the last ActiveUserPeriods.seven_days
[I 2023-10-18 18:58:34.202 JupyterHub metrics:278] Found 0 active users in the last ActiveUserPeriods.thirty_days
[I 2023-10-18 18:58:34.202 JupyterHub app:3142] Not starting proxy
[D 2023-10-18 18:58:34.202 JupyterHub proxy:880] Proxy: Fetching GET http://proxy-api:8001/api/routes
[D 2023-10-18 18:58:34.209 JupyterHub proxy:953] Omitting non-jupyterhub route '/'
[I 2023-10-18 18:58:34.209 JupyterHub app:3178] Hub API listening on http://:8081/hub/
[I 2023-10-18 18:58:34.209 JupyterHub app:3180] Private Hub API connect url http://hub:8081/hub/
[I 2023-10-18 18:58:34.209 JupyterHub app:3189] Starting managed service jupyterhub-idle-culler
[I 2023-10-18 18:58:34.210 JupyterHub service:385] Starting service 'jupyterhub-idle-culler': ['python3', '-m', 'jupyterhub_idle_culler', '--url=http://localhost:8081/hub/api', '--timeout=3600', '--cull-every=600', '--concurrency=10']
[I 2023-10-18 18:58:34.211 JupyterHub service:133] Spawning python3 -m jupyterhub_idle_culler --url=http://localhost:8081/hub/api --timeout=3600 --cull-every=600 --concurrency=10
[D 2023-10-18 18:58:34.212 JupyterHub spawner:1384] Polling subprocess every 30s
[D 2023-10-18 18:58:34.212 JupyterHub proxy:389] Fetching routes to check
[D 2023-10-18 18:58:34.213 JupyterHub proxy:880] Proxy: Fetching GET http://proxy-api:8001/api/routes
[D 2023-10-18 18:58:34.215 JupyterHub proxy:953] Omitting non-jupyterhub route '/'
[D 2023-10-18 18:58:34.215 JupyterHub proxy:392] Checking routes
[I 2023-10-18 18:58:34.215 JupyterHub proxy:477] Adding route for Hub: / => http://hub:8081
[D 2023-10-18 18:58:34.215 JupyterHub proxy:880] Proxy: Fetching POST http://proxy-api:8001/api/routes/
[I 2023-10-18 18:58:34.218 JupyterHub app:3247] JupyterHub is now running, internal Hub API at http://hub:8081/hub/
[D 2023-10-18 18:58:34.219 JupyterHub app:2852] It took 0.881 seconds for the Hub to start
[D 2023-10-18 18:58:35.038 JupyterHub base:299] Recording first activity for <APIToken('16a9...', service='jupyterhub-idle-culler', client_id='jupyterhub')>
[I 2023-10-18 18:58:35.048 JupyterHub log:191] 200 GET /hub/api/ (jupyterhub-idle-culler@::1) 13.21ms
[D 2023-10-18 18:58:35.053 JupyterHub scopes:877] Checking access to /hub/api/users via scope list:users
[D 2023-10-18 18:58:35.054 JupyterHub scopes:677] Unrestricted access to /hub/api/users via list:users
[I 2023-10-18 18:58:35.062 JupyterHub log:191] 200 GET /hub/api/users?state=[secret] (jupyterhub-idle-culler@::1) 11.00ms
[D 2023-10-18 18:58:35.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.65ms
[D 2023-10-18 18:58:37.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.70ms
[D 2023-10-18 18:58:39.489 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.76ms
[D 2023-10-18 18:58:41.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.72ms
[D 2023-10-18 18:58:43.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.67ms
[D 2023-10-18 18:58:45.489 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.77ms
[D 2023-10-18 18:58:47.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.65ms
[D 2023-10-18 18:58:49.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.64ms
[D 2023-10-18 18:58:51.487 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.61ms
[D 2023-10-18 18:58:53.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.66ms
[D 2023-10-18 18:58:55.489 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.78ms
[D 2023-10-18 18:58:57.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.79ms
[D 2023-10-18 18:58:59.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.61ms
[D 2023-10-18 18:59:01.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.65ms
[D 2023-10-18 18:59:03.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.60ms
[D 2023-10-18 18:59:05.489 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.91ms
[I 2023-10-18 18:59:06.358 JupyterHub log:191] 302 GET / -> /hub/ (@172.20.35.54) 0.55ms
[I 2023-10-18 18:59:06.417 JupyterHub log:191] 302 GET /hub/ -> /hub/login?next=%2Fhub%2F (@172.20.35.54) 0.70ms
[I 2023-10-18 18:59:06.513 JupyterHub log:191] 200 GET /hub/login?next=%2Fhub%2F (@172.20.35.54) 42.07ms
[D 2023-10-18 18:59:06.576 JupyterHub log:191] 200 GET /hub/static/css/style.min.css?v=01598a5386176f0279952a3b9632a07e7fce9a12aa53108973c83be9ec3473e7a59354876fab64bfeb01892eb503870183707aa03f207d7a94845ca7980c3819 (@172.20.35.54) 2.39ms
[D 2023-10-18 18:59:06.590 JupyterHub log:191] 200 GET /hub/static/components/requirejs/require.js?v=bd1aa102bdb0b27fbf712b32cfcd29b016c272acf3d864ee8469376eaddd032cadcf827ff17c05a8c8e20061418fe58cf79947049f5c0dff3b4f73fcc8cad8ec (@172.20.35.54) 2.03ms
[D 2023-10-18 18:59:06.590 JupyterHub log:191] 200 GET /hub/static/components/bootstrap/dist/js/bootstrap.min.js?v=a014e9acc78d10a0a7a9fbaa29deac6ef17398542d9574b77b40bf446155d210fa43384757e3837da41b025998ebfab4b9b6f094033f9c226392b800df068bce (@172.20.35.54) 2.40ms
[D 2023-10-18 18:59:06.591 JupyterHub log:191] 200 GET /hub/static/components/jquery/dist/jquery.min.js?v=de027062931edd07b01842eff24fc15fdbdcaa1af245dcd133155faba9e0c965f0a34dc6144ce3b149bc43b4597073c792cb6dabbfc6168c63095523923bcf77 (@172.20.35.54) 2.93ms
[D 2023-10-18 18:59:06.824 JupyterHub log:191] 200 GET /hub/logo (@172.20.35.54) 1.11ms
[D 2023-10-18 18:59:06.891 JupyterHub log:191] 200 GET /hub/static/favicon.ico?v=fde5757cd3892b979919d3b1faa88a410f28829feb5ba22b6cf069f2c6c98675fceef90f932e49b510e74d65c681d5846b943e7f7cc1b41867422f0481085c1f (@172.20.35.54) 0.99ms
[D 2023-10-18 18:59:07.489 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.67ms
[D 2023-10-18 18:59:09.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.62ms
[D 2023-10-18 18:59:11.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.71ms
[D 2023-10-18 18:59:12.116 JupyterHub log:191] 200 GET /hub/static/components/font-awesome/fonts/fontawesome-webfont.woff2?v=4.7.0 (@172.20.35.54) 0.90ms
[D 2023-10-18 18:59:12.126 JupyterHub roles:281] Assigning default role to User test
[I 2023-10-18 18:59:12.132 JupyterHub roles:238] Adding role user for User: test
[D 2023-10-18 18:59:12.149 JupyterHub roles:281] Assigning default role to User test
[D 2023-10-18 18:59:12.153 JupyterHub base:587] Setting cookie jupyterhub-session-id: {'httponly': True, 'secure': True, 'path': '/'}
[D 2023-10-18 18:59:12.153 JupyterHub base:591] Setting cookie for test: jupyterhub-hub-login
[D 2023-10-18 18:59:12.154 JupyterHub base:587] Setting cookie jupyterhub-hub-login: {'httponly': True, 'secure': True, 'path': '/hub/'}
[I 2023-10-18 18:59:12.154 JupyterHub base:837] User logged in: test
[I 2023-10-18 18:59:12.155 JupyterHub log:191] 302 POST /hub/login?next=%2Fhub%2F -> /hub/ (test@172.20.35.54) 33.65ms
[D 2023-10-18 18:59:12.211 JupyterHub base:299] Recording first activity for <User(test 0/1 running)>
[D 2023-10-18 18:59:12.221 JupyterHub user:431] Creating <class 'kubespawner.spawner.KubeSpawner'> for test:
[I 2023-10-18 18:59:12.227 JupyterHub log:191] 302 GET /hub/ -> /hub/spawn (test@172.20.35.54) 18.28ms
[D 2023-10-18 18:59:12.282 JupyterHub scopes:877] Checking access to /hub/spawn via scope servers
[D 2023-10-18 18:59:12.283 JupyterHub scopes:690] Argument-based access to /hub/spawn via servers
[D 2023-10-18 18:59:12.283 JupyterHub pages:217] Triggering spawn with default options for test
[D 2023-10-18 18:59:12.283 JupyterHub base:961] Initiating spawn for test
[D 2023-10-18 18:59:12.283 JupyterHub base:965] 0/64 concurrent spawns
[D 2023-10-18 18:59:12.283 JupyterHub base:970] 0 active servers
[I 2023-10-18 18:59:12.309 JupyterHub provider:659] Creating oauth client jupyterhub-user-test
[D 2023-10-18 18:59:12.333 JupyterHub user:794] Calling Spawner.start for test
[I 2023-10-18 18:59:12.337 JupyterHub log:191] 302 GET /hub/spawn -> /hub/spawn-pending/test (test@172.20.35.54) 56.43ms
[D 2023-10-18 18:59:12.394 JupyterHub scopes:877] Checking access to /hub/spawn-pending/test via scope servers
[D 2023-10-18 18:59:12.394 JupyterHub scopes:690] Argument-based access to /hub/spawn-pending/test via servers
[I 2023-10-18 18:59:12.395 JupyterHub pages:398] test is pending spawn
[I 2023-10-18 18:59:12.400 JupyterHub log:191] 200 GET /hub/spawn-pending/test (test@172.20.35.54) 8.11ms
[D 2023-10-18 18:59:12.495 JupyterHub scopes:877] Checking access to /hub/api/users/test/server/progress via scope read:servers
[D 2023-10-18 18:59:12.495 JupyterHub scopes:690] Argument-based access to /hub/api/users/test/server/progress via read:servers
[D 2023-10-18 18:59:13.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.60ms
[D 2023-10-18 18:59:15.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.67ms
[D 2023-10-18 18:59:17.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.61ms
[D 2023-10-18 18:59:19.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.66ms
[D 2023-10-18 18:59:21.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.96ms
[D 2023-10-18 18:59:23.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.51ms
[D 2023-10-18 18:59:25.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.77ms
[D 2023-10-18 18:59:27.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.67ms
[D 2023-10-18 18:59:29.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.58ms
[D 2023-10-18 18:59:31.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.69ms
[D 2023-10-18 18:59:33.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.64ms
[D 2023-10-18 18:59:34.219 JupyterHub proxy:880] Proxy: Fetching GET http://proxy-api:8001/api/routes
[D 2023-10-18 18:59:34.222 JupyterHub proxy:392] Checking routes
[D 2023-10-18 18:59:35.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.50ms
[D 2023-10-18 18:59:37.489 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.90ms
[D 2023-10-18 18:59:39.489 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.87ms
[D 2023-10-18 18:59:41.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.66ms
[D 2023-10-18 18:59:43.489 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.70ms
[D 2023-10-18 18:59:45.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.65ms
[D 2023-10-18 18:59:47.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.64ms
[D 2023-10-18 18:59:49.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.84ms
[D 2023-10-18 18:59:51.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.57ms
[D 2023-10-18 18:59:53.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.75ms
[D 2023-10-18 18:59:55.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.63ms
[D 2023-10-18 18:59:57.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.53ms
[D 2023-10-18 18:59:59.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.60ms
[D 2023-10-18 19:00:01.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.73ms
[D 2023-10-18 19:00:03.489 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.87ms
[D 2023-10-18 19:00:05.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.67ms
[D 2023-10-18 19:00:07.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.61ms
[D 2023-10-18 19:00:09.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.56ms
[D 2023-10-18 19:00:11.488 JupyterHub log:191] 200 GET /hub/health (@100.96.3.73) 0.71ms
[E 2023-10-18 19:00:12.612 JupyterHub reflector:397] Initial list of events failed
    Traceback (most recent call last):
      File "/usr/local/lib/python3.11/site-packages/kubespawner/reflector.py", line 395, in start
        await self._list_and_update()
      File "/usr/local/lib/python3.11/site-packages/kubespawner/reflector.py", line 231, in _list_and_update
        initial_resources_raw = await list_method(**kwargs)
                                ^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/api_client.py", line 185, in __call_api
        response_data = await self.request(
                        ^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/rest.py", line 196, in GET
        return (await self.request("GET", url,
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/rest.py", line 180, in request
        r = await self.pool_manager.request(**args)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/aiohttp/client.py", line 467, in _request
        with timer:
      File "/usr/local/lib/python3.11/site-packages/aiohttp/helpers.py", line 721, in __exit__
        raise asyncio.TimeoutError from None
    TimeoutError
    
[E 2023-10-18 19:00:12.615 JupyterHub spawner:2407] Reflector with key ('events', 'jhub-test') failed to start.
    Traceback (most recent call last):
      File "/usr/local/lib/python3.11/site-packages/kubespawner/spawner.py", line 2405, in catch_reflector_start
        await func
      File "/usr/local/lib/python3.11/site-packages/kubespawner/reflector.py", line 395, in start
        await self._list_and_update()
      File "/usr/local/lib/python3.11/site-packages/kubespawner/reflector.py", line 231, in _list_and_update
        initial_resources_raw = await list_method(**kwargs)
                                ^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/api_client.py", line 185, in __call_api
        response_data = await self.request(
                        ^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/rest.py", line 196, in GET
        return (await self.request("GET", url,
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/rest.py", line 180, in request
        r = await self.pool_manager.request(**args)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/aiohttp/client.py", line 467, in _request
        with timer:
      File "/usr/local/lib/python3.11/site-packages/aiohttp/helpers.py", line 721, in __exit__
        raise asyncio.TimeoutError from None
    TimeoutError
    
[E 2023-10-18 19:00:12.618 JupyterHub reflector:397] Initial list of pods failed
    Traceback (most recent call last):
      File "/usr/local/lib/python3.11/site-packages/kubespawner/reflector.py", line 395, in start
        await self._list_and_update()
      File "/usr/local/lib/python3.11/site-packages/kubespawner/reflector.py", line 231, in _list_and_update
        initial_resources_raw = await list_method(**kwargs)
                                ^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/api_client.py", line 185, in __call_api
        response_data = await self.request(
                        ^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/rest.py", line 196, in GET
        return (await self.request("GET", url,
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/rest.py", line 180, in request
        r = await self.pool_manager.request(**args)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/aiohttp/client.py", line 467, in _request
        with timer:
      File "/usr/local/lib/python3.11/site-packages/aiohttp/helpers.py", line 721, in __exit__
        raise asyncio.TimeoutError from None
    TimeoutError
    
[E 2023-10-18 19:00:12.620 JupyterHub spawner:2407] Reflector with key ('pods', 'jhub-test') failed to start.
    Traceback (most recent call last):
      File "/usr/local/lib/python3.11/site-packages/kubespawner/spawner.py", line 2405, in catch_reflector_start
        await func
      File "/usr/local/lib/python3.11/site-packages/kubespawner/reflector.py", line 395, in start
        await self._list_and_update()
      File "/usr/local/lib/python3.11/site-packages/kubespawner/reflector.py", line 231, in _list_and_update
        initial_resources_raw = await list_method(**kwargs)
                                ^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/api_client.py", line 185, in __call_api
        response_data = await self.request(
                        ^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/rest.py", line 196, in GET
        return (await self.request("GET", url,
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/rest.py", line 180, in request
        r = await self.pool_manager.request(**args)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/aiohttp/client.py", line 467, in _request
        with timer:
      File "/usr/local/lib/python3.11/site-packages/aiohttp/helpers.py", line 721, in __exit__
        raise asyncio.TimeoutError from None
    TimeoutError
    
[E 2023-10-18 19:00:12.621 JupyterHub web:1871] Uncaught exception GET /hub/api/users/test/server/progress?_xsrf=2%7C09658ca0%7Cd7c4467a0bdddaa7272755ed70306e0e%7C1697655546 (172.20.35.54)
    HTTPServerRequest(protocol='https', host='regn-codebook.datajoint.io', method='GET', uri='/hub/api/users/test/server/progress?_xsrf=2%7C09658ca0%7Cd7c4467a0bdddaa7272755ed70306e0e%7C1697655546', version='HTTP/1.1', remote_ip='172.20.35.54')
    Traceback (most recent call last):
      File "/usr/local/lib/python3.11/site-packages/tornado/web.py", line 1786, in _execute
        result = await result
                 ^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/jupyterhub/apihandlers/users.py", line 752, in get
        async for event in events:
      File "/usr/local/lib/python3.11/site-packages/jupyterhub/utils.py", line 623, in iterate_until
        yield item_future.result()
              ^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/jupyterhub/spawner.py", line 1274, in _generate_progress
        async for event in progress:
      File "/usr/local/lib/python3.11/site-packages/kubespawner/spawner.py", line 2294, in progress
        await self._start_watching_events()
      File "/usr/local/lib/python3.11/site-packages/kubespawner/spawner.py", line 2437, in _start_watching_events
        return await self._start_reflector(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubespawner/spawner.py", line 2373, in _start_reflector
        await previous_reflector.first_load_future
      File "/usr/local/lib/python3.11/site-packages/kubespawner/reflector.py", line 395, in start
        await self._list_and_update()
      File "/usr/local/lib/python3.11/site-packages/kubespawner/reflector.py", line 231, in _list_and_update
        initial_resources_raw = await list_method(**kwargs)
                                ^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/api_client.py", line 185, in __call_api
        response_data = await self.request(
                        ^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/rest.py", line 196, in GET
        return (await self.request("GET", url,
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/rest.py", line 180, in request
        r = await self.pool_manager.request(**args)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/aiohttp/client.py", line 467, in _request
        with timer:
      File "/usr/local/lib/python3.11/site-packages/aiohttp/helpers.py", line 721, in __exit__
        raise asyncio.TimeoutError from None
    TimeoutError
    
[E 2023-10-18 19:00:12.625 JupyterHub web:1274] Cannot send error response after headers written
[I 2023-10-18 19:00:12.626 JupyterHub log:191] 200 GET /hub/api/users/test/server/progress?_xsrf=[secret] (test@172.20.35.54) 60132.89ms
[E 2023-10-18 19:00:12.626 JupyterHub user:884] Unhandled error starting test's server: 'coroutine' object has no attribute 'cancel'
    Traceback (most recent call last):
      File "/usr/local/lib/python3.11/site-packages/jupyterhub/user.py", line 798, in spawn
        url = await gen.with_timeout(timedelta(seconds=spawner.start_timeout), f)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubespawner/spawner.py", line 2669, in _start
        future.cancel()
        ^^^^^^^^^^^^^
    AttributeError: 'coroutine' object has no attribute 'cancel'
    
[D 2023-10-18 19:00:12.629 JupyterHub user:982] Stopping test
[D 2023-10-18 19:00:12.643 JupyterHub user:1002] Deleting oauth client jupyterhub-user-test
[D 2023-10-18 19:00:12.654 JupyterHub user:1005] Finished stopping test
[E 2023-10-18 19:00:12.667 JupyterHub gen:630] Exception in Future <Task finished name='Task-109' coro=<BaseHandler.spawn_single_user.<locals>.finish_user_spawn() done, defined at /usr/local/lib/python3.11/site-packages/jupyterhub/handlers/base.py:981> exception=AttributeError("'coroutine' object has no attribute 'cancel'")> after timeout
    Traceback (most recent call last):
      File "/usr/local/lib/python3.11/site-packages/tornado/gen.py", line 625, in error_callback
        future.result()
      File "/usr/local/lib/python3.11/site-packages/jupyterhub/handlers/base.py", line 988, in finish_user_spawn
        await spawn_future
      File "/usr/local/lib/python3.11/site-packages/jupyterhub/user.py", line 902, in spawn
        raise e
      File "/usr/local/lib/python3.11/site-packages/jupyterhub/user.py", line 798, in spawn
        url = await gen.with_timeout(timedelta(seconds=spawner.start_timeout), f)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubespawner/spawner.py", line 2669, in _start
        future.cancel()
        ^^^^^^^^^^^^^
    AttributeError: 'coroutine' object has no attribute 'cancel'
1 Like
2

Thanks for this very clearly written writeup @yambottle!!

I’m interested to learn some details about your k8s cluster.

  • How is it setup? Is it based on GCP’s GKE / AWS’s EKS / Azure’s AKS, or a self managed k3s / microk8s / etc.?
  • Is the cluster very actively used for other things also?
[E 2023-10-18 19:00:12.612 JupyterHub reflector:397] Initial list of events failed
    Traceback (most recent call last):
      File "/usr/local/lib/python3.11/site-packages/kubespawner/reflector.py", line 395, in start
        await self._list_and_update()
      File "/usr/local/lib/python3.11/site-packages/kubespawner/reflector.py", line 231, in _list_and_update
        initial_resources_raw = await list_method(**kwargs)
                                ^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/api_client.py", line 185, in __call_api
        response_data = await self.request(
                        ^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/rest.py", line 196, in GET
        return (await self.request("GET", url,
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/kubernetes_asyncio/client/rest.py", line 180, in request
        r = await self.pool_manager.request(**args)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.11/site-packages/aiohttp/client.py", line 467, in _request
        with timer:
      File "/usr/local/lib/python3.11/site-packages/aiohttp/helpers.py", line 721, in __exit__
        raise asyncio.TimeoutError from None
    TimeoutError

This timeout error is the important error.

There is also another error about object has no attribute, but it is an error in the error handling of the timeout error, and therefore not the main issue. I’ve opened Object has no attribute 'cancel' - a secondary error when handling a timeout error · Issue #796 · jupyterhub/kubespawner · GitHub to avoid erroring during error handling.

3

Hi Erik,
Thanks for your response!

  • This is a self-hosted k8s cluster created by kOps, hosted on AWS EC2 instances, installed with: cert-manager, metrics-server, cilium CNI, EBS and EFS CSI, AWS autoscaler
# kubectl -n kube-system get pods
NAME                                                 READY   STATUS    RESTARTS      AGE
autoscaler-aws-cluster-autoscaler-5c9bd7b56b-c9dcx   1/1     Running   0             47h
aws-cloud-controller-manager-6hwlk                   1/1     Running   0             47h
cilium-ht7bx                                         1/1     Running   0             47h
cilium-jx7rp                                         1/1     Running   0             47h
cilium-operator-6d9d7cc568-68mtq                     1/1     Running   0             47h
cilium-trl4b                                         1/1     Running   0             47h
cilium-xjmcj                                         1/1     Running   0             47h
coredns-69998f855-7vrsv                              1/1     Running   0             47h
coredns-69998f855-hn459                              1/1     Running   0             47h
coredns-autoscaler-fcf87bf56-rd7bh                   1/1     Running   0             47h
dns-controller-74ff5dbdb8-hbgbs                      1/1     Running   0             47h
ebs-csi-controller-c746549d4-f8tcf                   5/5     Running   0             47h
ebs-csi-node-4xqsj                                   3/3     Running   0             47h
ebs-csi-node-5hnlk                                   3/3     Running   0             47h
ebs-csi-node-fvnjz                                   3/3     Running   0             47h
ebs-csi-node-wm6x5                                   3/3     Running   0             47h
efs-csi-node-6dqxx                                   3/3     Running   0             47h
efs-csi-node-7gmmg                                   3/3     Running   0             47h
efs-csi-node-m9qml                                   3/3     Running   0             47h
efs-csi-node-qxwrl                                   3/3     Running   0             47h
etcd-manager-events-i-0e30982b3f1e6e4ae              1/1     Running   0             47h
etcd-manager-main-i-0e30982b3f1e6e4ae                1/1     Running   0             47h
kops-controller-dxk5c                                1/1     Running   0             47h
kube-apiserver-i-0e30982b3f1e6e4ae                   2/2     Running   4 (47h ago)   47h
kube-controller-manager-i-0e30982b3f1e6e4ae          1/1     Running   5 (47h ago)   47h
kube-scheduler-i-0e30982b3f1e6e4ae                   1/1     Running   0             47h
metrics-server-5d875656f5-zq8qq                      1/1     Running   0             47h

and

# kops cluster creation config file only pasting instance group here
apiVersion: kops.k8s.io/v1alpha2
kind: InstanceGroup
metadata:
  creationTimestamp: null
  labels:
    kops.k8s.io/cluster: xxxxxxxxxxxxxxxxxxxxxxx
  name: control-plane-us-east-2a
spec:
  image: 099720109477/ubuntu/images/hvm-ssd/ubuntu-jammy-22.04-amd64-server-20230919
  machineType: t3a.large
  maxSize: 1
  minSize: 1
  role: Master
  subnets:
    - us-east-2a
  instanceMetadata:
    httpTokens: optional
  rootVolumeSize: 30
---
apiVersion: kops.k8s.io/v1alpha2
kind: InstanceGroup
metadata:
  creationTimestamp: null
  labels:
    kops.k8s.io/cluster: xxxxxxxxxxxxxxxxxxxxxxx
  name: nodes-us-east-2a
spec:
  image: 099720109477/ubuntu/images/hvm-ssd/ubuntu-jammy-22.04-amd64-server-20230919
  machineType: t3a.large
  maxSize: 5
  minSize: 1
  role: Node
  subnets:
    - us-east-2a
  cloudLabels:
    k8s.io/cluster-autoscaler/xxxxxxxxxxxxxxxxxxxxxxx: owned
    k8s.io/cluster-autoscaler/enable: "true"
  rootVolumeSize: 64
---
apiVersion: kops.k8s.io/v1alpha2
kind: InstanceGroup
metadata:
  creationTimestamp: null
  labels:
    kops.k8s.io/cluster: xxxxxxxxxxxxxxxxxxxxxxx
  name: jhub-user-nodes
  generation: 1
spec:
  image: 099720109477/ubuntu/images/hvm-ssd/ubuntu-jammy-22.04-amd64-server-20230919
  machineType: t3a.xlarge
  maxSize: 5
  minSize: 2
  role: Node
  subnets:
    - us-east-2a
  cloudLabels:
    k8s.io/cluster-autoscaler/xxxxxxxxxxxxxxxxxxxxxxx: owned
    k8s.io/cluster-autoscaler/enable: "true"
  rootVolumeSize: 64
  nodeLabels:
    kops.k8s.io/instancegroup: jhub-user-nodes
    hub.jupyter.org/node-purpose: user
  taints[0]: hub.jupyter.org/dedicated=user:NoSchedule

Is it possible this issue was caused by the node affinity on the jhub-user-nodes node pool? I’m doing the same thing on a jupyterhub 1.2.0 + 1.4.2 deployment and it works fine.
Actually, it might not be the cause, since I do have a general purpose node pool nodes-us-east-2a. Also, if this node affinity is the cause, then the pod would be spawned and getting a toleration error instead of my case: no pods been spawned at all and getting a timeout error to spawn in the hub pod.

  • This is a dev k8s cluster has been created very recently and jupyterhub is the only thing running on it
4

Aha cilium, there is an issue with that documented in `hub` pod unable to establish connections to k8s api-server etc on port 6443 with Cilium · Issue #3202 · jupyterhub/zero-to-jupyterhub-k8s · GitHub relating to networkpolicies, and cilium not being able to enforce them according to specification fully.

Test the workaround in the issue post adding egress for hub pod to port 6443, or to the port your k8s api server is accessed. You can do kubectl get service -n default and check the port on the kubernetes Service resource there

2 Likes
5

Thanks Erik!!!
To follow up with my solution:

# kubectl get service
NAME         TYPE        CLUSTER-IP   EXTERNAL-IP   PORT(S)   AGE
kubernetes   ClusterIP   100.64.0.1   <none>        443/TCP   2d1h

Since my kubernetes service is runnning on port 443(which is not a security best practice), so I have to add the egress with port 443 as well:

hub:
  networkPolicy:
    egress:
      - ports:
          - port: 6443
          - port: 443

and this makes the pod to spawn.

Do you think this is necessarily to be documented somewhere? Let me know if there is a good place to put this, I’d love to help.