@manics I selectively removed some of the logs in my earlier post to highlight the entires I thought were problematic. Here is the entire log entry for the hub and proxy. Im not sure what you mean by see all requests and all responses, so let me know if what I provided is enough. If you need extra info I can update the service to output info in the logs.
Error Clarification
When the api-gateway proxies a request to my services via the proxy-api
(via http://proxy-public.ems.svc.cluster.local:80
) I get the following error response in postman.
Error: getaddrinfo ENOTFOUND proxy-public.ems.svc.cluster.local
The service endpoint I am interacting with is simple and returns {status: "ok"}
. When I look at the hub and proxy logs it looks like the request makes it to the hub/service but then something go wrong (i.e. the 307 error in the hub and the error response from postman). it is a liottle confusing because I see a 200 and a 307 response in the logs for the service so im not sure what is happening.
I have attempted running jupyterhub in the same namespace as the api-gateway and adding the access labels to the gateway (i.e. hub.jupyter.org/network-access-proxy-http=true
) but that didnt make any difference.
hub logs
I removed all health check logs because they made the post to large.
[D 2022-11-10 16:28:24.451 JupyterHub application:837] Looking for /usr/local/etc/jupyterhub/jupyterhub_config in /srv/jupyterhub
Loading /usr/local/etc/jupyterhub/secret/values.yaml
No config at /usr/local/etc/jupyterhub/existing-secret/values.yaml
Loading /usr/local/etc/jupyterhub/jupyterhub_config.d config: __init__.py
Loading /usr/local/etc/jupyterhub/jupyterhub_config.d config: custom_services.py
Not working
Loading /usr/local/etc/jupyterhub/jupyterhub_config.d config: custom_spawner.py
[D 2022-11-10 16:28:27.170 JupyterHub application:858] Loaded config file: /usr/local/etc/jupyterhub/jupyterhub_config.py
[I 2022-11-10 16:28:27.178 JupyterHub app:2775] Running JupyterHub version 3.0.0
[I 2022-11-10 16:28:27.179 JupyterHub app:2805] Using Authenticator: jupyterhub.auth.DummyAuthenticator-3.0.0
[I 2022-11-10 16:28:27.179 JupyterHub app:2805] Using Spawner: builtins.CustomSpawner
[I 2022-11-10 16:28:27.179 JupyterHub app:2805] Using Proxy: jupyterhub.proxy.ConfigurableHTTPProxy-3.0.0
[D 2022-11-10 16:28:27.180 JupyterHub app:1783] Connecting to db: sqlite:///jupyterhub.sqlite
[D 2022-11-10 16:28:27.519 JupyterHub orm:967] Stamping empty database with alembic revision 651f5419b74d
[I 2022-11-10 16:28:27.526 alembic.runtime.migration migration:204] Context impl SQLiteImpl.
[I 2022-11-10 16:28:27.526 alembic.runtime.migration migration:207] Will assume non-transactional DDL.
[I 2022-11-10 16:28:27.545 alembic.runtime.migration migration:618] Running stamp_revision -> 651f5419b74d
[D 2022-11-10 16:28:27.546 alembic.runtime.migration migration:818] new branch insert 651f5419b74d
[D 2022-11-10 16:28:27.563 JupyterHub orm:967] Stamping empty database with alembic revision 651f5419b74d
[I 2022-11-10 16:28:27.565 alembic.runtime.migration migration:204] Context impl SQLiteImpl.
[I 2022-11-10 16:28:27.565 alembic.runtime.migration migration:207] Will assume non-transactional DDL.
[D 2022-11-10 16:28:27.764 JupyterHub app:2035] Loading roles into database
[I 2022-11-10 16:28:27.822 JupyterHub roles:173] Role jupyterhub-idle-culler added to database
[I 2022-11-10 16:28:27.831 JupyterHub app:1934] Not using allowed_users. Any authenticated user will be allowed.
[W 2022-11-10 16:28:27.869 JupyterHub app:2312] Service session sets `admin: True`, which is deprecated in JupyterHub 2.0. You can assign now assign roles via `JupyterHub.load_roles` configuration. If you specify services in the admin role configuration, the Service admin flag will be ignored.
[I 2022-11-10 16:28:27.870 JupyterHub roles:238] Adding role admin for Service: session
[I 2022-11-10 16:28:27.897 JupyterHub provider:651] Creating oauth client service-session
[I 2022-11-10 16:28:27.939 JupyterHub app:2244] Adding API token for service: session
[D 2022-11-10 16:28:27.956 JupyterHub app:2274] Purging expired APITokens
[D 2022-11-10 16:28:27.961 JupyterHub app:2274] Purging expired OAuthCodes
[D 2022-11-10 16:28:27.965 JupyterHub app:2110] Loading role assignments from config
[D 2022-11-10 16:28:28.000 JupyterHub app:2433] Initializing spawners
[D 2022-11-10 16:28:28.006 JupyterHub app:2564] Loaded users:
[I 2022-11-10 16:28:28.006 JupyterHub app:2844] Initialized 0 spawners in 0.007 seconds
[I 2022-11-10 16:28:28.010 JupyterHub app:3057] Not starting proxy
[D 2022-11-10 16:28:28.049 JupyterHub proxy:884] Proxy: Fetching GET http://proxy-api:8001/api/routes
[D 2022-11-10 16:28:28.110 JupyterHub proxy:957] Omitting non-jupyterhub route '/'
[I 2022-11-10 16:28:28.126 JupyterHub app:3093] Hub API listening on http://:8081/hub/
[I 2022-11-10 16:28:28.126 JupyterHub app:3095] Private Hub API connect url http://hub:8081/hub/
[I 2022-11-10 16:28:28.126 JupyterHub app:3104] Starting managed service jupyterhub-idle-culler
[I 2022-11-10 16:28:28.126 JupyterHub service:385] Starting service 'jupyterhub-idle-culler': ['python3', '-m', 'jupyterhub_idle_culler', '--url=http://localhost:8081/hub/api', '--timeout=3600', '--cull-every=600', '--concurrency=10']
[I 2022-11-10 16:28:28.130 JupyterHub service:133] Spawning python3 -m jupyterhub_idle_culler --url=http://localhost:8081/hub/api --timeout=3600 --cull-every=600 --concurrency=10
[D 2022-11-10 16:28:28.141 JupyterHub spawner:1369] Polling subprocess every 30s
[I 2022-11-10 16:28:28.142 JupyterHub app:3104] Starting managed service session at http://hub:8181
[I 2022-11-10 16:28:28.143 JupyterHub service:385] Starting service 'session': ['/home/jovyan/.local/bin/uvicorn', 'src.app:app', '--port', '8181', '--host', '0.0.0.0', '--app-dir', '/jhub-services/session']
[I 2022-11-10 16:28:28.148 JupyterHub service:133] Spawning /home/jovyan/.local/bin/uvicorn src.app:app --port 8181 --host 0.0.0.0 --app-dir /jhub-services/session
[D 2022-11-10 16:28:28.159 JupyterHub spawner:1369] Polling subprocess every 30s
[D 2022-11-10 16:28:28.263 JupyterHub log:186] 200 GET /hub/health (@10.36.1.1) 3.31ms
[D 2022-11-10 16:28:28.453 JupyterHub base:275] Recording first activity for <APIToken('4eeb...', service='jupyterhub-idle-culler', client_id='jupyterhub')>
[I 2022-11-10 16:28:28.468 JupyterHub log:186] 200 GET /hub/api/ (jupyterhub-idle-culler@127.0.0.1) 22.39ms
[D 2022-11-10 16:28:28.475 JupyterHub scopes:796] Checking access via scope list:users
[D 2022-11-10 16:28:28.475 JupyterHub scopes:610] Unrestricted access to /hub/api/users via list:users
[I 2022-11-10 16:28:28.485 JupyterHub log:186] 200 GET /hub/api/users?state=[secret] (jupyterhub-idle-culler@127.0.0.1) 13.05ms
INFO: Started server process [13]
INFO: Waiting for application startup.
[ uvicorn.error | on:startup:61 | 2022-11-10 16:28:28 UTC ] - INFO : Application startup complete.
[ uvicorn.error | server:_log_started_message:207 | 2022-11-10 16:28:28 UTC ] - INFO : Uvicorn running on http://0.0.0.0:8181 (Press CTRL+C to quit)
[ uvicorn.access | httptools_impl:send:474 | 2022-11-10 16:28:35 UTC ] - INFO : 10.36.1.1:49813 - "GET /services/session/ HTTP/1.1" 200
[D 2022-11-10 16:28:35.407 JupyterHub proxy:392] Fetching routes to check
[D 2022-11-10 16:28:35.407 JupyterHub proxy:884] Proxy: Fetching GET http://proxy-api:8001/api/routes
[D 2022-11-10 16:28:35.410 JupyterHub proxy:957] Omitting non-jupyterhub route '/'
[D 2022-11-10 16:28:35.410 JupyterHub proxy:395] Checking routes
[I 2022-11-10 16:28:35.410 JupyterHub proxy:480] Adding route for Hub: / => http://hub:8081
[W 2022-11-10 16:28:35.412 JupyterHub proxy:448] Adding missing route for session (Server(url=http://hub:8181/services/session/, bind_url=http://hub:8181/services/session/))
[D 2022-11-10 16:28:35.412 JupyterHub proxy:884] Proxy: Fetching POST http://proxy-api:8001/api/routes/
[I 2022-11-10 16:28:35.413 JupyterHub proxy:314] Adding service session to proxy /services/session/ => http://hub:8181
[D 2022-11-10 16:28:35.414 JupyterHub proxy:884] Proxy: Fetching POST http://proxy-api:8001/api/routes/services/session
[I 2022-11-10 16:28:35.421 JupyterHub app:3162] JupyterHub is now running, internal Hub API at http://hub:8081/hub/
[D 2022-11-10 16:28:35.421 JupyterHub app:2768] It took 10.979 seconds for the Hub to start
[D 2022-11-10 16:29:35.422 JupyterHub proxy:884] Proxy: Fetching GET http://proxy-api:8001/api/routes
[ uvicorn.access | httptools_impl:send:474 | 2022-11-10 16:29:35 UTC ] - INFO : 10.36.1.1:36361 - "GET /services/session/ HTTP/1.1" 200
[D 2022-11-10 16:29:35.428 JupyterHub proxy:395] Checking routes
[D 2022-11-10 16:29:35.430 JupyterHub app:2425] Managed service session running at http://hub:8181
[D 2022-11-10 16:30:35.422 JupyterHub proxy:884] Proxy: Fetching GET http://proxy-api:8001/api/routes
[D 2022-11-10 16:30:35.427 JupyterHub proxy:395] Checking routes
[ uvicorn.access | httptools_impl:send:474 | 2022-11-10 16:30:35 UTC ] - INFO : 10.36.1.1:5260 - "GET /services/session/ HTTP/1.1" 200
[D 2022-11-10 16:30:35.428 JupyterHub app:2425] Managed service session running at http://hub:8181
[D 2022-11-10 16:31:35.422 JupyterHub proxy:884] Proxy: Fetching GET http://proxy-api:8001/api/routes
[ uvicorn.access | httptools_impl:send:474 | 2022-11-10 16:31:35 UTC ] - INFO : 10.36.1.1:23132 - "GET /services/session/ HTTP/1.1" 200
[D 2022-11-10 16:31:35.429 JupyterHub proxy:395] Checking routes
[D 2022-11-10 16:31:35.430 JupyterHub app:2425] Managed service session running at http://hub:8181
[D 2022-11-10 16:32:35.422 JupyterHub proxy:884] Proxy: Fetching GET http://proxy-api:8001/api/routes
[ uvicorn.access | httptools_impl:send:474 | 2022-11-10 16:32:35 UTC ] - INFO : 10.36.1.1:6893 - "GET /services/session/ HTTP/1.1" 200
[D 2022-11-10 16:32:35.426 JupyterHub app:2425] Managed service session running at http://hub:8181
[D 2022-11-10 16:32:35.430 JupyterHub proxy:395] Checking routes
[D 2022-11-10 16:33:35.422 JupyterHub proxy:884] Proxy: Fetching GET http://proxy-api:8001/api/routes
[ uvicorn.access | httptools_impl:send:474 | 2022-11-10 16:33:35 UTC ] - INFO : 10.36.1.1:41126 - "GET /services/session/ HTTP/1.1" 200
[D 2022-11-10 16:33:35.428 JupyterHub app:2425] Managed service session running at http://hub:8181
[D 2022-11-10 16:33:35.428 JupyterHub proxy:395] Checking routes
[D 2022-11-10 16:34:35.422 JupyterHub proxy:884] Proxy: Fetching GET http://proxy-api:8001/api/routes
[D 2022-11-10 16:34:35.427 JupyterHub proxy:395] Checking routes
[ uvicorn.access | httptools_impl:send:474 | 2022-11-10 16:34:35 UTC ] - INFO : 10.36.1.1:57124 - "GET /services/session/ HTTP/1.1" 200
[D 2022-11-10 16:34:35.430 JupyterHub app:2425] Managed service session running at http://hub:8181
[D 2022-11-10 16:35:35.423 JupyterHub proxy:884] Proxy: Fetching GET http://proxy-api:8001/api/routes
[D 2022-11-10 16:35:35.429 JupyterHub proxy:395] Checking routes
[ uvicorn.access | httptools_impl:send:474 | 2022-11-10 16:35:35 UTC ] - INFO : 10.36.1.1:13121 - "GET /services/session/ HTTP/1.1" 200
[D 2022-11-10 16:35:35.431 JupyterHub app:2425] Managed service session running at http://hub:8181
[D 2022-11-10 16:36:35.423 JupyterHub proxy:884] Proxy: Fetching GET http://proxy-api:8001/api/routes
[D 2022-11-10 16:36:35.428 JupyterHub proxy:395] Checking routes
[ uvicorn.access | httptools_impl:send:474 | 2022-11-10 16:36:35 UTC ] - INFO : 10.36.1.1:55602 - "GET /services/session/ HTTP/1.1" 200
[D 2022-11-10 16:36:35.430 JupyterHub app:2425] Managed service session running at http://hub:8181
[D 2022-11-10 16:37:35.422 JupyterHub proxy:884] Proxy: Fetching GET http://proxy-api:8001/api/routes
[ uvicorn.access | httptools_impl:send:474 | 2022-11-10 16:37:35 UTC ] - INFO : 10.36.1.1:36895 - "GET /services/session/ HTTP/1.1" 200
[D 2022-11-10 16:37:35.427 JupyterHub proxy:395] Checking routes
[D 2022-11-10 16:37:35.429 JupyterHub app:2425] Managed service session running at http://hub:8181
[I 2022-11-10 16:38:28.545 JupyterHub log:186] 200 GET /hub/api/ (jupyterhub-idle-culler@127.0.0.1) 40.87ms
[D 2022-11-10 16:38:28.550 JupyterHub scopes:796] Checking access via scope list:users
[D 2022-11-10 16:38:28.550 JupyterHub scopes:610] Unrestricted access to /hub/api/users via list:users
[I 2022-11-10 16:38:28.553 JupyterHub log:186] 200 GET /hub/api/users?state=[secret] (jupyterhub-idle-culler@127.0.0.1) 6.30ms
[D 2022-11-10 16:38:35.423 JupyterHub proxy:884] Proxy: Fetching GET http://proxy-api:8001/api/routes
[ uvicorn.access | httptools_impl:send:474 | 2022-11-10 16:38:35 UTC ] - INFO : 10.36.1.1:3591 - "GET /services/session/ HTTP/1.1" 200
[D 2022-11-10 16:38:35.427 JupyterHub app:2425] Managed service session running at http://hub:8181
[D 2022-11-10 16:38:35.429 JupyterHub proxy:395] Checking routes
[D 2022-11-10 16:39:35.423 JupyterHub proxy:884] Proxy: Fetching GET http://proxy-api:8001/api/routes
[ uvicorn.access | httptools_impl:send:474 | 2022-11-10 16:39:35 UTC ] - INFO : 10.36.1.1:10589 - "GET /services/session/ HTTP/1.1" 200
[D 2022-11-10 16:39:35.430 JupyterHub proxy:395] Checking routes
[D 2022-11-10 16:39:35.431 JupyterHub app:2425] Managed service session running at http://hub:8181
[I 2022-11-10 16:40:26.284 JupyterHub log:186] 302 GET / -> /hub/ (@::ffff:10.36.1.229) 1.04ms
[D 2022-11-10 16:40:35.422 JupyterHub proxy:884] Proxy: Fetching GET http://proxy-api:8001/api/routes
[D 2022-11-10 16:40:35.427 JupyterHub proxy:395] Checking routes
[ uvicorn.access | httptools_impl:send:474 | 2022-11-10 16:40:35 UTC ] - INFO : 10.36.1.1:21945 - "GET /services/session/ HTTP/1.1" 200
[D 2022-11-10 16:40:35.429 JupyterHub app:2425] Managed service session running at http://hub:8181
[ uvicorn.access | httptools_impl:send:474 | 2022-11-10 16:40:40 UTC ] - INFO : 10.36.1.242:47954 - "GET /services/session HTTP/1.1" 307
[D 2022-11-10 16:41:35.422 JupyterHub proxy:884] Proxy: Fetching GET http://proxy-api:8001/api/routes
[D 2022-11-10 16:41:35.428 JupyterHub proxy:395] Checking routes
[ uvicorn.access | httptools_impl:send:474 | 2022-11-10 16:41:35 UTC ] - INFO : 10.36.1.1:14914 - "GET /services/session/ HTTP/1.1" 200
[D 2022-11-10 16:41:35.429 JupyterHub app:2425] Managed service session running at http://hub:8181
proxy logs
16:28:12.461 [ConfigProxy] info: Adding route / -> http://hub:8081
16:28:12.528 [ConfigProxy] info: Proxying http://*:8000 to http://hub:8081
16:28:12.528 [ConfigProxy] info: Proxy API at http://*:8001/api/routes
16:28:12.530 [ConfigProxy] info: Route added / -> http://hub:8081
16:28:28.110 [ConfigProxy] info: 200 GET /api/routes
16:28:35.409 [ConfigProxy] info: 200 GET /api/routes
16:28:35.416 [ConfigProxy] info: Adding route / -> http://hub:8081
16:28:35.417 [ConfigProxy] info: Route added / -> http://hub:8081
16:28:35.418 [ConfigProxy] info: 201 POST /api/routes/
16:28:35.419 [ConfigProxy] info: Adding route /services/session -> http://hub:8181
16:28:35.419 [ConfigProxy] info: Route added /services/session -> http://hub:8181
16:28:35.422 [ConfigProxy] info: 201 POST /api/routes/services/session
16:29:35.427 [ConfigProxy] info: 200 GET /api/routes
16:30:35.426 [ConfigProxy] info: 200 GET /api/routes
16:31:35.428 [ConfigProxy] info: 200 GET /api/routes
16:32:35.427 [ConfigProxy] info: 200 GET /api/routes
16:33:35.426 [ConfigProxy] info: 200 GET /api/routes
16:34:35.426 [ConfigProxy] info: 200 GET /api/routes
16:35:35.428 [ConfigProxy] info: 200 GET /api/routes
16:36:35.427 [ConfigProxy] info: 200 GET /api/routes
16:37:35.426 [ConfigProxy] info: 200 GET /api/routes
16:38:35.428 [ConfigProxy] info: 200 GET /api/routes
16:39:35.430 [ConfigProxy] info: 200 GET /api/routes
16:40:35.426 [ConfigProxy] info: 200 GET /api/routes
16:40:40.197 [ConfigProxy] debug: PROXY WEB /services/session to http://hub:8181
16:40:40.203 [ConfigProxy] debug: Not recording activity for status 307 on /services/session