Invocation of post_start_cmd not part of debug output

Question

Invocation of post_start_cmd not part of debug output

1kastner opened this issue 4 years ago · 7 comments

Bug description

I want to use the new post_start_cmd and I am having some troubles with that. I hoped that a simple c.DockerSpawner.debug = True would enable me to see what has gone wrong. However, I don't see any additional helpful output.

Expected behaviour

I set the following post_start_cmd so that scikit-learn databases could be downloaded before the participants arrive and start using the JupyterHub.

c.DockerSpawner.post_start_cmd = "cd /home/jovyan && jupyter nbconvert --execute --to notebook *.ipynb --stdout && touch .success

However, when I check the /home/jovyan directory in the user's Docker container, there is no file called .success. Therefore I conclude that the Jupyter Notebook has not been executed. I would love to see the output of the post_start_cmd somewhere in the Docker logs but I can't.

A peak into https://docker-py.readthedocs.io/en/1.7.1/api/#exec_start shows that the return of that method should be some (potentially insightful?) text. Could this be written to the debug? As well as any other output created by the triggered Docker commands? Or would that level of debug output be too verbose and we would need a second level of verbosity here?

Actual behaviour

The logs remain silent about where my mistake resides. Each of the commands works inside the Docker container once it is started.

How to reproduce

S. a.

Your personal set up

OS: Ubuntu 20.04
JupyterHub: 1.3
dockerspawner: 12.0

Jupyter Notebook Server Docker container logs

...
[I 2021-03-29 14:49:20.625 JupyterHub base:757] User logged in: user_xyp2tko8xi
[I 2021-03-29 14:49:20.628 JupyterHub log:181] 302 POST /hub/login?next= -> /hub/spawn (user_xyp2tko8xi@134.28.143.251) 38.07ms
[I 2021-03-29 14:49:20.714 JupyterHub dockerspawner:941] Container 'jupyter-user-5fxyp2tko8xi' is gone
[I 2021-03-29 14:49:20.779 JupyterHub dockerspawner:1162] Created container jupyter-user-5fxyp2tko8xi (id: ccc98e0) from image exam-scipy-notebook
[I 2021-03-29 14:49:20.779 JupyterHub dockerspawner:1186] Starting container jupyter-user-5fxyp2tko8xi (id: ccc98e0)
[I 2021-03-29 14:49:21.679 JupyterHub log:181] 302 GET /hub/spawn -> /hub/spawn-pending/user_xyp2tko8xi (user_xyp2tko8xi@134.28.143.251) 1011.49ms
[I 2021-03-29 14:49:21.720 JupyterHub pages:402] user_xyp2tko8xi is pending spawn
[I 2021-03-29 14:49:21.722 JupyterHub log:181] 200 GET /hub/spawn-pending/user_xyp2tko8xi (user_xyp2tko8xi@134.28.143.251) 4.79ms
[I 2021-03-29 14:49:22.918 JupyterHub log:181] 200 GET /hub/api (@172.20.0.5) 0.79ms
[I 2021-03-29 14:49:22.950 JupyterHub log:181] 200 POST /hub/api/users/user_xyp2tko8xi/activity (user_xyp2tko8xi@172.20.0.5) 22.77ms
[I 2021-03-29 14:49:23.048 JupyterHub base:904] User user_xyp2tko8xi took 2.370 seconds to start
[I 2021-03-29 14:49:23.049 JupyterHub proxy:257] Adding user user_xyp2tko8xi to proxy /user/user_xyp2tko8xi/ => http://172.20.0.5:8888
14:49:23.051 [ConfigProxy] info: Adding route /user/user_xyp2tko8xi -> http://172.20.0.5:8888
14:49:23.051 [ConfigProxy] info: Route added /user/user_xyp2tko8xi -> http://172.20.0.5:8888
14:49:23.052 [ConfigProxy] info: 201 POST /api/routes/user/user_xyp2tko8xi
[I 2021-03-29 14:49:23.054 JupyterHub users:664] Server user_xyp2tko8xi is ready
[I 2021-03-29 14:49:23.054 JupyterHub log:181] 200 GET /hub/api/users/user_xyp2tko8xi/server/progress (user_xyp2tko8xi@134.28.143.251) 1127.92ms
[I 2021-03-29 14:49:23.104 JupyterHub log:181] 302 GET /hub/spawn-pending/user_xyp2tko8xi -> /user/user_xyp2tko8xi/ (user_xyp2tko8xi@134.28.143.251) 4.73ms
[I 2021-03-29 14:49:23.252 JupyterHub log:181] 302 GET /hub/api/oauth2/authorize?client_id=jupyterhub-user-user_xyp2tko8xi&redirect_uri=%2Fuser%2Fuser_xyp2tko8xi%2Foauth_callback&response_type=code&state=[secret] -> /user/user_xyp2tko8xi/oauth_callback?code=[secret]&state=[secret] (user_xyp2tko8xi@134.28.143.251) 17.76ms
[I 2021-03-29 14:49:23.332 JupyterHub log:181] 200 POST /hub/api/oauth2/token (user_xyp2tko8xi@172.20.0.5) 24.55ms
[I 2021-03-29 14:49:23.348 JupyterHub log:181] 200 GET /hub/api/authorizations/token/[secret] (user_xyp2tko8xi@172.20.0.5) 11.16ms
14:49:58.393 [ConfigProxy] info: 200 GET /api/routes
[I 2021-03-29 14:49:58.401 JupyterHub proxy:319] Checking routes
[I 2021-03-29 14:50:19.707 JupyterHub log:181] 200 POST /hub/api/users/admin/activity (admin@172.20.0.4) 11.28ms
[I 2021-03-29 14:52:49.117 JupyterHub log:181] 200 GET /hub/api/oauth2/authorize?client_id=jupyterhub-user-admin&redirect_uri=%2Fuser%2Fadmin%2Foauth_callback&response_type=code&state=[secret] (user_xyp2tko8xi@134.28.143.251) 21.48ms
[I 2021-03-29 14:52:49.158 JupyterHub log:181] 200 GET /hub/api/oauth2/authorize?client_id=jupyterhub-user-admin&redirect_uri=%2Fuser%2Fadmin%2Foauth_callback&response_type=code&state=[secret] (user_xyp2tko8xi@134.28.143.251) 5.77ms
[I 2021-03-29 14:52:49.648 JupyterHub log:181] 200 GET /hub/api/oauth2/authorize?client_id=jupyterhub-user-admin&redirect_uri=%2Fuser%2Fadmin%2Foauth_callback&response_type=code&state=[secret] (user_xyp2tko8xi@134.28.143.251) 6.45ms
[I 2021-03-29 14:52:49.694 JupyterHub log:181] 200 GET /hub/api/oauth2/authorize?client_id=jupyterhub-user-admin&redirect_uri=%2Fuser%2Fadmin%2Foauth_callback&response_type=code&state=[secret] (user_xyp2tko8xi@134.28.143.251) 11.64ms
...

