Re: [HACKERS] logging statement levels

Andrew Dunstan wrote:
> >>Here are some options:
> >>
> >>1. change the type of "log_statement" option from boolean to string,
> >>with allowed values of "all, mod, ddl, none" with default "none".
> >>2. same as 1. but make boolean true values synonyms for "all" and
> >>boolean false values synonyms for "none".
> >>3. keep "log_statement" option as now and add a new option
> >>"log_statement_level" with the same options as 1. but default to "all",
> >>which will have no effect unless "log_statement" is true.
> >>
> >>
> >
> >I like 1.

OK, here is a patch that implements #1.  Here is sample output:

    test=> set client_min_messages = 'log';
    SET
    test=> set log_statement = 'mod';
    SET
    test=> select 1;
     ?column?
    ----------
            1
    (1 row)

    test=> update test set x=1;
    LOG:  statement: update test set x=1;
    ERROR:  relation "test" does not exist
    test=> update test set x=1;
    LOG:  statement: update test set x=1;
    ERROR:  relation "test" does not exist
    test=> copy test from '/tmp/x';
    LOG:  statement: copy test from '/tmp/x';
    ERROR:  relation "test" does not exist
    test=> copy test to  '/tmp/x';
    ERROR:  relation "test" does not exist
    test=> prepare xx as select 1;
    PREPARE
    test=> prepare xx as update x set y=1;
    LOG:  statement: prepare xx as update x set y=1;
    ERROR:  relation "x" does not exist
    test=> explain analyze select 1;;
                                         QUERY PLAN
    ------------------------------------------------------------------------------------
     Result  (cost=0.00..0.01 rows=1 width=0) (actual time=0.006..0.007 rows=1 loops=1)
     Total runtime: 0.046 ms
    (2 rows)

    test=> explain analyze update test set x=1;
    LOG:  statement: explain analyze update test set x=1;
    ERROR:  relation "test" does not exist
    test=> explain update test set x=1;
    ERROR:  relation "test" does not exist

It checks PREPARE and EXECUTE ANALYZE too.  The log_statement values are
'none', 'mod', 'ddl', and 'all'.  For 'all', it prints before the query
is parsed, and for ddl/mod, it does it right after parsing using the
node tag (or command tag for CREATE/ALTER/DROP), so any non-parse errors
will print after the log line.

--
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073
Index: doc/src/sgml/runtime.sgml
===================================================================
RCS file: /cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v
retrieving revision 1.257
diff -c -c -r1.257 runtime.sgml
*** doc/src/sgml/runtime.sgml    5 Apr 2004 03:02:03 -0000    1.257
--- doc/src/sgml/runtime.sgml    6 Apr 2004 03:56:08 -0000
***************
*** 2121,2132 ****
       </varlistentry>

       <varlistentry id="guc-log-statement" xreflabel="log_statement">
!       <term><varname>log_statement</varname> (<type>boolean</type>)</term>
        <listitem>
         <para>
!         Causes each SQL statement to be logged. The default is
!         off. Only superusers can disable this option if it has been
!         enabled by an administrator.
         </para>

         <note>
--- 2121,2141 ----
       </varlistentry>

       <varlistentry id="guc-log-statement" xreflabel="log_statement">
!       <term><varname>log_statement</varname> (<type>string</type>)</term>
        <listitem>
         <para>
!         Controls which SQL statement are logged. Valid values are
!         <literal>all</>, <literal>ddl</>, <literal>mod</>, and
!         <literal>none</>. <literal>ddl</> logs all data definition
!         commands like <literal>CREATE</>, <literal>ALTER</>, and
!         <literal>DROP</> commands. <literal>mod</> logs all
!         <literal>ddl</> statements, plus <literal>INSERT</>,
!         <literal>UPDATE</>, <literal>DELETE</>, <literal>TRUNCATE</>,
!         and <literal>COPY FROM</>. <literal>PREPARE</> and
!         <literal>EXPLAIN ANALYZE</> statements are also considered for
!         appropriate commands. The default is <literal>none</>. Only
!         superusers can reduce the detail of this option if it has been
!         set by an administrator.
         </para>

         <note>
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.397
diff -c -c -r1.397 postgres.c
*** src/backend/tcop/postgres.c    24 Mar 2004 22:40:29 -0000    1.397
--- src/backend/tcop/postgres.c    6 Apr 2004 03:56:11 -0000
***************
*** 87,92 ****
--- 87,94 ----
  /* flag for logging end of session */
  bool        Log_disconnections = false;

+ LogStmtLevel log_statement = LOGSTMT_NONE;
+
  /*
   * Flags for expensive function optimization -- JMH 3/9/92
   */
