Container is gone after start

JupyterHub
1

Hi !

I try to mount a jupyterhub container. The server seems to run smoothly but cannot create a user notebook container (DockerSpawner). After a few seconds, the container disappears. Hereafter is my jupyterhub log (user: donzel):

[D 2023-11-03 14:18:16.039 JupyterHub application:908] Looking for /srv/jupyterhub/jupyterhub_config in /srv/jupyterhub
[D 2023-11-03 14:18:16.054 JupyterHub application:929] Loaded config file: /srv/jupyterhub/jupyterhub_config.py
[I 2023-11-03 14:18:16.063 JupyterHub app:2859] Running JupyterHub version 4.0.2
[I 2023-11-03 14:18:16.063 JupyterHub app:2889] Using Authenticator: oauthenticator.gitlab.LocalGitLabOAuthenticator-16.1.1
[I 2023-11-03 14:18:16.064 JupyterHub app:2889] Using Spawner: dockerspawner.dockerspawner.DockerSpawner-12.1.0
[I 2023-11-03 14:18:16.064 JupyterHub app:2889] Using Proxy: jupyterhub.proxy.ConfigurableHTTPProxy-4.0.2
[I 2023-11-03 14:18:16.564 JupyterHub app:1664] Loading cookie_secret from /data/jupyterhub_cookie_secret
[D 2023-11-03 14:18:16.566 JupyterHub app:1833] Connecting to db: sqlite:////data/jupyterhub.sqlite
[D 2023-11-03 14:18:16.702 JupyterHub orm:1016] database schema version found: 0eee8c825d24
[D 2023-11-03 14:18:16.781 JupyterHub app:2104] Loading roles into database
[D 2023-11-03 14:18:16.797 JupyterHub auth:960] No UID for user donzel
[I 2023-11-03 14:18:16.797 JupyterHub auth:962] Creating user: adduser -q --gecos '""' --home /home/public/donzel --disabled-password donzel
[D 2023-11-03 14:18:17.695 JupyterHub auth:960] No UID for user berkachyr
[I 2023-11-03 14:18:17.695 JupyterHub auth:962] Creating user: adduser -q --gecos '""' --home /home/public/berkachyr --disabled-password berkachyr
[D 2023-11-03 14:18:18.064 JupyterHub auth:960] No UID for user testuser
[I 2023-11-03 14:18:18.064 JupyterHub auth:962] Creating user: adduser -q --gecos '""' --home /home/public/testuser --disabled-password testuser
[D 2023-11-03 14:18:18.480 JupyterHub auth:960] No UID for user sharednotebooks
[I 2023-11-03 14:18:18.481 JupyterHub auth:962] Creating user: adduser -q --gecos '""' --home /home/public/sharednotebooks --disabled-password sharednotebooks
[D 2023-11-03 14:18:18.938 JupyterHub app:2343] Purging expired APITokens
[D 2023-11-03 14:18:18.940 JupyterHub app:2343] Purging expired OAuthCodes
[D 2023-11-03 14:18:18.943 JupyterHub app:2179] Loading role assignments from config
[D 2023-11-03 14:18:18.943 JupyterHub app:2250] Assigning 4 allowed_users to the user role
[D 2023-11-03 14:18:18.962 JupyterHub app:2502] Initializing spawners
[D 2023-11-03 14:18:18.965 JupyterHub app:2633] Loaded users:
    
