diff --git a/contrib/postgres_fdw/connection.c b/contrib/postgres_fdw/connection.c index aab216959793f..cec919f3a4b8b 100644 --- a/contrib/postgres_fdw/connection.c +++ b/contrib/postgres_fdw/connection.c @@ -154,7 +154,7 @@ static void do_sql_command_end(PGconn *conn, const char *sql, static void begin_remote_xact(ConnCacheEntry *entry); static void pgfdw_report_internal(int elevel, PGresult *res, PGconn *conn, const char *sql); -static void pgfdw_xact_callback(XactEvent event, void *arg); +static void pgfdw_xact_callback(XactEvent event, void *arg, XLogRecPtr lsn); static void pgfdw_subxact_callback(SubXactEvent event, SubTransactionId mySubid, SubTransactionId parentSubid, @@ -1170,7 +1170,7 @@ pgfdw_report_internal(int elevel, PGresult *res, PGconn *conn, * COMMIT TRANSACTION may run deferred triggers.) */ static void -pgfdw_xact_callback(XactEvent event, void *arg) +pgfdw_xact_callback(XactEvent event, void *arg, XLogRecPtr lsn) { HASH_SEQ_STATUS scan; ConnCacheEntry *entry; diff --git a/contrib/sepgsql/label.c b/contrib/sepgsql/label.c index 01c2074a0edfa..02aa213ee1593 100644 --- a/contrib/sepgsql/label.c +++ b/contrib/sepgsql/label.c @@ -161,7 +161,7 @@ sepgsql_set_client_label(const char *new_label) * changes in the client_label_pending list. */ static void -sepgsql_xact_callback(XactEvent event, void *arg) +sepgsql_xact_callback(XactEvent event, void *arg, XLogRecPtr lsn) { if (event == XACT_EVENT_COMMIT) { diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 0848c18d329e3..6be3dd3cfcafe 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -8055,6 +8055,75 @@ local0.* /var/log/postgresql + + log_object_drops (boolean) + + log_object_drops configuration parameter + + + + + Causes DROP TABLE and DROP DATABASE + operations to be logged with their commit LSN (Log Sequence Number). + The commit LSN represents the point in the write-ahead log where the + drop operation becomes durable and visible to other transactions. + + + + Each logged entry includes the schema name, table name, OID, and the + commit LSN. For example: + + LOG: DROP TABLE: relation "public.employees" (OID 16384), commit LSN: 0/015D4A48 + LOG: DROP DATABASE: database "testdb" (OID 16385), commit LSN: 0/015D4B20 + + + + + Logged operations include: direct DROP TABLE statements, + tables dropped via DROP SCHEMA CASCADE, + partitioned tables and their partitions, tables in inheritance hierarchies, + and DROP DATABASE commands. + Operations that are rolled back (via ROLLBACK or + ROLLBACK TO SAVEPOINT) are not logged. + Temporary tables are not logged, since their contents cannot be + recovered by point-in-time recovery. + + + + This parameter is useful for tracking and auditing destructive operations, + and for coordinating with external systems that monitor the write-ahead log. + Note that enabling this option may generate substantial log volume + when dropping schemas or databases containing many tables. + + + + The default is off. Only superusers and users with + the appropriate SET privilege can change this setting. + + + + Using the logged LSN for point-in-time recovery. + The logged value is the LSN at which the commit + record of the transaction that performed the drop begins, which is the + value compares against. To + recover the dropped object, recovery must stop + before that record is replayed. + Because defaults to + on, which stops recovery after + the target LSN, setting recovery_target_lsn to the + logged LSN alone would replay the drop and lose the object again. + You must also set recovery_target_inclusive to + off: + +recovery_target_lsn = '0/015D4A48' # the commit LSN from the log message +recovery_target_inclusive = off # required: stop BEFORE the drop commits + + With these settings, recovery stops just short of the drop, and the + object is present in the recovered cluster. Note that any transaction + that committed after this LSN is also not recovered. + + + log_duration (boolean) diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c index 3a89149016fe6..6562a188f8078 100644 --- a/src/backend/access/transam/xact.c +++ b/src/backend/access/transam/xact.c @@ -340,7 +340,7 @@ static void AtCommit_Memory(void); static void AtStart_Cache(void); static void AtStart_Memory(void); static void AtStart_ResourceOwner(void); -static void CallXactCallbacks(XactEvent event); +static void CallXactCallbacks(XactEvent event, XLogRecPtr lsn); static void CallSubXactCallbacks(SubXactEvent event, SubTransactionId mySubid, SubTransactionId parentSubid); @@ -1342,9 +1342,10 @@ AtSubStart_ResourceOwner(void) * If you change this function, see RecordTransactionCommitPrepared also. */ static TransactionId -RecordTransactionCommit(void) +RecordTransactionCommit(XLogRecPtr *commit_lsn_out) { TransactionId xid = GetTopTransactionIdIfAny(); + XLogRecPtr commit_lsn = InvalidXLogRecPtr; bool markXidCommitted = TransactionIdIsValid(xid); TransactionId latestXid = InvalidTransactionId; int nrels; @@ -1481,13 +1482,24 @@ RecordTransactionCommit(void) /* * Insert the commit XLOG record. */ - XactLogCommitRecord(GetCurrentTransactionStopTimestamp(), - nchildren, children, nrels, rels, - ndroppedstats, droppedstats, - nmsgs, invalMessages, - RelcacheInitFileInval, - MyXactFlags, - InvalidTransactionId, NULL /* plain commit */ ); + (void) XactLogCommitRecord(GetCurrentTransactionStopTimestamp(), + nchildren, children, nrels, rels, + ndroppedstats, droppedstats, + nmsgs, invalMessages, + RelcacheInitFileInval, + MyXactFlags, + InvalidTransactionId, NULL /* plain commit */ ); + + /* + * Report the *start* of the commit record to XactCallbacks, not its + * end. Recovery compares recovery_target_lsn against the start LSN of + * each record (see recoveryStopsBefore()), so the start LSN is the + * value a DBA can feed back to recovery_target_lsn, together with + * recovery_target_inclusive = off, to stop just before this + * transaction commits. The end LSN would be the start of the *next* + * record and would therefore replay this commit. + */ + commit_lsn = ProcLastRecPtr; if (replorigin) /* Move LSNs forward for this replication origin */ @@ -1610,6 +1622,9 @@ RecordTransactionCommit(void) if (ndroppedstats) pfree(droppedstats); + if (commit_lsn_out) + *commit_lsn_out = commit_lsn; + return latestXid; } @@ -2272,6 +2287,7 @@ CommitTransaction(void) TransactionState s = CurrentTransactionState; TransactionId latestXid; bool is_parallel_worker; + XLogRecPtr commit_lsn = InvalidXLogRecPtr; is_parallel_worker = (s->blockState == TBLOCK_PARALLEL_INPROGRESS); @@ -2320,7 +2336,8 @@ CommitTransaction(void) */ CallXactCallbacks(is_parallel_worker ? XACT_EVENT_PARALLEL_PRE_COMMIT - : XACT_EVENT_PRE_COMMIT); + : XACT_EVENT_PRE_COMMIT, + InvalidXLogRecPtr); /* * If this xact has started any unfinished parallel operation, clean up @@ -2404,7 +2421,7 @@ CommitTransaction(void) * We need to mark our XIDs as committed in pg_xact. This is where we * durably commit. */ - latestXid = RecordTransactionCommit(); + latestXid = RecordTransactionCommit(&commit_lsn); } else { @@ -2447,7 +2464,8 @@ CommitTransaction(void) */ CallXactCallbacks(is_parallel_worker ? XACT_EVENT_PARALLEL_COMMIT - : XACT_EVENT_COMMIT); + : XACT_EVENT_COMMIT, + commit_lsn); CurrentResourceOwner = NULL; ResourceOwnerRelease(TopTransactionResourceOwner, @@ -2597,7 +2615,7 @@ PrepareTransaction(void) break; } - CallXactCallbacks(XACT_EVENT_PRE_PREPARE); + CallXactCallbacks(XACT_EVENT_PRE_PREPARE, InvalidXLogRecPtr); /* * The remaining actions cannot call any user-defined code, so it's safe @@ -2757,7 +2775,7 @@ PrepareTransaction(void) * that cure could be worse than the disease. */ - CallXactCallbacks(XACT_EVENT_PREPARE); + CallXactCallbacks(XACT_EVENT_PREPARE, InvalidXLogRecPtr); ResourceOwnerRelease(TopTransactionResourceOwner, RESOURCE_RELEASE_BEFORE_LOCKS, @@ -3011,9 +3029,9 @@ AbortTransaction(void) if (TopTransactionResourceOwner != NULL) { if (is_parallel_worker) - CallXactCallbacks(XACT_EVENT_PARALLEL_ABORT); + CallXactCallbacks(XACT_EVENT_PARALLEL_ABORT, InvalidXLogRecPtr); else - CallXactCallbacks(XACT_EVENT_ABORT); + CallXactCallbacks(XACT_EVENT_ABORT, InvalidXLogRecPtr); ResourceOwnerRelease(TopTransactionResourceOwner, RESOURCE_RELEASE_BEFORE_LOCKS, @@ -3889,7 +3907,7 @@ UnregisterXactCallback(XactCallback callback, void *arg) } static void -CallXactCallbacks(XactEvent event) +CallXactCallbacks(XactEvent event, XLogRecPtr lsn) { XactCallbackItem *item; XactCallbackItem *next; @@ -3898,7 +3916,7 @@ CallXactCallbacks(XactEvent event) { /* allow callbacks to unregister themselves when called */ next = item->next; - item->callback(event, item->arg); + item->callback(event, item->arg, lsn); } } diff --git a/src/backend/catalog/dependency.c b/src/backend/catalog/dependency.c index c54774b327590..2ce9ee9f2a25a 100644 --- a/src/backend/catalog/dependency.c +++ b/src/backend/catalog/dependency.c @@ -18,6 +18,7 @@ #include "access/htup_details.h" #include "access/table.h" #include "access/xact.h" +#include "access/xlog.h" #include "catalog/catalog.h" #include "catalog/dependency.h" #include "catalog/heap.h" @@ -71,6 +72,7 @@ #include "catalog/pg_ts_template.h" #include "catalog/pg_type.h" #include "catalog/pg_user_mapping.h" +#include "utils/guc.h" #include "commands/comment.h" #include "commands/defrem.h" #include "commands/event_trigger.h" @@ -182,6 +184,185 @@ static bool stack_address_present_add_flags(const ObjectAddress *object, ObjectAddressStack *stack); static void DeleteInitPrivs(const ObjectAddress *object); +/* Kind of object recorded for drop logging */ +typedef enum DropLogKind +{ + DROP_LOG_TABLE, + DROP_LOG_DATABASE, +} DropLogKind; + +/* Structure to hold information about a dropped object */ +typedef struct DropObjectInfo +{ + DropLogKind kind; + Oid objoid; + char objname[NAMEDATALEN]; + char schemaname[NAMEDATALEN]; /* only used for DROP_LOG_TABLE */ + SubTransactionId subxid; + bool valid; +} DropObjectInfo; + +/* Per-transaction list of dropped objects */ +static List *pending_object_drops = NIL; +static bool drop_object_callback_registered = false; + +static void DropObjectXactCallback(XactEvent event, void *arg, XLogRecPtr lsn); +static void DropObjectSubXactCallback(SubXactEvent event, SubTransactionId mySubid, + SubTransactionId parentSubid, void *arg); + +/* + * Record a dropped object so that its commit LSN can be logged once the + * transaction commits. Logging is deferred to the commit callback because + * only the commit LSN is meaningful for point-in-time recovery: the LSN of + * the catalog change itself is useless to a DBA, as the drop does not become + * durable (and other backends cannot observe it) until the commit record is + * written. Deferring also means a drop that is later rolled back is never + * logged at all. + */ +static void +RegisterDropObject(DropLogKind kind, Oid objoid, const char *objname, + const char *schemaname) +{ + DropObjectInfo *info; + MemoryContext oldcontext; + + if (!drop_object_callback_registered) + { + RegisterXactCallback(DropObjectXactCallback, NULL); + RegisterSubXactCallback(DropObjectSubXactCallback, NULL); + drop_object_callback_registered = true; + } + + oldcontext = MemoryContextSwitchTo(TopTransactionContext); + + info = (DropObjectInfo *) palloc(sizeof(DropObjectInfo)); + info->kind = kind; + info->objoid = objoid; + strlcpy(info->objname, objname, NAMEDATALEN); + strlcpy(info->schemaname, schemaname ? schemaname : "", NAMEDATALEN); + info->subxid = GetCurrentSubTransactionId(); + info->valid = true; + + pending_object_drops = lappend(pending_object_drops, info); + + MemoryContextSwitchTo(oldcontext); +} + +/* + * RegisterDropDatabaseForLogging + * Record a DROP DATABASE for commit-LSN logging. + * + * Exposed for dbcommands.c, which does not go through performDeletion(). + */ +void +RegisterDropDatabaseForLogging(Oid dboid, const char *dbname) +{ + RegisterDropObject(DROP_LOG_DATABASE, dboid, dbname, NULL); +} + +/* + * SubXactCallback - handle ROLLBACK TO SAVEPOINT + */ +static void +DropObjectSubXactCallback(SubXactEvent event, SubTransactionId mySubid, + SubTransactionId parentSubid, void *arg) +{ + ListCell *lc; + + if (pending_object_drops == NIL) + return; + + /* + * On subtransaction abort, invalidate all entries belonging to the + * aborted subtransaction and its children. + */ + if (event == SUBXACT_EVENT_ABORT_SUB) + { + foreach(lc, pending_object_drops) + { + DropObjectInfo *info = (DropObjectInfo *) lfirst(lc); + + /* + * Mark entries that belong to our subtransactions. + * SubTransactionIds are assigned incrementally, so we can compare + * them. + */ + if (info->subxid >= mySubid) + info->valid = false; + } + } +} + +/* + * DropObjectXactCallback + * Transaction callback to log the commit LSN for dropped objects. + */ +static void +DropObjectXactCallback(XactEvent event, void *arg, XLogRecPtr commit_lsn) +{ + ListCell *lc; + + if (pending_object_drops == NIL) + return; + + if (event == XACT_EVENT_COMMIT) + { + /* + * Any transaction that dropped a table or a database necessarily + * modified the catalogs, so it must have been assigned an XID and + * written a commit record. + * + * commit_lsn is the start LSN of that commit record, which is + * precisely the value to hand to recovery_target_lsn (with + * recovery_target_inclusive = off) to recover the dropped object. + */ + Assert(!XLogRecPtrIsInvalid(commit_lsn)); + + foreach(lc, pending_object_drops) + { + DropObjectInfo *info = (DropObjectInfo *) lfirst(lc); + + if (!info->valid) + continue; + + switch (info->kind) + { + case DROP_LOG_TABLE: + ereport(LOG, + (errmsg("DROP TABLE: relation \"%s.%s\" (OID %u), commit LSN: %X/%08X", + info->schemaname, + info->objname, + info->objoid, + LSN_FORMAT_ARGS(commit_lsn)))); + break; + case DROP_LOG_DATABASE: + ereport(LOG, + (errmsg("DROP DATABASE: database \"%s\" (OID %u), commit LSN: %X/%08X", + info->objname, + info->objoid, + LSN_FORMAT_ARGS(commit_lsn)))); + break; + } + } + } + + /* Clean up after commit or abort */ + if (event == XACT_EVENT_COMMIT || + event == XACT_EVENT_ABORT || + event == XACT_EVENT_PARALLEL_ABORT) + { + /* Free the DropObjectInfo structures */ + foreach(lc, pending_object_drops) + { + DropObjectInfo *info = (DropObjectInfo *) lfirst(lc); + + pfree(info); + } + + list_free(pending_object_drops); + pending_object_drops = NIL; + } +} /* * Go through the objects given running the final actions on them, and execute @@ -1423,6 +1604,39 @@ doDeletion(const ObjectAddress *object, int flags) { char relKind = get_rel_relkind(object->objectId); + /* + * Log all table drops that go through this function. + * + * Temporary tables are deliberately excluded: their contents + * are not recoverable by point-in-time recovery in the first + * place, and they are routinely dropped at session end, which + * would swamp the log with entries no DBA can act on. + */ + if ((relKind == RELKIND_RELATION || + relKind == RELKIND_PARTITIONED_TABLE) && + log_object_drops && + get_rel_persistence(object->objectId) != RELPERSISTENCE_TEMP) + { + char *relname = get_rel_name(object->objectId); + + if (relname != NULL) + { + char *schemaname = NULL; + Oid schemaoid = get_rel_namespace(object->objectId); + + if (OidIsValid(schemaoid)) + schemaname = get_namespace_name(schemaoid); + + RegisterDropObject(DROP_LOG_TABLE, object->objectId, + relname, + schemaname ? schemaname : "unknown"); + + pfree(relname); + if (schemaname) + pfree(schemaname); + } + } + if (relKind == RELKIND_INDEX || relKind == RELKIND_PARTITIONED_INDEX) { diff --git a/src/backend/commands/dbcommands.c b/src/backend/commands/dbcommands.c index 51dcbd9cace4f..578e261cfad73 100644 --- a/src/backend/commands/dbcommands.c +++ b/src/backend/commands/dbcommands.c @@ -1862,6 +1862,17 @@ dropdb(const char *dbname, bool missing_ok, bool force) CatalogTupleDelete(pgdbrel, &tup->t_self); heap_freetuple(tup); + /* + * Record the drop so that the commit LSN can be logged once this + * transaction commits. We must not log GetXLogInsertRecPtr() here: at + * this point the commit record has not been written yet, and dropdb() + * still has substantial work to do (including forcing a checkpoint), so + * the current insert pointer can be far behind the commit LSN. Only the + * commit LSN is a valid point-in-time recovery target. + */ + if (log_object_drops) + RegisterDropDatabaseForLogging(db_id, dbname); + /* * Drop db-specific replication slots. */ diff --git a/src/backend/utils/misc/guc_parameters.dat b/src/backend/utils/misc/guc_parameters.dat index d421cdbde76da..6c842387c2077 100644 --- a/src/backend/utils/misc/guc_parameters.dat +++ b/src/backend/utils/misc/guc_parameters.dat @@ -1792,6 +1792,13 @@ assign_hook => 'assign_log_min_messages', }, +{ name => 'log_object_drops', type => 'bool', context => 'PGC_SUSET', group => 'LOGGING_WHAT', + short_desc => 'Logs LSN for DROP TABLE and DROP DATABASE operations.', + long_desc => 'When enabled, the system will log the LSN (Log Sequence Number) whenever a DROP TABLE or DROP DATABASE command is executed.', + variable => 'log_object_drops', + boot_val => 'false', +}, + { name => 'log_parameter_max_length', type => 'int', context => 'PGC_SUSET', group => 'LOGGING_WHAT', short_desc => 'Sets the maximum length in bytes of data logged for bind parameter values when logging statements.', long_desc => '-1 means log values in full.', diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c index 90aa374b3ec70..2b1ddf78cdded 100644 --- a/src/backend/utils/misc/guc_tables.c +++ b/src/backend/utils/misc/guc_tables.c @@ -545,6 +545,7 @@ bool Debug_write_read_parse_plan_trees; bool Debug_raw_expression_coverage_test; #endif +bool log_object_drops = false; bool log_parser_stats = false; bool log_planner_stats = false; bool log_executor_stats = false; diff --git a/src/include/access/xact.h b/src/include/access/xact.h index a8cbdf247c866..b1195a0311b81 100644 --- a/src/include/access/xact.h +++ b/src/include/access/xact.h @@ -136,7 +136,7 @@ typedef enum XACT_EVENT_PRE_PREPARE, } XactEvent; -typedef void (*XactCallback) (XactEvent event, void *arg); +typedef void (*XactCallback) (XactEvent event, void *arg, XLogRecPtr lsn); typedef enum { diff --git a/src/include/catalog/dependency.h b/src/include/catalog/dependency.h index 2f3c1eae3c71d..fbc6c9f7cb850 100644 --- a/src/include/catalog/dependency.h +++ b/src/include/catalog/dependency.h @@ -238,4 +238,6 @@ extern void shdepDropOwned(List *roleids, DropBehavior behavior); extern void shdepReassignOwned(List *roleids, Oid newrole); +extern void RegisterDropDatabaseForLogging(Oid dboid, const char *dbname); + #endif /* DEPENDENCY_H */ diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h index 8057d7870adb4..e2275121964a6 100644 --- a/src/include/utils/guc.h +++ b/src/include/utils/guc.h @@ -304,6 +304,7 @@ extern PGDLLIMPORT int log_statement_max_length; extern PGDLLIMPORT double log_statement_sample_rate; extern PGDLLIMPORT double log_xact_sample_rate; extern PGDLLIMPORT char *backtrace_functions; +extern PGDLLIMPORT bool log_object_drops; extern PGDLLIMPORT int temp_file_limit; diff --git a/src/pl/plpgsql/src/pl_exec.c b/src/pl/plpgsql/src/pl_exec.c index 65b0fd0790f2e..4e127ccfb4ca2 100644 --- a/src/pl/plpgsql/src/pl_exec.c +++ b/src/pl/plpgsql/src/pl_exec.c @@ -8808,7 +8808,7 @@ plpgsql_destroy_econtext(PLpgSQL_execstate *estate) * it has to be cleaned up. The same for the simple-expression resowner. */ void -plpgsql_xact_cb(XactEvent event, void *arg) +plpgsql_xact_cb(XactEvent event, void *arg, XLogRecPtr lsn) { /* * If we are doing a clean transaction shutdown, free the EState and tell diff --git a/src/pl/plpgsql/src/plpgsql.h b/src/pl/plpgsql/src/plpgsql.h index addb14a9959c7..b89cff18c2ffa 100644 --- a/src/pl/plpgsql/src/plpgsql.h +++ b/src/pl/plpgsql/src/plpgsql.h @@ -1266,7 +1266,7 @@ extern HeapTuple plpgsql_exec_trigger(PLpgSQL_function *func, TriggerData *trigdata); extern void plpgsql_exec_event_trigger(PLpgSQL_function *func, EventTriggerData *trigdata); -extern void plpgsql_xact_cb(XactEvent event, void *arg); +extern void plpgsql_xact_cb(XactEvent event, void *arg, XLogRecPtr lsn); extern void plpgsql_subxact_cb(SubXactEvent event, SubTransactionId mySubid, SubTransactionId parentSubid, void *arg); extern PGDLLEXPORT Oid plpgsql_exec_get_datum_type(PLpgSQL_execstate *estate, diff --git a/src/test/recovery/meson.build b/src/test/recovery/meson.build index ad0d85f41897e..bd0f2c04e7d7c 100644 --- a/src/test/recovery/meson.build +++ b/src/test/recovery/meson.build @@ -63,6 +63,7 @@ tests += { 't/052_checkpoint_segment_missing.pl', 't/053_standby_login_event_trigger.pl', 't/054_unlogged_sequence_promotion.pl', + 't/055_drop_table_logging.pl', ], }, } diff --git a/src/test/recovery/t/055_drop_table_logging.pl b/src/test/recovery/t/055_drop_table_logging.pl new file mode 100644 index 0000000000000..2a06a0d127450 --- /dev/null +++ b/src/test/recovery/t/055_drop_table_logging.pl @@ -0,0 +1,659 @@ +# Copyright (c) 2025-2026, PostgreSQL Global Development Group + +# Test log_object_drops. +# +# Beyond checking that a log entry appears at all, this verifies that the +# logged LSN is the *actual commit LSN* of the dropping transaction, that +# nothing is logged when the feature is off / the drop is rolled back / the +# object is temporary, and that the LSN is usable as a point-in-time recovery +# target in the way the documentation prescribes. + +use strict; +use warnings FATAL => 'all'; +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +my $node = PostgreSQL::Test::Cluster->new('primary'); +$node->init(has_archiving => 1, allows_streaming => 1); +$node->append_conf( + 'postgresql.conf', qq{ +log_min_messages = log +logging_collector = off +log_destination = 'stderr' +log_object_drops = on + +# Keep the WAL stream quiet so that the "logged LSN == current insert LSN" +# assertions below are not perturbed by unrelated background WAL. +autovacuum = off +checkpoint_timeout = 1h +max_wal_size = 1GB +}); +$node->start; + +# ============================================================================== +# Log-reading helpers +# ============================================================================== + +my $log_offset = 0; +my $current_test_log_cache = undef; + +# Reset to start a new test - clears cache and updates offset +sub start_new_test +{ + my ($test_name) = @_; + note($test_name) if defined $test_name; + + $current_test_log_cache = undef; + $log_offset = -s $node->logfile; +} + +# Get log content produced since the current test started (cached). +sub get_test_log_content +{ + return $current_test_log_cache if defined $current_test_log_cache; + + my $logfile = $node->logfile; + my $current_size = -s $logfile; + + $log_offset = 0 if $log_offset > $current_size; + $current_test_log_cache = slurp_file($logfile, $log_offset); + + return $current_test_log_cache; +} + +sub count_drop_logs +{ + my ($pattern) = @_; + my $log = get_test_log_content(); + my @matches = $log =~ /$pattern/g; + return scalar @matches; +} + +sub get_log_lines +{ + my ($pattern) = @_; + my @lines = split /\n/, get_test_log_content(); + return grep { /$pattern/ } @lines; +} + +sub drop_table_pattern +{ + my ($schema, $table) = @_; + return qr/DROP TABLE: relation "$schema\.$table"/; +} + +sub drop_database_pattern +{ + my ($dbname) = @_; + return qr/DROP DATABASE: database "$dbname"/; +} + +# ============================================================================== +# LSN helpers +# ============================================================================== + +# Extract the commit LSN from a log line, as a "hi/lo" string. +sub extract_commit_lsn +{ + my ($line) = @_; + return $1 if $line =~ m{commit LSN: ([0-9A-F]+/[0-9A-F]+)}; + return undef; +} + +# Compare two LSN strings numerically. Returns -1, 0 or 1. +# Done by hand rather than by string equality so that the test does not depend +# on the zero-padding of either the log message or pg_lsn's output. +sub lsn_cmp +{ + my ($a, $b) = @_; + my ($ahi, $alo) = map { hex($_) } split m{/}, $a; + my ($bhi, $blo) = map { hex($_) } split m{/}, $b; + return $ahi <=> $bhi || $alo <=> $blo; +} + +sub current_insert_lsn +{ + my $lsn = $node->safe_psql('postgres', 'SELECT pg_current_wal_insert_lsn()'); + chomp $lsn; + return $lsn; +} + +# ============================================================================== +# Test helpers +# ============================================================================== + +sub test_drop_count +{ + my ($test_name, $sql, $pattern, $expected_count) = @_; + + start_new_test($test_name); + $node->safe_psql('postgres', $sql); + is(count_drop_logs($pattern), $expected_count, "$test_name: count check"); + return; +} + +sub test_drop_not_logged +{ + my ($test_name, $sql, $pattern) = @_; + + start_new_test($test_name); + $node->safe_psql('postgres', $sql); + is(count_drop_logs($pattern), 0, "$test_name: not logged"); + return; +} + +sub test_multiple_drops +{ + my ($test_name, $sql, @table_specs) = @_; + + start_new_test($test_name); + $node->safe_psql('postgres', $sql); + + foreach my $spec (@table_specs) + { + my ($schema, $table, $expected) = @$spec; + is(count_drop_logs(drop_table_pattern($schema, $table)), + $expected, "$test_name: $schema.$table"); + } + return; +} + +# ============================================================================== +# Test 1: the logged LSN is the ACTUAL commit LSN +# +# This is the core assertion. The transaction writes a large amount of WAL +# *between* the DROP and the COMMIT, so the LSN of the catalog change is far +# behind the commit LSN. A patch that logs GetXLogInsertRecPtr() at drop time +# (as the DROP DATABASE path used to) fails the "strictly greater" check; a +# patch that logs anything else fails the exact-match check. +# ============================================================================== + +start_new_test('Test 1: logged LSN is the actual commit LSN'); +$node->safe_psql('postgres', + 'CREATE TABLE filler (id int, pad text); CREATE TABLE test_commit_lsn (id int)'); + +my $out = $node->safe_psql( + 'postgres', q{ + BEGIN; + DROP TABLE test_commit_lsn; + SELECT pg_current_wal_insert_lsn(); + INSERT INTO filler SELECT i, repeat('x', 100) FROM generate_series(1, 50000) i; + SELECT pg_current_wal_insert_lsn(); + COMMIT; + SELECT pg_current_wal_insert_lsn(); +}); +my ($lsn_after_drop, $lsn_before_commit, $lsn_after_commit) = split /\n/, $out; + +my @lines = get_log_lines(drop_table_pattern('public', 'test_commit_lsn')); +is(scalar @lines, 1, 'Test 1: exactly one entry logged'); +my $logged = extract_commit_lsn($lines[0]); +ok(defined $logged, 'Test 1: commit LSN present in log message'); + +note("logged=$logged after_drop=$lsn_after_drop " + . "before_commit=$lsn_before_commit after_commit=$lsn_after_commit"); + +# The whole point of the feature: not the drop LSN. +ok(lsn_cmp($logged, $lsn_after_drop) > 0, + 'Test 1: logged LSN is past the drop LSN (not GetXLogInsertRecPtr at drop time)'); + +# The logged value must be the START of the commit record, because that is what +# recovery_target_lsn is compared against (recoveryStopsBefore() tests +# record->ReadRecPtr). lsn_before_commit is the insert pointer immediately +# before COMMIT, i.e. where the commit record begins; lsn_after_commit is where +# it ends. So: before_commit <= logged < after_commit. +# +# The lower bound is not asserted as exact equality because the commit record's +# start can be nudged forward past a WAL page header. +ok(lsn_cmp($logged, $lsn_before_commit) >= 0, + 'Test 1: logged LSN is at or after the start of the commit record'); +ok(lsn_cmp($logged, $lsn_after_commit) < 0, + 'Test 1: logged LSN is the START of the commit record, not its end'); + +# ============================================================================== +# Test 2: nothing is logged when the GUC is off +# ============================================================================== + +start_new_test('Test 2: nothing logged when log_object_drops = off'); +$node->safe_psql( + 'postgres', q{ + CREATE TABLE test_guc_off (id int); + SET log_object_drops = off; + DROP TABLE test_guc_off; +}); +is(count_drop_logs(drop_table_pattern('public', 'test_guc_off')), + 0, 'Test 2: GUC off - table drop not logged'); + +start_new_test('Test 2b: nothing logged for DROP DATABASE when GUC is off'); +$node->safe_psql( + 'postgres', q{ + SET log_object_drops = off; + CREATE DATABASE test_guc_off_db; + DROP DATABASE test_guc_off_db; +}); +is(count_drop_logs(drop_database_pattern('test_guc_off_db')), + 0, 'Test 2b: GUC off - database drop not logged'); + +# Confirm the GUC-off result above is meaningful: the same drop IS logged when on. +start_new_test('Test 2c: control - same drop logged when GUC is on'); +$node->safe_psql( + 'postgres', q{ + CREATE TABLE test_guc_on (id int); + DROP TABLE test_guc_on; +}); +is(count_drop_logs(drop_table_pattern('public', 'test_guc_on')), + 1, 'Test 2c: GUC on - table drop logged'); + +# ============================================================================== +# Test 3: nothing is logged on ROLLBACK +# ============================================================================== + +test_drop_not_logged( + 'Test 3: DROP TABLE with ROLLBACK', + q{ + CREATE TABLE test_rollback (id int); + BEGIN; + DROP TABLE test_rollback; + ROLLBACK; + }, + drop_table_pattern('public', 'test_rollback')); + +# The table must still be there, and dropping it for real must log. +test_drop_count( + 'Test 3b: committed DROP after rollback is logged', + q{ + SELECT * FROM test_rollback; + DROP TABLE test_rollback; + }, + drop_table_pattern('public', 'test_rollback'), + 1); + +# ============================================================================== +# Test 4: temporary tables are never logged +# ============================================================================== + +test_drop_not_logged( + 'Test 4: explicit DROP of a TEMP table', + q{ + CREATE TEMP TABLE test_temp (id int); + INSERT INTO test_temp VALUES (1); + BEGIN; + DROP TABLE test_temp; + COMMIT; + }, + qr/DROP TABLE: relation "pg_temp[^"]*\.test_temp"/); + +# ON COMMIT DROP and session-end cleanup are the noisy cases the exclusion +# exists for; neither must produce a log entry. +test_drop_not_logged( + 'Test 5: TEMP table with ON COMMIT DROP', + q{ + BEGIN; + CREATE TEMP TABLE test_temp_oncommit (id int) ON COMMIT DROP; + INSERT INTO test_temp_oncommit VALUES (1); + COMMIT; + }, + qr/DROP TABLE: relation "pg_temp[^"]*\.test_temp_oncommit"/); + +test_drop_not_logged( + 'Test 6: TEMP table dropped implicitly at session end', + q{ + CREATE TEMP TABLE test_temp_session (id int); + }, + qr/DROP TABLE: relation "pg_temp[^"]*\.test_temp_session"/); + +# A permanent table dropped in the same transaction as a temp one is still +# logged - the temp exclusion must not swallow its sibling. +start_new_test('Test 7: TEMP exclusion does not suppress permanent tables'); +$node->safe_psql( + 'postgres', q{ + CREATE TABLE test_perm_sibling (id int); + BEGIN; + CREATE TEMP TABLE test_temp_sibling (id int); + DROP TABLE test_temp_sibling; + DROP TABLE test_perm_sibling; + COMMIT; +}); +is(count_drop_logs(qr/DROP TABLE: relation "pg_temp[^"]*\.test_temp_sibling"/), + 0, 'Test 7: temp sibling not logged'); +is(count_drop_logs(drop_table_pattern('public', 'test_perm_sibling')), + 1, 'Test 7: permanent sibling logged'); + +# ============================================================================== +# Test 8: DROP DATABASE logs the commit LSN +# +# dropdb() forces an immediate checkpoint between the catalog delete and the +# commit, so the old GetXLogInsertRecPtr()-at-delete-time value is necessarily +# well before the commit record. Exact equality with the post-commit insert +# pointer pins this down. +# ============================================================================== + +start_new_test('Test 8: DROP DATABASE logs the commit LSN'); +$node->safe_psql('postgres', 'CREATE DATABASE test_drop_db'); +my $db_lsn_before = current_insert_lsn(); +$node->safe_psql('postgres', 'DROP DATABASE test_drop_db'); +my $db_lsn_after = current_insert_lsn(); + +my @db_lines = get_log_lines(drop_database_pattern('test_drop_db')); +is(scalar @db_lines, 1, 'Test 8: exactly one DROP DATABASE entry logged'); +my $db_logged = extract_commit_lsn($db_lines[0]); +ok(defined $db_logged, 'Test 8: DROP DATABASE reports a commit LSN'); +note("db logged=$db_logged before=$db_lsn_before after=$db_lsn_after"); +ok(lsn_cmp($db_logged, $db_lsn_before) > 0, + 'Test 8: DROP DATABASE LSN is past the pre-drop LSN'); +ok(lsn_cmp($db_logged, $db_lsn_after) < 0, + 'Test 8: DROP DATABASE LSN is the start of the commit record, not its end'); + +# A DROP DATABASE that fails must not log anything (the old code logged before +# the drop was durable, so a later failure still produced a log line). +start_new_test('Test 9: failed DROP DATABASE is not logged'); +$node->psql('postgres', 'DROP DATABASE test_nonexistent_db'); +is(count_drop_logs(drop_database_pattern('test_nonexistent_db')), + 0, 'Test 9: failed DROP DATABASE not logged'); + +# ============================================================================== +# Structural coverage carried over from v5 +# ============================================================================== + +test_drop_count( + 'Test 10: simple DROP TABLE in autocommit', + q{ + CREATE TABLE test_simple (id int); + DROP TABLE test_simple; + }, + drop_table_pattern('public', 'test_simple'), + 1); + +test_multiple_drops( + 'Test 11: DROP SCHEMA CASCADE', + q{ + CREATE SCHEMA test_schema; + CREATE TABLE test_schema.table1 (id int); + CREATE TABLE test_schema.table2 (name text); + BEGIN; + DROP SCHEMA test_schema CASCADE; + COMMIT; + }, + [ 'test_schema', 'table1', 1 ], + [ 'test_schema', 'table2', 1 ]); + +test_drop_count( + 'Test 12: DROP TABLE CASCADE with foreign keys', + q{ + CREATE TABLE test_parent (id int PRIMARY KEY); + CREATE TABLE test_child (id int, parent_id int REFERENCES test_parent(id)); + BEGIN; + DROP TABLE test_parent CASCADE; + COMMIT; + }, + drop_table_pattern('public', 'test_parent'), + 1); + +test_multiple_drops( + 'Test 13: multiple tables in a single DROP statement', + q{ + CREATE TABLE test_multi1 (id int); + CREATE TABLE test_multi2 (id int); + CREATE TABLE test_multi3 (id int); + BEGIN; + DROP TABLE test_multi1, test_multi2, test_multi3; + COMMIT; + }, + [ 'public', 'test_multi1', 1 ], + [ 'public', 'test_multi2', 1 ], + [ 'public', 'test_multi3', 1 ]); + +test_multiple_drops( + 'Test 14: partitioned table and partitions', + q{ + CREATE TABLE test_partitioned (id int, created_at date) PARTITION BY RANGE (created_at); + CREATE TABLE test_part_2024 PARTITION OF test_partitioned + FOR VALUES FROM ('2024-01-01') TO ('2025-01-01'); + CREATE TABLE test_part_2025 PARTITION OF test_partitioned + FOR VALUES FROM ('2025-01-01') TO ('2026-01-01'); + BEGIN; + DROP TABLE test_partitioned CASCADE; + COMMIT; + }, + [ 'public', 'test_partitioned', 1 ], + [ 'public', 'test_part_2024', 1 ], + [ 'public', 'test_part_2025', 1 ]); + +test_multiple_drops( + 'Test 15: inheritance hierarchy', + q{ + CREATE TABLE parent_inherit (id int); + CREATE TABLE child_inherit1 () INHERITS (parent_inherit); + CREATE TABLE child_inherit2 () INHERITS (parent_inherit); + BEGIN; + DROP TABLE parent_inherit CASCADE; + COMMIT; + }, + [ 'public', 'parent_inherit', 1 ], + [ 'public', 'child_inherit1', 1 ], + [ 'public', 'child_inherit2', 1 ]); + +# Views and indexes are not tables and must not be logged. +start_new_test('Test 16: views and indexes are not logged'); +$node->safe_psql( + 'postgres', q{ + CREATE TABLE test_view_base (id int); + CREATE VIEW test_view AS SELECT * FROM test_view_base; + CREATE INDEX test_idx ON test_view_base(id); + DROP VIEW test_view; + DROP INDEX test_idx; + DROP TABLE test_view_base; +}); +is(count_drop_logs(qr/DROP TABLE: relation "public\.test_view"/), + 0, 'Test 16: VIEW drop not logged'); +is(count_drop_logs(qr/DROP TABLE: relation "public\.test_idx"/), + 0, 'Test 16: INDEX drop not logged'); +is(count_drop_logs(drop_table_pattern('public', 'test_view_base')), + 1, 'Test 16: base table drop logged'); + +# ============================================================================== +# Subtransaction handling +# ============================================================================== + +start_new_test('Test 17: SAVEPOINT and ROLLBACK TO'); +$node->safe_psql( + 'postgres', q{ + CREATE TABLE test_savepoint1 (id int); + CREATE TABLE test_savepoint2 (id int); + CREATE TABLE test_savepoint3 (id int); + BEGIN; + DROP TABLE test_savepoint1; + SAVEPOINT sp1; + DROP TABLE test_savepoint2; + ROLLBACK TO sp1; + DROP TABLE test_savepoint3; + COMMIT; +}); +is(count_drop_logs(drop_table_pattern('public', 'test_savepoint1')), + 1, 'Test 17: savepoint1 logged'); +is(count_drop_logs(drop_table_pattern('public', 'test_savepoint2')), + 0, 'Test 17: savepoint2 NOT logged (rolled back to savepoint)'); +is(count_drop_logs(drop_table_pattern('public', 'test_savepoint3')), + 1, 'Test 17: savepoint3 logged'); + +start_new_test('Test 18: COMMIT AND CHAIN'); +$node->safe_psql( + 'postgres', q{ + CREATE TABLE chain_test1 (id int); + CREATE TABLE chain_test2 (id int); + CREATE TABLE chain_test3 (id int); + CREATE TABLE chain_test4 (id int); + BEGIN; + DROP TABLE chain_test1; + DROP TABLE chain_test2; + COMMIT AND CHAIN; + DROP TABLE chain_test3; + COMMIT AND CHAIN; + DROP TABLE chain_test4; + COMMIT; +}); +is(scalar(get_log_lines(qr/DROP TABLE: relation "public\.chain_test[1-4]"/)), + 4, 'Test 18: four COMMIT AND CHAIN drops logged'); + +start_new_test('Test 19: ROLLBACK AND CHAIN'); +$node->safe_psql( + 'postgres', q{ + CREATE TABLE rollback_chain1 (id int); + CREATE TABLE rollback_chain2 (id int); + CREATE TABLE rollback_chain3 (id int); + BEGIN; + DROP TABLE rollback_chain1; + ROLLBACK AND CHAIN; + DROP TABLE rollback_chain2; + COMMIT AND CHAIN; + DROP TABLE rollback_chain3; + COMMIT; +}); +is(count_drop_logs(drop_table_pattern('public', 'rollback_chain1')), + 0, 'Test 19: rollback_chain1 NOT logged (rolled back)'); +is(count_drop_logs(drop_table_pattern('public', 'rollback_chain2')), + 1, 'Test 19: rollback_chain2 logged'); +is(count_drop_logs(drop_table_pattern('public', 'rollback_chain3')), + 1, 'Test 19: rollback_chain3 logged'); + +start_new_test('Test 20: COMMIT AND CHAIN combined with SAVEPOINTs'); +$node->safe_psql( + 'postgres', q{ + CREATE TABLE chain_sp1 (id int); + CREATE TABLE chain_sp2 (id int); + CREATE TABLE chain_sp3 (id int); + CREATE TABLE chain_sp4 (id int); + BEGIN; + DROP TABLE chain_sp1; + SAVEPOINT sp1; + DROP TABLE chain_sp2; + ROLLBACK TO sp1; + DROP TABLE chain_sp3; + COMMIT AND CHAIN; + DROP TABLE chain_sp4; + COMMIT; +}); +is(count_drop_logs(drop_table_pattern('public', 'chain_sp1')), + 1, 'Test 20: chain_sp1 logged'); +is(count_drop_logs(drop_table_pattern('public', 'chain_sp2')), + 0, 'Test 20: chain_sp2 NOT logged (rolled back to savepoint)'); +is(count_drop_logs(drop_table_pattern('public', 'chain_sp3')), + 1, 'Test 20: chain_sp3 logged'); +is(count_drop_logs(drop_table_pattern('public', 'chain_sp4')), + 1, 'Test 20: chain_sp4 logged'); + +# PL/pgSQL EXCEPTION blocks are implicit subtransactions that commit. +test_drop_count( + 'Test 21: DROP in PL/pgSQL with EXCEPTION handler', + q{ + CREATE TABLE plpgsql_test (id int); + CREATE FUNCTION test_drop_with_exception() RETURNS void AS $$ + BEGIN + DROP TABLE plpgsql_test; + EXCEPTION + WHEN OTHERS THEN + RAISE NOTICE 'Exception caught'; + END; + $$ LANGUAGE plpgsql; + SELECT test_drop_with_exception(); + }, + drop_table_pattern('public', 'plpgsql_test'), + 1); + +# A drop inside a PL/pgSQL subtransaction that then raises must not be logged. +test_drop_not_logged( + 'Test 22: DROP undone by PL/pgSQL EXCEPTION rollback', + q{ + CREATE TABLE plpgsql_undone (id int); + CREATE FUNCTION test_drop_undone() RETURNS void AS $$ + BEGIN + BEGIN + DROP TABLE plpgsql_undone; + RAISE EXCEPTION 'boom'; + EXCEPTION + WHEN OTHERS THEN + RAISE NOTICE 'rolled back'; + END; + END; + $$ LANGUAGE plpgsql; + SELECT test_drop_undone(); + }, + drop_table_pattern('public', 'plpgsql_undone')); + +# ============================================================================== +# Test 23: end-to-end PITR using the logged LSN +# +# This is the feature's reason for existing, and it exercises the exact recipe +# the documentation gives, including the recovery_target_inclusive trap. +# ============================================================================== + +start_new_test('Test 23: PITR using the logged commit LSN'); + +$node->backup('pitr_backup'); +$node->safe_psql( + 'postgres', q{ + CREATE TABLE precious (id int); + INSERT INTO precious SELECT generate_series(1, 100); +}); +$node->safe_psql('postgres', 'DROP TABLE precious'); +$node->safe_psql('postgres', 'SELECT pg_switch_wal()'); + +my @pitr_lines = get_log_lines(drop_table_pattern('public', 'precious')); +is(scalar @pitr_lines, 1, 'Test 23: drop of precious logged'); +my $pitr_lsn = extract_commit_lsn($pitr_lines[0]); +ok(defined $pitr_lsn, 'Test 23: got a commit LSN to recover to'); +note("PITR target LSN = $pitr_lsn"); + +# 23a: the documented incantation - recovery_target_inclusive = off - must +# stop BEFORE the drop commits and bring the table back. +my $good = PostgreSQL::Test::Cluster->new('pitr_exclusive'); +$good->init_from_backup($node, 'pitr_backup', has_restoring => 1); +$good->append_conf( + 'postgresql.conf', qq{ +recovery_target_lsn = '$pitr_lsn' +recovery_target_inclusive = off +recovery_target_action = 'promote' +recovery_target_timeline = 1 +# The backup carries the primary's archive settings; leaving them on would +# publish this node's promoted timeline into the primary's archive and let the +# other recovery node below follow it. +archive_mode = off +}); +$good->start; +$good->poll_query_until('postgres', 'SELECT NOT pg_is_in_recovery()') + or die "timed out waiting for pitr_exclusive to promote"; + +is( $good->safe_psql( + 'postgres', + "SELECT count(*) FROM pg_class WHERE relname = 'precious'"), + '1', + 'Test 23a: recovery_target_inclusive=off recovers the dropped table'); +is($good->safe_psql('postgres', 'SELECT count(*) FROM precious'), + '100', 'Test 23a: recovered table has its rows'); +$good->stop; + +# 23b: the trap. Setting only recovery_target_lsn leaves +# recovery_target_inclusive at its default of on, which replays the drop and +# loses the table again. This test documents that failure mode so that any +# future change to the default is caught here. +my $trap = PostgreSQL::Test::Cluster->new('pitr_inclusive'); +$trap->init_from_backup($node, 'pitr_backup', has_restoring => 1); +$trap->append_conf( + 'postgresql.conf', qq{ +recovery_target_lsn = '$pitr_lsn' +recovery_target_action = 'promote' +recovery_target_timeline = 1 +archive_mode = off +}); +$trap->start; +$trap->poll_query_until('postgres', 'SELECT NOT pg_is_in_recovery()') + or die "timed out waiting for pitr_inclusive to promote"; + +is( $trap->safe_psql( + 'postgres', + "SELECT count(*) FROM pg_class WHERE relname = 'precious'"), + '0', + 'Test 23b: default recovery_target_inclusive=on replays the drop (documented trap)'); +$trap->stop; + +done_testing();