Logs flooded with 403s

JupyterHub
, ,
1

For last few weeks jupyterhub server logs have filled up with messages like these:

Mar 17 10:35:20 jupyter jupyterhub[1232207]: [W 2025-03-17 10:35:20.685 JupyterHub web:1873] 403 POST /hub/api/users/jsmith/activity (10.46.1.14): Missing or invalid credentials.
Mar 17 10:35:20 jupyter jupyterhub[1232207]: [W 2025-03-17 10:35:20.685 JupyterHub log:192] 403 POST /hub/api/users/jsmith/activity (@10.46.1.14) 2.04ms

Inspecting the single-user server logs the users see these:

[E 2025-03-17 10:46:54.649 JupyterHubSingleUser] Error notifying Hub of activity: HTTP 403: Forbidden
[E 2025-03-17 10:46:55.528 JupyterHubSingleUser] Error notifying Hub of activity: HTTP 403: Forbidden
[E 2025-03-17 10:46:57.069 JupyterHubSingleUser] Error notifying Hub of activity: HTTP 403: Forbidden
[E 2025-03-17 10:47:00.187 JupyterHubSingleUser] Error notifying Hub of activity: HTTP 403: Forbidden
[E 2025-03-17 10:47:02.333 JupyterHubSingleUser] Error notifying Hub of activity: HTTP 403: Forbidden
[E 2025-03-17 10:47:11.803 JupyterHubSingleUser] Error notifying Hub of activity: HTTP 403: Forbidden
[E 2025-03-17 10:47:16.248 JupyterHubSingleUser] Error notifying Hub of activity: HTTP 403: Forbidden
[E 2025-03-17 10:47:28.856 JupyterHubSingleUser] Error notifying Hub of activity: HTTP 403: Forbidden
[E 2025-03-17 10:47:31.515 JupyterHubSingleUser] Error notifying Hub of activity: HTTP 403: Forbidden
[E 2025-03-17 10:47:40.203 JupyterHubSingleUser] Error notifying Hub of activity: HTTP 403: Forbidden
[E 2025-03-17 10:47:45.320 JupyterHubSingleUser] Error notifying Hub of activity: HTTP 403: Forbidden
[E 2025-03-17 10:47:51.772 JupyterHubSingleUser] Error notifying Hub of activity: HTTP 403: Forbidden
[E 2025-03-17 10:47:51.772 JupyterHubSingleUser] Error notifying Hub of activity
    Traceback (most recent call last):
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterhub/singleuser/extension.py", line 469, in keep_activity_updated
        await self.notify_activity()
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterhub/singleuser/extension.py", line 449, in notify_activity
        await exponential_backoff(
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterhub/utils.py", line 265, in exponential_backoff
        raise asyncio.TimeoutError(fail_message)
    TimeoutError: Failed to notify Hub of activity

Running:

python = ">=3.11.0"
jupyterhub-singleuser = ">=5.2.1,<6"
jupyterlab = ">=4.3.4,<5"
jupyter_server = ">=2.15.0,<3"
pixi-kernel = ">=0.6.0,<0.7"
batchspawner = ">=1.3.0,<2"
jupyter-lsp = ">=2.2.5,<3"
ipympl = ">=0.9.4,<0.10"
jupyterlab-h5web = ">=12.3.0,<13"
hdf5-external-filter-plugins = ">=0.1.0,<0.2"
blosc-hdf5-plugin = ">=1.0.0,<2"
nbconvert-webpdf = ">=7.16.5,<8"
ipyaggrid = ">=0.5.4,<0.6"
voila = ">=0.5.8,<0.6"
jupytext = "==1.16.6"

Any hints/ideas on things I should check? Any time/attention much appreciated.

2

I did try the recommendation found here to set this in jupyterhub_config.py file. I did not see any change after doing so.

JUPYTERHUB_SINGLEUSER_EXTENSION=0
3

The singleuser server should probably backoff trying this.

Are there any logs about that particular server preceding the first event? My guess is the API token associated with the server either expired or was revoked, so it’s no longer authorized to make API requests.

4

Thanks for having a look at this minrk. I do see the below error at start of singleuser server logs which I thought unrelated but perhaps not. I checked db for a couple users and thyey still have valid tokens:

cat jupyterhub_slurmspawner_1209786.log 
[I 2025-03-18 13:42:20.240 ServerApp] Extension package dask_labextension took 1.6196s to import
[W 2025-03-18 13:42:20.240 ServerApp] A `_jupyter_server_extension_points` function was not found in dask_labextension. Instead, a `_jupyter_server_extension_paths` function was found and will be used for now. This function name will be deprecated in future releases of Jupyter Server.
[I 2025-03-18 13:42:20.615 ServerApp] Extension package jupyterlab took 0.2812s to import
[I 2025-03-18 13:42:23.245 ServerApp] Extension package jupyterlab_h5web took 1.2598s to import
[I 2025-03-18 13:42:23.498 ServerApp] Extension package jupyterlab_jupytext took 0.2533s to import
[I 2025-03-18 13:42:23.792 ServerApp] Extension package pixi_kernel took 0.2905s to import
[I 2025-03-18 13:42:24.282 ServerApp] Extension package voila.server_extension took 0.4899s to import
[I 2025-03-18 13:42:24.282 ServerApp] dask_labextension | extension was successfully linked.
[I 2025-03-18 13:42:24.282 ServerApp] jupyter_lsp | extension was successfully linked.
[I 2025-03-18 13:42:24.282 ServerApp] jupyter_server_proxy | extension was successfully linked.
[I 2025-03-18 13:42:24.288 ServerApp] jupyter_server_terminals | extension was successfully linked.
[I 2025-03-18 13:42:24.288 JupyterHubSingleUser] Starting jupyterhub single-user server extension version 5.2.1
[I 2025-03-18 13:42:24.288 JupyterHubSingleUser] Using default url from environment $JUPYTERHUB_DEFAULT_URL: /lab/tree/nsls2/users/jsmith
[I 2025-03-18 13:42:24.291 ServerApp] jupyterhub | extension was successfully linked.
[W 2025-03-18 13:42:24.294 LabApp] 'extra_template_paths' was found in both NotebookApp and ServerApp. This is likely a recent change. This config will only be set in NotebookApp. Please check if you should also config these traits in ServerApp for your purpose.
[I 2025-03-18 13:42:24.296 ServerApp] jupyterlab | extension was successfully linked.
[I 2025-03-18 13:42:24.296 ServerApp] jupyterlab_h5web | extension was successfully linked.
[I 2025-03-18 13:42:24.296 ServerApp] jupyterlab_jupytext | extension was successfully linked.
/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/traitlets/traitlets.py:1897: DeprecationWarning: ServerApp.token config is deprecated in jupyter-server 2.0. Use IdentityProvider.token
  return t.cast(Sentinel, self._get_trait_default_generator(names[0])(self))
[I 2025-03-18 13:42:24.311 ServerApp] notebook_shim | extension was successfully linked.
[I 2025-03-18 13:42:24.311 ServerApp] pixi_kernel | extension was successfully linked.
[I 2025-03-18 13:42:24.311 ServerApp] voila.server_extension | extension was successfully linked.
[I 2025-03-18 13:42:24.361 ServerApp] notebook_shim | extension was successfully loaded.
[I 2025-03-18 13:42:24.361 ServerApp] dask_labextension | extension was successfully loaded.
[I 2025-03-18 13:42:24.363 ServerApp] jupyter_lsp | extension was successfully loaded.
[I 2025-03-18 13:42:24.383 ServerApp] jupyter_server_proxy | extension was successfully loaded.
[I 2025-03-18 13:42:24.383 ServerApp] jupyter_server_terminals | extension was successfully loaded.
[I 2025-03-18 13:42:24.400 JupyterHubSingleUser] Updating Hub with activity every 300 seconds
[I 2025-03-18 13:42:24.400 ServerApp] jupyterhub | extension was successfully loaded.
[I 2025-03-18 13:42:24.435 LabApp] JupyterLab extension loaded from /nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterlab
[I 2025-03-18 13:42:24.435 LabApp] JupyterLab application directory is /nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/share/jupyter/lab
[I 2025-03-18 13:42:24.436 LabApp] Extension Manager is 'pypi'.
[I 2025-03-18 13:42:24.459 LabApp] Extensions will be fetched using proxy, proxy host and port: ('proxy.sdcc.bnl.local', '3128')
[I 2025-03-18 13:42:24.464 ServerApp] jupyterlab | extension was successfully loaded.
[I 2025-03-18 13:42:24.670 ServerApp] Jupyterlab-h5web extension will serve HDF5 files from /
[I 2025-03-18 13:42:24.670 ServerApp] jupyterlab_h5web | extension was successfully loaded.
[W 2025-03-18 13:42:24.671 ServerApp] [Jupytext Server Extension] Async contents managers like {base_class.__name__} are not supported at the moment (https://github.com/mwouts/jupytext/issues/1020). We will derive a contents manager from LargeFileManager instead.
[I 2025-03-18 13:42:24.671 ServerApp] [Jupytext Server Extension] Deriving a JupytextContentsManager from LargeFileManager
[I 2025-03-18 13:42:24.673 ServerApp] jupyterlab_jupytext | extension was successfully loaded.
pixi-kernel INFO: Registered pixi_kernel server extension
[I 2025-03-18 13:42:24.673 ServerApp] pixi_kernel | extension was successfully loaded.
[I 2025-03-18 13:42:24.678 ServerApp] Skipped non-installed server(s): bash-language-server, dockerfile-language-server-nodejs, javascript-typescript-langserver, jedi-language-server, julia-language-server, pyright, python-language-server, python-lsp-server, r-languageserver, sql-language-server, texlab, typescript-language-server, unified-language-server, vscode-css-languageserver-bin, vscode-html-languageserver-bin, vscode-json-languageserver-bin, yaml-language-server
[I 2025-03-18 13:42:24.685 ServerApp] voila.server_extension | extension was successfully loaded.
[I 2025-03-18 13:42:24.686 ServerApp] Serving notebooks from local directory: /
[I 2025-03-18 13:42:24.687 ServerApp] Jupyter Server 2.15.0 is running at:
[I 2025-03-18 13:42:24.687 ServerApp] http://hpc005.nsls2.bnl.local:58481/user/jsmith/lab/tree/nsls2/users/jsmith?token=...
[I 2025-03-18 13:42:24.687 ServerApp]     http://127.0.0.1:58481/user/jsmith/lab/tree/nsls2/users/jsmith?token=...
[I 2025-03-18 13:42:24.687 ServerApp] Use Control-C to stop this server and shut down all kernels (twice to skip confirmation).
[I 2025-03-18 13:42:27.949 ServerApp] New terminal with automatic name: 1
[I 2025-03-18 13:42:28.584 LabApp] Build is up to date
pixi-kernel INFO: TermSocket.open: 1
pixi-kernel INFO: TermSocket.open: Opened 1
2025-03-18 13:42:31,746 - ServerApp - ERROR - Uncaught exception GET /user/jsmith/lab/api/extensions?query&page=1&per_page=30&refresh=0&1742319751723 (192.203.218.24)
HTTPServerRequest(protocol='https', host='jupyter.nsls2.bnl.gov', method='GET', uri='/user/jsmith/lab/api/extensions?query&page=1&per_page=30&refresh=0&1742319751723', version='HTTP/1.1', remote_ip='192.203.218.24')
Traceback (most recent call last):
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/tornado/web.py", line 1790, in _execute
    result = await result
             ^^^^^^^^^^^^
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterlab/handlers/extension_manager_handler.py", line 37, in get
    extensions, last_page = await self.manager.list_extensions(query, page, per_page)
                            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterlab/extensions/manager.py", line 474, in list_extensions
    await self.refresh(query, page, per_page)
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterlab/extensions/manager.py", line 508, in refresh
    await self._update_extensions_list(query, page, per_page)
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterlab/extensions/manager.py", line 681, in _update_extensions_list
    extensions, last_page = await self.list_packages(query, page, per_page)
                            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterlab/extensions/pypi.py", line 270, in list_packages
    matches = await self.__get_all_extensions()
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterlab/extensions/pypi.py", line 324, in __get_all_extensions
    self.__all_packages_cache = await self.__throttleRequest(
                                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterlab/extensions/pypi.py", line 223, in __throttleRequest
    data = await current_loop.run_in_executor(None, fn, *args)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/xmlrpc/client.py", line 1122, in __call__
    return self.__send(self.__name, args)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/xmlrpc/client.py", line 1461, in __request
    response = self.__transport.request(
               ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/xmlrpc/client.py", line 1166, in request
    return self.single_request(host, handler, request_body, verbose)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/xmlrpc/client.py", line 1178, in single_request
    http_conn = self.send_request(host, handler, request_body, verbose)
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/xmlrpc/client.py", line 1291, in send_request
    self.send_content(connection, request_body)
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/xmlrpc/client.py", line 1321, in send_content
    connection.endheaders(request_body)
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/http/client.py", line 1331, in endheaders
    self._send_output(message_body, encode_chunked=encode_chunked)
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/http/client.py", line 1091, in _send_output
    self.send(msg)
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/http/client.py", line 1035, in send
    self.connect()
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/http/client.py", line 1011, in connect
    self._tunnel()
  File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/http/client.py", line 979, in _tunnel
    raise OSError(f"Tunnel connection failed: {code} {message.strip()}")
OSError: Tunnel connection failed: 403 Forbidden
[W 2025-03-18 13:42:31.750 ServerApp] wrote error: 'Unhandled error'
    Traceback (most recent call last):
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/tornado/web.py", line 1790, in _execute
        result = await result
                 ^^^^^^^^^^^^
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterlab/handlers/extension_manager_handler.py", line 37, in get
        extensions, last_page = await self.manager.list_extensions(query, page, per_page)
                                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterlab/extensions/manager.py", line 474, in list_extensions
        await self.refresh(query, page, per_page)
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterlab/extensions/manager.py", line 508, in refresh
        await self._update_extensions_list(query, page, per_page)
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterlab/extensions/manager.py", line 681, in _update_extensions_list
        extensions, last_page = await self.list_packages(query, page, per_page)
                                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterlab/extensions/pypi.py", line 270, in list_packages
        matches = await self.__get_all_extensions()
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterlab/extensions/pypi.py", line 324, in __get_all_extensions
        self.__all_packages_cache = await self.__throttleRequest(
                                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/site-packages/jupyterlab/extensions/pypi.py", line 223, in __throttleRequest
        data = await current_loop.run_in_executor(None, fn, *args)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/concurrent/futures/thread.py", line 58, in run
        result = self.fn(*self.args, **self.kwargs)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/xmlrpc/client.py", line 1122, in __call__
        return self.__send(self.__name, args)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/xmlrpc/client.py", line 1461, in __request
        response = self.__transport.request(
                   ^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/xmlrpc/client.py", line 1166, in request
        return self.single_request(host, handler, request_body, verbose)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/xmlrpc/client.py", line 1178, in single_request
        http_conn = self.send_request(host, handler, request_body, verbose)
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/xmlrpc/client.py", line 1291, in send_request
        self.send_content(connection, request_body)
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/xmlrpc/client.py", line 1321, in send_content
        connection.endheaders(request_body)
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/http/client.py", line 1331, in endheaders
        self._send_output(message_body, encode_chunked=encode_chunked)
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/http/client.py", line 1091, in _send_output
        self.send(msg)
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/http/client.py", line 1035, in send
        self.connect()
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/http/client.py", line 1011, in connect
        self._tunnel()
      File "/nsls2/software/common/jupyter/jupyter-server-env/.pixi/envs/prod/lib/python3.12/http/client.py", line 979, in _tunnel
        raise OSError(f"Tunnel connection failed: {code} {message.strip()}")
    OSError: Tunnel connection failed: 403 Forbidden
5

Interestingly I can reproduce the exception shown in that log with a GET with bearer token /user/jsmith/lab/api/extensions?query&page=1&per_page=30&refresh=0&1742319751723

Then when I GET /user/jsmith/lab/api/extensions I get the expected payload (list of extensions). However I’m not sure if this is unrelated issue.

6

I’m not certain those errors are related or not. Sorry, do you have logs from JupyterHub about that server from shortly before the errors start happening?

Is the server accessible and usable when these errors are being logged? If so, can you run:

import os
import requests

r = requests.get(
    f"{os.environ['JUPYTERHUB_API_URL']}/user",
    headers={"Authorization": f"Bearer {os.environ['JUPYTERHUB_API_TOKEN']}"},
)
r.json()
7

Ah! I should’ve pointed out the singleuser servers are working and the users are working we are not dead in the water.
Here is a 2m slice of journal logs grepping for a username to show activity:

[root@jupyter2 ~]# journalctl -xe -n all -S -2m | grep akhan1
Mar 19 07:09:30 jupyter2.nsls2.bnl.gov configurable-http-proxy[988026]: 07:09:30.857 [ConfigProxy] debug: PROXY WEB /hub/api/users/akhan1/activity to http://127.0.0.1:8081
Mar 19 07:09:30 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-19 07:09:30.862 JupyterHub base:411] Refreshing auth for akhan1
Mar 19 07:09:30 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-19 07:09:30.864 JupyterHub scopes:1010] Checking access to /hub/api/users/akhan1/activity via scope users:activity!user=akhan1
Mar 19 07:09:30 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-19 07:09:30.868 JupyterHub users:1011] Not updating activity for <User(akhan1 1/1 running)>: 2025-03-19T11:03:29.911017Z < 2025-03-19T11:03:59.874000Z
Mar 19 07:09:30 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-19 07:09:30.868 JupyterHub users:1032] Not updating server activity on akhan1/: 2025-03-19T11:03:29.911017Z < 2025-03-19T11:03:59.874000Z
Mar 19 07:09:30 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-19 07:09:30.869 JupyterHub log:192] 200 POST /hub/api/users/akhan1/activity (akhan1@10.46.1.14) 10.67ms
Mar 19 07:09:55 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-19 07:09:55.611 JupyterHub batchspawner:314] Spawner querying job: sudo -E -u akhan1 squeue -h -j 1209779 -o '%T %B'
Mar 19 07:09:55 jupyter2.nsls2.bnl.gov sudo[227822]:  jupyter : PWD=/etc/jupyterhub ; USER=akhan1 ; TSID=001V06 ; COMMAND=/usr/local/bin/squeue -h -j 1209779 -o '%T %B'
Mar 19 07:09:55 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=CRED_REFR msg=audit(1742382595.951:51231197): pid=227822 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="akhan1" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 19 07:09:55 jupyter2.nsls2.bnl.gov adclient[2161691]: INFO  AUDIT_TRAIL|Centrify Suite|PAM|1.0|500|PAM open session granted|5|user=akhan1(type:ad,akhan1@bnl.gov) pid=227822 utc=1742382595969 centrifyEventID=24500 DASessID=N/A DAInst=N/A status=GRANTED service=sudo tty=(none) client=(none)
Mar 19 07:09:56 jupyter2.nsls2.bnl.gov unix_chkpwd[227830]: could not obtain user info (akhan1)
Mar 19 07:09:56 jupyter2.nsls2.bnl.gov adclient[2161691]: INFO  AUDIT_TRAIL|Centrify Suite|PAM|1.0|301|PAM account management denied|5|user=akhan1(type:ad,akhan1@bnl.gov) pid=227829 utc=1742382596090 centrifyEventID=24301 DASessID=N/A DAInst=N/A status=DENIED service=systemd-user tty=(none) client=(none) reason=Permission denied
Mar 19 07:09:56 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=USER_ACCT msg=audit(1742382596.089:51231202): pid=227829 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='op=PAM:accounting grantors=? acct="akhan1" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' UID="root" AUID="unset"
Mar 19 07:09:56 jupyter2.nsls2.bnl.gov systemd[1]: Started Session c2097629 of User akhan1.
Mar 19 07:09:56 jupyter2.nsls2.bnl.gov sudo[227822]: pam_unix(sudo:session): session opened for user akhan1(uid=400286) by (uid=540)
Mar 19 07:09:56 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=USER_START msg=audit(1742382596.107:51231204): pid=227822 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:session_open grantors=pam_centrifydc,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="akhan1" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 19 07:09:56 jupyter2.nsls2.bnl.gov adclient[2161691]: INFO  AUDIT_TRAIL|Centrify Suite|PAM|1.0|600|PAM close session granted|5|user=akhan1(type:ad,akhan1@bnl.gov) pid=227822 utc=1742382596137 centrifyEventID=24600 DASessID=N/A DAInst=N/A status=GRANTED service=sudo tty=(none) client=(none)
Mar 19 07:09:56 jupyter2.nsls2.bnl.gov sudo[227822]: pam_unix(sudo:session): session closed for user akhan1
Mar 19 07:09:56 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=USER_END msg=audit(1742382596.139:51231205): pid=227822 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:session_close grantors=pam_centrifydc,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="akhan1" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 19 07:09:56 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=CRED_DISP msg=audit(1742382596.139:51231206): pid=227822 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="akhan1" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 19 07:10:25 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-19 07:10:25.464 JupyterHub batchspawner:314] Spawner querying job: sudo -E -u akhan1 squeue -h -j 1209779 -o '%T %B'
Mar 19 07:10:25 jupyter2.nsls2.bnl.gov sudo[228205]:  jupyter : PWD=/etc/jupyterhub ; USER=akhan1 ; TSID=001V1B ; COMMAND=/usr/local/bin/squeue -h -j 1209779 -o '%T %B'
Mar 19 07:10:25 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=CRED_REFR msg=audit(1742382625.935:51231626): pid=228205 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="akhan1" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 19 07:10:25 jupyter2.nsls2.bnl.gov adclient[2161691]: INFO  AUDIT_TRAIL|Centrify Suite|PAM|1.0|500|PAM open session granted|5|user=akhan1(type:ad,akhan1@bnl.gov) pid=228205 utc=1742382625956 centrifyEventID=24500 DASessID=N/A DAInst=N/A status=GRANTED service=sudo tty=(none) client=(none)
Mar 19 07:10:26 jupyter2.nsls2.bnl.gov unix_chkpwd[228215]: could not obtain user info (akhan1)
Mar 19 07:10:26 jupyter2.nsls2.bnl.gov adclient[2161691]: INFO  AUDIT_TRAIL|Centrify Suite|PAM|1.0|301|PAM account management denied|5|user=akhan1(type:ad,akhan1@bnl.gov) pid=228213 utc=1742382626120 centrifyEventID=24301 DASessID=N/A DAInst=N/A status=DENIED service=systemd-user tty=(none) client=(none) reason=Permission denied
Mar 19 07:10:26 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=USER_ACCT msg=audit(1742382626.120:51231632): pid=228213 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='op=PAM:accounting grantors=? acct="akhan1" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' UID="root" AUID="unset"
Mar 19 07:10:26 jupyter2.nsls2.bnl.gov systemd[1]: Started Session c2097669 of User akhan1.
Mar 19 07:10:26 jupyter2.nsls2.bnl.gov sudo[228205]: pam_unix(sudo:session): session opened for user akhan1(uid=400286) by (uid=540)
Mar 19 07:10:26 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=USER_START msg=audit(1742382626.143:51231634): pid=228205 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:session_open grantors=pam_centrifydc,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="akhan1" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 19 07:10:26 jupyter2.nsls2.bnl.gov adclient[2161691]: INFO  AUDIT_TRAIL|Centrify Suite|PAM|1.0|600|PAM close session granted|5|user=akhan1(type:ad,akhan1@bnl.gov) pid=228205 utc=1742382626171 centrifyEventID=24600 DASessID=N/A DAInst=N/A status=GRANTED service=sudo tty=(none) client=(none)
Mar 19 07:10:26 jupyter2.nsls2.bnl.gov sudo[228205]: pam_unix(sudo:session): session closed for user akhan1
Mar 19 07:10:26 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=USER_END msg=audit(1742382626.171:51231638): pid=228205 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:session_close grantors=pam_centrifydc,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="akhan1" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 19 07:10:26 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=CRED_DISP msg=audit(1742382626.171:51231639): pid=228205 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="akhan1" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 19 07:10:55 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-19 07:10:55.524 JupyterHub batchspawner:314] Spawner querying job: sudo -E -u akhan1 squeue -h -j 1209779 -o '%T %B'
Mar 19 07:10:56 jupyter2.nsls2.bnl.gov sudo[228565]:  jupyter : PWD=/etc/jupyterhub ; USER=akhan1 ; TSID=001V2E ; COMMAND=/usr/local/bin/squeue -h -j 1209779 -o '%T %B'
Mar 19 07:10:56 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=CRED_REFR msg=audit(1742382656.212:51232033): pid=228565 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="akhan1" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 19 07:10:56 jupyter2.nsls2.bnl.gov adclient[2161691]: INFO  AUDIT_TRAIL|Centrify Suite|PAM|1.0|500|PAM open session granted|5|user=akhan1(type:ad,akhan1@bnl.gov) pid=228565 utc=1742382656243 centrifyEventID=24500 DASessID=N/A DAInst=N/A status=GRANTED service=sudo tty=(none) client=(none)
Mar 19 07:10:56 jupyter2.nsls2.bnl.gov unix_chkpwd[228589]: could not obtain user info (akhan1)
Mar 19 07:10:56 jupyter2.nsls2.bnl.gov adclient[2161691]: INFO  AUDIT_TRAIL|Centrify Suite|PAM|1.0|301|PAM account management denied|5|user=akhan1(type:ad,akhan1@bnl.gov) pid=228586 utc=1742382656435 centrifyEventID=24301 DASessID=N/A DAInst=N/A status=DENIED service=systemd-user tty=(none) client=(none) reason=Permission denied
Mar 19 07:10:56 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=USER_ACCT msg=audit(1742382656.434:51232049): pid=228586 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='op=PAM:accounting grantors=? acct="akhan1" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' UID="root" AUID="unset"
Mar 19 07:10:56 jupyter2.nsls2.bnl.gov systemd[1]: Started Session c2097708 of User akhan1.
Mar 19 07:10:56 jupyter2.nsls2.bnl.gov sudo[228565]: pam_unix(sudo:session): session opened for user akhan1(uid=400286) by (uid=540)
Mar 19 07:10:56 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=USER_START msg=audit(1742382656.459:51232056): pid=228565 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:session_open grantors=pam_centrifydc,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="akhan1" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 19 07:10:56 jupyter2.nsls2.bnl.gov adclient[2161691]: INFO  AUDIT_TRAIL|Centrify Suite|PAM|1.0|600|PAM close session granted|5|user=akhan1(type:ad,akhan1@bnl.gov) pid=228565 utc=1742382656490 centrifyEventID=24600 DASessID=N/A DAInst=N/A status=GRANTED service=sudo tty=(none) client=(none)
Mar 19 07:10:56 jupyter2.nsls2.bnl.gov sudo[228565]: pam_unix(sudo:session): session closed for user akhan1
Mar 19 07:10:56 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=USER_END msg=audit(1742382656.490:51232060): pid=228565 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:session_close grantors=pam_centrifydc,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="akhan1" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 19 07:10:56 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=CRED_DISP msg=audit(1742382656.490:51232061): pid=228565 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="akhan1" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 19 07:11:24 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-19 07:11:24.951 JupyterHub batchspawner:314] Spawner querying job: sudo -E -u akhan1 squeue -h -j 1209779 -o '%T %B'
Mar 19 07:11:25 jupyter2.nsls2.bnl.gov sudo[228936]:  jupyter : PWD=/etc/jupyterhub ; USER=akhan1 ; TSID=001V3F ; COMMAND=/usr/local/bin/squeue -h -j 1209779 -o '%T %B'
Mar 19 07:11:25 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=CRED_REFR msg=audit(1742382685.140:51232441): pid=228936 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="akhan1" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 19 07:11:25 jupyter2.nsls2.bnl.gov adclient[2161691]: INFO  AUDIT_TRAIL|Centrify Suite|PAM|1.0|500|PAM open session granted|5|user=akhan1(type:ad,akhan1@bnl.gov) pid=228936 utc=1742382685155 centrifyEventID=24500 DASessID=N/A DAInst=N/A status=GRANTED service=sudo tty=(none) client=(none)
Mar 19 07:11:25 jupyter2.nsls2.bnl.gov unix_chkpwd[228943]: could not obtain user info (akhan1)
Mar 19 07:11:25 jupyter2.nsls2.bnl.gov adclient[2161691]: INFO  AUDIT_TRAIL|Centrify Suite|PAM|1.0|301|PAM account management denied|5|user=akhan1(type:ad,akhan1@bnl.gov) pid=228942 utc=1742382685409 centrifyEventID=24301 DASessID=N/A DAInst=N/A status=DENIED service=systemd-user tty=(none) client=(none) reason=Permission denied
Mar 19 07:11:25 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=USER_ACCT msg=audit(1742382685.408:51232443): pid=228942 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='op=PAM:accounting grantors=? acct="akhan1" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' UID="root" AUID="unset"
Mar 19 07:11:25 jupyter2.nsls2.bnl.gov systemd[1]: Started Session c2097746 of User akhan1.
Mar 19 07:11:25 jupyter2.nsls2.bnl.gov sudo[228936]: pam_unix(sudo:session): session opened for user akhan1(uid=400286) by (uid=540)
Mar 19 07:11:25 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=USER_START msg=audit(1742382685.438:51232448): pid=228936 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:session_open grantors=pam_centrifydc,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="akhan1" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 19 07:11:25 jupyter2.nsls2.bnl.gov adclient[2161691]: INFO  AUDIT_TRAIL|Centrify Suite|PAM|1.0|600|PAM close session granted|5|user=akhan1(type:ad,akhan1@bnl.gov) pid=228936 utc=1742382685454 centrifyEventID=24600 DASessID=N/A DAInst=N/A status=GRANTED service=sudo tty=(none) client=(none)
Mar 19 07:11:25 jupyter2.nsls2.bnl.gov sudo[228936]: pam_unix(sudo:session): session closed for user akhan1
Mar 19 07:11:25 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=USER_END msg=audit(1742382685.453:51232449): pid=228936 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:session_close grantors=pam_centrifydc,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="akhan1" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 19 07:11:25 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=CRED_DISP msg=audit(1742382685.454:51232450): pid=228936 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="akhan1" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
8