The JupyterHub Docker container logs

[D 2021-03-29 14:45:18.683 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 14:45:18.684 SingleUserNotebookApp log:181] 304 GET /user/admin/custom/custom.js?v=20210329144509 (admin@134.28.143.251) 1.68ms
[D 2021-03-29 14:45:18.729 SingleUserNotebookApp auth:874] Allowing Hub user admin
[I 2021-03-29 14:45:18.730 SingleUserNotebookApp log:181] 101 GET /user/admin/terminals/websocket/1 (admin@134.28.143.251) 1.58ms
[D 2021-03-29 14:45:18.731 SingleUserNotebookApp zmqhandlers:154] Opening websocket /user/admin/terminals/websocket/1
TermSocket.open: 1
TermSocket.open: Opened 1
Websocket closed
[D 2021-03-29 14:49:00.515 SingleUserNotebookApp auth:874] Allowing Hub user admin
[I 2021-03-29 14:49:00.517 SingleUserNotebookApp log:181] 302 GET /user/admin/logout -> /hub/logout (admin@134.28.143.251) 2.96ms
[D 2021-03-29 14:50:19.691 SingleUserNotebookApp mixins:499] Notifying Hub of activity 2021-03-29T14:48:58.680381Z
[D 2021-03-29 14:52:49.018 SingleUserNotebookApp auth:504] No user identified
[D 2021-03-29 14:52:49.021 SingleUserNotebookApp auth:835] Redirecting to login url: /hub/api/oauth2/authorize?client_id=jupyterhub-user-admin&redirect_uri=%2Fuser%2Fadmin%2Foauth_callback&response_type=code&state=eyJ1dWlkIjogImQwMzkxYjU2NTE0ZDRiYmI4ZWY2MmE1ZTNmODNiOTM4IiwgIm5leHRfdXJsIjogIi91c2VyL2FkbWluL2FwaS9zZXNzaW9ucz9fPTE2MTcwMjkxMTIzNzUifQ
[I 2021-03-29 14:52:49.022 SingleUserNotebookApp log:181] 302 GET /user/admin/api/sessions?_=1617029112375 -> /hub/api/oauth2/authorize?client_id=jupyterhub-user-admin&redirect_uri=%2Fuser%2Fadmin%2Foauth_callback&response_type=code&state=[secret] (@134.28.143.251) 4.82ms
[D 2021-03-29 14:52:49.057 SingleUserNotebookApp auth:504] No user identified
[D 2021-03-29 14:52:49.058 SingleUserNotebookApp auth:835] Redirecting to login url: /hub/api/oauth2/authorize?client_id=jupyterhub-user-admin&redirect_uri=%2Fuser%2Fadmin%2Foauth_callback&response_type=code&state=eyJ1dWlkIjogImFiY2JjYzliZWM2NzQ0NWE4ZDk4OTQ5NThiZTExYjk0IiwgIm5leHRfdXJsIjogIi91c2VyL2FkbWluL2FwaS90ZXJtaW5hbHM_Xz0xNjE3MDI5MTEyMzc2In0
[I 2021-03-29 14:52:49.059 SingleUserNotebookApp log:181] 302 GET /user/admin/api/terminals?_=1617029112376 -> /hub/api/oauth2/authorize?client_id=jupyterhub-user-admin&redirect_uri=%2Fuser%2Fadmin%2Foauth_callback&response_type=code&state=[secret] (@134.28.143.251) 2.23ms
[D 2021-03-29 14:52:49.570 SingleUserNotebookApp auth:504] No user identified
[W 2021-03-29 14:52:49.570 SingleUserNotebookApp auth:682] Detected unused OAuth state cookies
[D 2021-03-29 14:52:49.571 SingleUserNotebookApp auth:835] Redirecting to login url: /hub/api/oauth2/authorize?client_id=jupyterhub-user-admin&redirect_uri=%2Fuser%2Fadmin%2Foauth_callback&response_type=code&state=eyJ1dWlkIjogImMwMzNhOGFlYmUwODQxOTA5ODgyODQ5NzE5MDJlZjlmIiwgIm5leHRfdXJsIjogIi91c2VyL2FkbWluL2FwaS9zZXNzaW9ucz9fPTE2MTcwMjgyNDIyMTMiLCAiY29va2llX25hbWUiOiAianVweXRlcmh1Yi11c2VyLWFkbWluLW9hdXRoLXN0YXRlLXRyQktERFFzIn0
[I 2021-03-29 14:52:49.571 SingleUserNotebookApp log:181] 302 GET /user/admin/api/sessions?_=1617028242213 -> /hub/api/oauth2/authorize?client_id=jupyterhub-user-admin&redirect_uri=%2Fuser%2Fadmin%2Foauth_callback&response_type=code&state=[secret] (@134.28.143.251) 1.90ms
[D 2021-03-29 14:52:49.606 SingleUserNotebookApp auth:504] No user identified
[W 2021-03-29 14:52:49.607 SingleUserNotebookApp auth:682] Detected unused OAuth state cookies
[D 2021-03-29 14:52:49.607 SingleUserNotebookApp auth:835] Redirecting to login url: /hub/api/oauth2/authorize?client_id=jupyterhub-user-admin&redirect_uri=%2Fuser%2Fadmin%2Foauth_callback&response_type=code&state=eyJ1dWlkIjogImExYzYwNzhmNjAxZjQzYmFhNTdhMDJmY2YxYzUwNDQ3IiwgIm5leHRfdXJsIjogIi91c2VyL2FkbWluL2FwaS90ZXJtaW5hbHM_Xz0xNjE3MDI4MjQyMjE0IiwgImNvb2tpZV9uYW1lIjogImp1cHl0ZXJodWItdXNlci1hZG1pbi1vYXV0aC1zdGF0ZS1EUndRWXRwbiJ9
[I 2021-03-29 14:52:49.608 SingleUserNotebookApp log:181] 302 GET /user/admin/api/terminals?_=1617028242214 -> /hub/api/oauth2/authorize?client_id=jupyterhub-user-admin&redirect_uri=%2Fuser%2Fadmin%2Foauth_callback&response_type=code&state=[secret] (@134.28.143.251) 2.22ms
[D 2021-03-29 14:54:56.186 SingleUserNotebookApp mixins:499] Notifying Hub of activity 2021-03-29T14:48:58.680381Z
[D 2021-03-29 14:57:52.023 SingleUserNotebookApp auth:504] No user identified
[W 2021-03-29 14:57:52.023 SingleUserNotebookApp auth:682] Detected unused OAuth state cookies
[D 2021-03-29 14:57:52.024 SingleUserNotebookApp auth:835] Redirecting to login url: /hub/api/oauth2/authorize?client_id=jupyterhub-user-admin&redirect_uri=%2Fuser%2Fadmin%2Foauth_callback&response_type=code&state=eyJ1dWlkIjogIjRkMTI4ZTY3MmFjYzQzY2I5N2Q3NzhmMzI1NGI5YjYyIiwgIm5leHRfdXJsIjogIi91c2VyL2FkbWluL2FwaS9zZXNzaW9ucz9fPTE2MTcwMjgyNDIyMTUiLCAiY29va2llX25hbWUiOiAianVweXRlcmh1Yi11c2VyLWFkbWluLW9hdXRoLXN0YXRlLUtydVhBRWZkIn0

