Implement audit logging (database row level, 1 of 3)

[bickelj]

Do the things thought of in #1355

[bickelj]

It is expected that audit logs can be presented in an administrative interface. It is also expected that some reads would be included, not only writes. And also such actions as reading the audit logs themselves should be audit logged. This from a meeting 2025-04-01 (no joke).

[bickelj]

Trying audit-trigger locally

When adding this trigger-audit SQL directly to a migration file (does not yet pass lint) we end up with this table and these triggers:

pdc=> \d audit.logged_actions
                                                 Table "audit.logged_actions"
      Column       |           Type           | Collation | Nullable |                        Default                         
-------------------+--------------------------+-----------+----------+--------------------------------------------------------
 event_id          | bigint                   |           | not null | nextval('audit.logged_actions_event_id_seq'::regclass)
 schema_name       | text                     |           | not null | 
 table_name        | text                     |           | not null | 
 relid             | oid                      |           | not null | 
 session_user_name | text                     |           |          | 
 action_tstamp_tx  | timestamp with time zone |           | not null | 
 action_tstamp_stm | timestamp with time zone |           | not null | 
 action_tstamp_clk | timestamp with time zone |           | not null | 
 transaction_id    | bigint                   |           |          | 
 application_name  | text                     |           |          | 
 client_addr       | inet                     |           |          | 
 client_port       | integer                  |           |          | 
 client_query      | text                     |           |          | 
 action            | text                     |           | not null | 
 row_data          | jsonb                    |           |          | 
 changed_fields    | jsonb                    |           |          | 
 statement_only    | boolean                  |           | not null | 
 row_id            | bigint                   |           |          | 
Indexes:
    "logged_actions_pkey" PRIMARY KEY, btree (event_id)
    "logged_actions_action_idx" btree (action)
    "logged_actions_action_tstamp_tx_stm_idx" btree (action_tstamp_stm)
    "logged_actions_relid_idx" btree (relid)
Check constraints:
    "logged_actions_action_check" CHECK (action = ANY (ARRAY['I'::text, 'D'::text, 'U'::text, 'T'::text]))
pdc=> \df audit.*
                                                                           List of functions
 Schema |       Name       | Result data type |                                               Argument data types                                               | Type 
--------+------------------+------------------+-----------------------------------------------------------------------------------------------------------------+------
 audit  | audit_table      | void             | target_table regclass                                                                                           | func
 audit  | audit_table      | void             | target_table regclass, audit_rows boolean, audit_query_text boolean                                             | func
 audit  | audit_table      | void             | target_table regclass, audit_rows boolean, audit_query_text boolean, audit_inserts boolean                      | func
 audit  | audit_table      | void             | target_table regclass, audit_rows boolean, audit_query_text boolean, audit_inserts boolean, ignored_cols text[] | func
 audit  | audit_table      | void             | target_table regclass, audit_rows boolean, audit_query_text boolean, ignored_cols text[]                        | func
 audit  | deaudit_table    | void             | target_table regclass                                                                                           | func
 audit  | if_modified_func | trigger          |                                                                                                                 | func
(7 rows)

We should think about whether the functions should go in initialization separately from the migration or stay with the migration.

Also, note that it seems to expect only modification actions in the "logged_actions_action_check" CHECK (action = ANY (ARRAY['I'::text, 'D'::text, 'U'::text, 'T'::text])) which I assume stands for insert, delete, update, and truncate, respectively.

It also feels weird to be implementing a history of all of everything when that's basically how postgresql works in its transaction log. I wonder if there is something to keep and expose the actual log. Also I found https://wiki.postgresql.org/wiki/Temporal_Extensions. Most everything we see, though, uses the trigger and log table approach.

Back to the audit trigger approach, do we need to partition this by the ID on this audit table, perhaps? This will quickly become the biggest table in our schema given that it will have a row for most requests plus modification queries.

Here is the list of things to do.

• Make the audit log definitions SQL pass lint.
• Make the audit log definitions SQL work with our more complex queries such as capturing INSERT...ON CONFLICT...UPDATE. Update 2025-04-10: does not seem to be an issue.
• Make the audit log definitions SQL support reads. Update 2025-04-10: the triggers will only cover edits. Postgres does not support trigger on select statements. We will log application-level GET from the application.
• Make the audit log definitions SQL include allow the app to log JWT (or whatever authentication info we have). Update 2025-04-10: make sure the audit log table has a place for these data, maybe one of the existing JSONB columns.
• Call the functions on tables to audit (apply the audit logs) in DB initialization or migration.

