SlurmSpawner behaviors are different if installed through pip compared to installed locally

[ChengxuanHuang]

Bug description

When installing batchspawner through pip, JupyterHub stucks here:

[W 2023-05-10 23:04:27.108 JupyterHub base:183] Rolling back dirty objects IdentitySet([<Server(:0)>])
[I 2023-05-10 23:04:27.113 JupyterHub log:191] 302 GET /hub/spawn -> /hub/spawn-pending/root (root@::ffff:10.106.239.51) 1003.67ms
[D 2023-05-10 23:04:27.181 JupyterHub batchspawner:322] Spawner querying job:  /usr/local/bin/squeue -h -j 1897 -o '%T %B'
[D 2023-05-10 23:04:27.437 JupyterHub scopes:863] Checking access via scope servers
[D 2023-05-10 23:04:27.437 JupyterHub scopes:690] Argument-based access to /hub/spawn-pending/root via servers
[I 2023-05-10 23:04:27.438 JupyterHub pages:398] root is pending spawn
[I 2023-05-10 23:04:27.457 JupyterHub log:191] 200 GET /hub/spawn-pending/root (root@::ffff:10.106.239.51) 23.27ms
[D 2023-05-10 23:04:28.263 JupyterHub scopes:863] Checking access via scope read:servers
[D 2023-05-10 23:04:28.263 JupyterHub scopes:690] Argument-based access to /hub/api/users/root/server/progress via read:servers
[I 2023-05-10 23:04:32.834 JupyterHub log:191] 200 GET /hub/api (@192.168.23.10) 0.83ms
[D 2023-05-10 23:04:32.847 JupyterHub base:297] Recording first activity for <APIToken('6ebb...', user='root', client_id='jupyterhub')>
[D 2023-05-10 23:04:32.856 JupyterHub scopes:863] Checking access via scope users:activity
[D 2023-05-10 23:04:32.856 JupyterHub scopes:690] Argument-based access to /hub/api/users/root/activity via users:activity
[D 2023-05-10 23:04:32.858 JupyterHub users:874] Activity for user root: 2023-05-11T03:04:32.782337Z
[D 2023-05-10 23:04:32.858 JupyterHub users:892] Activity on server root/: 2023-05-11T03:04:32.782337Z
[I 2023-05-10 23:04:32.863 JupyterHub log:191] 200 POST /hub/api/users/root/activity (root@192.168.23.10) 18.10ms
[W 2023-05-10 23:04:36.109 JupyterHub base:1088] User root is slow to start (timeout=10)

Expected behaviour

When installing batchspawner through downloading the package on GitHub, the server and hub communicates, and the output is this:

[W 2023-05-10 22:53:21.431 JupyterHub base:183] Rolling back dirty objects IdentitySet([<Server(:0)>])
[I 2023-05-10 22:53:21.434 JupyterHub log:191] 302 GET /hub/spawn -> /hub/spawn-pending/root (root@::ffff:10.106.239.51) 1004.07ms
[D 2023-05-10 22:53:21.684 JupyterHub scopes:863] Checking access via scope servers
[D 2023-05-10 22:53:21.684 JupyterHub scopes:690] Argument-based access to /hub/spawn-pending/root via servers
[I 2023-05-10 22:53:21.686 JupyterHub pages:398] root is pending spawn
[I 2023-05-10 22:53:21.705 JupyterHub log:191] 200 GET /hub/spawn-pending/root (root@::ffff:10.106.239.51) 22.70ms
[D 2023-05-10 22:53:22.212 JupyterHub scopes:863] Checking access via scope read:servers
[D 2023-05-10 22:53:22.213 JupyterHub scopes:690] Argument-based access to /hub/api/users/root/server/progress via read:servers
[D 2023-05-10 22:53:25.427 JupyterHub base:297] Recording first activity for <APIToken('5182...', user='root', client_id='jupyterhub')>
[I 2023-05-10 22:53:25.436 JupyterHub log:191] 200 POST /hub/api/batchspawner (root@192.168.23.10) 11.58ms
[W 2023-05-10 22:53:25.518 JupyterHub spawner:170]
    The shared database session at Spawner.db is deprecated, and will be removed.
    Please manage your own database and connections.

    Contact JupyterHub at https://github.com/jupyterhub/jupyterhub/issues/3700
    if you have questions or ideas about direct database needs for your Spawner.

