Re: [HACKERS] logging statement levels

Patch applied.

---------------------------------------------------------------------------

Bruce Momjian wrote:
> 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(at)candle(dot)pha(dot)pa(dot)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 ----

>
> ---------------------------(end of broadcast)---------------------------
> TIP 7: don't forget to increase your free space map settings

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073