***************
*** 471,479 ****
  List *
  pg_parse_query(const char *query_string)
  {
!     List       *raw_parsetree_list;

!     if (log_statement)
          ereport(LOG,
                  (errmsg("statement: %s", query_string)));

--- 473,482 ----
  List *
  pg_parse_query(const char *query_string)
  {
!     List       *raw_parsetree_list,
!                *parsetree_item;

!     if (log_statement == LOGSTMT_ALL)
          ereport(LOG,
                  (errmsg("statement: %s", query_string)));

***************
*** 482,487 ****
--- 485,535 ----

      raw_parsetree_list = raw_parser(query_string);

+     /* do log_statement tests for mod and ddl */
+     if (log_statement == LOGSTMT_MOD ||
+         log_statement == LOGSTMT_DDL)
+     {
+         foreach(parsetree_item, raw_parsetree_list)
+         {
+             Node       *parsetree = (Node *) lfirst(parsetree_item);
+             const char *commandTag;
+
+             if (IsA(parsetree, ExplainStmt) &&
+                 ((ExplainStmt *)parsetree)->analyze)
+                 parsetree = (Node *)(((ExplainStmt *)parsetree)->query);
+
+             if (IsA(parsetree, PrepareStmt))
+                 parsetree = (Node *)(((PrepareStmt *)parsetree)->query);
+
+             if (IsA(parsetree, SelectStmt))
+                 continue;    /* optimization for frequent command */
+
+             if (log_statement == LOGSTMT_MOD &&
+                 (IsA(parsetree, InsertStmt) ||
+                  IsA(parsetree, UpdateStmt) ||
+                  IsA(parsetree, DeleteStmt) ||
+                  IsA(parsetree, TruncateStmt) ||
+                  (IsA(parsetree, CopyStmt) &&
+                   ((CopyStmt *)parsetree)->is_from)))    /* COPY FROM */
+             {
+                 ereport(LOG,
+                         (errmsg("statement: %s", query_string)));
+                 break;
+             }
+             commandTag = CreateCommandTag(parsetree);
+             if (strncmp(commandTag, "CREATE ", strlen("CREATE ")) == 0 ||
+                 strncmp(commandTag, "ALTER ", strlen("ALTER ")) == 0 ||
+                 strncmp(commandTag, "DROP ", strlen("DROP ")) == 0 ||
+                 IsA(parsetree, GrantStmt) ||    /* GRANT or REVOKE */
+                 IsA(parsetree, CommentStmt))
+             {
+                 ereport(LOG,
+                         (errmsg("statement: %s", query_string)));
+                 break;
+             }
+         }
+     }
+
      if (log_parser_stats)
          ShowUsage("PARSER STATISTICS");

***************
*** 2488,2494 ****
          SetConfigOption("log_disconnections", "true", debug_context, gucsource);
      }
      if (debug_flag >= 2)
!         SetConfigOption("log_statement", "true", debug_context, gucsource);
      if (debug_flag >= 3)
          SetConfigOption("debug_print_parse", "true", debug_context, gucsource);
      if (debug_flag >= 4)
--- 2536,2542 ----
          SetConfigOption("log_disconnections", "true", debug_context, gucsource);
      }
      if (debug_flag >= 2)
!         SetConfigOption("log_statement", "all", debug_context, gucsource);
      if (debug_flag >= 3)
          SetConfigOption("debug_print_parse", "true", debug_context, gucsource);
      if (debug_flag >= 4)
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.197
diff -c -c -r1.197 guc.c
*** src/backend/utils/misc/guc.c    5 Apr 2004 03:02:07 -0000    1.197
--- src/backend/utils/misc/guc.c    6 Apr 2004 03:56:14 -0000
***************
*** 86,103 ****
                  bool doit, GucSource source);
  #endif

! static const char *assign_defaultxactisolevel(const char *newval,
!                            bool doit, GucSource source);
! static const char *assign_log_min_messages(const char *newval,
!                         bool doit, GucSource source);
  static const char *assign_client_min_messages(const char *newval,
                             bool doit, GucSource source);
  static const char *assign_min_error_statement(const char *newval, bool doit,
                             GucSource source);
! static const char *assign_msglvl(int *var, const char *newval,
!               bool doit, GucSource source);
  static const char *assign_log_error_verbosity(const char *newval, bool doit,
                             GucSource source);
  static bool assign_phony_autocommit(bool newval, bool doit, GucSource source);


--- 86,107 ----
                  bool doit, GucSource source);
  #endif