[I 2023-05-10 22:53:25.518 JupyterHub batchspawner:463] Notebook server job 1896 started at c1:43581
[D 2023-05-10 22:53:25.523 JupyterHub spawner:1384] Polling subprocess every 30s
[I 2023-05-10 22:53:26.971 JupyterHub log:191] 200 GET /hub/api (@192.168.23.10) 0.70ms
[D 2023-05-10 22:53:26.980 JupyterHub scopes:863] Checking access via scope users:activity
[D 2023-05-10 22:53:26.980 JupyterHub scopes:690] Argument-based access to /hub/api/users/root/activity via users:activity
[D 2023-05-10 22:53:26.982 JupyterHub users:874] Activity for user root: 2023-05-11T02:53:26.922296Z
[D 2023-05-10 22:53:26.982 JupyterHub users:892] Activity on server root/: 2023-05-11T02:53:26.922296Z
[I 2023-05-10 22:53:26.986 JupyterHub log:191] 200 POST /hub/api/users/root/activity (root@192.168.23.10) 7.84ms
[D 2023-05-10 22:53:28.486 JupyterHub utils:278] Server at http://c1:43581/user/root/ responded with 302
[D 2023-05-10 22:53:28.487 JupyterHub _version:74] jupyterhub and jupyterhub-singleuser both on version 4.0.0
[I 2023-05-10 22:53:28.487 JupyterHub base:988] User root took 8.057 seconds to start
[I 2023-05-10 22:53:28.487 JupyterHub proxy:330] Adding user root to proxy /user/root/ => http://c1:43581
[D 2023-05-10 22:53:28.487 JupyterHub proxy:880] Proxy: Fetching POST http://127.0.0.1:8001/api/routes/user/root
22:53:28.488 [ConfigProxy] info: Adding route /user/root -> http://c1:43581
22:53:28.489 [ConfigProxy] info: Route added /user/root -> http://c1:43581
22:53:28.490 [ConfigProxy] info: 201 POST /api/routes/user/root
[I 2023-05-10 22:53:28.490 JupyterHub users:768] Server root is ready
[I 2023-05-10 22:53:28.491 JupyterHub log:191] 200 GET /hub/api/users/root/server/progress?_xsrf=[secret] (root@::ffff:10.106.239.51) 6279.81ms
[D 2023-05-10 22:53:28.522 JupyterHub scopes:863] Checking access via scope servers
[D 2023-05-10 22:53:28.522 JupyterHub scopes:690] Argument-based access to /hub/spawn-pending/root via servers
[I 2023-05-10 22:53:28.522 JupyterHub log:191] 302 GET /hub/spawn-pending/root -> /user/root/ (root@::ffff:10.106.239.51) 2.50ms
[D 2023-05-10 22:53:28.920 JupyterHub provider:420] Validating client id jupyterhub-user-root

How to reproduce

I created two conda environments: "bs-local", "bs-conda". The two envs share in common the following requirements.txt:

• python==3.11.3
• jupyterhub==4.0.0
• jupyterlab==3.5.3
• jupyter_server=1.23.6
• notebook==6.5.4

Possible solution

I see that batchspawner's last update on PyPI is on Oct, 2022. Maybe updating the package on PyPI will solve the issue.

[welcome]

Thank you for opening your first issue in this project! Engagement like this is essential for open source projects! 🤗

If you haven't done so already, check out Jupyter's Code of Conduct. Also, please try to follow the issue template as it helps other other community members to contribute more effectively.

You can meet the other Jovyans by joining our Discourse forum. There is also an intro thread there where you can stop by and say Hi! 👋

Welcome to the Jupyter community! 🎉

[opoplawski]

I seem to be seeing something similar where jobs eventually timeout despite contacting the hub api. Unfortunately I've not be able to resolve, despite trying to install the current git head version of batchspawner.

[opoplawski]

Figured out how to properly overwrite the current install with the git head - and now I can start my notebook. Looks like it's time to make a new release of batchspawner to get this out to users. Thanks.

[consideRatio]

Looks like it's time to make a new release of batchspawner to get this out to users. Thanks.

Good catch, we need a release newer than 1.2.0. I opened #277 to track that and referenced this issue with details on what happens otherwise when used with modern JupyterHub versions.

Thanks for a nice report @opoplawski!