Investigating using the audit trigger out of the box

When adding a trigger to base fields via select audit.audit_table('public.base_fields');, no problem, I get the expected results when adding a new base field. However, when doing it for data providers, I get an error when trying to add a new data provider:

            "where": "PL/pgSQL assignment \"audit_row = ROW(\n    nextval('audit.logged_actions_event_id_seq'),\n    -- event_id\n    TG_TABLE_SCHEMA::text,\n    -- schema_name\n    TG_TABLE_NAME::text,\n    -- table_name\n    TG_RELID,\n    -- relation OID for much quicker searches\n    session_user::text,\n    -- session_user_name\n    current_timestamp,\n    -- action_tstamp_tx\n    statement_timestamp(),\n    -- action_tstamp_stm\n    clock_timestamp(),\n    -- action_tstamp_clk\n    txid_current(),\n    -- transaction ID\n    current_setting('application_name'),\n    -- client application\n    inet_client_addr(),\n    -- client_addr\n    inet_client_port(),\n    -- client_port\n    current_query(),\n    -- top-level query or queries (if multistatement) from client\n    substring(TG_OP, 1, 1),\n    -- action\n    NULL,\n    NULL,\n    -- row_data, changed_fields\n    'f', -- statement_only,\n    COALESCE(OLD.id, NULL) -- pk ID of the row\n)\"\nPL/pgSQL function audit.if_modified_func() line 11 at assignment",

Oh interesting: the failure mode is such that the row was actually created, but the response to the (HTTP) caller indicates an error because of the trigger failures. So we end up with a successful row creation, unaudited, and a fake failure. I suppose we need to make sure that our test harness includes the audit trigger for all of our existing queries in order to catch this scenario at test-time.

A more readable version of the failure:

 INSERT INTO data_providers (short_code,name,keycloak_organization_id) VALUES ('pdwwww','philanthropy data warehouse 2', '39f30184-b818-45d8-a269-8c0e04cc8ffc') ON CONFLICT (short_code) DO UPDATE SET name = excluded.name, keycloak_organization_id = excluded.keycloak_organization_id RETURNING data_provider_to_json(data_providers) AS object;
ERROR:  record "old" has no field "id"
CONTEXT:  PL/pgSQL assignment "audit_row = ROW(
    nextval('audit.logged_actions_event_id_seq'),
    -- event_id
    TG_TABLE_SCHEMA::text,
    -- schema_name
    TG_TABLE_NAME::text,
    -- table_name
    TG_RELID,
    -- relation OID for much quicker searches
    session_user::text,
    -- session_user_name
    current_timestamp,
    -- action_tstamp_tx
    statement_timestamp(),
    -- action_tstamp_stm
    clock_timestamp(),
    -- action_tstamp_clk
    txid_current(),
    -- transaction ID
    current_setting('application_name'),
    -- client application
    inet_client_addr(),
    -- client_addr
    inet_client_port(),
    -- client_port
    current_query(),
    -- top-level query or queries (if multistatement) from client
    substring(TG_OP, 1, 1),
    -- action
    NULL,
    NULL,
    -- row_data, changed_fields
    'f', -- statement_only,
    COALESCE(OLD.id, NULL) -- pk ID of the row
)"
PL/pgSQL function audit.if_modified_func() line 11 at assignment

It is referencing OLD.id which doesn't exist, and COALESCE does not prevent error here. It seems to assume we will have an id column everywhere? Whattayaknow, the one outstanding pull request might address this: iloveitaly/audit-trigger#3. But that is mighty complex for a redundant column anyway. I think everything we need already exists in the other columns, right? Removing that extra id column as redundant.

It doesn't seem to capture INSERT...ON CONFLICT...UPDATE changes... but when restoring or starting from scratch it seems to capture it. Probably OK here.

