Re: [HACKERS] Deadlock with pg_dump?

Tom Lane wrote:
> Bruce Momjian <bruce@momjian.us> writes:
> > This is not the first GUC that has needed this.
>
> Exactly.  I think that we simply made a mistake in the initial
> implementation of log_min_error_statement: we failed to think about
> whether it should use client or server priority ordering, and the
> easy-to-code behavior was the wrong one.

I have coded up the following patch which places LOG just above ERROR in
log_min_error_statement.

It also adds the new log level LOG_NO_STATEMENT, which is used only for
internal use by ereport() calls that should not print the statement.
This is particularly useful so log_statemant and
log_min_duration_statement do not print the statement twice.

--
  Bruce Momjian  <bruce@momjian.us>          http://momjian.us
  EnterpriseDB                               http://www.enterprisedb.com

  + If your life is a hard drive, Christ can be your backup. +
Index: doc/src/sgml/config.sgml
===================================================================
RCS file: /cvsroot/pgsql/doc/src/sgml/config.sgml,v
retrieving revision 1.112
diff -c -c -r1.112 config.sgml
*** doc/src/sgml/config.sgml    16 Feb 2007 16:37:29 -0000    1.112
--- doc/src/sgml/config.sgml    1 Mar 2007 01:56:33 -0000
***************
*** 2507,2518 ****
          <literal>DEBUG2</literal>, <literal>DEBUG1</literal>,
          <literal>INFO</literal>, <literal>NOTICE</literal>,
          <literal>WARNING</literal>, <literal>ERROR</literal>,
!         <literal>FATAL</literal>, and <literal>PANIC</literal>.
!         The default is <literal>ERROR</literal>, which means statements
!         causing errors, fatal errors, or panics will be logged.
!         To effectively turn off logging of failing statements,
!         set this parameter to <literal>PANIC</literal>.
!         Only superusers can change this setting.
         </para>
        </listitem>
       </varlistentry>
--- 2507,2518 ----
          <literal>DEBUG2</literal>, <literal>DEBUG1</literal>,
          <literal>INFO</literal>, <literal>NOTICE</literal>,
          <literal>WARNING</literal>, <literal>ERROR</literal>,
!         <literal>LOG</literal>, <literal>FATAL</literal>, and
!         <literal>PANIC</literal>.  The default is <literal>ERROR</literal>,
!         which means statements causing errors, log messages, fatal errors,
!         or panics will be logged.  To turn off logging of statements for
!         all levela, set this parameter to <literal>PANIC</literal>.  Only
!         superusers can change this setting.
         </para>
        </listitem>
       </varlistentry>
