Regular session invalidation and login prompts due to expiring id_token #938
Comments
|
Hi @Dev25, thanks for reporting. The intended behavior is that Pomerium will refresh identity tokens as needed before expiration, up to the maximum Pomerium session lifetime that you've set (96h), so it definitely looks like something isn't working correctly. Could you search your logs for any entries with |
|
Thanks @kenjenkins I can indeed see those logs that show its either refreshing a user or session on a regular basis. {"level":"info","service":"identity_manager","user_id":"73ddd3ad-964c-420b-bfb4-88a30f991b9b","session_id":"ce350423-189e-4b8a-8f60-8ebc657e085c","time":"2024-04-10T08:14:52Z","message":"refreshing session"}
{"level":"info","service":"identity_manager","user_id":"01819efa-92f4-4a4d-9383-a1f8b31f90f9","time":"2024-04-10T08:15:01Z","message":"refreshing user"}
{"level":"info","service":"identity_manager","user_id":"40ac6505-4ed8-4d70-86b9-650e04fc3863","session_id":"0ee4ab7f-7c45-4eaf-99da-2c45f7a30af4","time":"2024-04-10T08:15:13Z","message":"refreshing session"}
{"level":"info","service":"identity_manager","user_id":"8d982fd7-45a0-4998-bc31-39cb2e427ce5","session_id":"f2dae595-5492-4881-a91f-9a270244fade","time":"2024-04-10T08:15:23Z","message":"refreshing session"}
{"level":"info","service":"identity_manager","user_id":"c6f77b53-b344-433b-82ee-64163bab298e","session_id":"c83c6f08-346a-466b-ad6d-412157015c1c","time":"2024-04-10T08:15:29Z","message":"refreshing session"}
{"level":"info","service":"identity_manager","user_id":"c4026093-9487-4a56-8cf3-220645a0d61a","session_id":"68b95a2c-f05a-4245-bec4-6e71cec33ada","time":"2024-04-10T08:15:52Z","message":"refreshing session"}
{"level":"info","service":"identity_manager","user_id":"820430d4-f07d-47ab-9b35-704cbd4a0feb","session_id":"b2fe2ce1-7536-4b99-9bff-fc5ad5da9a8d","time":"2024-04-10T08:15:55Z","message":"refreshing session"}
{"level":"info","service":"identity_manager","user_id":"52aada95-6e3c-4db4-afa2-822963385ec5","session_id":"e5c2a986-6503-47b6-9363-b0d0d9cfb502","time":"2024-04-10T08:15:55Z","message":"refreshing session"}
{"level":"info","service":"identity_manager","user_id":"05a110ef-1c95-44b4-a1ed-7ef08c1060d9","time":"2024-04-10T08:16:04Z","message":"refreshing user"}
{"level":"info","service":"identity_manager","user_id":"2f546480-7d0f-44ad-a9b9-d677845fa73f","session_id":"5b4fc6c1-2b20-4d20-995e-2a34edf3eb69","time":"2024-04-10T08:16:12Z","message":"refreshing session"}
{"level":"info","service":"identity_manager","user_id":"b6f988c9-5183-4b92-a2bb-20f2e2324ff1","session_id":"b899eea4-5bdd-41a6-b473-4bb2975effa9","time":"2024-04-10T08:16:17Z","message":"refreshing session"}
{"level":"info","service":"identity_manager","user_id":"8598af72-1472-4d55-bf9a-ea9d123ca5e7","time":"2024-04-10T08:16:38Z","message":"refreshing user"}
{"level":"info","service":"identity_manager","user_id":"ce17b551-bf63-4036-83ac-a32518207389","time":"2024-04-10T08:16:38Z","message":"refreshing user"}
{"level":"info","service":"identity_manager","user_id":"4d41bfee-1da6-49c4-8944-e6cbb13d143e","time":"2024-04-10T08:16:38Z","message":"refreshing user"}
{"level":"info","service":"identity_manager","user_id":"16d4f91f-1aca-44b0-a496-63baef8e535e","time":"2024-04-10T08:16:38Z","message":"refreshing user"}If i take a look at a single
If i look at single |
|
Thanks @Dev25 for the details. I was hoping there would be an obvious error message in the logs — Pomerium should log an entry The timings for an individual session look odd; it looks like the time between session refresh varies considerably, from 1:00:04 up to 1:25:39. If you don't mind sharing, roughly how many total sessions do you have at any given time? I wonder if we have some performance problem affecting the scheduling of the session refresh loop. |
|
One other thing; @Dev25 would you mind querying for the individual access token lifetimes? (i.e. include both The Microsoft documentation mentions that:
That may explain the irregular session refresh timing, rather than a performance problem to do with session refresh scheduling. |
|
So i did a scan for logs for Regarding sessions here are some numbers for a single user or across all users on the # Single User
pomerium> select COUNT(1), data->'idToken'->>'issuer' as issuer from pomerium.records where type='type.googleapis.com/session.Session' and data->>'claims' LIKE '%user%' group by issuer;
+-------+-----------------------------------------------------------------------------+
| count | issuer |
|-------+-----------------------------------------------------------------------------|
| 1 | auth.domain.tld |
| 13 | https://login.microsoftonline.com/UUID/v2.0 |
+-------+-----------------------------------------------------------------------------+
# Global
pomerium> select COUNT(1), data->'idToken'->>'issuer' as issuer from pomerium.records where type='type.googleapis.com/session.Session' group by issuer;
+-------+-----------------------------------------------------------------------------+
| count | issuer |
|-------+-----------------------------------------------------------------------------|
| 656 | https://login.microsoftonline.com/UUID/v2.0 |
| 20 | auth.domain.tld |
+-------+-----------------------------------------------------------------------------+Here is the latest query results with the idtoken issued at: pomerium> select id, version, modified_at,
data->'claims'->>'email' as email,
data->>'audience' as audience,
data->'idToken'->>'issuer' as issuer,
data->>'issuedAt' as issuedAt,
data->>'expiresAt' as expiresAt,
data->'idToken'->>'issuedAt' as id_token_issuedAt,
data->'idToken'->>'expiresAt' as id_token_ExpiresAt
from pomerium.records
where
type = 'type.googleapis.com/session.Session' and data->>'claims' like '%user%'
order by version;
+--------------------------------------+-----------+-------------------------------+----------------------------+--------------------------------------------+-----------------------------------------------------------------------------+--------------------------------+--------------------------------+----------------------+--------------------------------+
| id | version | modified_at | email | audience | issuer | issuedat | expiresat | id_token_issuedat | id_token_expiresat |
|--------------------------------------+-----------+-------------------------------+----------------------------+--------------------------------------------+-----------------------------------------------------------------------------+--------------------------------+--------------------------------+----------------------+--------------------------------|
| f0cb08f3-9b3b-409d-91e1-2898fe2c7566 | 114281307 | 2024-04-12 15:17:15.462503+00 | ["[email protected]"] | ["auth.domain.tld", "app1.domain.tld"] | https://login.microsoftonline.com/UUID/v2.0 | 2024-04-09T10:35:37.231006442Z | 2024-04-13T10:35:37.231004967Z | 2024-04-12T15:12:15Z | 2024-04-12T16:17:15Z |
| cefdbba1-50ee-4cd9-bb15-f331256ccf1b | 114284117 | 2024-04-12 15:36:31.003719+00 | ["[email protected]"] | ["auth.domain.tld", "app2.domain.tld"] | https://login.microsoftonline.com/UUID/v2.0 | 2024-04-09T08:20:09.962659398Z | 2024-04-13T08:20:09.962657961Z | 2024-04-12T15:31:30Z | 2024-04-12T16:36:30Z |
| 38d38c04-3c6e-4135-a0f8-209762b9174b | 114284380 | 2024-04-12 15:39:42.771539+00 | ["[email protected]"] | ["auth.domain.tld", "app1.domain.tld"] | https://login.microsoftonline.com/UUID/v2.0 | 2024-04-10T13:52:14.704972342Z | 2024-04-14T13:52:14.704970788Z | 2024-04-12T15:34:42Z | 2024-04-12T16:39:42Z |
| 2e5dd869-c46b-46f1-b5a8-652fe0280581 | 114287826 | 2024-04-12 16:01:15.957528+00 | ["[email protected]"] | ["auth.domain.tld", "app2.domain.tld"] | https://login.microsoftonline.com/UUID/v2.0 | 2024-04-09T17:03:25.572018813Z | 2024-04-13T17:03:25.572017198Z | 2024-04-12T15:56:15Z | 2024-04-12T17:01:15Z |
| 5c38d7e3-6e4a-4330-95bc-22682a16ff1c | 114289646 | 2024-04-12 16:14:18.929384+00 | ["[email protected]"] | ["auth.domain.tld", "app1.domain.tld"] | https://login.microsoftonline.com/UUID/v2.0 | 2024-04-11T08:15:35.607710839Z | 2024-04-15T08:15:35.607706684Z | 2024-04-12T16:09:18Z | 2024-04-12T17:14:18Z |
| d015abca-aed4-4740-82f2-4f60b353c93c | 114289989 | 2024-04-12 16:17:59.50053+00 | ["[email protected]"] | ["auth.domain.tld", "app3.domain.tld"] | https://login.microsoftonline.com/UUID/v2.0 | 2024-04-10T11:50:40.910607155Z | 2024-04-14T11:50:40.910605582Z | 2024-04-12T16:12:59Z | 2024-04-12T17:17:59Z |
| 243d163b-fe49-438c-aef1-296fa6a276ce | 114290143 | 2024-04-12 16:19:21.923295+00 | ["[email protected]"] | ["auth.domain.tld", "app4.domain.tld"] | https://login.microsoftonline.com/UUID/v2.0 | 2024-04-09T14:59:43.140956826Z | 2024-04-13T14:59:43.140955208Z | 2024-04-12T16:14:21Z | 2024-04-12T17:19:21Z |
| d2845997-a514-46f6-b5cb-98be2198fe74 | 114291109 | 2024-04-12 16:23:52.448441+00 | ["[email protected]"] | ["auth.domain.tld", "app1.domain.tld"] | https://login.microsoftonline.com/UUID/v2.0 | 2024-04-12T13:28:46.171800434Z | 2024-04-16T13:28:46.171799140Z | 2024-04-12T16:18:52Z | 2024-04-12T17:23:52Z |
| ca7ca0ee-662f-46bc-987c-0bfdb992b829 | 114291209 | 2024-04-12 16:25:12.189421+00 | ["[email protected]"] | ["auth.domain.tld", "app1.domain.tld"] | https://login.microsoftonline.com/UUID/v2.0 | 2024-04-09T10:36:23.921825873Z | 2024-04-13T10:36:23.921824942Z | 2024-04-12T16:20:12Z | 2024-04-12T17:25:12Z |
| 76018bc5-d800-4be7-b47d-23013882f87e | 114291256 | 2024-04-12 16:25:50.485988+00 | ["[email protected]"] | ["auth.domain.tld", "127.0.0.1"] | https://login.microsoftonline.com/UUID/v2.0 | 2024-04-12T11:07:39.914260903Z | 2024-04-16T11:07:39.914259197Z | 2024-04-12T16:20:50Z | 2024-04-12T17:25:50Z |
| d01c9e37-c182-4f7a-8c5b-7ce496bceed1 | 114291389 | 2024-04-12 16:27:12.142207+00 | ["[email protected]"] | ["auth.domain.tld", "app1.domain.tld"] | https://login.microsoftonline.com/UUID/v2.0 | 2024-04-10T09:40:52.223573221Z | 2024-04-14T09:40:52.223571770Z | 2024-04-12T16:22:11Z | 2024-04-12T17:27:11Z |
| 842f0b90-bade-4971-a365-b67ecb044f0c | 114291688 | 2024-04-12 16:30:56.280481+00 | ["[email protected]"] | ["auth.domain.tld", "app1.domain.tld"] | https://login.microsoftonline.com/UUID/v2.0 | 2024-04-11T08:15:41.531398121Z | 2024-04-15T08:15:41.531396719Z | 2024-04-12T16:25:56Z | 2024-04-12T17:30:56Z |
| ef5a4790-602d-4bcd-9089-492fa532bc2d | 114292339 | 2024-04-12 16:32:57.689977+00 | ["[email protected]"] | ["auth.domain.tld", "app1.domain.tld"] | https://login.microsoftonline.com/UUID/v2.0 | 2024-04-09T12:38:28.663591249Z | 2024-04-13T12:38:28.663590088Z | 2024-04-12T16:27:57Z | 2024-04-12T17:32:57Z |
| 89a15bd5-54de-4c45-856e-7e635ce8e8b7 | 114292976 | 2024-04-12 16:40:24.907801+00 | ["[email protected]"] | ["auth.domain.tld", "app1.domain.tld"] | auth.domain.tld | 2024-04-12T15:57:01.570944172Z | 2024-04-16T15:57:01.570942464Z | 2024-04-12T15:57:01Z | 2024-04-16T15:57:01.570942464Z |
+--------------------------------------+-----------+-------------------------------+----------------------------+--------------------------------------------+-----------------------------------------------------------------------------+--------------------------------+--------------------------------+----------------------+--------------------------------+
SELECT 14 |
|
Thanks for the additional information; I think we'll have to see if we can reproduce this problem ourselves in order to investigate further. |
6 tasks
|
The identity manager has been rewritten to better handle a large number of sessions. This will be released in v0.26. |
|
Thanks for the update @calebdoxsey , any ETA on when v0.26 is expected to be released or if a pre-release build of a ingress-controller with the change is available so i could perhaps test that to confirm. |
|
Hi @Dev25, we build a kubectl apply -k github.com/pomerium/ingress-controller/config/default\?ref=main |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
What happened?
Users constantly being asked to reauthenticate with the AzureAD IDP, multiple times a day far more frequently then the desired 4 day pomerium session TTL.
Seeing tens of thousands of logs daily about id_token being expired which appears to be referencing the Azure ID 1hr token?. The additional token checks were introduced in pomerium/pomerium#4543 which attempts to validate id_token along with session/access_tokens.
What did you expect to happen?
Pomerium sessions to not expire before the cookie expiry time (4 days), users with a valid cookie should not need to re-authenticate with the Azure IDP multiple times throughout the day.
As often as required pomerium should fetch a new token from the IDP automatically before the id_token expires.
How'd it happen?
Randomly throughout the entire day, when attempting to use a SSO protected application e.g. grafana
Note earlier versions of pomerum-ingress controller (prior to 0.23.0/above PR) did not have this problem.
What's your environment like?
What's your config.yaml?
What did you see in the logs?
{"level":"warn","error":"session has expired: id_token expired at 2024-04-09 10:55:45 +0000 UTC","time":"2024-04-09T11:18:34Z","message":"clearing session due to missing or invalid session or service account"} {"level":"warn","error":"session has expired: id_token expired at 2024-04-09 10:55:45 +0000 UTC","time":"2024-04-09T11:18:36Z","message":"clearing session due to missing or invalid session or service account"} {"level":"warn","error":"session has expired: id_token expired at 2024-04-09 10:55:45 +0000 UTC","time":"2024-04-09T11:18:36Z","message":"clearing session due to missing or invalid session or service account"} {"level":"warn","error":"session has expired: id_token expired at 2024-04-09 11:11:20 +0000 UTC","time":"2024-04-09T11:24:43Z","message":"clearing session due to missing or invalid session or service account"} {"level":"warn","error":"session has expired: id_token expired at 2024-04-09 11:11:20 +0000 UTC","time":"2024-04-09T11:24:44Z","message":"clearing session due to missing or invalid session or service account"} {"level":"warn","error":"session has expired: id_token expired at 2024-04-09 11:11:20 +0000 UTC","time":"2024-04-09T11:24:45Z","message":"clearing session due to missing or invalid session or service account"} {"level":"warn","error":"session has expired: id_token expired at 2024-04-09 11:11:20 +0000 UTC","time":"2024-04-09T11:24:46Z","message":"clearing session due to missing or invalid session or service account"} {"level":"warn","error":"session has expired: id_token expired at 2024-04-09 11:11:20 +0000 UTC","time":"2024-04-09T11:24:46Z","message":"clearing session due to missing or invalid session or service account"} {"level":"error","error":"Unauthorized","status":401,"status-text":"Unauthorized","request-id":"5b1e983e-cf50-4442-a449-d2e51287ccca","time":"2024-04-09T11:18:38Z","message":"httputil: error"} {"level":"error","error":"Unauthorized","status":401,"status-text":"Unauthorized","request-id":"d54cb2e9-f95b-4b65-a15b-75ae3bdf8ba6","time":"2024-04-09T11:18:38Z","message":"httputil: error"} {"level":"warn","error":"session has expired: id_token expired at 2024-04-09 10:55:45 +0000 UTC","time":"2024-04-09T11:18:39Z","message":"clearing session due to missing or invalid session or service account"} {"level":"error","error":"Unauthorized","status":401,"status-text":"Unauthorized","request-id":"78fabdd5-b6ea-4b43-aa7c-40145ad4eef9","time":"2024-04-09T11:18:39Z","message":"httputil: error"} {"level":"warn","error":"session has expired: id_token expired at 2024-04-09 11:11:20 +0000 UTC","time":"2024-04-09T11:24:48Z","message":"clearing session due to missing or invalid session or service account"} {"level":"warn","error":"session has expired: id_token expired at 2024-04-09 11:09:26 +0000 UTC","time":"2024-04-09T11:24:48Z","message":"clearing session due to missing or invalid session or service account"} {"level":"warn","error":"session has expired: id_token expired at 2024-04-09 11:09:26 +0000 UTC","time":"2024-04-09T11:24:49Z","message":"clearing session due to missing or invalid session or service account"} {"level":"warn","error":"session has expired: id_token expired at 2024-04-09 10:55:45 +0000 UTC","time":"2024-04-09T11:18:39Z","message":"clearing session due to missing or invalid session or service account"} {"level":"error","error":"Unauthorized","status":401,"status-text":"Unauthorized","request-id":"8312921f-5efc-4130-b66b-7568bcb4e030","time":"2024-04-09T11:18:39Z","message":"httputil: error"}Additional context
Looking at the datastore i notice the bulk of the idToken sessions are issued by Azure IDP whilst a single record is issued by pomerium.
I can query my current cookie's session in the record_changes table and can see it linked to a session that has its idToken issued by pomerium and expires in 4 days, however i've also had to frequently login today (1-2 times per hour).
The text was updated successfully, but these errors were encountered: