feat: audit logs

[mrl5]

related to https://github.com/neondatabase/cloud/issues/21940

===
test log:

setup

MY_JWK='{"kty":"EC","crv":"P-256","x":"3oRIkYbjbm-BlWJNpRj2LkcCvFAj73iazhg68H2drag","y":"ZzS4QsyZ__AEnPcqqvxepqlkdh8lhZON-_yb7L1VAwA"}'

JWT_FOO='eyJraWQiOjF9.eyJzdWIiOiJmb28iLCJqdGkiOjF9.nACvT55fhP5Ec1QJhvFkFd0CArmfkaaSKjnJLWkp15WMw9Z2tOxwoCNcmpXHlzPFGas12fStpvjtyCv9jARjNA'
JWT_BAR='eyJraWQiOjF9.eyJzdWIiOiJiYXIiLCJqdGkiOjJ9.d7hom_VweINaqbU6gKqHI3w4S18kgvz80_VaUitsIn_V6KYqAJsmGX2H59SAM45WlXN4aF6lPyoS7bAr9VvV_g'

export PGOPTIONS="-c pg_session_jwt.jwk=$MY_JWK"
cargo pgrx run pg16

simple valid sig

select auth.jwt_session_init('eyJraWQiOjF9.eyJzdWIiOiJmb28iLCJqdGkiOjF9.nACvT55fhP5Ec1QJhvFkFd0CArmfkaaSKjnJLWkp15WMw9Z2tOxwoCNcmpXHlzPFGas12fStpvjtyCv9jARjNA');

logs produced

2025-01-08 18:31:19.534 CET [519668] LOG:  valid JWT, sub="foo" aud=""
2025-01-08 18:31:19.534 CET [519668] STATEMENT:  select auth.jwt_session_init('eyJraWQiOjF9.eyJzdWIiOiJmb28iLCJqdGkiOjF9.nACvT55fhP5Ec1QJhvFkFd0CArmfkaaSKjnJLWkp15WMw9Z2tOxwoCNcmpXHlzPFGas12fStpvjtyCv9jARjNA');

simple invalid sig

select auth.jwt_session_init('eyJraWQiOjF9.eyJzdWIiOiJmb28iLCJqdGkiOjF9.d7hom_VweINaqbU6gKqHI3w4S18kgvz80_VaUitsIn_V6KYqAJsmGX2H59SAM45WlXN4aF6lPyoS7bAr9VvV_g');

logs produced

2025-01-08 18:32:13.948 CET [519668] ERROR:  invalid JWT signature
2025-01-08 18:32:13.948 CET [519668] STATEMENT:  select auth.jwt_session_init('eyJraWQiOjF9.eyJzdWIiOiJmb28iLCJqdGkiOjF9.d7hom_VweINaqbU6gKqHI3w4S18kgvz80_VaUitsIn_V6KYqAJsmGX2H59SAM45WlXN4aF6lPyoS7bAr9VvV_g');

init then SET

select auth.jwt_session_init('eyJraWQiOjF9.eyJzdWIiOiJmb28iLCJqdGkiOjF9.nACvT55fhP5Ec1QJhvFkFd0CArmfkaaSKjnJLWkp15WMw9Z2tOxwoCNcmpXHlzPFGas12fStpvjtyCv9jARjNA');
select auth.user_id();

SET pg_session_jwt.jwt = 'eyJraWQiOjF9.eyJzdWIiOiJiYXIiLCJqdGkiOjJ9.d7hom_VweINaqbU6gKqHI3w4S18kgvz80_VaUitsIn_V6KYqAJsmGX2H59SAM45WlXN4aF6lPyoS7bAr9VvV_g';
select auth.user_id();

logs produced

2025-01-08 19:05:14.982 CET [549131] LOG:  valid JWT, sub="foo" aud=""
2025-01-08 19:05:14.982 CET [549131] STATEMENT:  select auth.jwt_session_init('eyJraWQiOjF9.eyJzdWIiOiJmb28iLCJqdGkiOjF9.nACvT55fhP5Ec1QJhvFkFd0CArmfkaaSKjnJLWkp15WMw9Z2tOxwoCNcmpXHlzPFGas12fStpvjtyCv9jARjNA');
2025-01-08 19:05:34.181 CET [549131] LOG:  valid JWT, sub="bar" aud=""
2025-01-08 19:05:34.181 CET [549131] STATEMENT:  select auth.user_id();

parallel scan with explicit init and WHERE statement

CREATE TABLE foo (
  id bigint GENERATED ALWAYS AS IDENTITY PRIMARY KEY,
  bar text
);
INSERT INTO foo (bar)
  SELECT md5(baz::text) from generate_series(1,1e6) as baz;

INSERT INTO foo (bar) VALUES ( 'foo' );
INSERT INTO foo (bar) VALUES ( 'bar' );

INSERT INTO foo (bar)
  SELECT md5(baz::text) from generate_series(1,1e3) as baz;