Indeed I get a response for that for myself:

{'name': 'msnyder',
 'groups': [],
 'admin': True,
 'last_activity': '2025-03-19T11:13:30.712251Z',
 'kind': 'user',
 'token_id': 'a6019',
 'session_id': None,
 'scopes': ['access:servers!server=msnyder/',
  'read:users:activity!user=msnyder',
  'read:users:groups!user=msnyder',
  'read:users:name!user=msnyder',
  'users:activity!user=msnyder']}
9

I see you are on a HPC system. Are you using HTTP Proxy on compute nodes? If so, are you sure that the proxy env variables are being set on single user server process?

10

Thanks Mahendra. Yes we are using a proxy like this:

env | grep -i proxy
http_proxy=http://proxy{...}:3128
https_proxy=http://proxy{...}:3128
no_proxy=.bnl.local,.bnl.gov

(redacted some of it)
And it’s successfully used to communicate back to the hub.

11

ok, it really doesn’t make sense to me that you can make a request with $JUPYTERHUB_API_TOKEN to /api/user, but requests to /api/users/:user/activity are failing with 403 at the same time with the same token. That’s very mysterious. Just to be clear, you do have logs showing that:

  1. activity requests are failing with 403
  2. manual requests to /api/user with $JUPYTERHUB_API_TOKEN at the same time, from the same server succeed and return users:activity...?

