Investigate AzureAD login issues with utoronto

[pnasrat]

Context

Reported via freshdesk https://2i2c.freshdesk.com/a/tickets/764

Proposal

No response

Updates and actions

log grep for 500

``` ovyan@hub-749bb69658-fpk6n:/srv/jupyterhub$ tail -10000 jupyterhub.log | grep \]\ 500 [E 2023-06-08 20:12:29.357 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.4) 160.73ms [E 2023-06-08 20:41:24.749 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.7) 220.95ms [E 2023-06-08 20:41:44.609 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.7) 140.10ms [E 2023-06-08 20:49:14.602 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 331.61ms jovyan@hub-749bb69658-fpk6n:/srv/jupyterhub$ tail -20000 jupyterhub.log | grep \]\ 500 [W 2023-06-08 19:33:47.616 JupyterHub web:1796] 500 GET /hub/user/2c94f0af-dd06-4e88-8563-a6bfa646d6aa/rstudio/?redirects=2 (10.1.0.5): Redirect loop detected. Notebook has jupyterhub version 3.1.0, but the Hub expects 3.1.1. Try installing jupyterhub==3.1.1 in the user environment if you continue to have problems. [E 2023-06-08 19:33:47.617 JupyterHub log:186] 500 GET /hub/user/2c94f0af-dd06-4e88-8563-a6bfa646d6aa/rstudio/?redirects=2 (2c94f0af-dd06-4e88-8563-a6bfa646d6aa@10.1.0.5) 2.87ms [E 2023-06-08 19:46:00.632 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.10) 258.97ms [E 2023-06-08 19:59:35.308 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.4) 631.53ms [E 2023-06-08 20:12:03.539 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.9) 226.09ms [E 2023-06-08 20:12:29.357 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.4) 160.73ms [E 2023-06-08 20:41:24.749 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.7) 220.95ms [E 2023-06-08 20:41:44.609 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.7) 140.10ms [E 2023-06-08 20:49:14.602 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 331.61ms jovyan@hub-749bb69658-fpk6n:/srv/jupyterhub$ tail -50000 jupyterhub.log | grep \]\ 500 [E 2023-06-08 17:14:17.719 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.8) 160.46ms [E 2023-06-08 17:14:46.689 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.14) 175.70ms [E 2023-06-08 17:16:34.925 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 192.54ms [E 2023-06-08 17:16:46.842 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 224.42ms [E 2023-06-08 17:17:02.691 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 137.63ms [E 2023-06-08 17:17:19.268 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 207.07ms [E 2023-06-08 17:17:20.087 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.5) 195.35ms [E 2023-06-08 17:17:24.486 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 128.78ms [E 2023-06-08 17:17:59.134 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.14) 200.27ms [E 2023-06-08 17:18:32.520 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 208.24ms [E 2023-06-08 17:18:38.091 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 163.02ms [E 2023-06-08 17:18:44.920 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 170.81ms [E 2023-06-08 17:18:47.708 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 181.25ms [E 2023-06-08 17:18:50.077 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 168.56ms [E 2023-06-08 17:19:14.801 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.5) 267.95ms [E 2023-06-08 17:19:35.747 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.5) 162.76ms [E 2023-06-08 17:20:02.200 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.5) 149.38ms [E 2023-06-08 17:20:12.738 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.9) 168.12ms [E 2023-06-08 17:20:14.807 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.5) 145.61ms [E 2023-06-08 17:20:34.674 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.5) 163.03ms [E 2023-06-08 17:20:52.493 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.5) 178.09ms [E 2023-06-08 17:23:14.392 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.4) 255.13ms [E 2023-06-08 17:24:34.919 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 141.01ms [E 2023-06-08 17:24:41.219 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.10) 216.93ms [E 2023-06-08 17:27:05.948 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 191.61ms [E 2023-06-08 17:28:01.865 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.4) 505.16ms [E 2023-06-08 17:28:20.708 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 182.80ms [E 2023-06-08 17:28:31.024 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 135.73ms [E 2023-06-08 17:29:42.582 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.9) 147.06ms [E 2023-06-08 17:30:59.162 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.5) 357.22ms [E 2023-06-08 17:31:23.669 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.14) 205.90ms [E 2023-06-08 17:42:17.237 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.14) 221.38ms [E 2023-06-08 17:42:51.309 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.14) 138.36ms [E 2023-06-08 17:43:15.543 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.14) 141.55ms [E 2023-06-08 17:43:36.816 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 134.59ms [E 2023-06-08 17:44:07.522 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 160.12ms [E 2023-06-08 17:44:11.469 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 251.03ms [E 2023-06-08 18:04:16.125 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 274.32ms [E 2023-06-08 18:06:59.776 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.9) 361.96ms [E 2023-06-08 18:07:06.278 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.9) 220.45ms [E 2023-06-08 18:07:10.470 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.9) 143.28ms [E 2023-06-08 18:09:30.157 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.5) 234.91ms [E 2023-06-08 18:09:35.034 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.5) 150.76ms [E 2023-06-08 18:09:39.838 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.5) 158.44ms [E 2023-06-08 18:11:03.025 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.4) 142.81ms [E 2023-06-08 18:24:47.559 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.7) 335.65ms [E 2023-06-08 18:31:54.783 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.14) 295.95ms [E 2023-06-08 18:32:25.630 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.10) 215.90ms [E 2023-06-08 18:32:55.716 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.10) 158.22ms [E 2023-06-08 18:33:10.285 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.10) 137.49ms [E 2023-06-08 18:33:17.150 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.7) 140.13ms [E 2023-06-08 18:34:16.914 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.14) 134.23ms [E 2023-06-08 18:34:51.073 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 272.04ms [E 2023-06-08 19:03:18.088 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 154.11ms [W 2023-06-08 19:33:47.616 JupyterHub web:1796] 500 GET /hub/user/2c94f0af-dd06-4e88-8563-a6bfa646d6aa/rstudio/?redirects=2 (10.1.0.5): Redirect loop detected. Notebook has jupyterhub version 3.1.0, but the Hub expects 3.1.1. Try installing jupyterhub==3.1.1 in the user environment if you continue to have problems. [E 2023-06-08 19:33:47.617 JupyterHub log:186] 500 GET /hub/user/2c94f0af-dd06-4e88-8563-a6bfa646d6aa/rstudio/?redirects=2 (2c94f0af-dd06-4e88-8563-a6bfa646d6aa@10.1.0.5) 2.87ms [E 2023-06-08 19:46:00.632 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.10) 258.97ms [E 2023-06-08 19:59:35.308 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.4) 631.53ms [E 2023-06-08 20:12:03.539 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.9) 226.09ms [E 2023-06-08 20:12:29.357 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.4) 160.73ms [E 2023-06-08 20:41:24.749 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.7) 220.95ms [E 2023-06-08 20:41:44.609 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.7) 140.10ms [E 2023-06-08 20:49:14.602 JupyterHub log:186] 500 GET /hub/oauth_callback?code=[secret]&state=[secret]&session_state=[secret] (@10.1.0.15) 331.61ms ```

