Identity manager expects to be able to read user ID from deleted session records

[kenjenkins]

What happened?

While working on debugging another issue, I noticed an unexpected behavior related to the (not-yet-released) stateful authentication flow changes (#4819): some time after signing out of a Pomerium session, Pomerium would attempt to use the (now revoked) OAuth2 token from that session to try to refresh the user info.

What did you expect to happen?

After signing out of Pomerium and ending an underlying OAuth2 session with the configured identity provider, Pomerium should no longer attempt to use the access token from that OAuth2 session.

How'd it happen?

1. Run a build of Pomerium from the main branch, configured with a self-hosted authenticate service.
2. Sign in at a Pomerium route and then sign back out.
3. Wait 10 minutes.

What's your environment like?

• Pomerium version (retrieve with pomerium --version):
  pomerium: v0.23.0-247-g18717a96+18717a96
  envoy: 1.28.0+cf3c0b96f4f3258bda685a245620b8d4d5c34eb680716d2bb82cffb80d4085cc
• Server Operating System/Architecture/Cloud: macOS

What's your config.yaml?

authenticate_service_url: https://authenticate.localhost.pomerium.io

idp_provider: google
idp_client_id: [redacted]
idp_client_secret: [redacted]

routes:
  - from: https://verify.localhost.pomerium.io
    to: http://localhost:8000
    allow_any_authenticated_user: true
    pass_identity_headers: true

...

What did you see in the logs?

{"level":"info","config_file_source":".config.basic.yaml","bootstrap":true,"service":"identity_manager","user_id":"111124447713896378131","time":"2024-01-02T12:38:08-08:00","message":"refreshing user"}
{"level":"error","config_file_source":".config.basic.yaml","bootstrap":true,"service":"identity_manager","error":"identity/oidc: user info endpoint: 401 Unauthorized: {\"error\":\"invalid_request\",\"error_description\":\"Invalid Credentials\"}","user_id":"111124447713896378131","session_id":"c943e916-3ebc-4592-b41d-a24421249939","time":"2024-01-02T12:38:09-08:00","message":"failed to update user info, deleting session"}
{"level":"info","address":"127.0.0.1:57958","time":"2024-01-02T12:38:09-08:00","message":"grpc: dialing"}
{"level":"info","type":"type.googleapis.com/session.Session","id":"c943e916-3ebc-4592-b41d-a24421249939","time":"2024-01-02T12:38:09-08:00","message":"get"}
{"level":"info","record-type":"type.googleapis.com/pomerium.events.LastError","record-id":"identity_manager_last_user_refresh_errors","time":"2024-01-02T12:38:09-08:00","message":"put"}

Additional context

I believe this is what is going on:

The identity manager keeps all active sessions in memory. It uses a databroker syncer to listen for session record changes, in order to keep this in-memory set of sessions in sync with the storage backend.

When a session record is deleted from the storage backend, the identity manager expects to be able to read its session ID and user ID from the syncer update:

pomerium/internal/identity/manager/manager.go

Line 393 in ed6f5e7

mgr.sessions.Delete(session.GetUserId(), session.GetId())

However, some of the restored stateful authentication flow code includes a call to session.Delete(), which is a databroker wrapper method for deleting a session. This inserts an empty databroker session record, which naturally does not contain either a session ID or a user ID.

When the identity manager learns of this record deletion from its syncer, it cannot identify which in-memory session should be removed. As a result the expired in-memory session persists until the next user info refresh interval.

It's not yet clear to me what the impact of this may be.

[desimone]

@ssveta7ak to confirm

[ssveta7ak]

Fixed. Checked on
Core v0.25.0-41-g7edd538b + 7edd538