I know you’ve confirmed that both situations are happening, but I want to be extra sure that they are confirmed to be happening at the same time with the same token from the same server (i.e. JupyterHub logs show 403 on /users/:name/activity, then 200 on /api/user from that user, then another 403 on /users/:name/activity). Because I don’t understand how that could be the case, and it will take some serious mystery solving to track down if that’s really what’s happening.

12

@minrk This can happen in a specific case of using HTTP Proxy. If the HTTP Proxy env variables are not set on single user server process, it will not be able to contact Hub. But when we launch a terminal in JupyterLab, it sources /etc/profile which presumably populates HTTP Proxy variables. So, assuming that API request scriplet is executed from terminal of the single user server, yes, we will get response from hub.

@maatthias is using batch spawner and it makes an API request to hub to send port information. Not sure if that request is being successful or not.

@maatthias Could you share the logs of only JupyterHub using journalctl -r -u jupyterhub right from the time where you start spawning process till the single user server has spawned? Also can you check the env variables of single user server using /proc/<pid of single user server>/environ to ensure that HTTP Proxy vars are set? Cheers!!

1 Like
13

Hi minrk- I had a user run these in his single-user server (who is currently POSTing 403s back to jupyterhub) Here are the results:

curl -XGET -H "Authorization: Bearer ${JUPYTERHUB_API_TOKEN}" -H "Accept: application/json" https://jupyter.nsls2.bnl.gov/hub/api/user
{"name": "rmahon", "groups": [], "admin": false, "last_activity": "2025-03-21T15:33:16.213899Z", "kind": "user", "token_id": "a6113", "session_id": null, "scopes": ["access:servers!server=rmahon/chx-staff", "read:users:activity!user=rmahon", "read:users:groups!user=rmahon", "read:users:name!user=rmahon", "users:activity!user=rmahon"]}

