feat: add Server-Timing header with JWT duration

[taimoorzaeem]

Part of #2771.

[steve-chavez]

@taimoorzaeem Interesting feature! So I've been playing a bit with it and I've noticed that:

$ PGRST_JWT_SECRET="reallyreallyreallyreallyverysafe" PGRST_DB_PLAN_ENABLED="true" postgrest-with-postgresql-15 postgrest-run

export JWT="eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJleHAiOjk5OTk5OTk5OTksInJvbGUiOiJwb3N0Z3Jlc3RfdGVzdF9hdXRob3IiLCJpZCI6Impkb2UiLCJhdWQiOiJ5b3VyYXVkaW
VuY2UifQ.fJ4tLKSmolWGWehWN20qiU9dMO-WY0RI2VvacL7-ZGo"

$ curl 'localhost:3000/authors_only' -H "Authorization: Bearer $JWT" -D -
HTTP/1.1 200 OK
Server-Timing: jwt;dur=335.1

$ curl 'localhost:3000/authors_only' -H "Authorization: Bearer $JWT" -D -
HTTP/1.1 200 OK
Server-Timing: jwt;dur=147.7

$ curl 'localhost:3000/authors_only' -H "Authorization: Bearer $JWT" -D -
HTTP/1.1 200 OK
Server-Timing: jwt;dur=145.9

$ curl 'localhost:3000/authors_only' -H "Authorization: Bearer $JWT" -D -
Server-Timing: jwt;dur=146.2

# restarting the postgrest server

$ curl 'localhost:3000/authors_only' -H "Authorization: Bearer $JWT" -D -
HTTP/1.1 200 OK
Server-Timing: jwt;dur=327.1

$ curl 'localhost:3000/authors_only' -H "Authorization: Bearer $JWT" -D -
HTTP/1.1 200 OK
Server-Timing: jwt;dur=141.3

$ curl 'localhost:3000/authors_only' -H "Authorization: Bearer $JWT" -D -
HTTP/1.1 200 OK
Server-Timing: jwt;dur=143.9

$ curl 'localhost:3000/authors_only' -H "Authorization: Bearer $JWT" -D -
HTTP/1.1 200 OK
Server-Timing: jwt;dur=142.5

The first jwt decode always takes longer than the subsequent ones. Is this because of laziness? Related: #2450

[steve-chavez]

@taimoorzaeem Also please rebase. Sorry, I wanted to do the refactoring for completing all the other durations (#2771 (comment)) but I got carried away and did other changes.

[steve-chavez]

Strange that the idempotence test fails. Maybe some mutations on the new tests are not rolled back (which is the default for all tests configDbTxRollbackAll = True).

[taimoorzaeem]

The first jwt decode always takes longer than the subsequent ones. Is this because of laziness? Related: #2450

Hmm, I'll get into it. Would that be okay to test this using strict evaluation using seq? I am not sure because AFAIK GHC optimizes code much better with laziness than with strict evaluation. So maybe getting rid of laziness might not help us.

[steve-chavez]

Would that be okay to test this using strict evaluation using seq? I am not sure because AFAIK GHC optimizes code much better with laziness than with strict evaluation. So maybe getting rid of laziness might not help us.

Yeah, not necessary to be strict. I mostly wanted to check if it's really because of laziness and why would it take more than double the time the first time. On #2450, it's clear it takes a while because the schema cache loading is an expensive process. On this case I don't know what initialization takes place.

[taimoorzaeem]

Strange that the idempotence test fails. Maybe some mutations on the new tests are not rolled back (which is the default for all tests configDbTxRollbackAll = True).

I think this is more than just mutations not being rollbacked. For instance:

test/spec/Feature/Query/QuerySpec.hs:64:34: 
  1) Feature.Query.QuerySpec, Filtering response, matches nulls using not operator
       body mismatch:
         expected: "[{\"a\":\"1\",\"b\":\"0\"},{\"a\":\"2\",\"b\":\"0\"}]"
         but got:  "[{\"a\":\"1\",\"b\":\"1\"}, \n {\"a\":\"2\",\"b\":\"1\"}]"

Where is the \n coming from? So yeah, strange indeed.

[wolfgangwalther]

The first jwt decode always takes longer than the subsequent ones. Is this because of laziness?

I just tested and I observe the same thing. I wondered whether that was only the case with the same JWT token or also with different ones: It's the same, even when using different JWTs between requests. The first one will always be significantly slower.

Any tests for the jwt caching feature will need to take this into account. They'd basically need a "warmup" before doing any testing.

[steve-chavez]

@taimoorzaeem Btw, could we make the JWT evaluation stricter with bang patterns?

• https://ghc.gitlab.haskell.org/ghc/doc/users_guide/exts/strict.html
• https://wiki.haskell.org/Performance/Strictness

Pros of doing this:

• Will not confuse users when reading Server-Timing durations.
• Make JWT caching easier to test.

[taimoorzaeem]

@taimoorzaeem Btw, could we make the JWT evaluation stricter with bang patterns?

Hmm, I tried BangPatterns but it made no difference to the duration.