Answer 1 · 2021-03-29T15:58:41.000Z

If it's not already working then I think logging the output of running post_start_cmd as DEBUG or INFO should be added (I'm surprised it's not already).

For your particular problem I suspect the problem might be you've entered a shell statement that needs to be intepreted by a shell instead of a command. Quick workaround might be to wrap it in sh -c '...'? That's just a guess though.

Answer 2 · 2021-03-29T18:19:39.000Z

Thank you very much, @manics ! Your hint with sh -c '...' solved it for me!

However, here are the logs that I would expect to contain some indication:

Executing the command: jupyterhub-singleuser --ip=0.0.0.0 --port=8888 --notebook-dir=/home/jovyan/ --debug
[D 2021-03-29 18:04:47.312 SingleUserNotebookApp migrate:83] No files in /home/jovyan/.ipython/nbextensions
[D 2021-03-29 18:04:47.312 SingleUserNotebookApp application:164] Searching ['/home/jovyan', '/home/jovyan/.jupyter', '/opt/conda/etc/jupyter', '/usr/local/etc/jupyter', '/etc/jupyter'] for config files
[D 2021-03-29 18:04:47.312 SingleUserNotebookApp application:730] Looking for jupyter_config in /etc/jupyter
[D 2021-03-29 18:04:47.313 SingleUserNotebookApp application:730] Looking for jupyter_config in /usr/local/etc/jupyter
[D 2021-03-29 18:04:47.313 SingleUserNotebookApp application:730] Looking for jupyter_config in /opt/conda/etc/jupyter
[D 2021-03-29 18:04:47.313 SingleUserNotebookApp application:730] Looking for jupyter_config in /home/jovyan/.jupyter
[D 2021-03-29 18:04:47.313 SingleUserNotebookApp application:730] Looking for jupyter_config in /home/jovyan
[D 2021-03-29 18:04:47.314 SingleUserNotebookApp application:730] Looking for jupyter_notebook_config in /etc/jupyter
[D 2021-03-29 18:04:47.314 SingleUserNotebookApp application:752] Loaded config file: /etc/jupyter/jupyter_notebook_config.py
[D 2021-03-29 18:04:47.315 SingleUserNotebookApp application:730] Looking for jupyter_notebook_config in /usr/local/etc/jupyter
[D 2021-03-29 18:04:47.315 SingleUserNotebookApp application:730] Looking for jupyter_notebook_config in /opt/conda/etc/jupyter
[D 2021-03-29 18:04:47.315 SingleUserNotebookApp application:730] Looking for jupyter_notebook_config in /home/jovyan/.jupyter
[D 2021-03-29 18:04:47.315 SingleUserNotebookApp application:752] Loaded config file: /home/jovyan/.jupyter/jupyter_notebook_config.py
[D 2021-03-29 18:04:47.316 SingleUserNotebookApp application:730] Looking for jupyter_notebook_config in /home/jovyan
[W 2021-03-29 18:04:47.318 SingleUserNotebookApp configurable:190] Config option `open_browser` not recognized by `SingleUserNotebookApp`.  Did you mean `browser`?
[D 2021-03-29 18:04:47.323 SingleUserNotebookApp config_manager:96] Paths used for configuration of jupyter_notebook_config:
        /etc/jupyter/jupyter_notebook_config.json
[D 2021-03-29 18:04:47.323 SingleUserNotebookApp config_manager:96] Paths used for configuration of jupyter_notebook_config:
        /usr/local/etc/jupyter/jupyter_notebook_config.json
[D 2021-03-29 18:04:47.323 SingleUserNotebookApp config_manager:96] Paths used for configuration of jupyter_notebook_config:
        /opt/conda/etc/jupyter/jupyter_notebook_config.d/jupyterlab.json
        /opt/conda/etc/jupyter/jupyter_notebook_config.json
[D 2021-03-29 18:04:47.324 SingleUserNotebookApp config_manager:96] Paths used for configuration of jupyter_notebook_config:
        /home/jovyan/.jupyter/jupyter_notebook_config.json