echo $JUPYTERHUB_ACTIVITY_URL
https://jupyter.nsls2.bnl.gov/hub/api/users/rmahon/activity

curl -XGET -H "Authorization: Bearer ${JUPYTERHUB_API_TOKEN}" ${JUPYTERHUB_ACTIVITY_URL}
{"status": 405, "message": "Method Not Allowed"}
14

There is no GET handler on activity, only POST, so that 405 makes sense. Can you try a POST? with an empty body (it should give you a 400, but that would mean everything’s working).

15

Hello Mahendra- Yes here is the jupyterhub log while spawn …

Mar 21 12:13:55 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:13:55.771 JupyterHub log:192] 302 GET /user/msnyder/403test/dask/clusters?1742573635748 -> /hub/user/msnyder/403test/dask/clusters?1742573635748 (@192.203.218.25) 0.77ms
Mar 21 12:13:55 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [W 2025-03-21 12:13:55.806 JupyterHub log:192] 424 GET /hub/user/msnyder/403test/dask/clusters?1742573635748 (msnyder@192.203.218.25) 7.97ms
Mar 21 12:14:01 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:01.236 JupyterHub log:192] 302 GET /hub/ -> /hub/admin (msnyder@192.203.218.25) 6.20ms
Mar 21 12:14:01 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:01.283 JupyterHub log:192] 304 GET /hub/admin (msnyder@192.203.218.25) 7.83ms
Mar 21 12:14:01 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:01.507 JupyterHub log:192] 200 GET /hub/api/users?include_stopped_servers=1&offset=0&limit=50&name_filter=&sort=id&state=[secret]&_xsrf=[secret] (msnyder@192.203.218.25) 36.18ms
Mar 21 12:14:12 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:12.109 JupyterHub log:192] 200 GET /hub/home (msnyder@192.203.218.25) 7.43ms
Mar 21 12:14:27 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:27.442 JupyterHub scopes:1010] Checking access to /hub/spawn/msnyder/403test via scope servers!server=msnyder/403test
Mar 21 12:14:27 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:27.443 JupyterHub user:496] Creating <class 'wrapspawner.wrapspawner.ProfilesSpawner'> for msnyder:403test
Mar 21 12:14:27 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:27.447 JupyterHub pages:208] Serving options form for msnyder:403test
Mar 21 12:14:27 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:27.449 JupyterHub log:192] 304 GET /hub/spawn/msnyder/403test (msnyder@192.203.218.25) 11.80ms
Mar 21 12:14:31 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:31.159 JupyterHub scopes:1010] Checking access to /hub/spawn/msnyder/403test via scope servers!server=msnyder/403test
Mar 21 12:14:31 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:31.160 JupyterHub pages:256] Triggering spawn with supplied form options for msnyder:403test
Mar 21 12:14:31 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:31.161 JupyterHub base:1095] Initiating spawn for msnyder:403test
Mar 21 12:14:31 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:31.175 JupyterHub provider:661] Creating oauth client jupyterhub-user-msnyder-403test
Mar 21 12:14:31 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:31.186 JupyterHub user:913] Calling Spawner.start for msnyder:403test
Mar 21 12:14:31 jupyter2.nsls2.bnl.gov sudo[3779154]:  jupyter : PWD=/etc/jupyterhub ; USER=msnyder ; TSID=001RQR ; COMMAND=/bin/mkdir -p /nsls2/users/msnyder/.local/var/log/jupyterhub_batchspawner/
Mar 21 12:14:31 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:31.737 JupyterHub batchspawner:281] Spawner script options: {'account': '', 'cluster': '', 'epilogue': '', 'gres': '', 'homedir': '', 'host': '', 'keepvars': 'PATH,LANG,JUPYTERHUB_API_TOKEN,JPY_API_TOKEN,JUPYTERHUB_CLIENT_ID,JUPYTERHUB_COOKIE_HOST_PREFIX_ENABLED,JUPYTERHUB_HOST,JUPYTERHUB_OAUTH_CALLBACK_URL,JUPYTERHUB_OAUTH_SCOPES,JUPYTERHUB_OAUTH_ACCESS_SCOPES,JUPYTERHUB_OAUTH_CLIENT_ALLOWED_SCOPES,JUPYTERHUB_USER,JUPYTERHUB_SERVER_NAME,JUPYTERHUB_API_URL,JUPYTERHUB_ACTIVITY_URL,JUPYTERHUB_BASE_URL,JUPYTERHUB_SERVICE_PREFIX,JUPYTERHUB_SERVICE_URL,JUPYTERHUB_PUBLIC_URL,JUPYTERHUB_PUBLIC_HUB_URL,JUPYTERHUB_ROOT_DIR,JUPYTERHUB_DEFAULT_URL,TILED_SITE_PROFILES,TZ,http_proxy,https_proxy,no_proxy,JUPYTER_CONFIG_PATH,JUPYTER_PATH,DASK_CONFIG_BASE,JUPYTERHUB_STAGE,USER,HOME,SHELL', 'keepvars_extra': '', 'memory': '256gb', 'ngpus': '', 'nprocs': '8', 'options': '', 'partition': 'jupyter', 'prologue': '\nexport PATH=, 'qos': '', 'queue': '', 'reservation': '', 'runtime': '7-1', 'srun': 'srun', 'username': 'msnyder', 'cmd': 'batchspawner-singleuser /.../cmd --NotebookApp.default_url=/lab', 'profile': 'pixi-test'}
Mar 21 12:14:31 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:31.737 JupyterHub batchspawner:282] Spawner submitting command: sudo -E -u msnyder sbatch --parsable
Mar 21 12:14:31 jupyter2.nsls2.bnl.gov jupyterhub[1232207]:     #SBATCH --output=/nsls2/users/msnyder/.local/var/log/jupyterhub_batchspawner/jupyterhub_slurmspawner_%j.log
Mar 21 12:14:31 jupyter2.nsls2.bnl.gov jupyterhub[1232207]:     #SBATCH --chdir=/nsls2/users/msnyder
Mar 21 12:14:31 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:31.739 JupyterHub batchspawner:284] Spawner submitting environment: {'PATH': '/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/opt/jupyterhub/bin', 'LANG': 'en_US.UTF-8', 'JUPYTERHUB_API_TOKEN': 'ee2b...', 'JPY_API_TOKEN': 'ee2b...', 'JUPYTERHUB_CLIENT_ID': 'jupyterhub-user-msnyder-403test', 'JUPYTERHUB_COOKIE_HOST_PREFIX_ENABLED': '0', 'JUPYTERHUB_HOST': '', 'JUPYTERHUB_OAUTH_CALLBACK_URL': '/user/msnyder/403test/oauth_callback', 'JUPYTERHUB_OAUTH_SCOPES': '["access:servers!server=msnyder/403test", "access:servers!user=msnyder"]', 'JUPYTERHUB_OAUTH_ACCESS_SCOPES': '["access:servers!server=msnyder/403test", "access:servers!user=msnyder"]', 'JUPYTERHUB_OAUTH_CLIENT_ALLOWED_SCOPES': '[]', 'JUPYTERHUB_USER': 'msnyder', 'JUPYTERHUB_SERVER_NAME': '403test', 'JUPYTERHUB_API_URL': 'https://jupyter.nsls2.bnl.gov/hub/api', 'JUPYTERHUB_ACTIVITY_URL': 'https://jupyter.nsls2.bnl.gov/hub/api/users/msnyder/activity', 'JUPYTERHUB_BASE_URL': '/', 'JUPYTERHUB_SERVICE_PREFIX': '/user/msnyder/403test/', 'JUPYTERHUB_SERVICE_URL': 'http://0.0.0.0:0/user/msnyder/403test/', 'JUPYTERHUB_PUBLIC_URL': '', 'JUPYTERHUB_PUBLIC_HUB_URL': '', 'JUPYTERHUB_ROOT_DIR': '/', 'JUPYTERHUB_DEFAULT_URL': '/lab/tree/nsls2/users/msnyder', 'TZ': 'EST5EDT', 'http_proxy': 'http://proxy...:3128', 'https_proxy': 'http://proxy...:3128', 'no_proxy': '.bnl.local,.bnl.gov', 'JUPYTER_CONFIG_PATH': , 'JUPYTER_PATH': , 'DASK_CONFIG_BASE': '', 'JUPYTERHUB_STAGE': 'prod', 'USER': 'msnyder', 'HOME': '', 'SHELL': '/bin/bash'}
Mar 21 12:14:31 jupyter2.nsls2.bnl.gov sudo[3779170]:  jupyter : PWD=/etc/jupyterhub ; USER=msnyder ; TSID=001RQT ; COMMAND=/usr/local/bin/sbatch --parsable
Mar 21 12:14:31 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:31.995 JupyterHub batchspawner:314] Spawner querying job: sudo -E -u msnyder squeue -h -j 1210711 -o '%T %B'
Mar 21 12:14:32 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:32.162 JupyterHub log:192] 302 POST /hub/spawn/msnyder/403test?_xsrf=[secret] -> /hub/spawn-pending/msnyder/403test?_xsrf=[secret] (msnyder@192.203.218.25) 1008.45ms
Mar 21 12:14:32 jupyter2.nsls2.bnl.gov sudo[3779178]:  jupyter : PWD=/etc/jupyterhub ; USER=msnyder ; TSID=001RQU ; COMMAND=/usr/local/bin/squeue -h -j 1210711 -o '%T %B'
Mar 21 12:14:32 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:32.198 JupyterHub scopes:1010] Checking access to /hub/spawn-pending/msnyder/403test via scope servers!server=msnyder/403test
Mar 21 12:14:32 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:32.198 JupyterHub pages:397] msnyder:403test is pending spawn
Mar 21 12:14:32 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:32.199 JupyterHub log:192] 200 GET /hub/spawn-pending/msnyder/403test?_xsrf=[secret] (msnyder@192.203.218.25) 8.21ms
Mar 21 12:14:32 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:32.333 JupyterHub scopes:1010] Checking access to /hub/api/users/msnyder/servers/403test/progress via scope read:servers!server=msnyder/403test
Mar 21 12:14:35 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:35.682 JupyterHub base:366] Recording first activity for <APIToken('ee2b...', user='msnyder', client_id='jupyterhub')>
Mar 21 12:14:35 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:35.686 JupyterHub log:192] 200 POST /hub/api/batchspawner (msnyder@10.46.1.12) 6.39ms
Mar 21 12:14:35 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:35.733 JupyterHub utils:292] Waiting 360s for server at http://hpc003:53625/user/msnyder/403test/api
Mar 21 12:14:41 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:41.162 JupyterHub batchspawner:314] Spawner querying job: sudo -E -u msnyder squeue -h -j 1210711 -o '%T %B'
Mar 21 12:14:41 jupyter2.nsls2.bnl.gov sudo[3779377]:  jupyter : PWD=/etc/jupyterhub ; USER=msnyder ; TSID=001RRC ; COMMAND=/usr/local/bin/squeue -h -j 1210711 -o '%T %B'
Mar 21 12:14:41 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [W 2025-03-21 12:14:41.505 JupyterHub base:1258] User msnyder:403test is slow to become responsive (timeout=10)
Mar 21 12:14:41 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:41.505 JupyterHub base:1263] Expecting server for msnyder:403test at: http://hpc003:53625/user/msnyder/403test/
Mar 21 12:14:45 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:45.409 JupyterHub scopes:1010] Checking access to /hub/api/users/msnyder/activity via scope users:activity!user=msnyder
Mar 21 12:14:45 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:45.414 JupyterHub users:1006] Activity for user msnyder: 2025-03-21T16:14:45.035304Z
Mar 21 12:14:45 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:45.414 JupyterHub users:1024] Activity on server msnyder/403test: 2025-03-21T16:14:45.035304Z
Mar 21 12:14:45 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:45.417 JupyterHub log:192] 200 POST /hub/api/users/msnyder/activity (msnyder@10.46.1.12) 10.67ms
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:47.832 JupyterHub utils:328] Server at http://hpc003:53625/user/msnyder/403test/api responded in 12.10s
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:47.832 JupyterHub base:1124] User msnyder:403test took 16.672 seconds to start
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:47.832 JupyterHub proxy:331] Adding user msnyder to proxy /user/msnyder/403test/ => http://hpc003:53625
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:47.833 JupyterHub proxy:925] Proxy: Fetching POST http://localhost:8001/api/routes/user/msnyder/403test
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:47.835 JupyterHub users:899] Server msnyder:403test is ready
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:47.835 JupyterHub log:192] 200 GET /hub/api/users/msnyder/servers/403test/progress?_xsrf=[secret] (msnyder@192.203.218.25) 15507.77ms
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:47.884 JupyterHub scopes:1010] Checking access to /hub/spawn-pending/msnyder/403test via scope servers!server=msnyder/403test
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:47.884 JupyterHub log:192] 302 GET /hub/spawn-pending/msnyder/403test?_xsrf=[secret] -> /user/msnyder/403test/ (msnyder@192.203.218.25) 7.16ms
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:47.961 JupyterHub provider:421] Validating client id jupyterhub-user-msnyder-403test
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:47.962 oauthlib.oauth2.rfc6749.grant_types.authorization_code authorization_code:362] Validating redirection uri /user/msnyder/403test/oauth_callback for client jupyterhub-user-msnyder-403test.
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:47.963 oauthlib.oauth2.rfc6749.grant_types.base base:231] Using provided redirect_uri /user/msnyder/403test/oauth_callback
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:47.963 JupyterHub provider:497] validate_redirect_uri: client_id=jupyterhub-user-msnyder-403test, redirect_uri=/user/msnyder/403test/oauth_callback
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:47.965 oauthlib.oauth2.rfc6749.grant_types.base base:172] Validating access to scopes ['read:users:groups!user', 'read:users:name!user', 'access:servers!server=msnyder/403test'] for client 'jupyterhub-user-msnyder-403test' (<OAuthClient(identifier='jupyterhub-user-msnyder-403test')>).
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:47.966 JupyterHub provider:624] Allowing request for scope(s) for jupyterhub-user-msnyder-403test:  access:servers!server=msnyder/403test,read:users:name!user,read:users:groups!user
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:47.967 JupyterHub auth:326] Skipping oauth confirmation for <User(msnyder 1/2 running)> accessing Server at /user/msnyder/403test/
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:47.967 JupyterHub provider:421] Validating client id jupyterhub-user-msnyder-403test
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:47.968 oauthlib.oauth2.rfc6749.grant_types.authorization_code authorization_code:362] Validating redirection uri /user/msnyder/403test/oauth_callback for client jupyterhub-user-msnyder-403test.
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:47.968 oauthlib.oauth2.rfc6749.grant_types.base base:231] Using provided redirect_uri /user/msnyder/403test/oauth_callback
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:47.968 JupyterHub provider:497] validate_redirect_uri: client_id=jupyterhub-user-msnyder-403test, redirect_uri=/user/msnyder/403test/oauth_callback
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:47.969 oauthlib.oauth2.rfc6749.grant_types.base base:172] Validating access to scopes {'access:servers!server=msnyder/403test', 'read:users:name!user', 'read:users:groups!user'} for client 'jupyterhub-user-msnyder-403test' (<OAuthClient(identifier='jupyterhub-user-msnyder-403test')>).
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:47.970 JupyterHub provider:624] Allowing request for scope(s) for jupyterhub-user-msnyder-403test:  access:servers!server=msnyder/403test,read:users:name!user,read:users:groups!user
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:47.970 JupyterHub provider:247] Saving authorization code jupyterhub-user-msnyder-403test, 2r2..., (), {}
Mar 21 12:14:47 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:47.975 JupyterHub log:192] 302 GET /hub/api/oauth2/authorize?client_id=jupyterhub-user-msnyder-403test&redirect_uri=%2Fuser%2Fmsnyder%2F403test%2Foauth_callback&response_type=code&state=[secret] -> /user/msnyder/403test/oauth_callback?code=[secret]&state=[secret] (msnyder@192.203.218.25) 20.62ms
Mar 21 12:14:48 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:48.021 oauthlib.oauth2.rfc6749.grant_types.authorization_code authorization_code:533] Using provided redirect_uri /user/msnyder/403test/oauth_callback
Mar 21 12:14:48 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:48.022 JupyterHub provider:117] confirm_redirect_uri: client_id=jupyterhub-user-msnyder-403test, redirect_uri=/user/msnyder/403test/oauth_callback
Mar 21 12:14:48 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:48.022 JupyterHub provider:345] Saving bearer token {'access_token': 'REDACTED', 'expires_in': 1209600, 'token_type': 'Bearer', 'scope': 'access:servers!server=msnyder/403test read:users:name!user read:users:groups!user', 'refresh_token': 'REDACTED'}
Mar 21 12:14:48 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:48.028 JupyterHub provider:205] Deleting oauth code 2r2... for jupyterhub-user-msnyder-403test
Mar 21 12:14:48 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:48.033 JupyterHub log:192] 200 POST /hub/api/oauth2/token (msnyder@10.46.1.12) 29.09ms
Mar 21 12:14:48 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-21 12:14:48.047 JupyterHub base:366] Recording first activity for <APIToken('Rx2E...', user='msnyder', client_id='jupyterhub-user-msnyder-403test')>
Mar 21 12:14:48 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [I 2025-03-21 12:14:48.051 JupyterHub log:192] 200 GET /hub/api/user (msnyder@10.46.1.12) 7.32ms
16

