In a previous post I discussed a way to find out which transaction dropped a table by examining the transaction log, in order to set a restore point to right before the table was dropped.
But what if we have the luxury of planning ahead (right? Well, let's call it the second time it happens?). Shouldn't we be able to log which transaction dropped a table, and use that? Of course we should.
The first thing one tries is then of course something like this in
log_statement='ddl' log_line_prefix = '%t [%u@%d] <%x> '
to include the transaction id of the table. Unfortunately:
2017-02-12 12:16:39 CET [mha@postgres] <0> LOG: statement: drop table testtable;
0 as a transaction id indicates that this command was run in a virtual transaction, and did not have a real transaction id. The reason for this is that the statement logging happens before the statement has actually acquired a transaction. For example, if I instead drop two tables, and do so in a transaction:
postgres=# BEGIN; BEGIN postgres=# DROP TABLE test1; DROP TABLE postgres=# DROP TABLE test2; DROP TABLE postgres=# COMMIT; COMMIT
I get this interesting output:
2017-02-12 12:17:43 CET [mha@postgres] <0> LOG: statement: DROP TABLE test1; 2017-02-12 12:17:45 CET [mha@postgres] <156960> LOG: statement: DROP TABLE test2;
Which shows two different transaction ids (one real and one not) for statements in the same transaction. That's obviously not true - they were both dropped by transaction
156960. The transaction id just wasn't available at the time of logging.
So what can we do about that? Event triggers to the rescue!
Event triggers can fire on a number of events, one of them being a
DROP TABLE. So let's see how we can leverage that.
First a quick reminder -- event triggers are per database, so if you have multiple databases you have to create your event triggers once in each database!
With event triggers we can capture the actual
DROP TABLE statement, and log it either to the regular postgresql log (see caveat below) or even to a table. As usual with PostgreSQL, a trigger always calls a function (no in-line triggers), so let's start with a function:
CREATE OR REPLACE FUNCTION public.trg_log_drop() RETURNS event_trigger LANGUAGE plpgsql AS $function$ DECLARE obj record; BEGIN FOR obj in SELECT * FROM pg_event_trigger_dropped_objects() LOOP IF obj.object_type = 'table' THEN RAISE NOTICE 'TABLE % DROPPED by transaction % (pre-commit)', obj.object_identity, txid_current(); INSERT INTO public.droplog (tablename, dropxid) VALUES (obj.object_identity, txid_current()); END IF; END LOOP; END; $function$
This trigger function will log all drop tables in two ways - it both to the system log (using
RAISE NOTICE) and to a table called
public.droplog. It logs only the most basic information, but it's of course also possible to add things like which user issued the drop etc. The table used for logging is just a standard table:
CREATE TABLE droplog ( ts timestamptz NOT NULL DEFAULT CURRENT_TIMESTAMP, tablename text NOT NULL, dropxid bigint )
And finally we have to create the event trigger itself:
CREATE EVENT TRIGGER table_drop_logger ON sql_drop WHEN TAG IN ('DROP TABLE') EXECUTE PROCEDURE public.trg_log_drop()
When rerunning the drop above after the event trigger has been created, it produces the following log:
2017-02-12 12:47:02 CET [mha@postgres] <156975> LOG: TABLE public.testtable DROPPED by transaction 156975 (pre-commit)
And the following contents of the table:
postgres=# SELECT * FROM droplog; ts │ tablename │ dropxid ───────────────────────────────┼──────────────────┼───────── 2017-02-12 12:47:02.445561+01 │ public.testtable │ 156975
Notice that little text saying (pre-commit). That is because the event trigger runs as part of the same transaction as the
DROP TABLE, so if that transaction is rolled back the results of the event trigger will also be rolled back. Except for things like
RAISE which log things outside the transaction context. So if I instead run:
postgres=# BEGIN; BEGIN postgres=# DROP TABLE test3; DROP TABLE postgres=# ROLLBACK; ROLLBACK
I still get a lot of:
2017-02-12 12:52:30 CET [mha@postgres] <156978> LOG: TABLE public.test3 DROPPED by transaction 156978 (pre-commit)
even though the transaction rolled back. But I get no entry for test3 in the table:
postgres=# SELECT * FROM droplog where tablename='public.test3'; ts │ tablename │ dropxid ────┼───────────┼───────── (0 rows)
Obviously this example can be extended to cover other objects than tables if necessary, but it's usually the dropping of tables that people ask for in relation to "what transaction do I set my recovery_target_xid to". But it's simple to track multiple event tags and then just store which one it was in another column in the droplog table.