select auth.jwt_session_init('eyJraWQiOjF9.eyJzdWIiOiJmb28iLCJqdGkiOjF9.nACvT55fhP5Ec1QJhvFkFd0CArmfkaaSKjnJLWkp15WMw9Z2tOxwoCNcmpXHlzPFGas12fStpvjtyCv9jARjNA');

EXPLAIN ANALYZE SELECT * from foo where bar = auth.user_id();
SELECT * from foo where bar = auth.user_id();

with query plan

                                                       QUERY PLAN
------------------------------------------------------------------------------------------------------------------------
 Gather  (cost=1000.00..17934.40 rows=5614 width=40) (actual time=400.718..403.585 rows=1 loops=1)
   Workers Planned: 2
   Workers Launched: 2
   ->  Parallel Seq Scan on foo  (cost=0.00..16373.00 rows=2339 width=40) (actual time=394.153..394.283 rows=0 loops=3)
         Filter: (bar = auth.user_id())
         Rows Removed by Filter: 333667
 Planning Time: 0.744 ms
 Execution Time: 403.626 ms
(8 rows)

logs produced

2025-01-08 18:34:55.647 CET [521485] LOG:  valid JWT, sub="foo" aud=""
2025-01-08 18:34:55.647 CET [521485] STATEMENT:  select auth.jwt_session_init('eyJraWQiOjF9.eyJzdWIiOiJmb28iLCJqdGkiOjF9.nACvT55fhP5Ec1QJhvFkFd0CArmfkaaSKjnJLWkp15WMw9Z2tOxwoCNcmpXHlzPFGas12fStpvjtyCv9jARjNA');
2025-01-08 18:35:01.492 CET [523028] LOG:  valid JWT, sub="foo" aud=""
2025-01-08 18:35:01.492 CET [523028] STATEMENT:  EXPLAIN ANALYZE SELECT * from foo where bar = auth.user_id();
2025-01-08 18:35:01.496 CET [523029] LOG:  valid JWT, sub="foo" aud=""
2025-01-08 18:35:01.496 CET [523029] STATEMENT:  EXPLAIN ANALYZE SELECT * from foo where bar = auth.user_id();
2025-01-08 18:35:51.123 CET [523687] LOG:  valid JWT, sub="foo" aud=""
2025-01-08 18:35:51.123 CET [523687] STATEMENT:  SELECT * from foo where bar = auth.user_id();
2025-01-08 18:35:51.124 CET [523688] LOG:  valid JWT, sub="foo" aud=""
2025-01-08 18:35:51.124 CET [523688] STATEMENT:  SELECT * from foo where bar = auth.user_id();

parallel scan with SET and WHERE statement

SET pg_session_jwt.jwt = 'eyJraWQiOjF9.eyJzdWIiOiJiYXIiLCJqdGkiOjJ9.d7hom_VweINaqbU6gKqHI3w4S18kgvz80_VaUitsIn_V6KYqAJsmGX2H59SAM45WlXN4aF6lPyoS7bAr9VvV_g';

SELECT * from foo where bar = auth.user_id();

logs produced

2025-01-08 18:37:33.291 CET [521485] LOG:  valid JWT, sub="bar" aud=""
2025-01-08 18:37:33.291 CET [521485] STATEMENT:  SELECT * from foo where bar = auth.user_id();
2025-01-08 18:37:33.303 CET [525027] LOG:  valid JWT, sub="bar" aud=""
2025-01-08 18:37:33.303 CET [525027] STATEMENT:  SELECT * from foo where bar = auth.user_id();
2025-01-08 18:37:33.307 CET [525028] LOG:  valid JWT, sub="bar" aud=""
2025-01-08 18:37:33.307 CET [525028] STATEMENT:  SELECT * from foo where bar = auth.user_id();

parallel scan without WHERE but with RLS

create user foobar;
grant usage ON schema auth TO foobar;
grant select ON foo to foobar;
create policy enforce_user_check on foo for select to foobar using ( (select auth.user_id()) = bar);
alter table foo enable row level security;
set role foobar;

SET pg_session_jwt.jwt = 'eyJraWQiOjF9.eyJzdWIiOiJiYXIiLCJqdGkiOjJ9.d7hom_VweINaqbU6gKqHI3w4S18kgvz80_VaUitsIn_V6KYqAJsmGX2H59SAM45WlXN4aF6lPyoS7bAr9VvV_g';
SELECT * from foo;

returned

   id    | bar
---------+-----
 1000002 | bar
(1 row)

logs produced

2025-01-08 19:01:03.546 CET [545605] LOG:  valid JWT, sub="bar" aud=""
2025-01-08 19:01:03.546 CET [545605] STATEMENT:  SELECT * from foo;

[mrl5]

for RLS case produced

2025-01-09 19:42:16.803 CET [479356] LOG:  Validated JWT: sub="bar" aud=""
2025-01-09 19:42:16.803 CET [479356] STATEMENT:  SELECT * from foo;

[MihaiBojin]

Thank you very much! Having the events get logged in PG means we satisfy the audit log requirements for HIPAA!