! static const char *assign_defaultxactisolevel(const char *newval, bool doit,
!                            GucSource source);
! static const char *assign_log_min_messages(const char *newval, bool doit,
!                            GucSource source);
  static const char *assign_client_min_messages(const char *newval,
                             bool doit, GucSource source);
  static const char *assign_min_error_statement(const char *newval, bool doit,
                             GucSource source);
! static const char *assign_msglvl(int *var, const char *newval, bool doit,
!                            GucSource source);
  static const char *assign_log_error_verbosity(const char *newval, bool doit,
                             GucSource source);
+ static const char *assign_log_statement(const char *newval, bool doit,
+                            GucSource source);
+ static const char *assign_log_stmtlvl(int *var, const char *newval,
+                            bool doit, GucSource source);
  static bool assign_phony_autocommit(bool newval, bool doit, GucSource source);


***************
*** 107,113 ****
  #ifdef USE_ASSERT_CHECKING
  bool        assert_enabled = true;
  #endif
- bool        log_statement = false;
  bool        log_duration = false;
  bool        Debug_print_plan = false;
  bool        Debug_print_parse = false;
--- 111,116 ----
***************
*** 145,150 ****
--- 148,154 ----
  static char *client_min_messages_str;
  static char *log_min_messages_str;
  static char *log_error_verbosity_str;
+ static char *log_statement_str;
  static char *log_min_error_statement_str;
  static char *log_destination_string;
  static bool phony_autocommit;