[I 2021-03-29 18:04:48.121 SingleUserNotebookApp extension:162] JupyterLab extension loaded from /opt/conda/lib/python3.8/site-packages/jupyterlab
[I 2021-03-29 18:04:48.122 SingleUserNotebookApp extension:163] JupyterLab application directory is /opt/conda/share/jupyter/lab
[I 2021-03-29 18:04:48.129 SingleUserNotebookApp mixins:557] Starting jupyterhub-singleuser server version 1.3.0
[D 2021-03-29 18:04:48.134 SingleUserNotebookApp _version:76] jupyterhub and jupyterhub-singleuser both on version 1.3.0
[I 2021-03-29 18:04:48.134 SingleUserNotebookApp notebookapp:2257] Serving notebooks from local directory: /home/jovyan
[I 2021-03-29 18:04:48.135 SingleUserNotebookApp notebookapp:2257] Jupyter Notebook 6.2.0 is running at:
[I 2021-03-29 18:04:48.135 SingleUserNotebookApp notebookapp:2257] http://517ca5251c67:8888/user/admin/
[I 2021-03-29 18:04:48.135 SingleUserNotebookApp notebookapp:2258] Use Control-C to stop this server and shut down all kernels (twice to skip confirmation).
[I 2021-03-29 18:04:48.140 SingleUserNotebookApp mixins:537] Updating Hub with activity every 300 seconds
[D 2021-03-29 18:04:48.141 SingleUserNotebookApp mixins:499] Notifying Hub of activity 2021-03-29T18:04:47.373831Z
[I 2021-03-29 18:04:55.850 SingleUserNotebookApp log:181] 302 GET /user/admin/ -> /user/admin/tree? (@172.18.0.2) 0.83ms
[I 2021-03-29 18:04:56.008 SingleUserNotebookApp log:181] 302 GET /user/admin/ -> /user/admin/tree? (@134.28.143.251) 1.01ms
[D 2021-03-29 18:04:56.073 SingleUserNotebookApp auth:504] No user identified
[D 2021-03-29 18:04:56.075 SingleUserNotebookApp auth:835] Redirecting to login url: /hub/api/oauth2/authorize?client_id=jupyterhub-user-admin&redirect_uri=%2Fuser%2Fadmin%2Foauth_callback&response_type=code&state=eyJ1dWlkIjogImJjODI5MGU4NjU3ZjQ0YzM5NmQxZmMyZDU2Mjg2NWQxIiwgIm5leHRfdXJsIjogIi91c2VyL2FkbWluL3RyZWU_In0
[I 2021-03-29 18:04:56.076 SingleUserNotebookApp log:181] 302 GET /user/admin/tree? -> /hub/api/oauth2/authorize?client_id=jupyterhub-user-admin&redirect_uri=%2Fuser%2Fadmin%2Foauth_callback&response_type=code&state=[secret] (@134.28.143.251) 3.57ms
[D 2021-03-29 18:04:56.216 SingleUserNotebookApp auth:504] No user identified
[D 2021-03-29 18:04:56.248 SingleUserNotebookApp auth:309] HubAuth cache miss: token:6f606b50024c43cfabb681d178326002:wqNFhCxotLVjrz7ZzT3z4ci8gdRR6w
[D 2021-03-29 18:04:56.267 SingleUserNotebookApp auth:315] Received request from Hub user {'kind': 'user', 'name': 'admin', 'admin': True, 'groups': [], 'server': '/user/admin/', 'pending': None, 'created': '2021-03-29T17:58:16.215339Z', 'last_activity': '2021-03-29T18:04:56.261465Z', 'servers': None}
[I 2021-03-29 18:04:56.267 SingleUserNotebookApp auth:983] Logged-in user {'kind': 'user', 'name': 'admin', 'admin': True, 'groups': [], 'server': '/user/admin/', 'pending': None, 'created': '2021-03-29T17:58:16.215339Z', 'last_activity': '2021-03-29T18:04:56.261465Z', 'servers': None}
[D 2021-03-29 18:04:56.268 SingleUserNotebookApp auth:743] Setting oauth cookie for 134.28.143.251: jupyterhub-user-admin, {'path': '/user/admin/', 'httponly': True}
[I 2021-03-29 18:04:56.269 SingleUserNotebookApp log:181] 302 GET /user/admin/oauth_callback?code=[secret]&state=[secret] -> /user/admin/tree? (@134.28.143.251) 53.38ms
[D 2021-03-29 18:04:56.348 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 18:04:56.349 SingleUserNotebookApp handlers:251] Using contents: services/contents
[D 2021-03-29 18:04:56.398 SingleUserNotebookApp handlers:836] Path base/images/favicon.ico served from /opt/conda/lib/python3.8/site-packages/notebook/static/base/images/favicon.ico
[D 2021-03-29 18:04:56.398 SingleUserNotebookApp handlers:836] Path components/jquery-ui/themes/smoothness/jquery-ui.min.css served from /opt/conda/lib/python3.8/site-packages/notebook/static/components/jquery-ui/themes/smoothness/jquery-ui.min.css
[D 2021-03-29 18:04:56.398 SingleUserNotebookApp handlers:836] Path components/jquery-typeahead/dist/jquery.typeahead.min.css served from /opt/conda/lib/python3.8/site-packages/notebook/static/components/jquery-typeahead/dist/jquery.typeahead.min.css
[D 2021-03-29 18:04:56.399 SingleUserNotebookApp handlers:836] Path style/style.min.css served from /opt/conda/lib/python3.8/site-packages/notebook/static/style/style.min.css
[D 2021-03-29 18:04:56.400 SingleUserNotebookApp handlers:836] Path components/es6-promise/promise.min.js served from /opt/conda/lib/python3.8/site-packages/notebook/static/components/es6-promise/promise.min.js
[D 2021-03-29 18:04:56.400 SingleUserNotebookApp handlers:836] Path components/react/react.production.min.js served from /opt/conda/lib/python3.8/site-packages/notebook/static/components/react/react.production.min.js
[D 2021-03-29 18:04:56.400 SingleUserNotebookApp handlers:836] Path components/react/react-dom.production.min.js served from /opt/conda/lib/python3.8/site-packages/notebook/static/components/react/react-dom.production.min.js
[D 2021-03-29 18:04:56.401 SingleUserNotebookApp handlers:836] Path components/create-react-class/index.js served from /opt/conda/lib/python3.8/site-packages/notebook/static/components/create-react-class/index.js
[D 2021-03-29 18:04:56.401 SingleUserNotebookApp handlers:836] Path components/requirejs/require.js served from /opt/conda/lib/python3.8/site-packages/notebook/static/components/requirejs/require.js
[D 2021-03-29 18:04:56.402 SingleUserNotebookApp handlers:836] Path tree/js/main.min.js served from /opt/conda/lib/python3.8/site-packages/notebook/static/tree/js/main.min.js
[I 2021-03-29 18:04:56.406 SingleUserNotebookApp log:181] 200 GET /user/admin/tree? (admin@134.28.143.251) 58.61ms
[D 2021-03-29 18:04:56.550 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 18:04:56.552 SingleUserNotebookApp log:181] 304 GET /user/admin/static/components/es6-promise/promise.min.js?v=bea335d74136a63ae1b5130f5ac9a50c6256a5f435e6e09fef599491a84d834a8b0f011ca3eaaca3b4ab6a2da2d3e1191567a2f171e60da1d10e5b9d52f84184 (admin@134.28.143.251) 2.17ms
[D 2021-03-29 18:04:56.631 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 18:04:56.633 SingleUserNotebookApp log:181] 304 GET /user/admin/static/components/requirejs/require.js?v=d37b48bb2137faa0ab98157e240c084dd5b1b5e74911723aa1d1f04c928c2a03dedf922d049e4815f7e5a369faa2e6b6a1000aae958b7953b5cc60411154f593 (admin@134.28.143.251) 3.28ms
[D 2021-03-29 18:04:56.634 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 18:04:56.635 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 18:04:56.636 SingleUserNotebookApp log:181] 304 GET /user/admin/static/components/react/react.production.min.js?v=9a0aaf84a316c8bedd6c2ff7d5b5e0a13f8f84ec02442346cba0b842c6c81a6bf6176e64f3675c2ebf357cb5bb048e0b527bd39377c95681d22468da3d5de735 (admin@134.28.143.251) 2.26ms
[D 2021-03-29 18:04:56.637 SingleUserNotebookApp handlers:836] Path custom.css served from /opt/conda/lib/python3.8/site-packages/notebook/static/custom/custom.css
[D 2021-03-29 18:04:56.637 SingleUserNotebookApp log:181] 304 GET /user/admin/custom/custom.css (admin@134.28.143.251) 2.30ms
[D 2021-03-29 18:04:56.638 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 18:04:56.639 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 18:04:56.639 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 18:04:56.640 SingleUserNotebookApp log:181] 304 GET /user/admin/static/tree/js/main.min.js?v=8f7e7406ab7351ee411d39e25476fcfa4abff362e3bd52e62bd12feebff7f0157fa859d3dad0a918d55983cf2c54918da245aa8465cad3ff0f7bd1d5a9fad127 (admin@134.28.143.251) 2.97ms
[D 2021-03-29 18:04:56.641 SingleUserNotebookApp log:181] 304 GET /user/admin/static/components/react/react-dom.production.min.js?v=6fc58c1c4736868ff84f57bd8b85f2bdb985993a9392718f3b4af4bfa10fb4efba2b4ddd68644bd2a8daf0619a3844944c9c43f8528364a1aa6fc01ec1b8ae84 (admin@134.28.143.251) 2.92ms
[D 2021-03-29 18:04:56.642 SingleUserNotebookApp log:181] 304 GET /user/admin/static/components/create-react-class/index.js?v=894ad57246e682b4cfbe7cd5e408dcd6b38d06af4de4f3425991e2676fdc2ef1732cbd19903104198878ae77de12a1996de3e7da3a467fb226bdda8f4618faec (admin@134.28.143.251) 2.67ms
[D 2021-03-29 18:04:56.759 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 18:04:56.759 SingleUserNotebookApp handlers:836] Path services/contents.js served from /opt/conda/lib/python3.8/site-packages/notebook/static/services/contents.js
[D 2021-03-29 18:04:56.760 SingleUserNotebookApp log:181] 200 GET /user/admin/static/services/contents.js?v=20210329180447 (admin@134.28.143.251) 2.11ms
[D 2021-03-29 18:04:56.844 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 18:04:56.845 SingleUserNotebookApp config_manager:96] Paths used for configuration of tree:
        /etc/jupyter/nbconfig/tree.json
