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