supabase / auth / 9112884321

67%

Build Type

push

github

Committed by web-flow

Commit Message

fix: improve logging structure (#1583)

## What kind of change does this PR introduce?
* Remove unformatted logs which do not confirm to JSON
* Previously, we were logging both `time` (not UTC) and `timestamp` (in
UTC) which is redundant. I've opted to remove `timestamp` and just log
the UTC time as the `time` field, which is supported by logrus
* Previously, the `request_id` was not being logged because it was
unable to retrieve the context properly. Now, the `request_id` field is
added to every log entry, which allows us to filter by `request_id` to
see the entire lifecycle of the request
* Previously, panics weren't being handled properly and they were just
logged as text instead of JSON. The server would return an empty reply,
which leads to ugly responses like "Unexpected token < in JSON..." if
using fetch in JS. Now, the server returns a proper 500 error response:
`{"code":500,"error_code":"unexpected_failure","msg":"Internal Server
Error"}`
* Added tests for `recoverer` and `NewStructuredLogger` to prevent
regression
* Remove "request started" log since the `request_id` can be used to
keep track of the entire request lifecycle. This cuts down on the noise
to signal ratio as well.


## Log format
* Panics are now logged like this (note the additional fields like
`panic` and `stack` - which is a dump of the stack trace):
```json
{
  "component":"api",
  "duration":6065700500,
  "level":"info",
  "method":"GET",
  "msg":"request completed",
  "panic":"test panic",
  "path":"/panic",
  "referer":"http://localhost:3001",
  "remote_addr":"127.0.0.1",
  "request_id":"4cde5f20-2c3c-4645-bc75-52d6231e22e2",
  "stack":"goroutine 82 [running]:...rest of stack trace omitted for brevity",
  "status":500,
  "time":"2024-05-15T09:37:42Z"
}
```

* Requests that call `NewAuditLogEntry` will be logged with the
`auth_event` payload in this format (note that the timestamp field no
longer exists)
```json
{
  "auth_eve... (continued)

Run Details

98 of 111 new or added lines in 14 files covered. (88.29%)

7 existing lines in 3 files now uncovered.

8423 of 12794 relevant lines covered (65.84%)

64.35 hits per line