[D 2021-03-29 18:04:56.846 SingleUserNotebookApp config_manager:96] Paths used for configuration of tree:
        /usr/local/etc/jupyter/nbconfig/tree.json
[D 2021-03-29 18:04:56.846 SingleUserNotebookApp config_manager:96] Paths used for configuration of tree:
        /opt/conda/etc/jupyter/nbconfig/tree.json
[D 2021-03-29 18:04:56.847 SingleUserNotebookApp config_manager:96] Paths used for configuration of tree:
        /home/jovyan/.jupyter/nbconfig/tree.json
[I 2021-03-29 18:04:56.848 SingleUserNotebookApp log:181] 200 GET /user/admin/api/config/tree?_=1617041096514 (admin@134.28.143.251) 4.27ms
[D 2021-03-29 18:04:56.893 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 18:04:56.895 SingleUserNotebookApp config_manager:96] Paths used for configuration of common:
        /etc/jupyter/nbconfig/common.json
[D 2021-03-29 18:04:56.897 SingleUserNotebookApp config_manager:96] Paths used for configuration of common:
        /usr/local/etc/jupyter/nbconfig/common.json
[D 2021-03-29 18:04:56.898 SingleUserNotebookApp config_manager:96] Paths used for configuration of common:
        /opt/conda/etc/jupyter/nbconfig/common.json
[D 2021-03-29 18:04:56.899 SingleUserNotebookApp config_manager:96] Paths used for configuration of common:
        /home/jovyan/.jupyter/nbconfig/common.json
