Re: logging enhancements, minor code cleanup (retry) - Mailing list pgsql-patches

This has been saved for the 7.5 release:

    http:/momjian.postgresql.org/cgi-bin/pgpatches2

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

Andrew Dunstan wrote:
>
> revised patch attached, including docco. I think this attends to all the
> comments I received.
>
> cheers
>
> andrew
>
>

> Index: doc/src/sgml/runtime.sgml
> ===================================================================
> RCS file: /projects/cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v
> retrieving revision 1.199
> diff -c -w -r1.199 runtime.sgml
> *** doc/src/sgml/runtime.sgml    10 Aug 2003 01:20:34 -0000    1.199
> --- doc/src/sgml/runtime.sgml    13 Aug 2003 20:59:13 -0000
> ***************
> *** 1801,1806 ****
> --- 1801,1820 ----
>
>
>        <varlistentry>
> +       <term><varname>LOG_SESSION_END</varname> (<type>boolean</type>)</term>
> +       <listitem>
> +        <para>
> +      This outputs a line to the server logs similar to LOG_CONNECTIONS
> +      but at the end of a session, and including the duration of the
> +      session.This is off by default. This option can only be set at
> +      server start or in the <filename>postgresql.conf</filename>
> +      configuration file.
> +        </para>
> +       </listitem>
> +      </varlistentry>
> +
> +
> +      <varlistentry>
>         <term><varname>LOG_DURATION</varname> (<type>boolean</type>)</term>
>         <listitem>
>          <para>
> ***************
> *** 1825,1830 ****
> --- 1839,1876 ----
>           the process ID.
>          </para>
>         </listitem>
> +      </varlistentry>
> +
> +      <varlistentry>
> +       <term><varname>LOG_LINE_FORMAT</varname> (<type>string</type>)</term>
> +       <listitem>
> +        <para>
> +      Prefixes each message in the server log file or syslog with extra
> +      information as specidied in the string. The default is an empty
> +      string. The following sequences in the string are translated:
> +      <literal>'%U'</literal> is replace with the username,
> +      <literal>'%D'</literal> is replaced by the database name,
> +      and <literal>'%%'</literal> is replaced by <literal>'%'</literal>.
> +      All other characters are copied literally to the log. For example,
> + <programlisting>
> + log_line_format = '<%U%%%D> '
> + </programlisting>
> +      will produce output like this:
> + <programlisting>
> + <myuser%mydb> LOG:  query: create table foo(blah text);
> + </programlisting>
> +      </para>
> +     <para>
> +      If <varname>LOG_PID</varname> or <varname>LOG_TIMESTAMP</varname>
> +      are turned on the output from <varname>LOG_LINE_FORMAT</varname>
> +      will follow those items but precede any other output on the line.
> +     </para>
> +     <para>
> +      This option can only be set at server start or in the
> +         <filename>postgresql.conf</filename> configuration file.
> +     </para>
> +
> +        </listitem>
>        </varlistentry>
>
>        <varlistentry>
> Index: src/backend/commands/vacuum.c
> ===================================================================
> RCS file: /projects/cvsroot/pgsql-server/src/backend/commands/vacuum.c,v
> retrieving revision 1.259
> diff -c -w -r1.259 vacuum.c
> *** src/backend/commands/vacuum.c    4 Aug 2003 02:39:58 -0000    1.259
> --- src/backend/commands/vacuum.c    13 Aug 2003 20:59:14 -0000
> ***************
> *** 3109,3118 ****
>   void
>   vac_init_rusage(VacRUsage *ru0)
>   {
> -     struct timezone tz;
> -
>       getrusage(RUSAGE_SELF, &ru0->ru);
> !     gettimeofday(&ru0->tv, &tz);
>   }
>
>   /*
> --- 3109,3116 ----
>   void
>   vac_init_rusage(VacRUsage *ru0)
>   {
>       getrusage(RUSAGE_SELF, &ru0->ru);
> !     gettimeofday(&ru0->tv, NULL);
>   }
>
>   /*
> Index: src/backend/postmaster/postmaster.c
> ===================================================================
> RCS file: /projects/cvsroot/pgsql-server/src/backend/postmaster/postmaster.c,v
> retrieving revision 1.341
> diff -c -w -r1.341 postmaster.c
> *** src/backend/postmaster/postmaster.c    12 Aug 2003 18:23:20 -0000    1.341
> --- src/backend/postmaster/postmaster.c    13 Aug 2003 20:59:15 -0000
> ***************
> *** 1000,1009 ****
>       int            nSockets;
>       struct timeval now,
>                   later;
> -     struct timezone tz;
>       int            i;
>
> !     gettimeofday(&now, &tz);
>
>       nSockets = initMasks(&readmask);
>
> --- 1000,1008 ----
>       int            nSockets;
>       struct timeval now,
>                   later;
>       int            i;
>
> !     gettimeofday(&now, NULL);
>
>       nSockets = initMasks(&readmask);
>
> ***************
> *** 1085,1091 ****
>            */
>           while (random_seed == 0)
>           {
> !             gettimeofday(&later, &tz);
>
>               /*
>                * We are not sure how much precision is in tv_usec, so we
> --- 1084,1090 ----
>            */
>           while (random_seed == 0)
>           {
> !             gettimeofday(&later, NULL);
>
>               /*
>                * We are not sure how much precision is in tv_usec, so we
> ***************
> *** 2320,2326 ****
>       int            i;
>       int            status;
>       struct timeval now;
> -     struct timezone tz;
>       char        remote_host[NI_MAXHOST];
>       char        remote_port[NI_MAXSERV];
>
> --- 2319,2324 ----
> ***************
> *** 2342,2350 ****
>       /* Close the postmaster's other sockets */
>       ClosePostmasterPorts(true);
>
> -     /* Save port etc. for ps status */
> -     MyProcPort = port;
> -
>       /* Reset MyProcPid to new backend's pid */
>       MyProcPid = getpid();
>
> --- 2340,2345 ----
> ***************
> *** 2416,2421 ****
> --- 2411,2423 ----
>           elog(FATAL, "could not set timer for authorization timeout");
>
>       /*
> +      * Save port etc. for ps status
> +      * do this after we log connections or auth failures so that we don't use
> +      * the format line before the details are filled in
> +      */
> +     MyProcPort = port;
> +
> +     /*
>        * Receive the startup packet (which might turn out to be a cancel
>        * request packet).
>        */
> ***************
> *** 2456,2462 ****
>        * start a new random sequence in the random() library function.
>        */
>       random_seed = 0;
> !     gettimeofday(&now, &tz);
>       srandom((unsigned int) now.tv_usec);
>
>       /* ----------------
> --- 2458,2464 ----
>        * start a new random sequence in the random() library function.
>        */
>       random_seed = 0;
> !     gettimeofday(&now, NULL);
>       srandom((unsigned int) now.tv_usec);
>
>       /* ----------------
> ***************
> *** 2539,2544 ****
> --- 2541,2554 ----
>       MemoryContextSwitchTo(TopMemoryContext);
>       MemoryContextDelete(PostmasterContext);
>       PostmasterContext = NULL;
> +
> +     /*
> +      * set up remaining members of port stucture while in the
> +      * TopMemoryContext
> +      */
> +     port->remote_host = pstrdup(remote_host);
> +     port->remote_port = pstrdup(remote_port);
> +     gettimeofday(&(port->session_start),NULL);
>
>       /*
>        * Debug: print arguments being passed to backend
> Index: src/backend/tcop/postgres.c
> ===================================================================
> RCS file: /projects/cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
> retrieving revision 1.359
> diff -c -w -r1.359 postgres.c
> *** src/backend/tcop/postgres.c    12 Aug 2003 18:52:38 -0000    1.359
> --- src/backend/tcop/postgres.c    13 Aug 2003 20:59:15 -0000
> ***************
> *** 85,90 ****
> --- 85,93 ----
>   bool        Warn_restart_ready = false;
>   bool        InError = false;
>
> + /* flag for logging end of session */
> + bool        Log_session_end = false;
> +
>   /*
>    * Flags for expensive function optimization -- JMH 3/9/92
>    */
> ***************
> *** 150,155 ****
> --- 153,159 ----
>   static void finish_xact_command(void);
>   static void SigHupHandler(SIGNAL_ARGS);
>   static void FloatExceptionHandler(SIGNAL_ARGS);
> + static void log_session_end(void);
>
>
>   /* ----------------------------------------------------------------
> ***************
> *** 2426,2432 ****
> --- 2430,2439 ----
>        * other output options.
>        */
>       if (debug_flag >= 1)
> +     {
>           SetConfigOption("log_connections", "true", debug_context, gucsource);
> +         SetConfigOption("log_session_end", "true", debug_context, gucsource);
> +     }
>       if (debug_flag >= 2)
>           SetConfigOption("log_statement", "true", debug_context, gucsource);
>       if (debug_flag >= 3)
> ***************
> *** 2455,2460 ****
> --- 2462,2472 ----
>               gucopts = lnext(gucopts);
>               SetConfigOption(name, value, PGC_BACKEND, PGC_S_CLIENT);
>           }
> +        /*
> +         * set up handler to log session end.
> +         */
> +         if (IsUnderPostmaster && Log_session_end)
> +             on_proc_exit(log_session_end,0);
>       }
>
>       /*
> ***************
> *** 3195,3198 ****
> --- 3207,3269 ----
>                errdetail("%s", str.data)));
>
>       pfree(str.data);
> + }
> +
> +
> + /*
> +  * on_proc_exit handler to log end of session
> +  */
> + static void
> + log_session_end(void)
> + {
> +     Port * port = MyProcPort;
> +     struct timeval end;
> +     int  hours, minutes, seconds;
> +
> +     char session_time[20];
> +     char uname[6+NAMEDATALEN];
> +     char dbname[10+NAMEDATALEN];
> +     char remote_host[7 + NI_MAXHOST];
> +     char remote_port[7 + NI_MAXSERV];
> +
> +     snprintf(uname, sizeof(uname)," user=%s",port->user_name);
> +     snprintf(dbname, sizeof(dbname)," database=%s",port->database_name);
> +     snprintf(remote_host,sizeof(remote_host)," host=%s",
> +              port->remote_host);
> +     /* prevent redundant or empty reporting of port */
> +     if (!LogSourcePort && strlen(port->remote_port))
> +         snprintf(remote_port,sizeof(remote_port)," port=%s",port->remote_port);
> +     else
> +         remote_port[0] = '\0';
> +
> +
> +     gettimeofday(&end,NULL);
> +
> +     if (end.tv_usec < port->session_start.tv_usec)
> +     {
> +         end.tv_sec--;
> +         end.tv_usec += 1000000;
> +     }
> +     end.tv_sec -= port->session_start.tv_sec;
> +     end.tv_usec -= port->session_start.tv_usec;
> +
> +     hours = end.tv_sec / 3600;
> +     end.tv_sec %= 3600;
> +     minutes = end.tv_sec / 60;
> +     seconds = end.tv_sec % 60;
> +
> +     /* if time has gone backwards for some reason say so, or print time */
> +
> +     if (end.tv_sec < 0)
> +         snprintf(session_time,sizeof(session_time),"negative!");
> +     else
> +         /* for stricter accuracy here we could round - this is close enough */
> +         snprintf(session_time, sizeof(session_time),"%d:%02d:%02d.%02ld",
> +              hours, minutes, seconds, end.tv_usec/10000);
> +
> +     ereport(
> +         LOG,
> +         (errmsg("session end: duration: %s%s%s%s%s",
> +             session_time,uname,dbname,remote_host,remote_port)));
> +
>   }
> Index: src/backend/utils/adt/nabstime.c
> ===================================================================
> RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/adt/nabstime.c,v
> retrieving revision 1.113
> diff -c -w -r1.113 nabstime.c
> *** src/backend/utils/adt/nabstime.c    4 Aug 2003 02:40:05 -0000    1.113
> --- src/backend/utils/adt/nabstime.c    13 Aug 2003 20:59:16 -0000
> ***************
> *** 1745,1757 ****
>   timeofday(PG_FUNCTION_ARGS)
>   {
>       struct timeval tp;
> -     struct timezone tpz;
>       char        templ[100];
>       char        buf[100];
>       text       *result;
>       int            len;
>
> !     gettimeofday(&tp, &tpz);
>       strftime(templ, sizeof(templ), "%a %b %d %H:%M:%S.%%06d %Y %Z",
>                localtime((time_t *) &tp.tv_sec));
>       snprintf(buf, sizeof(buf), templ, tp.tv_usec);
> --- 1745,1756 ----
>   timeofday(PG_FUNCTION_ARGS)
>   {
>       struct timeval tp;
>       char        templ[100];
>       char        buf[100];
>       text       *result;
>       int            len;
>
> !     gettimeofday(&tp, NULL);
>       strftime(templ, sizeof(templ), "%a %b %d %H:%M:%S.%%06d %Y %Z",
>                localtime((time_t *) &tp.tv_sec));
>       snprintf(buf, sizeof(buf), templ, tp.tv_usec);
> Index: src/backend/utils/error/elog.c
> ===================================================================
> RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/error/elog.c,v
> retrieving revision 1.119
> diff -c -w -r1.119 elog.c
> *** src/backend/utils/error/elog.c    8 Aug 2003 21:42:11 -0000    1.119
> --- src/backend/utils/error/elog.c    13 Aug 2003 20:59:16 -0000
> ***************
> *** 72,77 ****
> --- 72,78 ----
>   bool        Log_timestamp = false;        /* show timestamps in stderr
>                                            * output */
>   bool        Log_pid = false;    /* show PIDs in stderr output */
> + char        *Log_line_format_str = ""; /* format for extra log line info */
>
>   #ifdef HAVE_SYSLOG
>   /*
> ***************
> *** 145,150 ****
> --- 146,152 ----
>   static const char *error_severity(int elevel);
>   static const char *print_timestamp(void);
>   static const char *print_pid(void);
> + static const char *log_line_extra(void);
>
>
>   /*
> ***************
> *** 1019,1024 ****
> --- 1021,1099 ----
>   }
>   #endif   /* HAVE_SYSLOG */
>
> + /*
> +  * Formatted extra info for log if option is set and we have data,
> +  * or empty string otherwise.
> +  */
> + static const char *
> + log_line_extra(void)
> + {
> +     /* space for option string + 2 identifiers */
> +     /* Note: if more identifiers are built in this will have to increase */
> +     static char *result = NULL;
> +     int format_len = strlen(Log_line_format_str);
> +     int result_len = 2*NAMEDATALEN + format_len +3 ;
> +     if (result == NULL)
> +         result = malloc(result_len);
> +     result[0] = '\0';
> +
> +     if (format_len > 0 && MyProcPort)
> +     {
> +         int i,j;
> +         char * dbname = MyProcPort->database_name;
> +         char * username = MyProcPort->user_name;
> +         if (dbname == NULL)
> +             dbname="";
> +         if (username == NULL)
> +             username = "";
> +
> +         /*
> +          * invariant through each iteration of this loop:
> +          *  . j is the index of the trailing null on result
> +          *  . result_len - j is the number of chars we have room for
> +          *    including the trailing null
> +          *  . there is room to write at least one more non-null char plus the
> +          *    trailing null
> +          */
> +         for (i = 0, j=0; i < format_len && j < result_len-1; i++)
> +         {
> +             if(Log_line_format_str[i] != '%')
> +             {
> +                 /* literal char, just copy */
> +                 result[j]=Log_line_format_str[i];
> +                 j++;
> +                 result[j] = '\0';
> +                 continue;
> +             }
> +             else if (i == format_len - 1)
> +             {
> +                 /* format error - skip it */
> +                 continue;
> +             }
> +             /* go to char after '%', take action accordingly */
> +             i++;
> +             switch (Log_line_format_str[i])
> +             {
> +                 case 'U':
> +                     j += snprintf(result+j,result_len-j,"%s",username);
> +                     break;
> +                 case 'D':
> +                     j += snprintf(result+j,result_len-j,"%s",dbname);
> +                     break;
> +                 case '%':
> +                     result[j] = '%';
> +                     j++;
> +                     result[j] = '\0';
> +                     break;
> +                 default:
> +                     /* format error - skip it */
> +                     break;
> +             }
> +         }
> +     }
> +     return result;
> + }
> +
>
>   /*
>    * Write error report to server's log
> ***************
> *** 1028,1036 ****
>   {
>       StringInfoData buf;
>
>       initStringInfo(&buf);
>
> !     appendStringInfo(&buf, "%s:  ", error_severity(edata->elevel));
>
>       if (Log_error_verbosity >= PGERROR_VERBOSE)
>       {
> --- 1103,1115 ----
>   {
>       StringInfoData buf;
>
> +     const char *extra_info = log_line_extra();
> +
>       initStringInfo(&buf);
>
> !     appendStringInfo(&buf, "%s%s:  ",
> !                      extra_info,
> !                      error_severity(edata->elevel));
>
>       if (Log_error_verbosity >= PGERROR_VERBOSE)
>       {
> ***************
> *** 1062,1080 ****
>       if (Log_error_verbosity >= PGERROR_DEFAULT)
>       {
>           if (edata->detail)
> !             appendStringInfo(&buf, gettext("DETAIL:  %s\n"), edata->detail);
>           if (edata->hint)
> !             appendStringInfo(&buf, gettext("HINT:  %s\n"), edata->hint);
>           if (edata->context)
> !             appendStringInfo(&buf, gettext("CONTEXT:  %s\n"), edata->context);
>           if (Log_error_verbosity >= PGERROR_VERBOSE)
>           {
>               if (edata->funcname && edata->filename)
> !                 appendStringInfo(&buf, gettext("LOCATION:  %s, %s:%d\n"),
>                                    edata->funcname, edata->filename,
>                                    edata->lineno);
>               else if (edata->filename)
> !                 appendStringInfo(&buf, gettext("LOCATION:  %s:%d\n"),
>                                    edata->filename, edata->lineno);
>           }
>       }
> --- 1141,1167 ----
>       if (Log_error_verbosity >= PGERROR_DEFAULT)
>       {
>           if (edata->detail)
> !             appendStringInfo(&buf, gettext("%sDETAIL:  %s\n"),
> !                              extra_info,
> !                              edata->detail);
>           if (edata->hint)
> !             appendStringInfo(&buf, gettext("%sHINT:  %s\n"),
> !                              extra_info,
> !                              edata->hint);
>           if (edata->context)
> !             appendStringInfo(&buf, gettext("%sCONTEXT:  %s\n"),
> !                              extra_info,
> !                              edata->context);
>           if (Log_error_verbosity >= PGERROR_VERBOSE)
>           {
>               if (edata->funcname && edata->filename)
> !                 appendStringInfo(&buf, gettext("%sLOCATION:  %s, %s:%d\n"),
> !                                  extra_info,
>                                    edata->funcname, edata->filename,
>                                    edata->lineno);
>               else if (edata->filename)
> !                 appendStringInfo(&buf, gettext("%sLOCATION:  %s:%d\n"),
> !                                  extra_info,
>                                    edata->filename, edata->lineno);
>           }
>       }
> ***************
> *** 1086,1092 ****
>        * improve?
>        */
>       if (edata->elevel >= log_min_error_statement && debug_query_string != NULL)
> !         appendStringInfo(&buf, gettext("STATEMENT:  %s\n"),
>                            debug_query_string);
>
>
> --- 1173,1180 ----
>        * improve?
>        */
>       if (edata->elevel >= log_min_error_statement && debug_query_string != NULL)
> !         appendStringInfo(&buf, gettext("%sSTATEMENT:  %s\n"),
> !                          extra_info,
>                            debug_query_string);
>
>
> Index: src/backend/utils/misc/guc.c
> ===================================================================
> RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
> retrieving revision 1.149
> diff -c -w -r1.149 guc.c
> *** src/backend/utils/misc/guc.c    11 Aug 2003 23:04:49 -0000    1.149
> --- src/backend/utils/misc/guc.c    13 Aug 2003 20:59:17 -0000
> ***************
> *** 66,71 ****
> --- 66,72 ----
>
>   /* XXX these should appear in other modules' header files */
>   extern bool Log_connections;
> + extern bool Log_session_end;
>   extern int    PreAuthDelay;
>   extern int    AuthenticationTimeout;
>   extern int    CheckPointTimeout;
> ***************
> *** 488,493 ****
> --- 489,502 ----
>           false, NULL, NULL
>       },
>       {
> +         {"log_session_end", PGC_BACKEND, LOGGING_WHAT,
> +             gettext_noop("Logs end of a session, including duration"),
> +             NULL
> +         },
> +         &Log_session_end,
> +         false, NULL, NULL
> +     },
> +     {
>           {"log_timestamp", PGC_SIGHUP, LOGGING_WHAT,
>               gettext_noop("Prefixes server log messages with a time stamp"),
>               NULL
> ***************
> *** 1334,1339 ****
> --- 1343,1357 ----
>           },
>           &log_min_error_statement_str,
>           "panic", assign_min_error_statement, NULL
> +     },
> +
> +     {
> +         {"log_line_format", PGC_SIGHUP, LOGGING_WHAT,
> +             gettext_noop("Controls extra information on each log line"),
> +             gettext_noop("if blank no extra info is logged")
> +         },
> +         &Log_line_format_str,
> +         "", NULL, NULL
>       },
>
>       {
> Index: src/backend/utils/misc/postgresql.conf.sample
> ===================================================================
> RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/misc/postgresql.conf.sample,v
> retrieving revision 1.87
> diff -c -w -r1.87 postgresql.conf.sample
> *** src/backend/utils/misc/postgresql.conf.sample    29 Jul 2003 00:03:18 -0000    1.87
> --- src/backend/utils/misc/postgresql.conf.sample    13 Aug 2003 20:59:17 -0000
> ***************
> *** 171,178 ****
> --- 171,180 ----
>   #debug_print_plan = false
>   #debug_pretty_print = false
>   #log_connections = false
> + #log_session_end = false
>   #log_duration = false
>   #log_pid = false
> + #log_line_format = ''     # e.g. '<%U%%%D> ' - %U=username %D=databasename %%=%
>   #log_statement = false
>   #log_timestamp = false
>   #log_hostname = false
> Index: src/include/libpq/libpq-be.h
> ===================================================================
> RCS file: /projects/cvsroot/pgsql-server/src/include/libpq/libpq-be.h,v
> retrieving revision 1.37
> diff -c -w -r1.37 libpq-be.h
> *** src/include/libpq/libpq-be.h    4 Aug 2003 02:40:13 -0000    1.37
> --- src/include/libpq/libpq-be.h    13 Aug 2003 20:59:17 -0000
> ***************
> *** 42,47 ****
> --- 42,50 ----
>       ProtocolVersion proto;        /* FE/BE protocol version */
>       SockAddr    laddr;            /* local addr (postmaster) */
>       SockAddr    raddr;            /* remote addr (client) */
> +     char         *remote_host;    /* name (or ip addr) of remote host */
> +     char        *remote_port;    /* text rep of remote port */
> +     struct timeval    session_start;    /* for session duration logging */
>
>       /*
>        * Information that needs to be saved from the startup packet and
> Index: src/include/utils/elog.h
> ===================================================================
> RCS file: /projects/cvsroot/pgsql-server/src/include/utils/elog.h,v
> retrieving revision 1.63
> diff -c -w -r1.63 elog.h
> *** src/include/utils/elog.h    8 Aug 2003 21:42:55 -0000    1.63
> --- src/include/utils/elog.h    13 Aug 2003 20:59:17 -0000
> ***************
> *** 171,176 ****
> --- 171,177 ----
>   extern PGErrorVerbosity Log_error_verbosity;
>   extern bool Log_timestamp;
>   extern bool Log_pid;
> + extern char *Log_line_format_str;
>
>   #ifdef HAVE_SYSLOG
>   extern int    Use_syslog;

>
> ---------------------------(end of broadcast)---------------------------
> TIP 9: the planner will ignore your desire to choose an index scan if your
>       joining column's datatypes do not match

--
  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