@minrk Indeed… POST gives a 400:

curl -XPOST -H "Authorization: Bearer ${JUPYTERHUB_API_TOKEN}" ${JUPYTERHUB_ACTIVITY_URL}
{"status": 400, "message": "body must be a json dict"}

And @mahendrapaipuri indeed proxy env vars are set in process of single-user server:

cat /proc/2431146/environ
...
http_proxy=http://proxy.sdcc.bnl.local:3128
...
https_proxy=http://proxy.sdcc.bnl.local:3128
...
17

Do you have a log snippet from the hub showing 403 before and after and 400 in the middle?

Both requests using the same token and the same endpoint is very strange, and makes me think somehow the token is being rewritten for the activity requests, possibly by a server extension somewhere. I’ll have a think about if/how that might be possible.

18

Sure @minrk here is journal grepped for the user throwing throwing the 403. Let me know if you need wider or perhaps not grepped for username:

Mar 22 14:13:20 jupyter2.nsls2.bnl.gov configurable-http-proxy[988026]: 14:13:20.025 [ConfigProxy] debug: PROXY WEB /hub/api/users/jsmith/activity to http://127.0.0.1:8081
Mar 22 14:13:20 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [W 2025-03-22 14:13:20.030 JupyterHub web:1873] 403 POST /hub/api/users/jsmith/activity (10.66.80.33): Missing or invalid credentials.
Mar 22 14:13:20 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [W 2025-03-22 14:13:20.030 JupyterHub log:192] 403 POST /hub/api/users/jsmith/activity (@10.66.80.33) 3.85ms
Mar 22 14:13:28 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [D 2025-03-22 14:13:28.167 JupyterHub batchspawner:314] Spawner querying job: sudo -E -u jsmith squeue -h -j 1209700 -o '%T %B'
Mar 22 14:13:28 jupyter2.nsls2.bnl.gov sudo[1562009]:  jupyter : PWD=/etc/jupyterhub ; USER=jsmith ; TSID=000QS9 ; COMMAND=/usr/local/bin/squeue -h -j 1209700 -o '%T %B'
Mar 22 14:13:28 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=CRED_REFR msg=audit(1742667208.537:56122637): pid=1562009 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="jsmith" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 22 14:13:28 jupyter2.nsls2.bnl.gov adclient[2161691]: INFO  AUDIT_TRAIL|Centrify Suite|PAM|1.0|500|PAM open session granted|5|user=jsmith(type:ad,jsmith@bnl.gov) pid=1562009 utc=1742667208565 centrifyEventID=24500 DASessID=N/A DAInst=N/A status=GRANTED service=sudo tty=(none) client=(none)
Mar 22 14:13:28 jupyter2.nsls2.bnl.gov unix_chkpwd[1562035]: could not obtain user info (jsmith)
Mar 22 14:13:28 jupyter2.nsls2.bnl.gov adclient[2161691]: INFO  AUDIT_TRAIL|Centrify Suite|PAM|1.0|301|PAM account management denied|5|user=jsmith(type:ad,jsmith@bnl.gov) pid=1562033 utc=1742667208704 centrifyEventID=24301 DASessID=N/A DAInst=N/A status=DENIED service=systemd-user tty=(none) client=(none) reason=Permission denied
Mar 22 14:13:28 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=USER_ACCT msg=audit(1742667208.703:56122656): pid=1562033 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='op=PAM:accounting grantors=? acct="jsmith" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' UID="root" AUID="unset"
Mar 22 14:13:28 jupyter2.nsls2.bnl.gov systemd[1]: Started Session c2545502 of User jsmith.
Mar 22 14:13:28 jupyter2.nsls2.bnl.gov sudo[1562009]: pam_unix(sudo:session): session opened for user jsmith(uid=404233) by (uid=540)
Mar 22 14:13:28 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=USER_START msg=audit(1742667208.712:56122658): pid=1562009 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:session_open grantors=pam_centrifydc,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="jsmith" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 22 14:13:28 jupyter2.nsls2.bnl.gov adclient[2161691]: INFO  AUDIT_TRAIL|Centrify Suite|PAM|1.0|600|PAM close session granted|5|user=jsmith(type:ad,jsmith@bnl.gov) pid=1562009 utc=1742667208727 centrifyEventID=24600 DASessID=N/A DAInst=N/A status=GRANTED service=sudo tty=(none) client=(none)
Mar 22 14:13:28 jupyter2.nsls2.bnl.gov sudo[1562009]: pam_unix(sudo:session): session closed for user jsmith
Mar 22 14:13:28 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=USER_END msg=audit(1742667208.727:56122659): pid=1562009 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:session_close grantors=pam_centrifydc,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="jsmith" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 22 14:13:28 jupyter2.nsls2.bnl.gov audisp-syslog[810]: type=CRED_DISP msg=audit(1742667208.727:56122660): pid=1562009 uid=540 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="jsmith" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success' UID="jupyter" AUID="unset"
Mar 22 14:13:29 jupyter2.nsls2.bnl.gov configurable-http-proxy[988026]: 14:13:29.298 [ConfigProxy] debug: PROXY WEB /hub/api/users/jsmith/activity to http://127.0.0.1:8081
Mar 22 14:13:29 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [W 2025-03-22 14:13:29.301 JupyterHub web:1873] 403 POST /hub/api/users/jsmith/activity (10.66.80.33): Missing or invalid credentials.
Mar 22 14:13:29 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [W 2025-03-22 14:13:29.301 JupyterHub log:192] 403 POST /hub/api/users/jsmith/activity (@10.66.80.33) 2.50ms
Mar 22 14:13:29 jupyter2.nsls2.bnl.gov configurable-http-proxy[988026]: 14:13:29.862 [ConfigProxy] debug: PROXY WEB /hub/api/users/jsmith/activity to http://127.0.0.1:8081
Mar 22 14:13:29 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [W 2025-03-22 14:13:29.864 JupyterHub web:1873] 403 POST /hub/api/users/jsmith/activity (10.66.80.33): Missing or invalid credentials.
Mar 22 14:13:29 jupyter2.nsls2.bnl.gov jupyterhub[1232207]: [W 2025-03-22 14:13:29.865 JupyterHub log:192] 403 POST /hub/api/users/jsmith/activity (@10.66.80.33) 2.25ms
19

Sorry, what I meant was a logs snippet showing both the 403 and the 400, demonstrating that they are happening from the same instance at the same time (and therefore presumably with the same token).

If you can find the first 403 for a given server and show a chunk of hub logs before that, that might shed some light as well.

What Authenticator are you using? Is it PAM?