search

pomerium / ingress-controller

Pomerium Kubernetes Ingress Controller
https://pomerium.com
Apache License 2.0
22 stars 11 forks source link

Regular session invalidation and login prompts due to expiring id_token #938

Open Dev25 opened 4 months ago

Dev25 commented 4 months ago

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 https://github.com/pomerium/pomerium/pull/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?

apiVersion: ingress.pomerium.io/v1
kind: Pomerium
metadata:  
  name: global
spec:
  authenticate:
    url: https://authenticate.domain.tld
  certificates:
    - <namespace>/domain-tld-tls
  cookie:
    domain: domain.tld
    expire: 96h    
  identityProvider:
    provider: azure
    secret: pomerium/pomerium-idp
    url: https://login.microsoftonline.com/<UUID>/v2.0
  secrets: pomerium/bootstrap
  storage:
    postgres:
      secret: pomerium/db-config
---
# Standard Ingress annotations
  annotations:
    ingress.pomerium.io/preserve_host_header: "true"
    ingress.pomerium.io/service_proxy_upstream: "true"
    ingress.pomerium.io/timeout: "60s"
    ingress.pomerium.io/policy: |

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).

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'->>'expiresAt' as idExpiresAt
  from pomerium.records 
  where 
    type = 'type.googleapis.com/session.Session' and data->>'claims' like '%user@azure.tld%' 
  order by version;
