Idle culler not culling

rook · September 7, 2023, 2:54pm

I’m seeing a growing number of older servers (currently up to 22 days old, the age of the cluster). The culler seems to start and run at the expected 10 minute interval, but none of the containers get cleaned up:

[I 2023-09-07 14:41:11.218 JupyterHub app:3189] Starting managed service jupyterhub-idle-culler
[I 2023-09-07 14:41:11.218 JupyterHub service:385] Starting service 'jupyterhub-idle-culler': ['python3', '-m', 'jupyterhub_idle_culler', '--url=http://localhost:8081/hub/api', '--timeout=86400', '--cull-every=600', '--concurrency=10', '--max-age=1209600']
[I 2023-09-07 14:41:11.219 JupyterHub service:133] Spawning python3 -m jupyterhub_idle_culler --url=http://localhost:8081/hub/api --timeout=86400 --cull-every=600 --concurrency=10 --max-age=1209600
[D 2023-09-07 14:41:11.771 JupyterHub base:299] Recording first activity for <APIToken('7ba6...', service='jupyterhub-idle-culler', client_id='jupyterhub')>
[I 2023-09-07 14:41:11.790 JupyterHub log:191] 200 GET /hub/api/ (jupyterhub-idle-culler@127.0.0.1) 24.38ms
[I 2023-09-07 14:41:11.811 JupyterHub log:191] 200 GET /hub/api/users?state=[secret] (jupyterhub-idle-culler@127.0.0.1) 18.11ms
[I 2023-09-07 14:51:11.872 JupyterHub log:191] 200 GET /hub/api/ (jupyterhub-idle-culler@127.0.0.1) 20.24ms
[I 2023-09-07 14:51:11.886 JupyterHub log:191] 200 GET /hub/api/users?state=[secret] (jupyterhub-idle-culler@127.0.0.1) 7.60ms

I added the --max-age=1209600 to factor out if indeed there were an unusually large number of active connections, but servers older than 14 days are not culled so that doesn’t seem to be the case. I’ve tried some lower thresholds, down to 4800 seconds, though that doesn’t seem to clean up servers either.

When enabled the culler does seem to work on cleaning up old users from the DB, but not running servers.

The hub itself seems to identify that there are many servers that have not been active in the last 24 hours:

[I 2023-09-07 14:41:11.176 JupyterHub metrics:278] Found 28 active users in the last ActiveUserPeriods.twenty_four_hours
[I 2023-09-07 14:41:11.177 JupyterHub metrics:278] Found 43 active users in the last ActiveUserPeriods.seven_days
[I 2023-09-07 14:41:11.178 JupyterHub metrics:278] Found 69 active users in the last ActiveUserPeriods.thirty_days

I’m not seeing any errors from the hub container. Leaving me unsure of where to look.

I’m running zero-to-jupyterhub 3.0.0 where the hub container has jupyterhub-idle-culler==1.2.1

manics · September 7, 2023, 5:16pm

Can you try configuring the idle culler to output debug logs, this should provide information on what pods the culler can see:

github.com

jupyterhub/jupyterhub-idle-culler/blob/238f692584c99ec4ff5da11cbdca877ad977cc19/jupyterhub_idle_culler/init.py#L171-L260


      
          async def handle_server(user, server_name, server, max_age, inactive_limit):
              """Handle (maybe) culling a single server
          
              "server" is the entire server model from the API.
          
              Returns True if server is now stopped (user removable),
              False otherwise.
              """
              log_name = user["name"]
              if server_name:
                  log_name = "%s/%s" % (user["name"], server_name)
              if server.get("pending"):
                  app_log.warning(
                      "Not culling server %s with pending %s", log_name, server["pending"]
                  )
                  return False
          
              # jupyterhub < 0.9 defined 'server.url' once the server was ready
              # as an *implicit* signal that the server was ready.
              # 0.9 adds a dedicated, explicit 'ready' field.

This file has been truncated. show original

In addition can you login to JupyterHub as an admin, and see whether the long running servers are still listed as running?

Can you also allow us your Z2jh config?

rook · September 7, 2023, 10:01pm

Thank you for your response! Sure enough the admin panel is not showing the old servers as running. As you divined I am seeing them through kubectl. So maybe the culler is working, but the servers aren’t shutting down?

Indeed, looking at the long running server logs now, showing a lot of:

[E 2023-09-07 21:49:57.798 JupyterHubSingleUser] Error notifying Hub of activity
    Traceback (most recent call last):
      File "/srv/paws/lib/python3.10/site-packages/jupyterhub/singleuser/extension.py", line 425, in notify
        await client.fetch(req)
    tornado.httpclient.HTTPClientError: HTTP 403: Forbidden