***************
*** 528,541 ****
          false, NULL, NULL
      },
      {
-         {"log_statement", PGC_USERLIMIT, LOGGING_WHAT,
-             gettext_noop("Logs each SQL statement."),
-             NULL
-         },
-         &log_statement,
-         false, NULL, NULL
-     },
-     {
          {"log_duration", PGC_USERLIMIT, LOGGING_WHAT,
              gettext_noop("Logs the duration each completed SQL statement."),
              NULL
--- 532,537 ----
***************
*** 1442,1447 ****
--- 1438,1451 ----
          &log_error_verbosity_str,
          "default", assign_log_error_verbosity, NULL
      },
+     {
+         {"log_statement", PGC_USERLIMIT, LOGGING_WHAT,
+             gettext_noop("Sets the type of statements logged."),
+             gettext_noop("Valid values are \"none\", \"mod\", \"ddl\", and \"all\".")
+         },
+         &log_statement_str,
+         "none", assign_log_statement, NULL
+     },

      {
          {"log_min_error_statement", PGC_USERLIMIT, LOGGING_WHEN,
***************
*** 2007,2020 ****
                      struct config_string *conf = (struct config_string *) gconf;
                      char       *str;

!                     /*
!                      * Check to make sure we only have valid
!                      * PGC_USERLIMITs
!                      */
                      Assert(conf->gen.context != PGC_USERLIMIT ||
                             conf->assign_hook == assign_log_min_messages ||
!                        conf->assign_hook == assign_client_min_messages ||
!                         conf->assign_hook == assign_min_error_statement);
                      *conf->variable = NULL;
                      conf->reset_val = NULL;
                      conf->session_val = NULL;
--- 2011,2021 ----
                      struct config_string *conf = (struct config_string *) gconf;
                      char       *str;

!                     /* Check to make sure we only have valid PGC_USERLIMITs */
                      Assert(conf->gen.context != PGC_USERLIMIT ||
                             conf->assign_hook == assign_log_min_messages ||
!                            conf->assign_hook == assign_min_error_statement ||
!                            conf->assign_hook == assign_log_statement);
                      *conf->variable = NULL;
                      conf->reset_val = NULL;
                      conf->session_val = NULL;
***************
*** 3025,3039 ****
                      if (record->context == PGC_USERLIMIT &&
                          IsUnderPostmaster && !superuser())
                      {
!                         int            old_int_value,
!                                     new_int_value;

!                         /* all USERLIMIT strings are message levels */
!                         assign_msglvl(&new_int_value, newval,
!                                       true, source);
!                         assign_msglvl(&old_int_value, conf->reset_val,
!                                       true, source);
!                         if (new_int_value > old_int_value)
                          {
                              /* Limit non-superuser changes */
                              if (source > PGC_S_UNPRIVILEGED)
--- 3026,3048 ----
                      if (record->context == PGC_USERLIMIT &&
                          IsUnderPostmaster && !superuser())
                      {
!                         int        var_value, reset_value, new_value;
!                         const char * (*var_hook) (int *var, const char *newval,
!                                     bool doit, GucSource source);
!
!                         if (conf->assign_hook == assign_log_statement)
!                             var_hook = assign_log_stmtlvl;
!                         else
!                             var_hook = assign_msglvl;
!
!                         (*var_hook) (&new_value, newval, true, source);
!                         (*var_hook) (&reset_value, conf->reset_val,    true,
!                                      source);
!                         (*var_hook) (&var_value, *conf->variable, true,
!                                      source);

!                         /* Limit non-superuser changes */
!                         if (new_value > reset_value)
                          {
                              /* Limit non-superuser changes */
                              if (source > PGC_S_UNPRIVILEGED)
***************
*** 3046,3055 ****
                                  return false;
                              }
                          }
!                             /* Allow change if admin should override */
!                         assign_msglvl(&old_int_value, *conf->variable,
!                                       true, source);
!                         if (new_int_value < old_int_value)
                          {
                              if (source < PGC_S_UNPRIVILEGED &&
                                  record->source > PGC_S_UNPRIVILEGED)
--- 3055,3063 ----
                                  return false;
                              }
                          }
!
!                         /* Allow change if admin should override */
!                         if (new_value < var_value)
                          {
                              if (source < PGC_S_UNPRIVILEGED &&
                                  record->source > PGC_S_UNPRIVILEGED)
***************
*** 4646,4651 ****
--- 4654,4693 ----
      {
          if (doit)
              Log_error_verbosity = PGERROR_VERBOSE;
+     }
+     else
+         return NULL;            /* fail */
+     return newval;                /* OK */
+ }
+
+ static const char *
+ assign_log_statement(const char *newval, bool doit, GucSource source)
+ {
+     return (assign_log_stmtlvl((int *)&log_statement, newval, doit, source));
+ }
+
+ static const char *
+ assign_log_stmtlvl(int *var, const char *newval, bool doit, GucSource source)
+ {
+     if (strcasecmp(newval, "none") == 0)
+     {
+         if (doit)
+             (*var) = LOGSTMT_NONE;
+     }
+     else if (strcasecmp(newval, "mod") == 0)
+     {
+         if (doit)
+             (*var) = LOGSTMT_MOD;
+     }
+     else if (strcasecmp(newval, "ddl") == 0)
+     {
+         if (doit)
+             (*var) = LOGSTMT_DDL;
+     }
+     else if (strcasecmp(newval, "all") == 0)
+     {
+         if (doit)
+             (*var) = LOGSTMT_ALL;
      }
      else
          return NULL;            /* fail */
Index: src/backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.112
diff -c -c -r1.112 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample    5 Apr 2004 03:02:08 -0000    1.112
--- src/backend/utils/misc/postgresql.conf.sample    6 Apr 2004 03:56:14 -0000
***************
*** 191,197 ****
                  # %s=session start timestamp
                  # %x=stop here in non-session processes
                  # %%='%'
! #log_statement = false
  #log_hostname = false


--- 191,197 ----
                  # %s=session start timestamp
                  # %x=stop here in non-session processes
                  # %%='%'
! #log_statement = 'none'        # none, mod, ddl, all
  #log_hostname = false


Index: src/include/tcop/tcopprot.h
===================================================================
RCS file: /cvsroot/pgsql-server/src/include/tcop/tcopprot.h,v
retrieving revision 1.63
diff -c -c -r1.63 tcopprot.h
*** src/include/tcop/tcopprot.h    24 Mar 2004 22:40:29 -0000    1.63
--- src/include/tcop/tcopprot.h    6 Apr 2004 03:56:14 -0000
***************
*** 35,40 ****
--- 35,53 ----
  extern char *rendezvous_name;
  extern int    max_stack_depth;

+ /* GUC-configurable parameters */
+
+ typedef enum
+ {
+     /* Reverse order so GUC USERLIMIT is easier */
+     LOGSTMT_ALL = 0,            /* log all statements, can not be -1 */
+     LOGSTMT_DDL,                /* log data definition statements */
+     LOGSTMT_MOD,                /* log modification statements, plus DDL */
+     LOGSTMT_NONE                /* log no statements */
+ } LogStmtLevel;
+
+ extern LogStmtLevel log_statement;
+
  #ifndef BOOTSTRAP_INCLUDE

  extern List *pg_parse_and_rewrite(const char *query_string,
Index: src/include/utils/guc.h
===================================================================
RCS file: /cvsroot/pgsql-server/src/include/utils/guc.h,v
retrieving revision 1.44
diff -c -c -r1.44 guc.h
*** src/include/utils/guc.h    19 Jan 2004 19:04:40 -0000    1.44
--- src/include/utils/guc.h    6 Apr 2004 03:56:15 -0000
***************
*** 103,109 ****
  } GucSource;

  /* GUC vars that are actually declared in guc.c, rather than elsewhere */
- extern bool log_statement;
  extern bool log_duration;
  extern bool Debug_print_plan;
  extern bool Debug_print_parse;
--- 103,108 ----