[I 2021-03-29 18:04:56.900 SingleUserNotebookApp log:181] 200 GET /user/admin/api/config/common?_=1617041096515 (admin@134.28.143.251) 7.84ms
[D 2021-03-29 18:04:56.901 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 18:04:56.902 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 18:04:56.903 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 18:04:56.904 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 18:04:56.904 SingleUserNotebookApp auth:874] Allowing Hub user admin
[I 2021-03-29 18:04:56.905 SingleUserNotebookApp log:181] 200 GET /user/admin/api/terminals?_=1617041096516 (admin@134.28.143.251) 4.80ms
[I 2021-03-29 18:04:56.906 SingleUserNotebookApp log:181] 200 GET /user/admin/api/terminals?_=1617041096518 (admin@134.28.143.251) 4.54ms
[D 2021-03-29 18:04:56.906 SingleUserNotebookApp handlers:836] Path custom.js served from /opt/conda/lib/python3.8/site-packages/notebook/static/custom/custom.js
[D 2021-03-29 18:04:56.907 SingleUserNotebookApp log:181] 200 GET /user/admin/custom/custom.js?v=20210329180447 (admin@134.28.143.251) 4.68ms
[I 2021-03-29 18:04:56.908 SingleUserNotebookApp log:181] 200 GET /user/admin/api/sessions?_=1617041096517 (admin@134.28.143.251) 5.28ms
[D 2021-03-29 18:04:56.909 SingleUserNotebookApp kernelspec:168] Found kernel python3 in /opt/conda/share/jupyter/kernels
[D 2021-03-29 18:04:56.912 SingleUserNotebookApp log:181] 304 GET /user/admin/api/kernelspecs (admin@134.28.143.251) 7.82ms
[D 2021-03-29 18:04:56.996 SingleUserNotebookApp auth:874] Allowing Hub user admin
[I 2021-03-29 18:04:56.998 SingleUserNotebookApp log:181] 200 GET /user/admin/api/contents?type=directory&_=1617041096519 (admin@134.28.143.251) 3.42ms
[D 2021-03-29 18:04:59.515 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 18:04:59.517 SingleUserNotebookApp handlers:251] Using contents: services/contents
[I 2021-03-29 18:04:59.520 SingleUserNotebookApp log:181] 200 GET /user/admin/view/index.html (admin@134.28.143.251) 5.93ms
[D 2021-03-29 18:04:59.591 SingleUserNotebookApp auth:874] Allowing Hub user admin
[D 2021-03-29 18:04:59.594 SingleUserNotebookApp log:181] 200 GET /user/admin/files/index.html (admin@134.28.143.251) 3.66ms
[D 2021-03-29 18:05:07.382 SingleUserNotebookApp auth:874] Allowing Hub user admin
[I 2021-03-29 18:05:07.383 SingleUserNotebookApp log:181] 200 GET /user/admin/api/sessions?_=1617041096520 (admin@134.28.143.251) 1.43ms
[D 2021-03-29 18:05:07.417 SingleUserNotebookApp auth:874] Allowing Hub user admin
[I 2021-03-29 18:05:07.418 SingleUserNotebookApp log:181] 200 GET /user/admin/api/terminals?_=1617041096521 (admin@134.28.143.251) 2.41ms
[D 2021-03-29 18:05:07.457 SingleUserNotebookApp auth:874] Allowing Hub user admin
[I 2021-03-29 18:05:07.459 SingleUserNotebookApp log:181] 200 GET /user/admin/api/contents?type=directory&_=1617041096522 (admin@134.28.143.251) 2.96ms
[D 2021-03-29 18:05:11.847 SingleUserNotebookApp auth:874] Allowing Hub user admin
[I 2021-03-29 18:05:11.848 SingleUserNotebookApp log:181] 200 GET /user/admin/api/sessions?_=1617041075646 (admin@134.28.143.251) 1.60ms
[D 2021-03-29 18:05:11.885 SingleUserNotebookApp auth:874] Allowing Hub user admin
[I 2021-03-29 18:05:11.886 SingleUserNotebookApp log:181] 200 GET /user/admin/api/terminals?_=1617041075647 (admin@134.28.143.251) 2.09ms
[D 2021-03-29 18:05:11.920 SingleUserNotebookApp auth:874] Allowing Hub user admin
[I 2021-03-29 18:05:11.922 SingleUserNotebookApp log:181] 200 GET /user/admin/api/contents?type=directory&_=1617041075648 (admin@134.28.143.251) 3.31ms
[D 2021-03-29 18:05:13.287 SingleUserNotebookApp auth:874] Allowing Hub user admin
[I 2021-03-29 18:05:13.288 SingleUserNotebookApp log:181] 200 GET /user/admin/api/sessions?_=1617040910970 (admin@134.28.143.251) 1.41ms
[D 2021-03-29 18:05:13.323 SingleUserNotebookApp auth:874] Allowing Hub user admin
[I 2021-03-29 18:05:13.324 SingleUserNotebookApp log:181] 200 GET /user/admin/api/terminals?_=1617040910971 (admin@134.28.143.251) 1.50ms
[D 2021-03-29 18:05:13.384 SingleUserNotebookApp auth:874] Allowing Hub user admin
[I 2021-03-29 18:05:13.387 SingleUserNotebookApp log:181] 200 GET /user/admin/api/contents?type=directory&_=1617040910972 (admin@134.28.143.251) 2.86ms

and