+--------------------------------------+-----------+-------------------------------+----------------------------+--------------------------------------------+-----------------------------------------------------------------------------+--------------------------------+--------------------------------+--------------------------------+
| id                                   | version   | modified_at                   | email                      | audience                                   | issuer                                                                      | issuedat                       | expiresat                      | idexpiresat                    |
|--------------------------------------+-----------+-------------------------------+----------------------------+--------------------------------------------+-----------------------------------------------------------------------------+--------------------------------+--------------------------------+--------------------------------|
| f0cb08f3-9b3b-409d-91e1-2898fe2c7566 | 113864768 | 2024-04-09 14:12:31.633623+00 | ["user@azure.tld"]         | ["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-09T15:12:31Z           |
| 2e39172f-6fb6-4e92-8d25-8279b5ed9894 | 113865227 | 2024-04-09 14:16:15.590841+00 | ["user@azure.tld"]         | ["auth.domain.tld", "app2.domain.tld"]     | https://login.microsoftonline.com/<    UUID                           >/v2.0 | 2024-04-06T15:08:26.455666093Z | 2024-04-10T15:08:26.455664306Z | 2024-04-09T15:16:15Z           |
| 57cb5826-6dff-4cd2-9867-27fe5a0cca4d | 113865401 | 2024-04-09 14:16:43.975898+00 | ["user@azure.tld"]         | ["auth.domain.tld", "app1.domain.tld"]     | https://login.microsoftonline.com/<    UUID                           >/v2.0 | 2024-04-05T16:44:01.318202047Z | 2024-04-09T16:44:01.318200798Z | 2024-04-09T15:16:43Z           |
| 15dad253-ad12-4b88-96dc-f3f4613ea99a | 113866833 | 2024-04-09 14:26:09.469693+00 | ["user@azure.tld"]         | ["auth.domain.tld", "app2.domain.tld"]     | https://login.microsoftonline.com/<    UUID                           >/v2.0 | 2024-04-06T20:55:00.049111379Z | 2024-04-10T20:55:00.049109328Z | 2024-04-09T15:26:09Z           |
| adf8f920-0734-4749-8ae6-1accc9376719 | 113867074 | 2024-04-09 14:27:09.823364+00 | ["user@azure.tld"]         | ["auth.domain.tld", "app3.domain.tld"]     | https://login.microsoftonline.com/<    UUID                           >/v2.0 | 2024-04-06T12:32:55.735334647Z | 2024-04-10T12:32:55.735333618Z | 2024-04-09T15:27:09Z           |
| 64f48e37-627d-4b4a-b459-e01e83427601 | 113867615 | 2024-04-09 14:31:07.123879+00 | ["user@azure.tld"]         | ["auth.domain.tld", "app1.domain.tld"]     | https://login.microsoftonline.com/<    UUID                           >/v2.0 | 2024-04-08T15:30:12.788828243Z | 2024-04-12T15:30:12.788826091Z | 2024-04-09T15:31:06Z           |
| cefdbba1-50ee-4cd9-bb15-f331256ccf1b | 113868018 | 2024-04-09 14:33:56.625832+00 | ["user@azure.tld"]         | ["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-09T15:33:56Z           |
| c6d5dc7b-82a0-4e42-b0e5-c84b5428750e | 113868471 | 2024-04-09 14:36:40.978261+00 | ["user@azure.tld"]         | ["auth.domain.tld", "app1.domain.tld"]     | https://login.microsoftonline.com/<    UUID                           >/v2.0 | 2024-04-08T08:41:13.237075375Z | 2024-04-12T08:41:13.237074090Z | 2024-04-09T15:36:40Z           |
| 807027c3-d980-4d71-a6cc-59bc8a985346 | 113868495 | 2024-04-09 14:36:45.443579+00 | ["user@azure.tld"]         | ["auth.domain.tld", "app1.domain.tld"]     | https://login.microsoftonline.com/<    UUID                           >/v2.0 | 2024-04-08T13:07:27.375426560Z | 2024-04-12T13:07:27.375425389Z | 2024-04-09T15:36:45Z           |
| ca7ca0ee-662f-46bc-987c-0bfdb992b829 | 113869334 | 2024-04-09 14:42:24.017739+00 | ["user@azure.tld"]         | ["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-09T15:42:23Z           |
| 68b95a2c-f05a-4245-bec4-6e71cec33ada | 113869650 | 2024-04-09 14:44:48.1952+00   | ["user@azure.tld"]         | ["auth.domain.tld", "app2.domain.tld"]     | https://login.microsoftonline.com/<    UUID                           >/v2.0 | 2024-04-07T15:28:36.478516877Z | 2024-04-11T15:28:36.478515884Z | 2024-04-09T15:44:48Z           |
| 41700119-7fbd-4df9-b2e6-e077d6cb3e11 | 113871587 | 2024-04-09 14:58:05.037501+00 | ["user@azure.tld"]         | ["auth.domain.tld", "app1.domain.tld"]     | https://login.microsoftonline.com/<    UUID                           >/v2.0 | 2024-04-08T13:07:07.124858302Z | 2024-04-12T13:07:07.124857139Z | 2024-04-09T15:58:04Z           |
| 64054eb9-984b-4a49-b778-d79a318eaea2 | 113872785 | 2024-04-09 15:06:44.176341+00 | ["user@azure.tld"]         | ["auth.domain.tld", "app1.domain.tld"]     | https://login.microsoftonline.com/<    UUID                           >/v2.0 | 2024-04-08T10:53:44.755227465Z | 2024-04-12T10:53:44.755226165Z | 2024-04-09T16:06:44Z           |
| ef5a4790-602d-4bcd-9089-492fa532bc2d | 113873427 | 2024-04-09 15:10:06.049745+00 | ["user@azure.tld"]         | ["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-09T16:10:05Z           |
| 243d163b-fe49-438c-aef1-296fa6a276ce | 113875324 | 2024-04-09 15:22:04.959462+00 | ["user@azure.tld"]         | ["auth.domain.tld", "app4.domain.tld"]     | auth.domain.tld                                                              | 2024-04-09T14:59:43.140956826Z | 2024-04-13T14:59:43.140955208Z | 2024-04-13T14:59:43.140955208Z |
+--------------------------------------+-----------+-------------------------------+----------------------------+--------------------------------------------+-----------------------------------------------------------------------------+--------------------------------+--------------------------------+--------------------------------+
kenjenkins commented 4 months ago

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 "service":"identity_manager"? This is the service responsible for refreshing identity tokens. I'd expect to see a "refreshing session" log entry (at info level) roughly once per hour for each active Pomerium session. Do you see these entries in your logs?

Dev25 commented 4 months ago

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 user_id logs for service=identity_manager, over the last 24 hours i see

INFO 2024-04-09T15:59:37Z [jsonPayload.service: identity_manager] [jsonPayload.sessionId: 68b95a2c-f05a-4245-bec4-6e71cec33ada] refreshing session
INFO 2024-04-09T15:59:48Z [jsonPayload.service: identity_manager] refreshing user
INFO 2024-04-09T16:02:57Z [jsonPayload.service: identity_manager] [jsonPayload.sessionId: c6d5dc7b-82a0-4e42-b0e5-c84b5428750e] refreshing session
INFO 2024-04-09T16:03:22Z [jsonPayload.service: identity_manager] [jsonPayload.sessionId: 243d163b-fe49-438c-aef1-296fa6a276ce] refreshing session
INFO 2024-04-09T16:05:05Z [jsonPayload.service: identity_manager] [jsonPayload.sessionId: ca7ca0ee-662f-46bc-987c-0bfdb992b829] refreshing session
INFO 2024-04-09T16:09:49Z [jsonPayload.service: identity_manager] refreshing user
INFO 2024-04-09T16:11:03Z [jsonPayload.service: identity_manager] [jsonPayload.sessionId: 64054eb9-984b-4a49-b778-d79a318eaea2] refreshing session
INFO 2024-04-09T16:19:35Z [jsonPayload.service: identity_manager] [jsonPayload.sessionId: ef5a4790-602d-4bcd-9089-492fa532bc2d] refreshing session
INFO 2024-04-09T16:19:50Z [jsonPayload.service: identity_manager] refreshing user
INFO 2024-04-09T16:23:33Z [jsonPayload.service: identity_manager] [jsonPayload.sessionId: 41700119-7fbd-4df9-b2e6-e077d6cb3e11] refreshing session
INFO 2024-04-09T16:28:36Z [jsonPayload.service: identity_manager] [jsonPayload.sessionId: adf8f920-0734-4749-8ae6-1accc9376719] refreshing session
INFO 2024-04-09T16:29:51Z [jsonPayload.service: identity_manager] refreshing user
INFO 2024-04-09T16:39:52Z [jsonPayload.service: identity_manager] refreshing user
INFO 2024-04-09T16:40:45Z [jsonPayload.service: identity_manager] [jsonPayload.sessionId: f0cb08f3-9b3b-409d-91e1-2898fe2c7566] refreshing session
INFO 2024-04-09T16:44:01Z [jsonPayload.service: identity_manager] [jsonPayload.sessionId: 57cb5826-6dff-4cd2-9867-27fe5a0cca4d] deleting expired session
INFO 2024-04-09T16:44:01Z [jsonPayload.service: identity_manager] [jsonPayload.sessionId: 57cb5826-6dff-4cd2-9867-27fe5a0cca4d] refreshing session
INFO 2024-04-09T16:46:00Z [jsonPayload.service: identity_manager] [jsonPayload.sessionId: 15dad253-ad12-4b88-96dc-f3f4613ea99a] refreshing session
INFO 2024-04-09T16:48:01Z [jsonPayload.service: identity_manager] [jsonPayload.sessionId: 807027c3-d980-4d71-a6cc-59bc8a985346] refreshing session
INFO 2024-04-09T16:49:53Z [jsonPayload.service: identity_manager] refreshing user
INFO 2024-04-09T16:53:17Z [jsonPayload.service: identity_manager] [jsonPayload.sessionId: 2e39172f-6fb6-4e92-8d25-8279b5ed9894] refreshing session
INFO 2024-04-09T16:58:08Z [jsonPayload.service: identity_manager] [jsonPayload.sessionId: 64f48e37-627d-4b4a-b459-e01e83427601] refreshing session
INFO 2024-04-09T16:59:54Z [jsonPayload.service: identity_manager] refreshing user

If i look at single session_id, each unique session has up to 20 logs associated with it which as far as i can see just has 'refreshing session' as the log entry. Here's the timestamp for the last 24hrs for a random one, it looks like we miss some hours randomly but i don't see any logs to indicate why.

INFO 2024-04-09T09:31:03Z refreshing session
INFO 2024-04-09T10:40:48Z refreshing session
INFO 2024-04-09T11:56:06Z refreshing session
INFO 2024-04-09T13:10:09Z refreshing session
INFO 2024-04-09T14:33:56Z refreshing session
INFO 2024-04-09T15:43:39Z refreshing session
INFO 2024-04-09T17:07:33Z refreshing session
INFO 2024-04-09T18:11:33Z refreshing session
INFO 2024-04-09T19:23:00Z refreshing session
INFO 2024-04-09T20:41:00Z refreshing session
INFO 2024-04-09T21:47:57Z refreshing session
INFO 2024-04-09T22:53:49Z refreshing session
INFO 2024-04-10T00:15:20Z refreshing session
INFO 2024-04-10T01:20:51Z refreshing session
INFO 2024-04-10T02:44:53Z refreshing session
INFO 2024-04-10T03:55:39Z refreshing session
INFO 2024-04-10T05:13:37Z refreshing session
INFO 2024-04-10T06:39:16Z refreshing session
INFO 2024-04-10T07:39:20Z refreshing session
kenjenkins commented 4 months ago

Thanks @Dev25 for the details. I was hoping there would be an obvious error message in the logs — Pomerium should log an entry failed to refresh oauth2 token or failed to update user info (along with error details) in the case that a request to the IdP fails while refreshing a Pomerium session.

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.

kenjenkins commented 4 months ago

One other thing; @Dev25 would you mind querying for the individual access token lifetimes? (i.e. include both data->'idToken'->>'issuedAt' and data->'idToken'->>'expiresAt' in your database query)

The Microsoft documentation mentions that:

The default lifetime of an access token is variable. When issued, an access token's default lifetime is assigned a random value ranging between 60-90 minutes (75 minutes on average). The default lifetime also varies depending on the client application requesting the token or if Conditional Access is enabled in the tenant.

(https://learn.microsoft.com/en-us/entra/identity-platform/configurable-token-lifetimes#:~:text=The%20default%20lifetime,in%20the%20tenant.)

That may explain the irregular session refresh timing, rather than a performance problem to do with session refresh scheduling.

Dev25 commented 4 months ago

@kenjenkins

So i did a scan for logs for failed to in the last 7 days only had a single hit for a DB patch failing.

{
  error: "rpc error: code = DeadlineExceeded desc = storage/postgres: error patching record "f2dae595-5492-4881-a91f-9a270244fade" of type "type.googleapis.com/session.Session": postgres: failed to execute query: timeout: context already done: context deadline exceeded"
  level: "error"
  message: "authorize: error updating session last access timestamp"
}

Regarding sessions here are some numbers for a single user or across all users on the records table

# 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 | ["user.foobar@domain.tld"] | ["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 | ["user.foobar@domain.tld"] | ["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 | ["user.foobar@domain.tld"] | ["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 | ["user.foobar@domain.tld"] | ["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 | ["user.foobar@domain.tld"] | ["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  | ["user.foobar@domain.tld"] | ["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 | ["user.foobar@domain.tld"] | ["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 | ["user.foobar@domain.tld"] | ["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 | ["user.foobar@domain.tld"] | ["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 | ["user.foobar@domain.tld"] | ["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 | ["user.foobar@domain.tld"] | ["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 | ["user.foobar@domain.tld"] | ["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 | ["user.foobar@domain.tld"] | ["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 | ["user.foobar@domain.tld"] | ["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
kenjenkins commented 4 months ago

Thanks for the additional information; I think we'll have to see if we can reproduce this problem ourselves in order to investigate further.

calebdoxsey commented 4 months ago

The identity manager has been rewritten to better handle a large number of sessions. This will be released in v0.26.

Dev25 commented 4 months ago

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.

kenjenkins commented 4 months ago

Hi @Dev25, we build a main docker image of the Ingress Controller. The most recent main tag should include these pending changes to the identity manager code. You should be able to deploy with a command like:

kubectl apply -k github.com/pomerium/ingress-controller/config/default\?ref=main
Dev25 commented 2 months ago

Just to provide a update i did deploy a pre release and then also the v0.26.0 release but unfortunately still showing the same symptoms.

kenjenkins commented 1 month ago

Hi @Dev25, thanks for the update, and sorry that the v0.26 release hasn't resolved this issue. The good news is that we believe we've identified the root cause of this issue. We'll let you know when we have a fix ready.

Dev25 commented 1 month ago

Thanks, i've deployed the latest main from this week that includes the fix, seems promising so far. Will close this issue after a bit more testing time/release has been cut.