Servers with activity are getting culled

[yannsartori]

Bug description

If I open a server and exhibit activity on the server (e.g. open a notebook -> create and run cells and periodically save the notebook), it appears that my server gets removed, despite this activity.

Expected behaviour

I would anticipate that my server remains up-and-running.

Actual behaviour

The server gets removed.

How to reproduce

1. Start up a server
2. Edit a notebook, actively saving and running/adding cells
3. See after around --timeout + --cull-every seconds, the server gets culled.

Your personal set up

I am running JupyterHub in Docker with a SwarmSpawner subclass (VariableSwamSpawner) as a spawner class, with support for ContainDSDashboard.

• OS:

Below is the Dockerfile I use for my jupyterhub server:

FROM jupyterhub/jupyterhub
COPY ./certs/ca-bundle.crt /usr/local/share/ca-certificates/
RUN pip install cdsdashboards oauthenticator dockerspawner ldap3 pyyaml jupyterhub-idle-culler && update-ca-certificates
COPY ./jupyterhub_config.py /srv/jupyterhub/jupyterhub_config.py
COPY ./templates /srv/jupyterhub/templates
# This command may be necesssary if jupyterhub complains about outdated database schemas
# CMD jupyterhub upgrade-db && jupyterhub

• Version(s):

• Full environment

# pip freeze
alembic @ file:///tmp/wheelhouse/alembic-1.7.5-py3-none-any.whl
async-generator @ file:///tmp/wheelhouse/async_generator-1.10-py3-none-any.whl
attrs @ file:///tmp/wheelhouse/attrs-21.4.0-py2.py3-none-any.whl
cdsdashboards==0.6.0
certifi @ file:///tmp/wheelhouse/certifi-2021.10.8-py2.py3-none-any.whl
certipy @ file:///tmp/wheelhouse/certipy-0.1.3-py3-none-any.whl
cffi @ file:///tmp/wheelhouse/cffi-1.15.0-cp38-cp38-manylinux_2_12_x86_64.manylinux2010_x86_64.whl
charset-normalizer @ file:///tmp/wheelhouse/charset_normalizer-2.0.10-py3-none-any.whl
cryptography @ file:///tmp/wheelhouse/cryptography-36.0.1-cp36-abi3-manylinux_2_24_x86_64.whl
docker==5.0.3
dockerspawner==12.1.0
entrypoints @ file:///tmp/wheelhouse/entrypoints-0.3-py2.py3-none-any.whl
escapism==1.0.1
greenlet @ file:///tmp/wheelhouse/greenlet-1.1.2-cp38-cp38-manylinux_2_17_x86_64.manylinux2014_x86_64.whl
idna @ file:///tmp/wheelhouse/idna-3.3-py3-none-any.whl
importlib-metadata @ file:///tmp/wheelhouse/importlib_metadata-4.10.0-py3-none-any.whl
importlib-resources @ file:///tmp/wheelhouse/importlib_resources-5.4.0-py3-none-any.whl
Jinja2 @ file:///tmp/wheelhouse/Jinja2-3.0.3-py3-none-any.whl
jsonschema @ file:///tmp/wheelhouse/jsonschema-4.3.3-py3-none-any.whl
jupyter-telemetry @ file:///tmp/wheelhouse/jupyter_telemetry-0.1.0-py3-none-any.whl
jupyterhub @ file:///tmp/wheelhouse/jupyterhub-2.0.2-py3-none-any.whl
jupyterhub-idle-culler==1.2.1
ldap3==2.9.1
Mako @ file:///tmp/wheelhouse/Mako-1.1.6-py2.py3-none-any.whl
MarkupSafe @ file:///tmp/wheelhouse/MarkupSafe-2.0.1-cp38-cp38-manylinux_2_5_x86_64.manylinux1_x86_64.manylinux_2_12_x86_64.manylinux2010_x86_64.whl
oauthenticator==14.2.0
oauthlib @ file:///tmp/wheelhouse/oauthlib-3.1.1-py2.py3-none-any.whl
packaging @ file:///tmp/wheelhouse/packaging-21.3-py3-none-any.whl
pamela @ file:///tmp/wheelhouse/pamela-1.0.0-py2.py3-none-any.whl
pluggy==1.0.0
prometheus-client @ file:///tmp/wheelhouse/prometheus_client-0.12.0-py2.py3-none-any.whl
pyasn1==0.4.8
pycparser @ file:///tmp/wheelhouse/pycparser-2.21-py2.py3-none-any.whl
pycurl==7.43.0.2
pyOpenSSL @ file:///tmp/wheelhouse/pyOpenSSL-21.0.0-py2.py3-none-any.whl
pyparsing @ file:///tmp/wheelhouse/pyparsing-3.0.6-py3-none-any.whl
pyrsistent @ file:///tmp/wheelhouse/pyrsistent-0.18.0-cp38-cp38-manylinux1_x86_64.whl
python-dateutil @ file:///tmp/wheelhouse/python_dateutil-2.8.2-py2.py3-none-any.whl
python-json-logger @ file:///tmp/wheelhouse/python_json_logger-2.0.2-py3-none-any.whl
PyYAML==6.0
requests @ file:///tmp/wheelhouse/requests-2.27.1-py2.py3-none-any.whl
ruamel.yaml @ file:///tmp/wheelhouse/ruamel.yaml-0.17.20-py3-none-any.whl
ruamel.yaml.clib @ file:///tmp/wheelhouse/ruamel.yaml.clib-0.2.6-cp38-cp38-manylinux1_x86_64.whl
six @ file:///tmp/wheelhouse/six-1.16.0-py2.py3-none-any.whl
SQLAlchemy @ file:///tmp/wheelhouse/SQLAlchemy-1.4.29-cp38-cp38-manylinux_2_5_x86_64.manylinux1_x86_64.manylinux_2_17_x86_64.manylinux2014_x86_64.whl
tornado @ file:///tmp/wheelhouse/tornado-6.1-cp38-cp38-manylinux2010_x86_64.whl
traitlets @ file:///tmp/wheelhouse/traitlets-5.1.1-py3-none-any.whl
urllib3 @ file:///tmp/wheelhouse/urllib3-1.26.8-py2.py3-none-any.whl
websocket-client==1.2.3
zipp @ file:///tmp/wheelhouse/zipp-3.7.0-py3-none-any.whl