User context? It looks like we use the user context within functions, not on tables or views, which removes the visibility for this trigger. Perhaps it can/should be included in modified_by or created_by in the relevant tables or all tables? That would give it to us without need for special handling. At least for modifications, but not for reads. Hmm. This may be trickier than I imagined. One idea (thanks qwen2.5-coder:14b) is to use a pre-audit layer such as middleware at the application level or intercepting SQL calls. That would be omitted when using direct DB calls, e.g. via psql, but we wouldn't have any application-level user in those instances either. I would hate to have two rows or two tables for the audit log but that may be the right approach for full coverage. The one captures every query on every table but misses out on the application-level details (and trails the call) while the other captures only queries that go through the application and includes the application-level details such as the user making the call. Linking the two might also be tricky, but perhaps keeping the same transaction or same session would be enough. The first suggestion (by qwen2.5-coder:14b as well) is to set an application-level variable in the postgresql session and then have the trigger access that variable. That is probably better because it would mean one single row with the user context when available. Not having the user context in that row indicates an outside-the-app call.

[bickelj]

At the moment, I think a hybrid approach will be needed but it could use a single database table to simplify viewing. Database triggers could log modifications to the table such that we wouldn't miss any modifications. The application could selectively write to the table along with the user context. Perhaps a single function (or family of functions) could be exposed that both the trigger and the application can use.

[bickelj]

Given that Postgres does not support trigger on select and given that we will likely need an application-level audit trail, a hybrid approach is still the way to go. The triggers can capture modifications. The app can log requests with the user context. It would be nice to be able to connect an app request with subsequent detailed database modifications, ideally with only one insert per request. This should be doable by logging the postgres session id but that assumes only one database session is used per request (I don't know if this is true).

[bickelj]

@slifty and I just spoke a bit about this and there are three levels of audit logs we may wish to have for exposure in an administrative interface:

1. Database table modifications (via triggers)
2. Application-level SQL function calls or queries (via generator functions, includes user context)
3. HTTP-level requests (via pino-http, also can include user context)

Each request may cause multiple application-level function calls or queries, and each of those in turn may cause multiple database row changes.

We also think that each of these audit trails should be in separate tailored database tables. For the purposes of presentation in a UI, we could conceivably merge the data using a view or function at that point. The only downside is that in order to "get the latest 1000 audit trail rows" we would have to query the latest 1000 rows from each table because we don't know which table has more or less data. That may not actually be an issue when writing the view, simply add a limit after ordering rows on the common timeline.

Even though hooking into pino-http (3) feels like it would be faster/easier than modifying our generator functions, I'm going to start with the triggers and then work in the application-level calls. The reason is we have no mod logs at all, those seem most important, and I already have made progress on this part, and we also already have request logging somewhere even if it isn't exposed.

[bickelj]

As for partitioning, it is premature optimization. We don't know for sure that we'll have mountains of data and I don't believe we have a use case for deletion of old data. We also don't want to create an artificial limit on time or row count blindly nor do we want to create too many partitions. Since we don't know exactly how this will play out, we probably shouldn't guess at a partitioning scheme. See here.

[bickelj]

I ran into some trouble with the separate audit schema created by the audit-trigger example code. I started down the path of letting the functions dynamically create a schema based on the current schema name but continued to have speed bumps along the way. Looking back at the article on the Postgres wiki I find this clue about separating the audit log into its own schema:

Changes by the table owner and superusers are tracked, but can be trivially tampered with.

If you want this audit log to be trustworthy, your app should run with a role that has at most USAGE to the audit schema and SELECT rights to audit.logged_actions. Most importantly, your app must not connect with a superuser role and must not own the tables it uses. Create your app's schema with a different user to the one your app runs as, and GRANT your app the minimum rights it needs.

These are all good suggestions for maintaining a strict separation. For example, we should (eventually) have the database user that performs database migrations be more privileged than the database user that is used by the PDC service at usual runtime. However, when thinking about the gains and losses of a separate schema specifically for audit logging, I don't think we gain much and we may lose a bunch of time:

1. We want the audit log available to the PDC service such that an administrative user can see the contents in a UI. A separate schema only adds complexity.
2. While more data is available to a database user who could see a hypothetical separate audit schema, the database user that can see the contents of our usual tables already has visibility into sensitive data. In other words, if the usual PDC service's database user already see the most sensitive stuff, including users and groups, the data about row data changes is only trivially more sensitive than that data itself, so there is no need to separate it.
3. We want the PDC service to log directly into audit tables. A separate schema for one but not all audit tables only adds complexity.