[pnasrat]

Froim log seems to be large no oauth errors. I don't see the standard http rate graphs I'd expect in grafana to look at error rates.

[pnasrat]

Some pods triggered cluster scale up by the look as we'd expect

https://grafana.utoronto.2i2c.cloud/d/Qx58n92nk/cluster-information?orgId=1&from=1686216758146&to=1686259958146&viewPanel=7

[pnasrat]

Relevent node scale up graph is https://grafana.utoronto.2i2c.cloud/d/Qx58n92nk/cluster-information?orgId=1&from=1686238436898&to=1686260036898&viewPanel=6

[pnasrat]

Community reports widespread howver

kubectl get pods -n prod | grep jupyter- | wc -l
39

https://grafana.utoronto.2i2c.cloud/d/Qx58n92nk/cluster-information?orgId=1&from=1686238607471&to=1686260207471&viewPanel=3

[pnasrat]

Both prod and r-prod spawn servers that work for me

[pnasrat]

I was trying to do some explore queries of the hub for 500 but they weren't working

[pnasrat]

 curl  http://localhost:8081/hub/metrics | grep code=\"5
jupyterhub_request_duration_seconds_bucket{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",le="0.005",method="GET"} 0.0
jupyterhub_request_duration_seconds_bucket{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",le="0.01",method="GET"} 0.0
1jupyterhub_request_duration_seconds_bucket{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",le="0.025",method="GET"} 0.0
0jupyterhub_request_duration_seconds_bucket{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",le="0.05",method="GET"} 0.0
0jupyterhub_request_duration_seconds_bucket{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",le="0.075",method="GET"} 0.0
 jupyterhub_request_duration_seconds_bucket{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",le="0.1",method="GET"} 0.0
 jupyterhub_request_duration_seconds_bucket{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",le="0.25",method="GET"} 1.0
1jupyterhub_request_duration_seconds_bucket{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",le="0.5",method="GET"} 4.0
2jupyterhub_request_duration_seconds_bucket{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",le="0.75",method="GET"} 4.0
0jupyterhub_request_duration_seconds_bucket{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",le="1.0",method="GET"} 4.0
kjupyterhub_request_duration_seconds_bucket{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",le="2.5",method="GET"} 4.0
 jupyterhub_request_duration_seconds_bucket{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",le="5.0",method="GET"} 4.0
 jupyterhub_request_duration_seconds_bucket{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",le="7.5",method="GET"} 4.0
1jupyterhub_request_duration_seconds_bucket{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",le="10.0",method="GET"} 4.0
0jupyterhub_request_duration_seconds_bucket{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",le="+Inf",method="GET"} 4.0
0jupyterhub_request_duration_seconds_count{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",method="GET"} 4.0
 jupyterhub_request_duration_seconds_sum{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",method="GET"} 1.1942851543426514
 120k    jupyterhub_request_duration_seconds_created{code="500",handler="oauthenticator.oauth2.OAuthCallbackHandler",method="GET"} 1.6861702662246656e+09

[pnasrat]

prod hub ip and node

kubectl get pod -n prod hub-749bb69658-fpk6n -o wide
NAME                   READY   STATUS    RESTARTS   AGE   IP            NODE                           NOMINATED NODE   READINESS GATES
hub-749bb69658-fpk6n   2/2     Running   0          38h   10.244.3.19   aks-core-34239724-vmss000006   <none>           <none>

[yuvipanda]

Looking at the hub logs, I do see 500 errors during oauth callback. I see error messages that look like this:

Error fetching 400 POST https://login.microsoftonline.com/78aac226-2f03-4b4d-9037-b46d56c55210/oauth2/token: {
     "claims": "{\"access_token\":{\"<token>\":{\"essential\":true,\"values\":[\"<value>\"]}}}",
     "correlation_id": "8abad1e8-5676-497b-8705-b3d34b4c360c",
     "error": "interaction_required",
     "error_codes": [
      50158
     ],
     "error_description": "AADSTS50158: External security challenge not satisfied. User will be redirected to another page or authentication provider to satisfy additional authentication challenges.\r\nTrace ID: b95f7414-ee40-43b3-b8b7-b0f933a97f00\r\nCorrelation ID: 8abad1e8-5676-497b-8705-b3d34b4c360c\r\nTimestamp: 2023-06-09 05:19:50Z",
     "error_uri": "https://login.microsoftonline.com/error?code=50158",
     "suberror": "basic_action",
     "timestamp": "2023-06-09 05:19:50Z",
     "trace_id": "b95f7414-ee40-43b3-b8b7-b0f933a97f00"
    }

[yuvipanda]

I've enabled 2FA on my utoronto.ca account, but can still login fine.