Auth_refresh_age not affecting the default 300 second background task that runs refresh_user

I’m trying to update the default auth_refresh_age of 300 seconds for the refresh_user function. My understanding of auth_refresh_age is that if changed to say 30 seconds the refresh_user function will be ran every 30 seconds in the background - but what I’m experiencing is that auth_refresh_age is changing how often refresh_user is ran when doing UI activities (i.e http requests to JupyterHub)

I.e when I refresh the JupyterHub page I see in the Hub logs that refresh_user has been ran. Then if I refresh again nothing will happen till 30 seconds goes by - once that time is up I can refresh the JupyterHub page and refresh_user is once again ran.

Is this the expected functionality? If so then how could I update how often refresh_user is ran in the background.

Some more information

Within refresh_user I’m printing the handler.class. Every 5 minutes the following handlers are seen ActivityAPIHandler/SelfAPIHandler

Hub image → FROM jupyterhub/k8s-hub:1.1.3-n285.h30f2255b

Partial config:

hub:
  image:
    name: [placeholder]
  config:
    Authenticator:
      auth_refresh_age: 30
      refresh_pre_spawn: True
      enable_auth_state: True
    JupyterHub:
      authenticator_class: [placeholder]
    LocalAuthenticator:
      create_system_users: True
  extraConfig:
    extraConfig.py: |
      c.Spawner.cmd = ['start.sh','jupyterhub-singleuser','--allow-root', '--FileContentsManager.delete_to_trash=True']
      c.KubeSpawner.args = ['--allow-root']
      def notebook_dir_hook(spawner):
        spawner.environment = {'NB_USER':spawner.user.name,'NB_UID':'1000'}
        spawner.args = ['--collaborative']
      c.Spawner.pre_spawn_hook = notebook_dir_hook

singleuser:
  [placeholder]

refresh_user is not run in the background. It is run only when a user makes an authenticated request, to refresh their authenticated info in case it has become stale (e.g. they have become no-longer admin, or an access token may have expired). It’s more like a cache expiration date than a background task.

The idea is basically:

  1. when a user makes an authenticated request, check how old their auth info is (last time they authenticated, or refresh_user was called)
  2. if it’s older than auth_refresh_age, refresh the auth info, to re-sync with the identity provider (call refresh_user()) in case things have changed in the meantime
  3. refresh_pre_spawn allows this check to occur at spawn time, regardless of the age of auth info
1 Like

Ok this makes sense. Thank you

My followup question would then be why are the two handlers seen in refresh_user every 5 minutes? ActivityAPIHandler/SelfAPIHandler

Something is causing refresh_user to be ran every 5 minutes.

= = =

The goal is to have refresh_user automatically run or be triggered somehow within the Lab environment. So if the user’s token is invalid I can log that user out or terminate the lab

ActivityAPIHandler is the /users/{name}/activity endpoint, used by the singleuser server (e.g. JupyterLab) to tell JupyterHub the server is still active. For example, this can be used by JupyterHub to automatically shutdown unused servers.

It should be configurable on the user side jupyterhub/mixins.py at 4a1842bf8a42caf663bf3da7e43c33d6e6c7eb58 · jupyterhub/jupyterhub · GitHub

Great! Thank you.

Is ActivityAPIHandler supposed to trigger refresh_user? I guess since it’s an authenticated call it can trigger refresh_user

Is lowering the hub_activity_interval value an ok way to have refresh_user be ran more often? From what I read hub_activity_interval could cause some performance issues depending how low of a value is set since it has to write to a DB

= = =

One more question as well. I’ve noticed that when I generate a JupyterHub API key for another user to use my session, it takes an extra 5 minutes for the user to be kicked out of the session. I.e I generate a token that expires in 15m - but the user will actually be kicked out after 20m. Do you have any idea what check in the backgorund doing this?

Appreciate the help with this

I’ve checked, and setting c.SingleUserNotebookAppMixin.hub_activity_interval = 10 in the singleuser server configuration (not the hub configuration) should work. Database performance will depend on how many users you have, try it and keep an eye on your resource usage.

There are some other properties on the JupyterHub side which might be relevant including c.JupyterHub.activity_resolution and c.JupyterHub.last_activity_interval, see Application configuration — JupyterHub 2.2.1 documentation

I’m not sure about the token timeout, but I’d guess it’s due to JupyterHub checking for token validity at fixed intervals rather than continuously.

Great. Appreciate all the help on this. Going to test see what I can get working

