Trigger-based audit logging do not function properly with current_setting

63 views Asked by At

I am developing an Apollo GraphQL API with Postgres as database system.

I have the following 4 Knex migrations for setting up a trigger-based audit log system, where the last snippet illustrates how all my triggers for all my tables are made:

export async function up(knex: Knex): Promise<void> {
  await knex.schema.createSchema('audit')

  await knex.raw(`
    REVOKE CREATE ON SCHEMA audit FROM public;
  `)

  await knex.raw(`
    GRANT USAGE ON SCHEMA audit TO public;
  `)
}

export async function up(knex: Knex): Promise<void> {
  await knex.schema.withSchema('audit').createTable('logged_actions', function (table) {
    table.string('schema_name', 63).notNullable()
    table.string('table_name', 63).notNullable()
    table.string('user_name', 63)
    table.timestamp('action_tms', { useTz: true }).defaultTo(knex.fn.now()).notNullable()
    table.text('action').notNullable()
    table.json('original_data')
    table.json('new_data')
    table.text('query')

    table.comment('Table for audit logging database actions.')
  })

  await knex.raw(`
    ALTER TABLE audit.logged_actions ADD CONSTRAINT check_action CHECK ( action IN ('I', 'D', 'U') );
  `)
}

export async function up(knex: Knex): Promise<void> {
  await knex.raw(`
    CREATE OR REPLACE FUNCTION audit.if_modified_func()
    RETURNS TRIGGER
    AS $$
    DECLARE
      v_old_data json;
      v_new_data json;
      auth0_user VARCHAR(127) := current_setting('auth0.user_id', true);
      active_user VARCHAR(127);
    BEGIN
      IF (auth0_user IS NOT NULL AND auth0_user != '') THEN
        active_user := auth0_user;
      ELSE
        active_user := CURRENT_USER;
      END IF;
      IF (TG_OP = 'UPDATE') THEN
        v_old_data := row_to_json(OLD);
        v_new_data := row_to_json(NEW);
        INSERT INTO kyc.logged_actions (schema_name,table_name,user_name,action,original_data,new_data,query)
        VALUES (TG_TABLE_SCHEMA::TEXT,TG_TABLE_NAME::TEXT,active_user::TEXT,substring(TG_OP,1,1),v_old_data,v_new_data, current_query());
        RETURN NEW;
      ELSIF (TG_OP = 'DELETE') THEN
        v_old_data := row_to_json(OLD);
        INSERT INTO kyc.logged_actions (schema_name,table_name,user_name,action,original_data,query)
        VALUES (TG_TABLE_SCHEMA::TEXT,TG_TABLE_NAME::TEXT,active_user::TEXT,substring(TG_OP,1,1),v_old_data, current_query());
        RETURN OLD;
      ELSIF (TG_OP = 'INSERT') THEN
        v_new_data := row_to_json(NEW);
        INSERT INTO kyc.logged_actions (schema_name,table_name,user_name,action,new_data,query)
        VALUES (TG_TABLE_SCHEMA::TEXT,TG_TABLE_NAME::TEXT,active_user::TEXT,substring(TG_OP,1,1),v_new_data, current_query());
        RETURN NEW;
      ELSE
        RAISE WARNING '[AUDIT.IF_MODIFIED_FUNC] - Other action occurred: %, at %',TG_OP,now();
        RETURN NULL;
      END IF;
      EXCEPTION
        WHEN data_exception THEN
          RAISE WARNING '[AUDIT.IF_MODIFIED_FUNC] - UDF ERROR [DATA EXCEPTION] - SQLSTATE: %, SQLERRM: %',SQLSTATE,SQLERRM;
          RETURN NULL;
        WHEN unique_violation THEN
          RAISE WARNING '[AUDIT.IF_MODIFIED_FUNC] - UDF ERROR [UNIQUE] - SQLSTATE: %, SQLERRM: %',SQLSTATE,SQLERRM;
          RETURN NULL;
        WHEN others THEN
          RAISE WARNING '[AUDIT.IF_MODIFIED_FUNC] - UDF ERROR [OTHER] - SQLSTATE: %, SQLERRM: %',SQLSTATE,SQLERRM;
          RETURN NULL;
    END;
    $$
    LANGUAGE plpgsql
    SECURITY DEFINER;
  `)
}

export async function up(knex: Knex): Promise<void> {
  await knex.raw(`
    CREATE TRIGGER audit_log_table_name
    AFTER INSERT OR UPDATE OR DELETE ON myschema.table_name
    FOR EACH ROW EXECUTE FUNCTION audit.if_modified_func();
  `)
}

In the trigger function audit.if_modified_func() I declare a variable auth0_user, based on an environment variable I set from application level using this code: await connection.raw('SELECT set_config(\'auth0.user_id\', ?, false)', [subClaim]), where subClaim has been fetched from sub-claim of access token.

If I try to simulate and trigger expected behavior directly from pgAdmin with code like this the triggering system functions perfectly fine:

BEGIN;
SELECT set_config('auth0.user_id', 'some dummy value', false);
SELECT current_setting('auth0.user_id', true);
SET ROLE some_role;
INSERT INTO myschema.table_name(col1, col2) VALUES ('some', 'value');
ROLLBACK;

But if I try to make inserts/updates from my Graphql API the triggers fail, and thus nothing gets audit logged.

Another weird behavior is that this audit logging system is a very similar system as one that I have already implemented in backend, where I log all changes, i.e. logging of all specific column changes happening during updates specifically. Thus, this audit logging is just a more extensive version of this logging system, and I would assume that this should work perfectly fine in similar fashion.

If I for instance modifies the beginning of trigger function from

IF (auth0_user IS NOT NULL AND auth0_user != '') THEN
    active_user := auth0_user;
ELSE
    active_user := CURRENT_USER;
END IF;
...

to just being

active_user := CURRENT_USER;
...

the system works fine and as expected. Thus, the problem lies in the usage of current_setting function. But since this works perfectly fine from pgAdmin (simulation above), and also function fine in my changelog system already implemented, I am lost. I feel like I have tried everything, both with respect to identifying the problem, as well as trying to solve it.

Has someone experienced similar problems, or know how this may be resolved?

I have tried to make requests from my GraphQL endpoint where I modify/add data to database. Then I would expect to see a new row with logging inside my logged_actions table. However, the table contained 0 rows of data.

I have also tried to simulate the flow through pgAdmin (i.e. on database layer), and this worked as expected with correct triggering.

0

There are 0 answers