• Configuration

# jupyterhub_config.py
import os
import sys

import yaml
from cdsdashboards.app import CDS_TEMPLATE_PATHS
from cdsdashboards.hubextension import cds_extra_handlers
from ldap3 import Connection, Server

c.Application.log_level = 'DEBUG'

# Configure the user servers
c.JupyterHub.spawner_class = 'cdsdashboards.hubextension.spawners.variabledocker.VariableSwarmSpawner'
c.DockerSpawner.image = os.environ['DOCKER_JUPYTER_IMAGE']
c.Spawner.http_timeout = c.Spawner.start_timeout = int(os.environ['STARTUP_TIMEOUT'])

# Set up default user permissions (the ability to start up others' dashboards
c.JupyterHub.load_roles = [
    {
        'name': 'user',
        'description': 'Standard user privileges',
        'scopes': [
            'self',
            'servers',
            'tokens',
            'list:services',
            'read:services',
            'access:services',
            'access:servers',
        ],
    },
]

# Configure shutting-down/culling
c.JupyterHub.load_roles += [
    {
       "name": "jupyterhub-idle-culler-role",
        "scopes": [
            "list:users",
            "read:users:activity",
            "read:servers",
            "delete:servers",
        ],
        # assignment of role's permissions to:
        "services": ["jupyterhub-idle-culler-service"],
    }
]
c.JupyterHub.services = [ # I use extreme values here just to ensure it works
    {
        "name": "jupyterhub-idle-culler-service",
        "command": [
            sys.executable,
            "-m", "jupyterhub_idle_culler",
            "--api-page-size=200",
            "--cull-every=10",
            "--remove-named-servers=True",
            "--timeout=30",
        ],
    }
]

