Thread: Trigger firing order
Hi,
I'm using triggers to implement a DML auditing mechanism. I've been doing some testing around cascading foreign key constraints and the results surprised me (and somewhat busted my mechanism haha). I was hoping to be able to log statement level data as well as actual row changes that link back to the logged statement.
Anyway, here's my test script:
begin;
create table t1 (id integer primary key, name text);
create table t2 (id integer primary key, name text, t1_id integer, constraint t1_fk foreign key (t1_id) references t1 (id) on delete cascade on update cascade);
insert into t1 values (10, 't1-10'), (20, 't1-20'), (30, 't1-30');
insert into t2 values (10, 't2-10', 10), (20, 't2-20', 10), (30, 't2-30', 20), (40, 't2-40', 30);
create function a_bs() returns trigger as $$
begin
raise warning 'a_bs: tname=% op=% qry=%', tg_table_name, tg_op, current_query();
return null;
end;
$$ language plpgsql;
create function a_as() returns trigger as $$
begin
raise warning 'a_as: tname=% op=% qry=%', tg_table_name, tg_op, current_query();
return null;
end;
$$ language plpgsql;
create function a_br() returns trigger as $$
declare
l_row text;
begin
if tg_op = 'DELETE' then
l_row := to_jsonb(old)::text;
else
l_row := to_jsonb(new)::text;
end if;
raise warning 'a_br: tname=% op=% qry=% row=%', tg_table_name, tg_op, current_query(), l_row;
if tg_op = 'DELETE' then
return old;
else
return new;
end if;
end;
$$ language plpgsql;
create function a_ar() returns trigger as $$
declare
l_row text;
begin
if tg_op = 'DELETE' then
l_row := to_jsonb(old)::text;
else
l_row := to_jsonb(new)::text;
end if;
raise warning 'a_ar: tname=% op=% qry=% row=%', tg_table_name, tg_op, current_query(), l_row;
return null;
end;
$$ language plpgsql;
create trigger t1_bs before insert or update or delete on t1 for each statement execute procedure a_bs();
create trigger t1_as after insert or update or delete on t1 for each statement execute procedure a_as();
create trigger t1_br before insert or update or delete on t1 for each row execute procedure a_br();
create trigger t1_ar after insert or update or delete on t1 for each row execute procedure a_ar();
create trigger t2_bs before insert or update or delete on t2 for each statement execute procedure a_bs();
create trigger t2_as after insert or update or delete on t2 for each statement execute procedure a_as();
create trigger t2_br before insert or update or delete on t2 for each row execute procedure a_br();
create trigger t2_ar after insert or update or delete on t2 for each row execute procedure a_ar();
delete from t1 where id = 10;
update t1 set id = 21 where id = 20;
rollback;
When I run this, here's the output:
:
psql:t-aud.sql:67: WARNING: a_bs: tname=t1 op=DELETE qry=delete from t1 where id = 10;
psql:t-aud.sql:67: WARNING: a_br: tname=t1 op=DELETE qry=delete from t1 where id = 10; row={"id": 10, "name": "t1-10"}
psql:t-aud.sql:67: WARNING: a_bs: tname=t2 op=DELETE qry=delete from t1 where id = 10;
psql:t-aud.sql:67: WARNING: a_br: tname=t2 op=DELETE qry=delete from t1 where id = 10; row={"id": 10, "name": "t2-10", "t1_id": 10}
psql:t-aud.sql:67: WARNING: a_br: tname=t2 op=DELETE qry=delete from t1 where id = 10; row={"id": 20, "name": "t2-20", "t1_id": 10}
psql:t-aud.sql:67: WARNING: a_ar: tname=t1 op=DELETE qry=delete from t1 where id = 10; row={"id": 10, "name": "t1-10"}
psql:t-aud.sql:67: WARNING: a_as: tname=t1 op=DELETE qry=delete from t1 where id = 10;
psql:t-aud.sql:67: WARNING: a_ar: tname=t2 op=DELETE qry=delete from t1 where id = 10; row={"id": 10, "name": "t2-10", "t1_id": 10}
psql:t-aud.sql:67: WARNING: a_ar: tname=t2 op=DELETE qry=delete from t1 where id = 10; row={"id": 20, "name": "t2-20", "t1_id": 10}
psql:t-aud.sql:67: WARNING: a_as: tname=t2 op=DELETE qry=delete from t1 where id = 10;
DELETE 1
psql:t-aud.sql:69: WARNING: a_bs: tname=t1 op=UPDATE qry=update t1 set id = 21 where id = 20;
psql:t-aud.sql:69: WARNING: a_br: tname=t1 op=UPDATE qry=update t1 set id = 21 where id = 20; row={"id": 21, "name": "t1-20"}
psql:t-aud.sql:69: WARNING: a_bs: tname=t2 op=UPDATE qry=update t1 set id = 21 where id = 20;
psql:t-aud.sql:69: WARNING: a_br: tname=t2 op=UPDATE qry=update t1 set id = 21 where id = 20; row={"id": 30, "name": "t2-30", "t1_id": 21}
psql:t-aud.sql:69: WARNING: a_ar: tname=t1 op=UPDATE qry=update t1 set id = 21 where id = 20; row={"id": 21, "name": "t1-20"}
psql:t-aud.sql:69: WARNING: a_as: tname=t1 op=UPDATE qry=update t1 set id = 21 where id = 20;
psql:t-aud.sql:69: WARNING: a_ar: tname=t2 op=UPDATE qry=update t1 set id = 21 where id = 20; row={"id": 30, "name": "t2-30", "t1_id": 21}
psql:t-aud.sql:69: WARNING: a_as: tname=t2 op=UPDATE qry=update t1 set id = 21 where id = 20;
:
What surprised me was the after statement trigger for t2 and 1+ of the after row triggers for t2 fired after the after statement trigger for t1.
I can imagine why. The engine is probably saying "I'm done with all changes to t1 so fire the after statement trigger".
I guess I had imagined all operations for 'nested' tables would complete before executing the after statement trigger of the outermost 'invoking' table. (I'm coming from having used Oracle for many years).
Can anyone point me to somewhere in the docs where this behaviour is explained? I understand postgres FK's are implement with triggers. How do I find them so I can see what they're doing and hopefully better understand the mechanism?
Thanks,
Steve
Steve Baldwin <steve.baldwin@gmail.com> writes:
> I'm using triggers to implement a DML auditing mechanism. I've been doing
> some testing around cascading foreign key constraints and the results
> surprised me (and somewhat busted my mechanism haha). I was hoping to be
> able to log statement level data as well as actual row changes that link
> back to the logged statement.
> ...
> What surprised me was the after statement trigger for t2 and 1+ of the
> after row triggers for t2 fired after the after statement trigger for t1.
Yeah. The reason is that all the "after" triggers fired by the outer
statement on t1 (the RI enforcement triggers, and your a_ar triggers on
t1, and your a_as trigger on t1) are queued up, then when the RI
enforcement triggers run and cause additional "after" trigger events
to be queued (the ones for t2), those go onto the end of the queue.
> I guess I had imagined all operations for 'nested' tables would complete
> before executing the after statement trigger of the outermost 'invoking'
> table. (I'm coming from having used Oracle for many years).
We could easily fire the newly-queued "after" triggers before returning
from each RI enforcement trigger, but that creates a new set of problems:
those triggers would see an incompletely-updated state of t2, if more RI
enforcement actions remain in the queue. Essentially that would make
visible the fact that whatever cascade actions need to be done are done
in a separate command for each cascaded-from row, whereas the SQL spec
would have us make it look like all the cascade effects occur in a single
statement. So we do it like this instead. (I'm not totally wedded to
this as being a great idea, but rejiggering it would be a complex task
with probably not a lot of payoff in the end.)
> Can anyone point me to somewhere in the docs where this behaviour is
> explained?
I doubt it's terribly well documented :-(
> I understand postgres FK's are implement with triggers. How do I
> find them so I can see what they're doing and hopefully better understand
> the mechanism?
Just look into pg_trigger, eg
SELECT t.tgname, pg_catalog.pg_get_triggerdef(t.oid, true), t.tgisinternal
FROM pg_catalog.pg_trigger t
WHERE t.tgrelid = 'mytable'::regclass
ORDER BY 1;
(psql's \d command does essentially this to show you a table's triggers,
but it skips "tgisinternal" triggers which is why you don't see the RI
triggers.)
regards, tom lane
Thanks again Tom. I really appreciate the time you take to respond to my noob questions.
Steve
On Thu, May 17, 2018 at 8:04 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Steve Baldwin <steve.baldwin@gmail.com> writes:
> I'm using triggers to implement a DML auditing mechanism. I've been doing
> some testing around cascading foreign key constraints and the results
> surprised me (and somewhat busted my mechanism haha). I was hoping to be
> able to log statement level data as well as actual row changes that link
> back to the logged statement.
> ...
> What surprised me was the after statement trigger for t2 and 1+ of the
> after row triggers for t2 fired after the after statement trigger for t1.
Yeah. The reason is that all the "after" triggers fired by the outer
statement on t1 (the RI enforcement triggers, and your a_ar triggers on
t1, and your a_as trigger on t1) are queued up, then when the RI
enforcement triggers run and cause additional "after" trigger events
to be queued (the ones for t2), those go onto the end of the queue.
> I guess I had imagined all operations for 'nested' tables would complete
> before executing the after statement trigger of the outermost 'invoking'
> table. (I'm coming from having used Oracle for many years).
We could easily fire the newly-queued "after" triggers before returning
from each RI enforcement trigger, but that creates a new set of problems:
those triggers would see an incompletely-updated state of t2, if more RI
enforcement actions remain in the queue. Essentially that would make
visible the fact that whatever cascade actions need to be done are done
in a separate command for each cascaded-from row, whereas the SQL spec
would have us make it look like all the cascade effects occur in a single
statement. So we do it like this instead. (I'm not totally wedded to
this as being a great idea, but rejiggering it would be a complex task
with probably not a lot of payoff in the end.)
> Can anyone point me to somewhere in the docs where this behaviour is
> explained?
I doubt it's terribly well documented :-(
> I understand postgres FK's are implement with triggers. How do I
> find them so I can see what they're doing and hopefully better understand
> the mechanism?
Just look into pg_trigger, eg
SELECT t.tgname, pg_catalog.pg_get_triggerdef(t.oid, true), t.tgisinternal
FROM pg_catalog.pg_trigger t
WHERE t.tgrelid = 'mytable'::regclass
ORDER BY 1;
(psql's \d command does essentially this to show you a table's triggers,
but it skips "tgisinternal" triggers which is why you don't see the RI
triggers.)
regards, tom lane