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