# Configure the network
c.DockerSpawner.network_name = os.environ['DOCKER_NETWORK_NAME']
c.JupyterHub.hub_connect_ip = os.environ['HUB_IP']
# TODO See if this is actually needed
c.DockerSpawner.use_internal_ip = True

# Configure ContainDS
c.JupyterHub.allow_named_servers = True
c.JupyterHub.template_paths = CDS_TEMPLATE_PATHS
c.JupyterHub.extra_handlers = cds_extra_handlers
c.CDSDashboardsConfig.include_servers = True
# ContainDS Auto-culling
c.VariableMixin.proxy_force_alive = False
c.VariableMixin.proxy_last_activity_interval = 15
c.VariableMixin.proxy_request_timeout = 10

c.CDSDashboardsConfig.builder_class = 'cdsdashboards.builder.dockerbuilder.DockerBuilder'

• Logs

[D 2022-01-27 23:53:00.102 JupyterHub swarmspawner:155] Getting task of service $SERVICE                                                                                                                                                                                [12/1843]
[D 2022-01-27 23:53:00.102 JupyterHub dockerspawner:982] Getting service $SERVICE
[D 2022-01-27 23:53:00.112 JupyterHub swarmspawner:144] Service upyx7ki status: {'ContainerStatus': {'ContainerID': 'c1b6b64ed3ef5d50ad786a685a8451562a30fcdc7b7f98d70b5a6ad131679c53',
                         'ExitCode': 0,
                         'PID': 9852},
     'Message': 'started',
     'PortStatus': {},
     'State': 'running',
     'Timestamp': '2022-01-27T23:52:29.645500796Z'}
[D 2022-01-27 23:53:08.554 JupyterHub scopes:298] Authenticated with token <APIToken('2221...', service='jupyterhub-idle-culler-service', client_id='jupyterhub')>
[I 2022-01-27 23:53:08.555 JupyterHub log:189] 200 GET /hub/api/ (jupyterhub-idle-culler-service@10.1.23.3) 4.47ms
[D 2022-01-27 23:53:08.561 JupyterHub scopes:298] Authenticated with token <APIToken('2221...', service='jupyterhub-idle-culler-service', client_id='jupyterhub')>
[D 2022-01-27 23:53:08.561 JupyterHub scopes:488] Checking access via scope list:users
[D 2022-01-27 23:53:08.561 JupyterHub scopes:386] Unrestricted access to /hub/api/users via list:users
[I 2022-01-27 23:53:08.565 JupyterHub log:189] 200 GET /hub/api/users?limit=200&state=[secret] (jupyterhub-idle-culler-service@10.1.23.3) 5.90ms
[I 220127 23:53:08 __init__:236] Culling server $USER (inactive for 00:00:36)
[D 2022-01-27 23:53:08.570 JupyterHub scopes:298] Authenticated with token <APIToken('2221...', service='jupyterhub-idle-culler-service', client_id='jupyterhub')>
[D 2022-01-27 23:53:08.570 JupyterHub scopes:488] Checking access via scope delete:servers
[D 2022-01-27 23:53:08.570 JupyterHub scopes:386] Unrestricted access to /hub/api/users/$USER/server via delete:servers
[D 2022-01-27 23:53:08.571 JupyterHub swarmspawner:155] Getting task of service $SERVICE
[D 2022-01-27 23:53:08.571 JupyterHub dockerspawner:982] Getting service $SERVICE
[D 2022-01-27 23:53:08.577 JupyterHub swarmspawner:144] Service upyx7ki status: {'ContainerStatus': {'ContainerID': 'c1b6b64ed3ef5d50ad786a685a8451562a30fcdc7b7f98d70b5a6ad131679c53',
                         'ExitCode': 0,
                         'PID': 9852},
     'Message': 'started',
     'PortStatus': {},
     'State': 'running',
     'Timestamp': '2022-01-27T23:52:29.645500796Z'}