Hmm. I set the values in extraConfig & nothing seemed to have changed. Not seeing the Activity handler any sooner than 300 seconds.You’d think that’d be the right configuration field to modify it

  extraConfig:
    extraConfig.py: |
      c.Spawner.cmd = ['start.sh','jupyterhub-singleuser','--allow-root', '--FileContentsManager.delete_to_trash=True']
      c.KubeSpawner.args = ['--allow-root']
      def notebook_dir_hook(spawner):
        spawner.environment = {'NB_USER':spawner.user.name,'NB_UID':'1000'}
        spawner.args = ['--collaborative']
      c.Spawner.pre_spawn_hook = notebook_dir_hook
      c.JupyterHub.last_activity_interval = 10
      c.SingleUserNotebookAppMixin.hub_activity_interval = 10

Looking at the debug logs I see two things running every 10 seconds

[D 2022-03-15 13:50:46.793 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.84ms
[D 2022-03-15 13:50:48.792 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.83ms
[D 2022-03-15 13:50:50.792 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.77ms
[D 2022-03-15 13:50:52.792 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.84ms
[D 2022-03-15 13:50:53.800 JupyterHub reflector:357] pods watcher timeout
[D 2022-03-15 13:50:53.800 JupyterHub reflector:282] Connecting pods watcher
[D 2022-03-15 13:50:54.119 JupyterHub reflector:357] events watcher timeout
[D 2022-03-15 13:50:54.119 JupyterHub reflector:282] Connecting events watcher
[D 2022-03-15 13:50:54.793 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.68ms
[D 2022-03-15 13:50:55.166 JupyterHub proxy:821] Proxy: Fetching GET http://proxy-api:8001/api/routes
[D 2022-03-15 13:50:55.209 JupyterHub proxy:346] Checking routes
[D 2022-03-15 13:50:56.793 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.84ms
[D 2022-03-15 13:50:58.793 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.82ms
[D 2022-03-15 13:51:00.793 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.79ms
[D 2022-03-15 13:51:02.792 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.82ms
[D 2022-03-15 13:51:03.816 JupyterHub reflector:357] pods watcher timeout
[D 2022-03-15 13:51:03.817 JupyterHub reflector:282] Connecting pods watcher
[D 2022-03-15 13:51:04.142 JupyterHub reflector:357] events watcher timeout
[D 2022-03-15 13:51:04.142 JupyterHub reflector:282] Connecting events watcher
[D 2022-03-15 13:51:04.792 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.89ms
[D 2022-03-15 13:51:05.165 JupyterHub proxy:821] Proxy: Fetching GET http://proxy-api:8001/api/routes
[D 2022-03-15 13:51:05.210 JupyterHub proxy:346] Checking routes
[D 2022-03-15 13:51:06.792 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.79ms
[D 2022-03-15 13:51:08.792 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.81ms
[D 2022-03-15 13:51:10.792 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.86ms
[D 2022-03-15 13:51:12.792 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.86ms
[D 2022-03-15 13:51:13.831 JupyterHub reflector:357] pods watcher timeout
[D 2022-03-15 13:51:13.832 JupyterHub reflector:282] Connecting pods watcher
[D 2022-03-15 13:51:14.158 JupyterHub reflector:357] events watcher timeout
[D 2022-03-15 13:51:14.160 JupyterHub reflector:282] Connecting events watcher
[D 2022-03-15 13:51:14.792 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.77ms
[D 2022-03-15 13:51:15.165 JupyterHub proxy:821] Proxy: Fetching GET http://proxy-api:8001/api/routes
[D 2022-03-15 13:51:15.178 JupyterHub proxy:346] Checking routes
[D 2022-03-15 13:51:16.793 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.92ms
[D 2022-03-15 13:51:18.792 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.87ms
[D 2022-03-15 13:51:20.794 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 1.77ms
[D 2022-03-15 13:51:20.795 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 2.43ms
[D 2022-03-15 13:51:22.793 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.91ms
[D 2022-03-15 13:51:23.844 JupyterHub reflector:357] pods watcher timeout
[D 2022-03-15 13:51:23.844 JupyterHub reflector:282] Connecting pods watcher
[D 2022-03-15 13:51:24.180 JupyterHub reflector:357] events watcher timeout
[D 2022-03-15 13:51:24.180 JupyterHub reflector:282] Connecting events watcher
[D 2022-03-15 13:51:24.792 JupyterHub log:189] 200 GET /hub/health (@10.79.1.1) 0.87ms

Edited:
The proxy fetch was what was modified, the pods watcher timeout is normal even without modifying the configuration values

This sets the interval on which the Hub checks with the proxy for last activity.

This is the right config, but to have an effect, it needs to be set in the user environment where the single user app runs, not the Hub environment. That means it needs to be in e.g. singleuser.extraFiles

It’s also worth noting that this should only be called every hub_activity_interval if there has been new activity on the server during that time. If the server is running but idle, it shouldn’t make any activity requests.

Thank you! Currently testing this