Index: src/backend/tcop/fastpath.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/fastpath.c,v
retrieving revision 1.95
diff -c -c -r1.95 fastpath.c
*** src/backend/tcop/fastpath.c    5 Jan 2007 22:19:39 -0000    1.95
--- src/backend/tcop/fastpath.c    1 Mar 2007 01:56:34 -0000
***************
*** 328,334 ****
      /* Log as soon as we have the function OID and name */
      if (log_statement == LOGSTMT_ALL)
      {
!         ereport(LOG,
                  (errmsg("fastpath function call: \"%s\" (OID %u)",
                          fip->fname, fid)));
          was_logged = true;
--- 328,334 ----
      /* Log as soon as we have the function OID and name */
      if (log_statement == LOGSTMT_ALL)
      {
!         ereport(LOG_NO_STATEMENT,
                  (errmsg("fastpath function call: \"%s\" (OID %u)",
                          fip->fname, fid)));
          was_logged = true;
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.525
diff -c -c -r1.525 postgres.c
*** src/backend/tcop/postgres.c    20 Feb 2007 17:32:16 -0000    1.525
--- src/backend/tcop/postgres.c    1 Mar 2007 01:56:35 -0000
***************
*** 821,827 ****
      /* Log immediately if dictated by log_statement */
      if (check_log_statement(parsetree_list))
      {
!         ereport(LOG,
                  (errmsg("statement: %s", query_string),
                   errdetail_execute(parsetree_list)));
          was_logged = true;
--- 821,827 ----
      /* Log immediately if dictated by log_statement */
      if (check_log_statement(parsetree_list))
      {
!         ereport(LOG_NO_STATEMENT,
                  (errmsg("statement: %s", query_string),
                   errdetail_execute(parsetree_list)));
          was_logged = true;
***************
*** 1023,1029 ****
                      (errmsg("duration: %s ms", msec_str)));
              break;
          case 2:
!             ereport(LOG,
                      (errmsg("duration: %s ms  statement: %s",
                              msec_str, query_string),
                       errdetail_execute(parsetree_list)));
--- 1023,1029 ----
                      (errmsg("duration: %s ms", msec_str)));
              break;
          case 2:
!             ereport(LOG_NO_STATEMENT,
                      (errmsg("duration: %s ms  statement: %s",
                              msec_str, query_string),
                       errdetail_execute(parsetree_list)));
***************
*** 1284,1290 ****
                      (errmsg("duration: %s ms", msec_str)));
              break;
          case 2:
!             ereport(LOG,
                      (errmsg("duration: %s ms  parse %s: %s",
                              msec_str,
                              *stmt_name ? stmt_name : "<unnamed>",
--- 1284,1290 ----
                      (errmsg("duration: %s ms", msec_str)));
              break;
          case 2:
!             ereport(LOG_NO_STATEMENT,
                      (errmsg("duration: %s ms  parse %s: %s",
                              msec_str,
                              *stmt_name ? stmt_name : "<unnamed>",
***************
*** 1638,1644 ****
                      (errmsg("duration: %s ms", msec_str)));
              break;
          case 2:
!             ereport(LOG,
                      (errmsg("duration: %s ms  bind %s%s%s: %s",
                              msec_str,
                              *stmt_name ? stmt_name : "<unnamed>",
--- 1638,1644 ----
                      (errmsg("duration: %s ms", msec_str)));
              break;
          case 2:
!             ereport(LOG_NO_STATEMENT,
                      (errmsg("duration: %s ms  bind %s%s%s: %s",
                              msec_str,
                              *stmt_name ? stmt_name : "<unnamed>",
***************
*** 1768,1774 ****
      /* Log immediately if dictated by log_statement */
      if (check_log_statement(portal->stmts))
      {
!         ereport(LOG,
                  (errmsg("%s %s%s%s%s%s",
                          execute_is_fetch ?
                          _("execute fetch from") :
--- 1768,1774 ----
      /* Log immediately if dictated by log_statement */
      if (check_log_statement(portal->stmts))
      {
!         ereport(LOG_NO_STATEMENT,
                  (errmsg("%s %s%s%s%s%s",
                          execute_is_fetch ?
                          _("execute fetch from") :
***************
*** 1849,1855 ****
                      (errmsg("duration: %s ms", msec_str)));
              break;
          case 2:
!             ereport(LOG,
                      (errmsg("duration: %s ms  %s %s%s%s%s%s",
                              msec_str,
                              execute_is_fetch ?
--- 1849,1855 ----
                      (errmsg("duration: %s ms", msec_str)));
              break;
          case 2:
!             ereport(LOG_NO_STATEMENT,
                      (errmsg("duration: %s ms  %s %s%s%s%s%s",
                              msec_str,
                              execute_is_fetch ?
Index: src/backend/utils/error/elog.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/error/elog.c,v
retrieving revision 1.182
diff -c -c -r1.182 elog.c
*** src/backend/utils/error/elog.c    11 Feb 2007 11:59:26 -0000    1.182
--- src/backend/utils/error/elog.c    1 Mar 2007 01:56:35 -0000
***************
*** 1629,1635 ****
      /*
       * If the user wants the query that generated this error logged, do it.
       */
!     if (edata->elevel >= log_min_error_statement && debug_query_string != NULL)
      {
          log_line_prefix(&buf);
          appendStringInfoString(&buf, _("STATEMENT:  "));
--- 1629,1636 ----
      /*
       * If the user wants the query that generated this error logged, do it.
       */
!     if (is_log_level_output(edata->elevel, log_min_error_statement) &&
!         edata->elevel != LOG_NO_STATEMENT && debug_query_string != NULL)
      {
          log_line_prefix(&buf);
          appendStringInfoString(&buf, _("STATEMENT:  "));
***************
*** 1653,1658 ****
--- 1654,1660 ----
                  syslog_level = LOG_DEBUG;
                  break;
              case LOG:
+             case LOG_NO_STATEMENT:
              case COMMERROR:
              case INFO:
                  syslog_level = LOG_INFO;
***************
*** 1968,1973 ****
--- 1970,1976 ----
              prefix = _("DEBUG");
              break;
          case LOG:
+         case LOG_NO_STATEMENT:
          case COMMERROR:
              prefix = _("LOG");
              break;
***************
*** 2062,2068 ****
       *    Complicated because LOG is sorted out-of-order here, between
       *    ERROR and FATAL.
       */
!     if (elevel == LOG || elevel == COMMERROR)
      {
          if (log_min_level == LOG || log_min_level <= ERROR)
              return true;
--- 2065,2071 ----
       *    Complicated because LOG is sorted out-of-order here, between
       *    ERROR and FATAL.
       */
!     if (elevel == LOG || elevel == LOG_NO_STATEMENT || elevel == COMMERROR)
      {
          if (log_min_level == LOG || log_min_level <= ERROR)
              return true;
Index: src/backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.209
diff -c -c -r1.209 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample    16 Feb 2007 17:07:00 -0000    1.209
--- src/backend/utils/misc/postgresql.conf.sample    1 Mar 2007 01:56:37 -0000
***************
*** 289,295 ****

  #log_error_verbosity = default        # terse, default, or verbose messages

! #log_min_error_statement = error    # Values in order of increasing severity:
                       #   debug5
                      #   debug4
                      #   debug3
--- 289,295 ----

  #log_error_verbosity = default        # terse, default, or verbose messages

! #log_min_error_statement = error    # Values in order of decreasing detail:
                       #   debug5
                      #   debug4
                      #   debug3
***************
*** 299,304 ****
--- 299,305 ----
                      #   notice
                      #   warning
                      #   error
+                     #   log
                      #   fatal
                      #   panic (effectively off)

Index: src/include/utils/elog.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/utils/elog.h,v
retrieving revision 1.83
diff -c -c -r1.83 elog.h
*** src/include/utils/elog.h    5 Jan 2007 22:19:59 -0000    1.83
--- src/include/utils/elog.h    1 Mar 2007 01:56:38 -0000
***************
*** 25,53 ****
  #define DEBUG1        14            /* used by GUC debug_* variables */
  #define LOG            15            /* Server operational messages; sent only to
                                   * server log by default. */
! #define COMMERROR    16            /* Client communication problems; same as LOG
                                   * for server reporting, but never sent to
                                   * client. */
! #define INFO        17            /* Informative messages that are always sent
                                   * to client;  is not affected by
                                   * client_min_messages */
! #define NOTICE        18            /* Helpful messages to users about query
                                   * operation;  sent to client and server log
                                   * by default. */
! #define WARNING        19            /* Warnings.  NOTICE is for expected messages
                                   * like implicit sequence creation by SERIAL.
                                   * WARNING is for unexpected messages. */
! #define ERROR        20            /* user error - abort transaction; return to
                                   * known state */
  /* Save ERROR value in PGERROR so it can be restored when Win32 includes
   * modify it.  We have to use a constant rather than ERROR because macros
   * are expanded only when referenced outside macros.
   */
  #ifdef WIN32
! #define PGERROR        20
  #endif
! #define FATAL        21            /* fatal error - abort process */
! #define PANIC        22            /* take down the other backends with me */

   /* #define DEBUG DEBUG1 */    /* Backward compatibility with pre-7.3 */

--- 25,55 ----
  #define DEBUG1        14            /* used by GUC debug_* variables */
  #define LOG            15            /* Server operational messages; sent only to
                                   * server log by default. */
! #define LOG_NO_STATEMENT 16        /* Like LOG, but avoids log_min_error_statement */
!
! #define COMMERROR    17            /* Client communication problems; same as LOG
                                   * for server reporting, but never sent to
                                   * client. */
! #define INFO        18            /* Informative messages that are always sent
                                   * to client;  is not affected by
                                   * client_min_messages */
! #define NOTICE        19            /* Helpful messages to users about query
                                   * operation;  sent to client and server log
                                   * by default. */
! #define WARNING        20            /* Warnings.  NOTICE is for expected messages
                                   * like implicit sequence creation by SERIAL.
                                   * WARNING is for unexpected messages. */
! #define ERROR        21            /* user error - abort transaction; return to
                                   * known state */
  /* Save ERROR value in PGERROR so it can be restored when Win32 includes
   * modify it.  We have to use a constant rather than ERROR because macros
   * are expanded only when referenced outside macros.
   */
  #ifdef WIN32
! #define PGERROR        21
  #endif
! #define FATAL        22            /* fatal error - abort process */
! #define PANIC        23            /* take down the other backends with me */

   /* #define DEBUG DEBUG1 */    /* Backward compatibility with pre-7.3 */