Re: Logging transaction IDs for DDL.

Hi,

On 2018-06-14 00:34:54 +0200, Vik Fearing wrote:
> I just noticed a problem with log_statement = 'ddl' and log_line_prefix
> containing '%x'. If the statement is the first in the transaction, it
> will be logged before it is executed, and more importantly, before a
> transaction ID is assigned. That means that %x will be 0.

This isn't particularly related to DDL, no? It's a general weakness of
how %x is handled. What's even worse is that by
log_min_duration_statement time the xid is already cleared out, when
using a single-statement transaction.

> If the administrator has configured postgres like this in order to ease
> PITR on bad DDL, it's actually of no use whatsoever and they'll have to
> use pg_waldump to try to figure things out.

To me that part seems like it'd be better handled if we had an option
that allows to log at a time where the xid is already assigned. Making
log_statement assign xids imo has a number of problems, but preserving
the xid for logging at the *end* of a statement should be much less
problematic.

> I'm undecided whether this is a bugfix or an improvement. I'm leaning
> towards bugfix.

It's been reported a couple times, without anybody working to fix
it. Your fix has a noticable regression potential, so I'm not
immediately in favor of backpatching.

> --
> Vik Fearing +33 6 46 75 15 36
> http://2ndQuadrant.fr PostgreSQL : Expertise, Formation et Support

> diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
> index f4133953be..27027a0fa8 100644
> --- a/src/backend/tcop/postgres.c
> +++ b/src/backend/tcop/postgres.c
> @@ -38,6 +38,7 @@
>
> #include "access/parallel.h"
> #include "access/printtup.h"
> +#include "access/transam.h"
> #include "access/xact.h"
> #include "catalog/pg_type.h"
> #include "commands/async.h"
> @@ -2098,16 +2099,31 @@ check_log_statement(List *stmt_list)
>
> if (log_statement == LOGSTMT_NONE)
> return false;
> - if (log_statement == LOGSTMT_ALL)
> +
> + /*
> + * If we're supposed to log mod or ddl statements, we need to make sure we
> + * have a TransactionId so it appears in log_line_prefix's %x wildcard.
> + * If the user is logging all statements, we can fast-track out if we
> + * already have a TransactionId, otherwise we need to loop through the
> + * statements.
> + */
> + if (log_statement == LOGSTMT_ALL && TransactionIdIsValid(GetTopTransactionIdIfAny()))
> return true;
>
> /* Else we have to inspect the statement(s) to see whether to log */
> foreach(stmt_item, stmt_list)
> {
> Node *stmt = (Node *) lfirst(stmt_item);
> + LogStmtLevel level = GetCommandLogLevel(stmt);
> +
> + if (level <= log_statement)
> + {
> + /* Make sure we have a TransactionId for mod and ddl statements. */
> + if (level == LOGSTMT_DDL || level == LOGSTMT_MOD)
> + (void) GetTopTransactionId();
>
> - if (GetCommandLogLevel(stmt) <= log_statement)
> return true;
> + }
> }

I'm not at all on board with this. For one this'll break in a number of
weird ways on a standby (wrong error messages at the least). For another
it increases the overhead of logging quite noticably. Thirdly moving
transaction assignment to a different place based on logging settings
seems like it'll be very confusing too.

Greetings,

Andres Freund