[E 2023-09-07 21:49:57.799 JupyterHubSingleUser] Error notifying Hub of activity
    Traceback (most recent call last):
      File "/srv/paws/lib/python3.10/site-packages/jupyterhub/singleuser/extension.py", line 450, in keep_activity_updated
        await self.notify_activity()
      File "/srv/paws/lib/python3.10/site-packages/jupyterhub/singleuser/extension.py", line 432, in notify_activity
        await exponential_backoff(
      File "/srv/paws/lib/python3.10/site-packages/jupyterhub/utils.py", line 237, in exponential_backoff
        raise asyncio.TimeoutError(fail_message)
    asyncio.exceptions.TimeoutError: Failed to notify Hub of activity

The z2jh config is defined in

With the values file at:

github.com

toolforge/paws/blob/1b3c59aeaa414cd9e3fb33b4838aadb6ce9fd56a/paws/values.yaml

---

# pawsPublicEnabled enables the anonymous viewing service for notebooks
pawsPublicEnabled: true
pawspublic:
  nbserve:
    image:
      name: quay.io/wikimedia-paws-prod/nbserve
      tag: pr-277 # nbserve tag managed by github actions
      # pawspublic.nbserve.image.template safely defines image:tag name in yaml
      template: "{{ .Values.pawspublic.nbserve.image.name}}:{{.Values.pawspublic.nbserve.image.tag }}"
    replicas: 1
    requests:
      memory: "20Mi"
  renderer:
    image:
      name: quay.io/wikimedia-paws-prod/renderer
      tag: pr-168 # renderer tag managed by github actions
      # pawspublic.nbserve.image.template safely defines image:tag name in yaml
      template: "{{ .Values.pawspublic.renderer.image.name}}:{{.Values.pawspublic.renderer.image.tag }}"

This file has been truncated. show original

I’m currently running off of GitHub - toolforge/paws at T345838 where I was tinkering with the culler options.

I’m not sure how to enable the debug for the culler specifically, I don’t see an option for it in GitHub - jupyterhub/jupyterhub-idle-culler: JupyterHub service to cull idle servers and users, though I did for jupyterhub in values.yaml (debug.enabled: true) in the branch that I’m working off of. Not sure if that is relevant considering what you lead me to find. Though if it is could you describe how I can enable debug for the culler.

manics · September 8, 2023, 11:26am

There’s a suspected bug in Kubespawner related to how the hub tracks pods, which might be fixed by this PR:

github.com/jupyterhub/kubespawner

return poll status after first load finish

jupyterhub:main ← ivyxjc:main

opened 05:55AM - 07 Jun 23 UTC

ivyxjc

+7 -1

Now, spawner does not wait for fist load finish. So it cannot detect the running… pod and return incorrect status to hub. ## Update by Erik This is a bugfix for a regression introduced with KubeSpawner version 5.0.0 and Z2JH since 3.0.0 (or the pre-release 3.0.0-alpha.1 or the development release `3.0.0-0.dev.git.6133.hbfc583f8`). It is resolved in KubeSpawner 6.1.0 and z2jh 3.1.0. For more information and help cleaning up orphaned user pods, see https://discourse.jupyter.org/t/how-to-cleanup-orphaned-user-pods-after-bug-in-z2jh-3-0-and-kubespawner-6-0/21677

It’s merged but not yet released, however if you’re comfortable rebuilding the hub image to upgrade Kubespawner to the head of the main branch that’s worth a try.

Sorry, you’re right! There should be an undocumented logging option, but it’s not configurable in Z2jh. I’ve opened a new issue:

github.com/jupyterhub/zero-to-jupyterhub-k8s

Support idle culler debug logging

opened 11:24AM - 08 Sep 23 UTC

manics

enhancement

### Proposed change The Z2jh idle culler does not support debug logging: https:…//github.com/jupyterhub/zero-to-jupyterhub-k8s/blob/b407b541b1ee2a0f699e90699b61c2299c460547/jupyterhub/files/hub/jupyterhub_config.py#L356-L391 For instance, it should be possible to enable debug logs using Tornado's [built-in option `--logging=debug`](https://www.tornadoweb.org/en/stable/options.html#module-tornado.options), which could be passed when `debug.enabled` is set in the chart. I noticed this whilst answering https://discourse.jupyter.org/t/idle-culler-not-culling/21301/3 ### Alternative options - Add a new option to control idle culler logging - Allowing an array of additional command line args to be passed - Allow the entire idle culler command to be overridden ### Who would use this feature? Admins wanting to debug the culling in z2jh. ### (Optional): Suggest a solution See above

Topic		Replies	Views
Auto culling Jupyterhub notebooks JupyterHub	4	1072	November 18, 2021
Long running kernels without browser activity Zero to JupyterHub on Kubernetes help-wanted	0	346	September 23, 2020
Prevent idle culler from culling active kernels? JupyterHub	3	434	September 26, 2023
Logs for jupyterhub-idle-culler in jupyterhub/k8s-hub:2.0.0 JupyterHub how-to , help-wanted	1	284	June 20, 2023
Stop inactive servers or stop server upon logout z2jh JupyterHub jupyterhub	10	362	March 2, 2024

Idle culler not culling

Related Topics