[I 2023-11-03 14:18:18.965 JupyterHub app:2928] Initialized 0 spawners in 0.003 seconds
[I 2023-11-03 14:18:18.971 JupyterHub metrics:278] Found 1 active users in the last ActiveUserPeriods.twenty_four_hours
[I 2023-11-03 14:18:18.972 JupyterHub metrics:278] Found 1 active users in the last ActiveUserPeriods.seven_days
[I 2023-11-03 14:18:18.973 JupyterHub metrics:278] Found 1 active users in the last ActiveUserPeriods.thirty_days
[I 2023-11-03 14:18:18.974 JupyterHub proxy:750] Starting proxy @ https://:443/
[D 2023-11-03 14:18:18.974 JupyterHub proxy:751] Proxy cmd: ['configurable-http-proxy', '--ip', '', '--port', '443', '--api-ip', '127.0.0.1', '--api-port', '8001', '--error-target', 'http://jupyterhub:8080/hub/error', '--log-level', 'info', '--ssl-key', '/srv/jupyterhub/secrets/jupyterhub.key', '--ssl-cert', '/srv/jupyterhub/secrets/jupyterhub.crt']
[D 2023-11-03 14:18:18.982 JupyterHub proxy:670] Writing proxy pid file: jupyterhub-proxy.pid
14:18:20.939 [ConfigProxy] info: Proxying https://*:443 to (no default)
14:18:20.963 [ConfigProxy] info: Proxy API at http://127.0.0.1:8001/api/routes
[D 2023-11-03 14:18:21.074 JupyterHub proxy:787] Proxy started and appears to be up
[D 2023-11-03 14:18:21.075 JupyterHub proxy:880] Proxy: Fetching GET http://127.0.0.1:8001/api/routes
[I 2023-11-03 14:18:21.095 JupyterHub app:3178] Hub API listening on http://0.0.0.0:8080/hub/
[I 2023-11-03 14:18:21.096 JupyterHub app:3180] Private Hub API connect url http://jupyterhub:8080/hub/
[I 2023-11-03 14:18:21.096 JupyterHub app:3189] Starting managed service idle-culler
[I 2023-11-03 14:18:21.096 JupyterHub service:385] Starting service 'idle-culler': ['/usr/bin/python3', '-m', 'jupyterhub_idle_culler', '--timeout=3600']
14:18:21.100 [ConfigProxy] info: 200 GET /api/routes 
[I 2023-11-03 14:18:21.104 JupyterHub service:133] Spawning /usr/bin/python3 -m jupyterhub_idle_culler --timeout=3600
[D 2023-11-03 14:18:21.105 JupyterHub spawner:1384] Polling subprocess every 30s
[D 2023-11-03 14:18:21.106 JupyterHub proxy:389] Fetching routes to check
[D 2023-11-03 14:18:21.106 JupyterHub proxy:880] Proxy: Fetching GET http://127.0.0.1:8001/api/routes
14:18:21.107 [ConfigProxy] info: 200 GET /api/routes 
[D 2023-11-03 14:18:21.108 JupyterHub proxy:392] Checking routes
[I 2023-11-03 14:18:21.108 JupyterHub proxy:477] Adding route for Hub: / => http://jupyterhub:8080
[D 2023-11-03 14:18:21.109 JupyterHub proxy:880] Proxy: Fetching POST http://127.0.0.1:8001/api/routes/
14:18:21.111 [ConfigProxy] info: Adding route / -> http://jupyterhub:8080
14:18:21.112 [ConfigProxy] info: Route added / -> http://jupyterhub:8080
[I 2023-11-03 14:18:21.116 JupyterHub app:3245] JupyterHub is now running at https://:443/
[D 2023-11-03 14:18:21.117 JupyterHub app:2852] It took 5.086 seconds for the Hub to start
14:18:21.118 [ConfigProxy] info: 201 POST /api/routes/ 
[D 2023-11-03 14:18:21.637 JupyterHub base:299] Recording first activity for <APIToken('bf7d...', service='idle-culler', client_id='jupyterhub')>
[I 2023-11-03 14:18:21.652 JupyterHub log:191] 200 GET /hub/api/ (idle-culler@172.21.0.2) 17.92ms
[D 2023-11-03 14:18:21.654 JupyterHub scopes:877] Checking access to /hub/api/users via scope list:users
[D 2023-11-03 14:18:21.655 JupyterHub scopes:677] Unrestricted access to /hub/api/users via list:users
[I 2023-11-03 14:18:21.661 JupyterHub log:191] 200 GET /hub/api/users?state=[secret] (idle-culler@172.21.0.2) 8.35ms
[I 2023-11-03 14:20:43.137 JupyterHub log:191] 302 GET / -> /hub/ (@::ffff:178.192.249.242) 0.66ms
[I 2023-11-03 14:20:43.156 JupyterHub log:191] 302 GET /hub/ -> /hub/login?next=%2Fhub%2F (@::ffff:178.192.249.242) 0.53ms
[I 2023-11-03 14:20:43.251 JupyterHub log:191] 200 GET /hub/login?next=%2Fhub%2F (@::ffff:178.192.249.242) 79.48ms
[I 2023-11-03 14:20:45.476 JupyterHub oauth2:97] OAuth redirect: https://jupyterhub.groupe-asam.ch/hub/oauth_callback
[D 2023-11-03 14:20:45.477 JupyterHub base:587] Setting cookie oauthenticator-state: {'httponly': True, 'secure': True, 'expires_days': 1}
[I 2023-11-03 14:20:45.479 JupyterHub log:191] 302 GET /hub/oauth_login?next=%2Fhub%2F -> https://gitlab.com/oauth/authorize?response_type=code&redirect_uri=https%3A%2F%2Fjupyterhub.groupe-asam.ch%2Fhub%2Foauth_callback&client_id=60f4f008ea39650de7839a7b14e144a95af5d173db5d5bdaad14f61d4823d446&state=[secret] (@::ffff:178.192.249.242) 3.34ms
[D 2023-11-03 14:20:54.579 JupyterHub roles:281] Assigning default role to User donzel
[D 2023-11-03 14:20:54.582 JupyterHub base:587] Setting cookie jupyterhub-session-id: {'httponly': True, 'secure': True, 'path': '/'}
[D 2023-11-03 14:20:54.582 JupyterHub base:591] Setting cookie for donzel: jupyterhub-hub-login
[D 2023-11-03 14:20:54.582 JupyterHub base:587] Setting cookie jupyterhub-hub-login: {'httponly': True, 'secure': True, 'path': '/hub/'}
[I 2023-11-03 14:20:54.583 JupyterHub base:837] User logged in: donzel
[I 2023-11-03 14:20:54.585 JupyterHub log:191] 302 GET /hub/oauth_callback?code=[secret]&state=[secret] -> /hub/ (@::ffff:178.192.249.242) 896.99ms
[D 2023-11-03 14:20:54.635 JupyterHub user:431] Creating <class 'dockerspawner.dockerspawner.DockerSpawner'> for donzel:
[I 2023-11-03 14:20:54.637 JupyterHub log:191] 302 GET /hub/ -> /hub/spawn (donzel@::ffff:178.192.249.242) 13.27ms
[D 2023-11-03 14:20:54.656 JupyterHub scopes:877] Checking access to /hub/spawn via scope servers
[D 2023-11-03 14:20:54.656 JupyterHub scopes:677] Unrestricted access to /hub/spawn via servers
[D 2023-11-03 14:20:54.656 JupyterHub pages:217] Triggering spawn with default options for donzel
[D 2023-11-03 14:20:54.657 JupyterHub base:961] Initiating spawn for donzel
[D 2023-11-03 14:20:54.657 JupyterHub base:965] 0/100 concurrent spawns
[D 2023-11-03 14:20:54.657 JupyterHub base:970] 0 active servers
[I 2023-11-03 14:20:54.684 JupyterHub provider:659] Creating oauth client jupyterhub-user-donzel
[D 2023-11-03 14:20:54.715 JupyterHub user:794] Calling Spawner.start for donzel
[D 2023-11-03 14:20:54.727 JupyterHub dockerspawner:982] Getting container 'jupyter-donzel'
[I 2023-11-03 14:20:54.729 JupyterHub dockerspawner:988] Container 'jupyter-donzel' is gone
[D 2023-11-03 14:20:54.730 JupyterHub dockerspawner:1148] Starting host with config: {'auto_remove': True, 'binds': {'jupyterhub-user-donzel': {'bind': '/home/jovyan/work', 'mode': 'rw'}, 'jupyterhub-user-sharednotebooks': {'bind': '/opt/shared_nbs/', 'mode': 'rw'}}, 'links': {}, 'mounts': [], 'mem_limit': 0, 'cpu_period': 100000, 'cpu_quota': 0, 'network_mode': 'jupyterhub-network'}
[I 2023-11-03 14:20:55.109 JupyterHub dockerspawner:1272] Created container jupyter-donzel (id: 249d28e) from image donzel/asam-notebook:oct2023
[I 2023-11-03 14:20:55.110 JupyterHub dockerspawner:1296] Starting container jupyter-donzel (id: 249d28e)
[I 2023-11-03 14:20:55.658 JupyterHub log:191] 302 GET /hub/spawn -> /hub/spawn-pending/donzel (donzel@::ffff:178.192.249.242) 1003.23ms
[D 2023-11-03 14:20:55.685 JupyterHub scopes:877] Checking access to /hub/spawn-pending/donzel via scope servers
[D 2023-11-03 14:20:55.685 JupyterHub scopes:677] Unrestricted access to /hub/spawn-pending/donzel via servers
[I 2023-11-03 14:20:55.685 JupyterHub pages:398] donzel is pending spawn
[I 2023-11-03 14:20:55.693 JupyterHub log:191] 200 GET /hub/spawn-pending/donzel (donzel@::ffff:178.192.249.242) 11.40ms
[D 2023-11-03 14:20:55.820 JupyterHub log:191] 200 GET /hub/static/css/style.min.css?v=01598a5386176f0279952a3b9632a07e7fce9a12aa53108973c83be9ec3473e7a59354876fab64bfeb01892eb503870183707aa03f207d7a94845ca7980c3819 (@::ffff:178.192.249.242) 22.29ms
[D 2023-11-03 14:20:55.853 JupyterHub spawner:1384] Polling subprocess every 30s
[D 2023-11-03 14:20:55.901 JupyterHub log:191] 200 GET /hub/static/components/bootstrap/dist/js/bootstrap.min.js?v=a014e9acc78d10a0a7a9fbaa29deac6ef17398542d9574b77b40bf446155d210fa43384757e3837da41b025998ebfab4b9b6f094033f9c226392b800df068bce (@::ffff:178.192.249.242) 5.22ms
[D 2023-11-03 14:20:55.904 JupyterHub log:191] 200 GET /hub/static/components/jquery/dist/jquery.min.js?v=de027062931edd07b01842eff24fc15fdbdcaa1af245dcd133155faba9e0c965f0a34dc6144ce3b149bc43b4597073c792cb6dabbfc6168c63095523923bcf77 (@::ffff:178.192.249.242) 7.82ms
[D 2023-11-03 14:20:55.913 JupyterHub log:191] 200 GET /hub/static/components/requirejs/require.js?v=bd1aa102bdb0b27fbf712b32cfcd29b016c272acf3d864ee8469376eaddd032cadcf827ff17c05a8c8e20061418fe58cf79947049f5c0dff3b4f73fcc8cad8ec (@::ffff:178.192.249.242) 15.85ms
[D 2023-11-03 14:20:55.953 JupyterHub log:191] 200 GET /hub/logo (@::ffff:178.192.249.242) 1.34ms
[D 2023-11-03 14:20:55.984 JupyterHub log:191] 200 GET /hub/static/components/font-awesome/fonts/fontawesome-webfont.woff2?v=4.7.0 (@::ffff:178.192.249.242) 10.74ms
[D 2023-11-03 14:20:55.996 JupyterHub scopes:877] Checking access to /hub/api/users/donzel/server/progress via scope read:servers
[D 2023-11-03 14:20:55.997 JupyterHub scopes:677] Unrestricted access to /hub/api/users/donzel/server/progress via read:servers
[D 2023-11-03 14:21:04.659 JupyterHub dockerspawner:982] Getting container 'jupyter-donzel'
[I 2023-11-03 14:21:04.661 JupyterHub dockerspawner:988] Container 'jupyter-donzel' is gone
[W 2023-11-03 14:21:04.662 JupyterHub dockerspawner:963] Container not found: jupyter-donzel
Task exception was never retrieved
future: <Task finished name='Task-214' coro=<BaseHandler.spawn_single_user() done, defined at /usr/local/lib/python3.10/dist-packages/jupyterhub/handlers/base.py:871> exception=HTTPError()>
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/dist-packages/jupyterhub/handlers/base.py", line 1078, in spawn_single_user
    await gen.with_timeout(
asyncio.exceptions.TimeoutError: Timeout

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/dist-packages/jupyterhub/handlers/base.py", line 1112, in spawn_single_user
    raise web.HTTPError(
tornado.web.HTTPError: HTTP 500: Internal Server Error (Spawner failed to start [status=0]. The logs for donzel may contain details.)
[D 2023-11-03 14:21:25.855 JupyterHub dockerspawner:982] Getting container 'jupyter-donzel'
[I 2023-11-03 14:21:25.858 JupyterHub dockerspawner:988] Container 'jupyter-donzel' is gone
[W 2023-11-03 14:21:25.858 JupyterHub dockerspawner:963] Container not found: jupyter-donzel
[W 2023-11-03 14:21:34.884 JupyterHub user:933] donzel's server never showed up at http://172.21.0.3:8888/user/donzel/ after 30 seconds. Giving up.
    
    Common causes of this timeout, and debugging tips:
    
    1. 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.
    2. The server started, but is not accessible at the specified URL.
       This may be a configuration issue specific to your chosen Spawner.
       Check the single-user server logs and resource to make sure the URL
       is correct and accessible from the Hub.
    3. (unlikely) Everything is working, but the server took too long to respond.
       To fix: increase `Spawner.http_timeout` configuration
       to a number of seconds that is enough for servers to become responsive.
    
[D 2023-11-03 14:21:34.885 JupyterHub user:982] Stopping donzel
[D 2023-11-03 14:21:34.885 JupyterHub dockerspawner:982] Getting container 'jupyter-donzel'
[I 2023-11-03 14:21:34.887 JupyterHub dockerspawner:988] Container 'jupyter-donzel' is gone
[W 2023-11-03 14:21:34.887 JupyterHub dockerspawner:963] Container not found: jupyter-donzel
[D 2023-11-03 14:21:34.897 JupyterHub user:1002] Deleting oauth client jupyterhub-user-donzel
[D 2023-11-03 14:21:34.909 JupyterHub user:1005] Finished stopping donzel
[E 2023-11-03 14:21:34.921 JupyterHub gen:630] Exception in Future <Task finished name='Task-215' coro=<BaseHandler.spawn_single_user.<locals>.finish_user_spawn() done, defined at /usr/local/lib/python3.10/dist-packages/jupyterhub/handlers/base.py:981> exception=TimeoutError("Server at http://172.21.0.3:8888/user/donzel/ didn't respond in 30 seconds")> after timeout
    Traceback (most recent call last):
      File "/usr/local/lib/python3.10/dist-packages/tornado/gen.py", line 625, in error_callback
        future.result()
      File "/usr/local/lib/python3.10/dist-packages/jupyterhub/handlers/base.py", line 988, in finish_user_spawn
        await spawn_future
      File "/usr/local/lib/python3.10/dist-packages/jupyterhub/user.py", line 914, in spawn
        await self._wait_up(spawner)
      File "/usr/local/lib/python3.10/dist-packages/jupyterhub/user.py", line 958, in _wait_up
        raise e
      File "/usr/local/lib/python3.10/dist-packages/jupyterhub/user.py", line 928, in _wait_up
        resp = await server.wait_up(
      File "/usr/local/lib/python3.10/dist-packages/jupyterhub/utils.py", line 289, in wait_for_http_server
        re = await exponential_backoff(
      File "/usr/local/lib/python3.10/dist-packages/jupyterhub/utils.py", line 237, in exponential_backoff
        raise asyncio.TimeoutError(fail_message)
    asyncio.exceptions.TimeoutError: Server at http://172.21.0.3:8888/user/donzel/ didn't respond in 30 seconds
    
[I 2023-11-03 14:21:34.936 JupyterHub log:191] 200 GET /hub/api/users/donzel/server/progress?_xsrf=[secret] (donzel@::ffff:178.192.249.242) 38948.41ms
[D 2023-11-03 14:21:40.641 JupyterHub scopes:877] Checking access to /hub/admin via scope admin-ui
[D 2023-11-03 14:21:40.642 JupyterHub scopes:677] Unrestricted access to /hub/admin via admin-ui
[I 2023-11-03 14:21:40.657 JupyterHub log:191] 200 GET /hub/admin (donzel@::ffff:178.192.249.242) 18.00ms
[I 2023-11-03 14:21:40.674 JupyterHub log:191] 302 GET /logo -> /hub/logo (@::ffff:178.192.249.242) 1.37ms
[D 2023-11-03 14:21:40.805 JupyterHub scopes:877] Checking access to /hub/api/users via scope list:users
[D 2023-11-03 14:21:40.805 JupyterHub scopes:677] Unrestricted access to /hub/api/users via list:users
[I 2023-11-03 14:21:40.818 JupyterHub log:191] 200 GET /hub/api/users?include_stopped_servers&offset=0&limit=50&name_filter=&_xsrf=[secret] (donzel@::ffff:178.192.249.242) 15.46ms

Any ideas?

1 Like
2

Do you have logs of the single user server that are failing?

I see from the logs that you posted that JupyterHub is creating the system users. You will have to make sure that those users will have access to docker group to be able to use Docker API. Probably that is why the single user docker containers werent able to start?

3

Also check the docker logs for clues.

4

Thank you both for the hints. After many trials, I didn’t find a solution. The container disappears immediately after it is created, so I can’t inspect its log file. I also have a docker group, and I’m a member of this group. Do you have other possible clues?

5

Try using watch command and redirect the logs to a file. Run watch -n1 docker logs jupyter-donzel >>docker_logs.txt 2>&1 in a terminal and launch a server from the JupyterHub. Hopefully you will be able to capture logs.

1 Like
6

And if that fails, you can also try changing the default Docker logging driver so it goes to a persistent store Configure logging drivers | Docker Docs

1 Like
7

Ahhh, didnt know that we can log to files. Good to know, Cheers!

8

Thank you very much for all the hints. The watch command permits me to spot the reason for the failure:

[FATAL tini (6)] exec start-singleuser.sh failed: Permission denied

I fixed it in the base-notebook docker file, and it works. :grinning:

1 Like