[I 2021-03-29 18:04:35.380 JupyterHub base:757] User logged in: admin
[I 2021-03-29 18:04:35.381 JupyterHub log:181] 302 POST /hub/login?next= -> /user/admin/ (admin@134.28.143.251) 23.83ms
[I 2021-03-29 18:04:35.545 JupyterHub log:181] 302 GET /hub/api/oauth2/authorize?client_id=jupyterhub-user-admin&redirect_uri=%2Fuser%2Fadmin%2Foauth_callback&response_type=code&state=[secret] -> /user/admin/oauth_callback?code=[secret]&state=[secret] (admin@134.28.143.251) 20.51ms
[I 2021-03-29 18:04:35.623 JupyterHub log:181] 200 POST /hub/api/oauth2/token (admin@172.18.0.4) 28.94ms
[I 2021-03-29 18:04:35.638 JupyterHub log:181] 200 GET /hub/api/authorizations/token/[secret] (admin@172.18.0.4) 10.61ms
[I 2021-03-29 18:04:42.574 JupyterHub log:181] 200 GET /hub/home (admin@134.28.143.251) 33.48ms
[I 2021-03-29 18:04:44.094 JupyterHub proxy:281] Removing user admin from proxy (/user/admin/)
18:04:44.096 [ConfigProxy] info: Removing route /user/admin
18:04:44.097 [ConfigProxy] info: 204 DELETE /api/routes/user/admin
[I 2021-03-29 18:04:44.102 JupyterHub dockerspawner:1280] Stopping container jupyter-admin (id: faf45d1)
18:04:44.727 [ConfigProxy] error: 503 GET /user/admin/terminals/websocket/1 read ECONNRESET
[I 2021-03-29 18:04:44.731 JupyterHub log:181] 200 GET /hub/error/503?url=%2Fuser%2Fadmin%2Fterminals%2Fwebsocket%2F1 (@172.18.0.2) 1.56ms
[I 2021-03-29 18:04:45.067 JupyterHub dockerspawner:971] Removing container faf45d1ac9fd35f8642453fc0d5f5b3a8352297484e923b13fe5730795d7ce2d
[I 2021-03-29 18:04:45.097 JupyterHub base:1110] User admin server took 1.003 seconds to stop
[I 2021-03-29 18:04:45.098 JupyterHub log:181] 204 DELETE /hub/api/users/admin/server (admin@134.28.143.251) 1013.79ms
[I 2021-03-29 18:04:46.141 JupyterHub dockerspawner:941] Container 'jupyter-admin' is gone
[I 2021-03-29 18:04:46.189 JupyterHub dockerspawner:1162] Created container jupyter-admin (id: 517ca52) from image exam-scipy-notebook
[I 2021-03-29 18:04:46.189 JupyterHub dockerspawner:1186] Starting container jupyter-admin (id: 517ca52)
[I 2021-03-29 18:04:47.112 JupyterHub log:181] 302 GET /hub/spawn/admin -> /hub/spawn-pending/admin (admin@134.28.143.251) 1007.53ms
[I 2021-03-29 18:04:47.160 JupyterHub pages:402] admin is pending spawn
[I 2021-03-29 18:04:47.161 JupyterHub log:181] 200 GET /hub/spawn-pending/admin (admin@134.28.143.251) 4.72ms
[I 2021-03-29 18:04:48.134 JupyterHub log:181] 200 GET /hub/api (@172.18.0.4) 0.77ms
[I 2021-03-29 18:04:48.166 JupyterHub log:181] 200 POST /hub/api/users/admin/activity (admin@172.18.0.4) 22.55ms
[I 2021-03-29 18:04:55.851 JupyterHub base:904] User admin took 9.741 seconds to start
[I 2021-03-29 18:04:55.851 JupyterHub proxy:257] Adding user admin to proxy /user/admin/ => http://172.18.0.4:8888
18:04:55.853 [ConfigProxy] info: Adding route /user/admin -> http://172.18.0.4:8888
18:04:55.853 [ConfigProxy] info: Route added /user/admin -> http://172.18.0.4:8888
18:04:55.854 [ConfigProxy] info: 201 POST /api/routes/user/admin
[I 2021-03-29 18:04:55.854 JupyterHub users:664] Server admin is ready
[I 2021-03-29 18:04:55.855 JupyterHub log:181] 200 GET /hub/api/users/admin/server/progress (admin@134.28.143.251) 8569.22ms
[I 2021-03-29 18:04:55.947 JupyterHub log:181] 302 GET /hub/spawn-pending/admin -> /user/admin/ (admin@134.28.143.251) 5.75ms
[I 2021-03-29 18:04:56.164 JupyterHub log:181] 302 GET /hub/api/oauth2/authorize?client_id=jupyterhub-user-admin&redirect_uri=%2Fuser%2Fadmin%2Foauth_callback&response_type=code&state=[secret] -> /user/admin/oauth_callback?code=[secret]&state=[secret] (admin@134.28.143.251) 23.02ms
[I 2021-03-29 18:04:56.246 JupyterHub log:181] 200 POST /hub/api/oauth2/token (admin@172.18.0.4) 20.45ms
[I 2021-03-29 18:04:56.266 JupyterHub log:181] 200 GET /hub/api/authorizations/token/[secret] (admin@172.18.0.4) 12.94ms
[I 2021-03-29 18:04:59.642 JupyterHub log:181] 302 GET /images/branding/googlelogo/1x/googlelogo_white_background_color_272x92dp.png -> /hub/images/branding/googlelogo/1x/googlelogo_white_background_color_272x92dp.png (@134.28.143.251) 0.75ms
[I 2021-03-29 18:04:59.681 JupyterHub log:181] 302 GET /xjs/_/js/k=xjs.hp.en.BxHjRa3OgwA.O/m=sb_he,d/am=AHiCOA/d=1/rs=ACT90oGILtRA5FPgbkaLQWCKM5XqMdmRQw -> /hub/xjs/_/js/k=xjs.hp.en.BxHjRa3OgwA.O/m=sb_he,d/am=AHiCOA/d=1/rs=ACT90oGILtRA5FPgbkaLQWCKM5XqMdmRQw (@134.28.143.251) 1.73ms
[I 2021-03-29 18:04:59.682 JupyterHub log:181] 302 GET /images/nav_logo229.png -> /hub/images/nav_logo229.png (@134.28.143.251) 1.87ms
[I 2021-03-29 18:04:59.683 JupyterHub log:181] 302 GET /client_204?&atyp=i&biw=1536&bih=750&ei=whZiYJW2IuGCi-gP_aO54Aw -> /hub/client_204?&atyp=i&biw=1536&bih=750&ei=whZiYJW2IuGCi-gP_aO54Aw (@134.28.143.251) 2.12ms
[W 2021-03-29 18:04:59.744 JupyterHub log:181] 404 GET /hub/images/branding/googlelogo/1x/googlelogo_white_background_color_272x92dp.png (admin@134.28.143.251) 29.72ms
[W 2021-03-29 18:04:59.790 JupyterHub log:181] 404 GET /hub/images/nav_logo229.png (admin@134.28.143.251) 7.68ms
[W 2021-03-29 18:04:59.792 JupyterHub log:181] 404 GET /hub/xjs/_/js/k=xjs.hp.en.BxHjRa3OgwA.O/m=sb_he,d/am=AHiCOA/d=1/rs=ACT90oGILtRA5FPgbkaLQWCKM5XqMdmRQw (admin@134.28.143.251) 9.00ms
[W 2021-03-29 18:04:59.795 JupyterHub log:181] 404 GET /hub/client_204?&atyp=i&biw=1536&bih=750&ei=whZiYJW2IuGCi-gP_aO54Aw (admin@134.28.143.251) 10.07ms
[I 2021-03-29 18:04:59.849 JupyterHub log:181] 302 GET /images/nav_logo229.png -> /hub/images/nav_logo229.png (@134.28.143.251) 1.27ms
[W 2021-03-29 18:04:59.897 JupyterHub log:181] 404 GET /hub/images/nav_logo229.png (admin@134.28.143.251) 6.03ms
[I 2021-03-29 18:07:07.123 JupyterHub log:181] 302 GET / -> /hub/ (@134.28.206.130) 1.89ms
[I 2021-03-29 18:07:07.127 JupyterHub log:181] 302 GET /hub/ -> /hub/login?next=%2Fhub%2F (@134.28.206.130) 1.40ms
[I 2021-03-29 18:07:07.136 JupyterHub log:181] 200 GET /hub/login?next=%2Fhub%2F (@134.28.206.130) 3.04ms
18:08:17.204 [ConfigProxy] info: 200 GET /api/routes
[I 2021-03-29 18:08:17.213 JupyterHub proxy:319] Checking routes

Now you might guess that in one cell of a Jupyter Notebook I added a !wget https://google.com, saved it and restarted my Jupyter Notebook server. But you can't read it from the logs. However, my expections would be that c.DockerSpawner.debug = True would provide me with exactly that information.

I am not sure how much should be logged from the Docker client in general. If in my case all stdout and stderr had been dumped to DEBUG, that would have been a great help! So DEBUG would be my first suggestion. If one decides to do the logging at the Docker client, I guess it should be placed somewhere close to https://github.com/jupyterhub/dockerspawner/blob/master/dockerspawner/dockerspawner.py#L903. But most of the times things work fine and it could create a lot of noise. Therefore, maybe a use-case specific handling at https://github.com/jupyterhub/dockerspawner/blob/master/dockerspawner/dockerspawner.py#L745 could be more straight-forward.

