Logging transactions that dropped tables

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 postgresql.conf:

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;

The 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;
postgres=# DROP TABLE test1;
postgres=# DROP TABLE test2;
postgres=# 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$
  obj record;
  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;

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 (
  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
  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;
postgres=# DROP TABLE test3;
postgres=# 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.


I speak at and organize conferences around Open Source in general and PostgreSQL in particular.


PGCon 2017
May 23-26, 2017
Ottawa, Canada


pgDay.paris 2017
Mar 23, 2017
Paris, France
Nordic PGDay 2017
Mar 21, 2017
Stockholm, Sweden
Confoo Montreal 2017
Mar 8-10, 2017
Montreal, Canada
Mar 2-5, 2017
Pasadena, California, USA
Open Source Infrastructure @ SCALE
Mar 2, 2017
Pasadena, California, USA
More past conferences