[I 2022-01-27 23:53:08.577 JupyterHub proxy:310] Removing user $USER from proxy (/user/$USER/)
[D 2022-01-27 23:53:08.577 JupyterHub proxy:821] Proxy: Fetching DELETE http://127.0.0.1:8001/api/routes/user/$USER
23:53:08.578 [ConfigProxy] info: Removing route /user/$USER
23:53:08.578 [ConfigProxy] info: 204 DELETE /api/routes/user/$USER
[D 2022-01-27 23:53:08.579 JupyterHub user:860] Stopping $USER
[D 2022-01-27 23:53:08.579 JupyterHub swarmspawner:155] Getting task of service $SERVICE
[D 2022-01-27 23:53:08.579 JupyterHub dockerspawner:982] Getting service $SERVICE
[D 2022-01-27 23:53:08.583 JupyterHub swarmspawner:144] Service upyx7ki status: {'ContainerStatus': {'ContainerID': 'c1b6b64ed3ef5d50ad786a685a8451562a30fcdc7b7f98d70b5a6ad131679c53',
                         'ExitCode': 0,
                         'PID': 9852},
     'Message': 'started',
     'PortStatus': {},
     'State': 'running',
     'Timestamp': '2022-01-27T23:52:29.645500796Z'}
[I 2022-01-27 23:53:08.583 JupyterHub dockerspawner:1390] Stopping service $SERVICE (id: upyx7ki)
[I 2022-01-27 23:53:08.583 JupyterHub swarmspawner:257] Removing service upyx7kig7y9x5rt15t5w8gpzg
[D 2022-01-27 23:53:08.595 JupyterHub user:880] Deleting oauth client jupyterhub-user-$USER
[D 2022-01-27 23:53:08.605 JupyterHub user:883] Finished stopping $USER
[I 2022-01-27 23:53:08.616 JupyterHub base:1150] User $USER server took 0.039 seconds to stop
[I 2022-01-27 23:53:08.617 JupyterHub log:189] 204 DELETE /hub/api/users/$USER/server (jupyterhub-idle-culler-service@10.1.23.3) 48.48ms
[I 2022-01-27 23:53:10.636 JupyterHub log:189] 302 GET /user/$USER/api/contents/Untitled.ipynb?content=0&1643327590437 -> /hub/user/$USER/api/contents/Untitled.ipynb?content=0&1643327590437 (@10.11.0.4) 2.43ms
[D 2022-01-27 23:53:10.673 JupyterHub user:347] Creating <class 'cdsdashboards.hubextension.spawners.variabledocker.VariableSwarmSpawner'> for $USER:
[W 2022-01-27 23:53:10.676 JupyterHub base:1389] Failing suspected API request to not-running server: /hub/user/$USER/api/contents/Untitled.ipynb
[W 2022-01-27 23:53:10.677 JupyterHub log:189] 424 GET /hub/user/$USER/api/contents/Untitled.ipynb?content=0&1643327590437 ($USER@10.11.0.4) 11.34ms
[I 2022-01-27 23:53:11.089 JupyterHub log:189] 302 GET /user/$USER/api/kernels?1643327590885 -> /hub/user/$USER/api/kernels?1643327590885 (@10.11.0.4) 2.91ms
[I 2022-01-27 23:53:11.122 JupyterHub log:189] 302 GET /user/$USER/api/sessions?1643327590919 -> /hub/user/$USER/api/sessions?1643327590919 (@10.11.0.4) 2.92ms
[W 2022-01-27 23:53:11.127 JupyterHub base:1389] Failing suspected API request to not-running server: /hub/user/$USER/api/kernels
[W 2022-01-27 23:53:11.128 JupyterHub log:189] 424 GET /hub/user/$USER/api/kernels?1643327590885 ($USER@10.11.0.4) 7.41ms

[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! 🎉

[consideRatio]

@yannsartori I suspect this is because what's reported as activity must be something more than just that a kernel is running - it must emit input/output in some way as well I think.

It’s in what the server considers activity to be reported. Messsged are activity (execution, output), but being statically busy is not considered activity.

This was a surprise to me as well, and it should at least be very clearly documented if we don't resolve it.

• Additions to how it works, and a simple "keep alive" strategy #55