feat: log all audit events separately to prevent missing events #2086
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Pull Request Test Coverage Report for Build 16472575471Details
💛 - Coveralls |
cemalkilic
pushed a commit
that referenced
this pull request
Aug 6, 2025
🤖 I have created a release *beep* *boop* --- ## [2.178.0](v2.177.0...v2.178.0) (2025-08-05) ### Features * add sign in with ethereum ([#2069](#2069)) ([079b242](079b242)) * add support for managing SSO providers by resource_id ([#2081](#2081)) ([5ca4489](5ca4489)) * log all audit events separately to prevent missing events ([#2086](#2086)) ([3b666f5](3b666f5)) * skip nonce check for Facebook Limited Login auth ([#2082](#2082)) ([f1b15ff](f1b15ff)) * support ledger solana offchain message signing ([#2093](#2093)) ([4c94443](4c94443)) --- This PR was generated with [Release Please](https://github.com/googleapis/release-please). See [documentation](https://github.com/googleapis/release-please#release-please). Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com>
cemalkilic
added a commit
that referenced
this pull request
Aug 7, 2025
## Problem
The `observability.LogEntrySetFields()` adds to request context, causing
multiple audit events in the same request to overwrite each other. For
example, refresh token requests call `NewAuditLogEntry()` twice
(`token_refreshed`, then
`token_revoked`) but only the last event (`token_revoked`) was logged.
## Solution
Create immediate separate log entries with "auth_audit_event" key. This
ensures all audit events are captured without overwriting.
## Example log output:
```sh
{"auth_audit_event":{"action":"token_refreshed","actor_id":"2670aa55-6f6f-465b-a749-2e75f61e1e8a","actor_username":"","actor_via_sso":false,"audit_log_id":"3e07849b-1784-451b-af99-1fbd455681e7","created_at":"2025-07-23T13:34:29.88400603Z","ip_address":"","log_type":"token","request_id":"3bd2f2fd-8b2a-434f-93da-656c9083762b","user_agent":"insomnia/11.1.0"},"level":"info","msg":"audit_event","time":"2025-07-23T13:34:29Z"}
{"auth_audit_event":{"action":"token_revoked","actor_id":"2670aa55-6f6f-465b-a749-2e75f61e1e8a","actor_username":"","actor_via_sso":false,"audit_log_id":"9dd3621b-9fd2-4e1d-a3a6-2236a16653c8","created_at":"2025-07-23T13:34:29.886232214Z","ip_address":"","log_type":"token","request_id":"3bd2f2fd-8b2a-434f-93da-656c9083762b","user_agent":"insomnia/11.1.0"},"level":"info","msg":"audit_event","time":"2025-07-23T13:34:29Z"}
{"action":"login","instance_id":"00000000-0000-0000-0000-000000000000","level":"info","login_method":"token","metering":true,"msg":"Login","time":"2025-07-23T13:34:29Z","user_id":"2670aa55-6f6f-465b-a749-2e75f61e1e8a"}
{"auth_event":{"action":"token_revoked","actor_id":"2670aa55-6f6f-465b-a749-2e75f61e1e8a","actor_username":"","actor_via_sso":false,"log_type":"token"},"component":"api","duration":21772353,"grant_type":"refresh_token","level":"info","method":"POST","msg":"request completed","path":"/token","referer":"http://localhost:3000","remote_addr":"192.168.117.1","request_id":"3bd2f2fd-8b2a-434f-93da-656c9083762b","status":200,"time":"2025-07-23T13:34:29Z"}
```
The first two are the _new_ audit events(added with this PR), the third
is the login metric and the last one was the request logging (containing
the only last audit event). Eventually, we're going to remove the audit
event from the request log (the last one)
issuedat
pushed a commit
that referenced
this pull request
Sep 30, 2025
## Problem
The `observability.LogEntrySetFields()` adds to request context, causing
multiple audit events in the same request to overwrite each other. For
example, refresh token requests call `NewAuditLogEntry()` twice
(`token_refreshed`, then
`token_revoked`) but only the last event (`token_revoked`) was logged.
## Solution
Create immediate separate log entries with "auth_audit_event" key. This
ensures all audit events are captured without overwriting.
## Example log output:
```sh
{"auth_audit_event":{"action":"token_refreshed","actor_id":"2670aa55-6f6f-465b-a749-2e75f61e1e8a","actor_username":"","actor_via_sso":false,"audit_log_id":"3e07849b-1784-451b-af99-1fbd455681e7","created_at":"2025-07-23T13:34:29.88400603Z","ip_address":"","log_type":"token","request_id":"3bd2f2fd-8b2a-434f-93da-656c9083762b","user_agent":"insomnia/11.1.0"},"level":"info","msg":"audit_event","time":"2025-07-23T13:34:29Z"}
{"auth_audit_event":{"action":"token_revoked","actor_id":"2670aa55-6f6f-465b-a749-2e75f61e1e8a","actor_username":"","actor_via_sso":false,"audit_log_id":"9dd3621b-9fd2-4e1d-a3a6-2236a16653c8","created_at":"2025-07-23T13:34:29.886232214Z","ip_address":"","log_type":"token","request_id":"3bd2f2fd-8b2a-434f-93da-656c9083762b","user_agent":"insomnia/11.1.0"},"level":"info","msg":"audit_event","time":"2025-07-23T13:34:29Z"}
{"action":"login","instance_id":"00000000-0000-0000-0000-000000000000","level":"info","login_method":"token","metering":true,"msg":"Login","time":"2025-07-23T13:34:29Z","user_id":"2670aa55-6f6f-465b-a749-2e75f61e1e8a"}
{"auth_event":{"action":"token_revoked","actor_id":"2670aa55-6f6f-465b-a749-2e75f61e1e8a","actor_username":"","actor_via_sso":false,"log_type":"token"},"component":"api","duration":21772353,"grant_type":"refresh_token","level":"info","method":"POST","msg":"request completed","path":"/token","referer":"http://localhost:3000","remote_addr":"192.168.117.1","request_id":"3bd2f2fd-8b2a-434f-93da-656c9083762b","status":200,"time":"2025-07-23T13:34:29Z"}
```
The first two are the _new_ audit events(added with this PR), the third
is the login metric and the last one was the request logging (containing
the only last audit event). Eventually, we're going to remove the audit
event from the request log (the last one)
issuedat
pushed a commit
that referenced
this pull request
Sep 30, 2025
🤖 I have created a release *beep* *boop* --- ## [2.178.0](v2.177.0...v2.178.0) (2025-08-05) ### Features * add sign in with ethereum ([#2069](#2069)) ([079b242](079b242)) * add support for managing SSO providers by resource_id ([#2081](#2081)) ([5ca4489](5ca4489)) * log all audit events separately to prevent missing events ([#2086](#2086)) ([3b666f5](3b666f5)) * skip nonce check for Facebook Limited Login auth ([#2082](#2082)) ([f1b15ff](f1b15ff)) * support ledger solana offchain message signing ([#2093](#2093)) ([4c94443](4c94443)) --- This PR was generated with [Release Please](https://github.com/googleapis/release-please). See [documentation](https://github.com/googleapis/release-please#release-please). Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com>
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Problem
The
observability.LogEntrySetFields()adds to request context, causing multiple audit events in the same request to overwrite each other. For example, refresh token requests callNewAuditLogEntry()twice (token_refreshed, thentoken_revoked) but only the last event (token_revoked) was logged.Solution
Create immediate separate log entries with "auth_audit_event" key. This ensures all audit events are captured without overwriting.
Example log output:
{"auth_audit_event":{"action":"token_refreshed","actor_id":"2670aa55-6f6f-465b-a749-2e75f61e1e8a","actor_username":"","actor_via_sso":false,"audit_log_id":"3e07849b-1784-451b-af99-1fbd455681e7","created_at":"2025-07-23T13:34:29.88400603Z","ip_address":"","log_type":"token","request_id":"3bd2f2fd-8b2a-434f-93da-656c9083762b","user_agent":"insomnia/11.1.0"},"level":"info","msg":"audit_event","time":"2025-07-23T13:34:29Z"} {"auth_audit_event":{"action":"token_revoked","actor_id":"2670aa55-6f6f-465b-a749-2e75f61e1e8a","actor_username":"","actor_via_sso":false,"audit_log_id":"9dd3621b-9fd2-4e1d-a3a6-2236a16653c8","created_at":"2025-07-23T13:34:29.886232214Z","ip_address":"","log_type":"token","request_id":"3bd2f2fd-8b2a-434f-93da-656c9083762b","user_agent":"insomnia/11.1.0"},"level":"info","msg":"audit_event","time":"2025-07-23T13:34:29Z"} {"action":"login","instance_id":"00000000-0000-0000-0000-000000000000","level":"info","login_method":"token","metering":true,"msg":"Login","time":"2025-07-23T13:34:29Z","user_id":"2670aa55-6f6f-465b-a749-2e75f61e1e8a"} {"auth_event":{"action":"token_revoked","actor_id":"2670aa55-6f6f-465b-a749-2e75f61e1e8a","actor_username":"","actor_via_sso":false,"log_type":"token"},"component":"api","duration":21772353,"grant_type":"refresh_token","level":"info","method":"POST","msg":"request completed","path":"/token","referer":"http://localhost:3000","remote_addr":"192.168.117.1","request_id":"3bd2f2fd-8b2a-434f-93da-656c9083762b","status":200,"time":"2025-07-23T13:34:29Z"}The first two are the new audit events(added with this PR), the third is the login metric and the last one was the request logging (containing the only last audit event). Eventually, we're going to remove the audit event from the request log (the last one)