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.