Answer 3 · 2021-04-30T09:17:32.000Z

Can you test out #427? - it logs stdout at debug-level and stderr at warning-level. Docker is weirdly inconsistent about where it puts error messages (usually on stdout in exec).

Answer 4 · 2021-04-30T12:50:47.000Z

It's wonderful! Here my example logs!

What I did:

FROM jupyterhub/jupyterhub:1.3
RUN apt-get update && apt-get -y install git
COPY jupyterhub_config.py /srv/jupyterhub/jupyterhub_config.py
RUN pip install -e git+https://github.com/minrk/dockerspawner.git@post-start-debug#egg=dockerspawner

And I removed the sh -c '...' for repeatability at c.DockerSpawner.post_start_cmd = .
That resulted in these logs:

jupyterhub_1_48ff1f33f231 | [I 2021-04-30 12:43:10.272 JupyterHub base:757] User logged in: hey
jupyterhub_1_48ff1f33f231 | [I 2021-04-30 12:43:10.273 JupyterHub log:181] 302 POST /hub/login?next=%2Fhub%2F -> /hub/ (hey@134.28.143.253) 49.10ms
jupyterhub_1_48ff1f33f231 | [I 2021-04-30 12:43:10.375 JupyterHub log:181] 302 GET /hub/ -> /hub/spawn (hey@134.28.143.253) 13.17ms
jupyterhub_1_48ff1f33f231 | [I 2021-04-30 12:43:10.487 JupyterHub dockerspawner:976] Container 'jupyter-hey' is gone
jupyterhub_1_48ff1f33f231 | [I 2021-04-30 12:43:10.564 JupyterHub dockerspawner:1197] Created container jupyter-hey (id: f0033b3) from image exam-scipy-notebook
jupyterhub_1_48ff1f33f231 | [I 2021-04-30 12:43:10.564 JupyterHub dockerspawner:1221] Starting container jupyter-hey (id: f0033b3)
jupyterhub_1_48ff1f33f231 | [W 2021-04-30 12:43:11.110 JupyterHub dockerspawner:782] post_start stderr in jupyter-hey: OCI runtime exec failed: exec failed: container_linux.go:367: starting container process caused: exec: "cd": executable file not found in $PATH: unknown
jupyterhub_1_48ff1f33f231 | [I 2021-04-30 12:43:11.429 JupyterHub log:181] 302 GET /hub/spawn -> /hub/spawn-pending/hey (hey@134.28.143.253) 1007.06ms
jupyterhub_1_48ff1f33f231 | [I 2021-04-30 12:43:11.476 JupyterHub pages:402] hey is pending spawn
jupyterhub_1_48ff1f33f231 | [I 2021-04-30 12:43:11.482 JupyterHub log:181] 200 GET /hub/spawn-pending/hey (hey@134.28.143.253) 9.10ms
jupyterhub_1_48ff1f33f231 | 12:43:11.699 [ConfigProxy] error: 503 GET /hub/static/favicon.ico?v=fde5757cd3892b979919d3b1faa88a410f28829feb5ba22b6cf069f2c6c98675fceef90f932e49b510e74d65c681d5846b943e7f7cc1b41867422f0481085c1f socket hang up
jupyterhub_1_48ff1f33f231 | [I 2021-04-30 12:43:11.713 JupyterHub log:181] 200 GET /hub/error/503?url=%2Fhub%2Fstatic%2Ffavicon.ico%3Fv%3Dfde5757cd3892b979919d3b1faa88a410f28829feb5ba22b6cf069f2c6c98675fceef90f932e49b510e74d65c681d5846b943e7f7cc1b41867422f0481085c1f (@172.18.0.2) 11.57ms
jupyterhub_1_48ff1f33f231 | [I 2021-04-30 12:43:14.284 JupyterHub log:181] 200 GET /hub/api (@172.18.0.4) 1.03ms
jupyterhub_1_48ff1f33f231 | [I 2021-04-30 12:43:14.308 JupyterHub log:181] 200 POST /hub/api/users/hey/activity (hey@172.18.0.4) 15.78ms
jupyterhub_1_48ff1f33f231 | [I 2021-04-30 12:43:14.920 JupyterHub base:904] User hey took 4.492 seconds to start
jupyterhub_1_48ff1f33f231 | [I 2021-04-30 12:43:14.920 JupyterHub proxy:257] Adding user hey to proxy /user/hey/ => http://172.18.0.4:8888
jupyterhub_1_48ff1f33f231 | 12:43:14.921 [ConfigProxy] info: Adding route /user/hey -> http://172.18.0.4:8888
jupyterhub_1_48ff1f33f231 | 12:43:14.922 [ConfigProxy] info: Route added /user/hey -> http://172.18.0.4:8888
jupyterhub_1_48ff1f33f231 | 12:43:14.922 [ConfigProxy] info: 201 POST /api/routes/user/hey
jupyterhub_1_48ff1f33f231 | [I 2021-04-30 12:43:14.923 JupyterHub users:664] Server hey is ready
jupyterhub_1_48ff1f33f231 | [I 2021-04-30 12:43:14.924 JupyterHub log:181] 200 GET /hub/api/users/hey/server/progress (hey@134.28.143.253) 3177.65ms

Here, we see the error message jupyterhub_1_48ff1f33f231 | [W 2021-04-30 12:43:11.110 JupyterHub dockerspawner:782] post_start stderr in jupyter-hey: OCI runtime exec failed: exec failed: container_linux.go:367: starting container process caused: exec: "cd": executable file not found in $PATH: unknown which would be helpful as a starting point.

Answer 5 · 2021-04-30T12:52:12.000Z

So based on that I would love to see #427 being merged.

Answer 6 · 2021-04-30T13:10:58.000Z

If it's not already working then I think logging the output of running post_start_cmd as DEBUG or INFO should be added (I'm surprised it's not already).

For your particular problem I suspect the problem might be you've entered a shell statement that needs to be intepreted by a shell instead of a command. Quick workaround might be to wrap it in sh -c '...'? That's just a guess though.

If somebody wonders why sh -c '...' is necessary (like me), https://docs.docker.com/engine/reference/commandline/exec/ can be of help.

Answer 7 · 2021-07-15T11:05:34.000Z

Thanks, for me the pull request #427 solved this perfectly!