Thread: logging enhancements, minor code cleanup

logging enhancements, minor code cleanup

From

Andrew Dunstan

Date:

09 August 2003, 23:34:28

The attached patch does 3 things:

. logs connection ends if log_connections = true
. provides a new option "log_line_format" which allows addition of extra
information on a log line before the keyword. Currently supported are
user name and database name, but it is easily extensible. The string is
in the flavor of a printf format, where "%U" means user name, "%D" means
database name, "%%" means "%" and anything else means itself, literally.
. minor code cleanup for consistency in calling gettimeofday().

cheers

andrew
Index: 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
*** backend/commands/vacuum.c    4 Aug 2003 02:39:58 -0000    1.259
--- backend/commands/vacuum.c    9 Aug 2003 21:17:11 -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: backend/postmaster/postmaster.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/postmaster/postmaster.c,v
retrieving revision 1.340
diff -c -w -r1.340 postmaster.c
*** backend/postmaster/postmaster.c    4 Aug 2003 02:40:02 -0000    1.340
--- backend/postmaster/postmaster.c    9 Aug 2003 21:17:13 -0000
***************
*** 995,1004 ****
      int            nSockets;
      struct timeval now,
                  later;
-     struct timezone tz;
      int            i;

!     gettimeofday(&now, &tz);

      nSockets = initMasks(&readmask);

--- 995,1003 ----
      int            nSockets;
      struct timeval now,
                  later;
      int            i;

!     gettimeofday(&now, NULL);

      nSockets = initMasks(&readmask);

***************
*** 1080,1086 ****
           */
          while (random_seed == 0)
          {
!             gettimeofday(&later, &tz);

              /*
               * We are not sure how much precision is in tv_usec, so we
--- 1079,1085 ----
           */
          while (random_seed == 0)
          {
!             gettimeofday(&later, NULL);

              /*
               * We are not sure how much precision is in tv_usec, so we
***************
*** 2302,2308 ****
      int            i;
      int            status;
      struct timeval now;
-     struct timezone tz;
      char        remote_host[NI_MAXHOST];
      char        remote_port[NI_MAXSERV];

--- 2301,2306 ----
***************
*** 2324,2332 ****
      /* 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();

--- 2322,2327 ----
***************
*** 2398,2403 ****
--- 2393,2405 ----
          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).
       */
***************
*** 2438,2444 ****
       * start a new random sequence in the random() library function.
       */
      random_seed = 0;
!     gettimeofday(&now, &tz);
      srandom((unsigned int) now.tv_usec);

      /* ----------------
--- 2440,2446 ----
       * start a new random sequence in the random() library function.
       */
      random_seed = 0;
!     gettimeofday(&now, NULL);
      srandom((unsigned int) now.tv_usec);

      /* ----------------
***************
*** 2521,2526 ****
--- 2523,2536 ----
      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: backend/tcop/postgres.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.357
diff -c -w -r1.357 postgres.c
*** backend/tcop/postgres.c    6 Aug 2003 17:46:45 -0000    1.357
--- backend/tcop/postgres.c    9 Aug 2003 21:17:13 -0000
***************
*** 68,73 ****
--- 68,74 ----
  extern int    optind;
  extern char *optarg;

+ extern bool Log_connections;

  /* ----------------
   *        global variables
***************
*** 150,155 ****
--- 151,157 ----
  static void finish_xact_command(void);
  static void SigHupHandler(SIGNAL_ARGS);
  static void FloatExceptionHandler(SIGNAL_ARGS);
+ static void log_session_end(void);


  /* ----------------------------------------------------------------
***************
*** 2453,2458 ****
--- 2455,2465 ----
              gucopts = lnext(gucopts);
              SetConfigOption(name, value, PGC_BACKEND, PGC_S_CLIENT);
          }
+        /*
+         * set up handler to log session end.
+         */
+         if (IsUnderPostmaster && Log_connections)
+             on_proc_exit(log_session_end,0);
      }

      /*
***************
*** 3190,3193 ****
--- 3197,3243 ----
               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];
+
+     snprintf(uname, sizeof(uname)," user=%s",port->user_name);
+     snprintf(dbname, sizeof(dbname)," database=%s",port->database_name);
+
+
+     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;
+
+     snprintf(session_time, sizeof(session_time),"%d:%02d:%02d.%02ld",
+              hours, minutes, seconds,
+              end.tv_usec/10000);
+
+     ereport(LOG,
+             (errmsg("session ended: duration: %s%s%s",
+                     session_time,uname,dbname)));
+
  }
Index: 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
*** backend/utils/adt/nabstime.c    4 Aug 2003 02:40:05 -0000    1.113
--- backend/utils/adt/nabstime.c    9 Aug 2003 21:17:13 -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: 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
*** backend/utils/error/elog.c    8 Aug 2003 21:42:11 -0000    1.119
--- backend/utils/error/elog.c    9 Aug 2003 21:17:14 -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,1089 ----
  }
  #endif   /* HAVE_SYSLOG */

+ /*
+  * Formatted extra info for log if option is set and we have a data,
+  * or empty string otherwise.
+  */
+ static const char *
+ log_line_extra(void)
+ {
+     /* space for option string + 2 identifiers */
+     /* Note: if more identifers are built in this will have to increase */
+     static char *result = NULL;
+     int flen = strlen(Log_line_format_str);
+     int i,j;
+     int tlen = 2*NAMEDATALEN + flen +3 ;
+     if (result == NULL)
+         result = malloc(tlen);
+     result[0] = '\0';
+
+     if (flen > 0 && MyProcPort)
+     {
+         char * dbname = MyProcPort->database_name;
+         char * username = MyProcPort->user_name;
+         if (dbname == NULL)
+             dbname="";
+         if (username == NULL)
+             username = "";
+         j = 0;
+         for (i = 0; i < flen && j < tlen-1; i++)
+         {
+             if(Log_line_format_str[i] != '%')
+             {
+                 result[j]=Log_line_format_str[i];
+                 j++;
+                 result[j] = '\0';
+                 continue;
+             }
+             else if (i == flen - 1)
+             {
+                 /* format error - just skip it */
+                 continue;
+             }
+             i++;
+             switch (Log_line_format_str[i])
+             {
+                 case 'U':
+                     j += snprintf(result+j,tlen-j,"%s",username);
+                     break;
+                 case 'D':
+                     j += snprintf(result+j,tlen-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)
      {
--- 1093,1105 ----
  {
      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);
          }
      }
--- 1131,1157 ----
      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);


--- 1163,1170 ----
       * improve?
       */
      if (edata->elevel >= log_min_error_statement && debug_query_string != NULL)
!         appendStringInfo(&buf, gettext("%sSTATEMENT:  %s\n"),
!                          extra_info,
                           debug_query_string);


Index: backend/utils/misc/guc.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.148
diff -c -w -r1.148 guc.c
*** backend/utils/misc/guc.c    4 Aug 2003 23:59:39 -0000    1.148
--- backend/utils/misc/guc.c    9 Aug 2003 21:17:15 -0000
***************
*** 1334,1339 ****
--- 1334,1348 ----
          },
          &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: 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
*** backend/utils/misc/postgresql.conf.sample    29 Jul 2003 00:03:18 -0000    1.87
--- backend/utils/misc/postgresql.conf.sample    9 Aug 2003 21:17:15 -0000
***************
*** 173,178 ****
--- 173,179 ----
  #log_connections = false
  #log_duration = false
  #log_pid = false
+ #log_line_format = '<%U~%D>'     # %U=username %D=databasename %%=%
  #log_statement = false
  #log_timestamp = false
  #log_hostname = false
Index: 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
*** include/libpq/libpq-be.h    4 Aug 2003 02:40:13 -0000    1.37
--- include/libpq/libpq-be.h    9 Aug 2003 21:17:15 -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: 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
*** include/utils/elog.h    8 Aug 2003 21:42:55 -0000    1.63
--- include/utils/elog.h    9 Aug 2003 21:17:15 -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;

Re: logging enhancements, minor code cleanup

From

Neil Conway

Date:

10 August 2003, 20:41:01

On Sat, Aug 09, 2003 at 07:22:56PM -0400, Andrew Dunstan wrote:
> The attached patch does 3 things:
>
> . logs connection ends if log_connections = true

Should this be a separate GUC variable? Personally, I'd rather not have
my log files bloated with info on both the beginning *and* the end of
each connection.

> . provides a new option "log_line_format" which allows addition of extra
> information on a log line before the keyword.

This patch should also update the documentation.

Some minor stylistic comments follow...

> Index: backend/tcop/postgres.c
> ===================================================================
> RCS file: /projects/cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
> retrieving revision 1.357
> diff -c -w -r1.357 postgres.c
> *** backend/tcop/postgres.c    6 Aug 2003 17:46:45 -0000    1.357
> --- backend/tcop/postgres.c    9 Aug 2003 21:17:13 -0000
> +     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;

Can you add an assertion that end.tv_sec >= port->session_start.tv_sec before
this line, please?

> Index: 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
> *** backend/utils/error/elog.c    8 Aug 2003 21:42:11 -0000    1.119
> --- backend/utils/error/elog.c    9 Aug 2003 21:17:14 -0000
> ***************
> *** 1019,1024 ****
> --- 1021,1089 ----
>   }
>   #endif   /* HAVE_SYSLOG */
>
> + /*
> +  * Formatted extra info for log if option is set and we have a data,
> +  * or empty string otherwise.
> +  */

This comment is a little awkward: "we have a data"?

> + static const char *
> + log_line_extra(void)
> + {
> +     /* space for option string + 2 identifiers */
> +     /* Note: if more identifers are built in this will have to increase */

"Identifier" is incorrectly spelled.

> +     static char *result = NULL;

Why is this static? IMHO it would be much cleaner to just return a palloc'ed
string.

> +     int flen = strlen(Log_line_format_str);
> +     int i,j;
> +     int tlen = 2*NAMEDATALEN + flen +3 ;

Can we choose some more helpful variable names than "flen" and
"tlen", please? Also, you can move the declaration of i & j to
the scope of the if statement.

> +     {
> +         char * dbname = MyProcPort->database_name;
> +         char * username = MyProcPort->user_name;
> +         if (dbname == NULL)
> +             dbname="";
> +         if (username == NULL)
> +             username = "";

Could either of these ever be NULL?

> diff -c -w -r1.87 postgresql.conf.sample
> *** backend/utils/misc/postgresql.conf.sample    29 Jul 2003 00:03:18 -0000    1.87
> --- backend/utils/misc/postgresql.conf.sample    9 Aug 2003 21:17:15 -0000
> ***************
> *** 173,178 ****
> --- 173,179 ----
>   #log_connections = false
>   #log_duration = false
>   #log_pid = false
> + #log_line_format = '<%U~%D>'     # %U=username %D=databasename %%=%

Shouldn't the commented-out line have the default value? (which is "", right?)

-Neil

Re: logging enhancements, minor code cleanup

From

Andrew Dunstan

Date:

10 August 2003, 22:21:44

Thanks. Responses interspersed below.

cheers

andrew

Neil Conway wrote:

>On Sat, Aug 09, 2003 at 07:22:56PM -0400, Andrew Dunstan wrote:
>
>
>>The attached patch does 3 things:
>>
>>. logs connection ends if log_connections = true
>>
>>
>
>Should this be a separate GUC variable? Personally, I'd rather not have
>my log files bloated with info on both the beginning *and* the end of
>each connection.
>
>

Sure. Very easy. Nobody suggested it when I floated the idea of logging
session end on the hackers list, but it's a simple change. How does
'log_session_end' sound? Or else we could make log_connections have
levels - 0 = none, 1 = start, 2 = start + end. What's the concensus?

>
>
>>. provides a new option "log_line_format" which allows addition of extra
>>information on a log line before the keyword.
>>
>>
>
>This patch should also update the documentation.
>

I'll submit a doc patch when the code is accepted. That's what I did
with the pg_hba.conf CIDR stuff and nobody objected. I think this is a
good way to operate, since I might make changes (for example, as a
result of your response), and would rather do the docs once.

>
>Some minor stylistic comments follow...
>
>
>
>>Index: backend/tcop/postgres.c
>>===================================================================
>>RCS file: /projects/cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
>>retrieving revision 1.357
>>diff -c -w -r1.357 postgres.c
>>*** backend/tcop/postgres.c    6 Aug 2003 17:46:45 -0000    1.357
>>--- backend/tcop/postgres.c    9 Aug 2003 21:17:13 -0000
>>+     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;
>>
>>
>
>Can you add an assertion that end.tv_sec >= port->session_start.tv_sec before
>this line, please?
>
>

Sure. Presumably to catch the situation where the machine's time is
changed (backwards) during the session - an event with fairly low
probability.

>
>
>>Index: 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
>>*** backend/utils/error/elog.c    8 Aug 2003 21:42:11 -0000    1.119
>>--- backend/utils/error/elog.c    9 Aug 2003 21:17:14 -0000
>>***************
>>*** 1019,1024 ****
>>--- 1021,1089 ----
>>  }
>>  #endif   /* HAVE_SYSLOG */
>>
>>+ /*
>>+  * Formatted extra info for log if option is set and we have a data,
>>+  * or empty string otherwise.
>>+  */
>>
>>
>
>This comment is a little awkward: "we have a data"?
>
>

Typo. will fix.

>
>
>>+ static const char *
>>+ log_line_extra(void)
>>+ {
>>+     /* space for option string + 2 identifiers */
>>+     /* Note: if more identifers are built in this will have to increase */
>>
>>
>
>"Identifier" is incorrectly spelled.
>
>

Typo again. will fix.

>
>
>>+     static char *result = NULL;
>>
>>
>
>Why is this static? IMHO it would be much cleaner to just return a palloc'ed
>string.
>
>

print_timestamp() and print_pid() in the same file use static buffers
which they return, so I just copied the style more or less, making
allowance for the fact I don't know the reasonable size at compile time.
It doesn't seem very efficient to palloc the string over and over
instead of once per backend. Wouldn't I then have to pfree it at a
remote spot in the code so as not to have a memory leak? That strikes me
as much more error prone.

>
>
>>+     int flen = strlen(Log_line_format_str);
>>+     int i,j;
>>+     int tlen = 2*NAMEDATALEN + flen +3 ;
>>
>>
>
>Can we choose some more helpful variable names than "flen" and
>"tlen", please? Also, you can move the declaration of i & j to
>the scope of the if statement.
>
>

Sure. Will do.

>
>
>>+     {
>>+         char * dbname = MyProcPort->database_name;
>>+         char * username = MyProcPort->user_name;
>>+         if (dbname == NULL)
>>+             dbname="";
>>+         if (username == NULL)
>>+             username = "";
>>
>>
>
>Could either of these ever be NULL?
>
>
I don't know. Maybe not. This was by way of defensive programming.

>
>
>>diff -c -w -r1.87 postgresql.conf.sample
>>*** backend/utils/misc/postgresql.conf.sample    29 Jul 2003 00:03:18 -0000    1.87
>>--- backend/utils/misc/postgresql.conf.sample    9 Aug 2003 21:17:15 -0000
>>***************
>>*** 173,178 ****
>>--- 173,179 ----
>>  #log_connections = false
>>  #log_duration = false
>>  #log_pid = false
>>+ #log_line_format = '<%U~%D>'     # %U=username %D=databasename %%=%
>>
>>
>
>Shouldn't the commented-out line have the default value? (which is "", right?)
>
>

Yes, default is "". I'll move the example to the comment, if you like.

Re: logging enhancements, minor code cleanup

From

Neil Conway

Date:

11 August 2003, 05:22:53

On Sun, Aug 10, 2003 at 06:19:05PM -0400, Andrew Dunstan wrote:
> Neil Conway wrote:
> >On Sat, Aug 09, 2003 at 07:22:56PM -0400, Andrew Dunstan wrote:
> Sure. Very easy. Nobody suggested it when I floated the idea of logging
> session end on the hackers list, but it's a simple change. How does
> 'log_session_end' sound? Or else we could make log_connections have
> levels - 0 = none, 1 = start, 2 = start + end. What's the concensus?

Either one works for me.

> >This patch should also update the documentation.
>
> I'll submit a doc patch when the code is accepted.

Fine with me -- at one point, I believe there was a policy that the docs
needed to be updated before a patch was committed (to avoid people
intending to update the docs but never remembering too), but I'm not
sure how strictely we're following that.

> >Can you add an assertion that end.tv_sec >= port->session_start.tv_sec
> >before
> >this line, please?
>
> Sure. Presumably to catch the situation where the machine's time is
> changed (backwards) during the session - an event with fairly low
> probability.

No -- an assertion should test a condition that always yields true, unless
some critical assumption about the state of the world has been violated
(i.e. something has gone wrong). Your point about changing the time is
a good one, although I agree the probability of it actually occurring
is very small. It's your call: if you want to worry about that case,
add actual code (not an assertion) to handle it.

> print_timestamp() and print_pid() in the same file use static buffers
> which they return, so I just copied the style more or less, making
> allowance for the fact I don't know the reasonable size at compile time.

Fair enough -- if the other code in that area uses the same style,
that's fine. It's worth noting that if the format string changes
between calls to the function, you may end up writing off the end of
your malloc'ed buffer -- since the GUC var can be set only after a
SIGHUP, I believe this can't happen, but IMHO it speaks to the
hokiness of using static variables unless really necessary.

> >Shouldn't the commented-out line have the default value? (which is "",
> >right?)
>
> Yes, default is "". I'll move the example to the comment, if you like.

Please do.

-Neil

Re: logging enhancements, minor code cleanup

From

"Andrew Dunstan"

Date:

11 August 2003, 13:20:35

----- Original Message -----
From: "Neil Conway" <neilc@samurai.com>
> Fair enough -- if the other code in that area uses the same style,
> that's fine. It's worth noting that if the format string changes
> between calls to the function, you may end up writing off the end of
> your malloc'ed buffer -- since the GUC var can be set only after a
> SIGHUP, I believe this can't happen, but IMHO it speaks to the
> hokiness of using static variables unless really necessary.
>

Actually, the code is written to ensure it *NEVER* overflows the buffer. The
result might be truncated but never overflowed. It doesn't require a format
change - if a user has long user/dbnames and uses them more than once in the
format string that will ensure a result which but for the overflow checks
would cause overflow ('%U%D%U%D' could do it) but actually causes
truncation.

Of course, I could parse the string when setting up the buffer looking for
the number of expansions required. Instead I made the (I think reasonable)
assumption that each possible expansion would be wanted at most once.

andrew

Re: logging enhancements, minor code cleanup

From

Tom Lane

Date:

11 August 2003, 15:03:08

"Andrew Dunstan" <andrew@dunslane.net> writes:
> Of course, I could parse the string when setting up the buffer looking for
> the number of expansions required. Instead I made the (I think reasonable)
> assumption that each possible expansion would be wanted at most once.

I think that's a reasonable assumption; the question was just about
whether your code acts sanely if the assumption isn't true.

            regards, tom lane

Re: logging enhancements, minor code cleanup

From

Andrew Dunstan

Date:

11 August 2003, 15:22:14

Answer = sane == 'fill buffer, don't overfill buffer' ? 'yes' : 'no';

:-)

Seriously, I will add comments when I submit the revised patch to
demonstrate the loop invariants etc. so nobody need get worried when
reading the code.

As for session end logging, I'm leaning in favor of a new
log_session_end or log_connection_end boolean, so that there is minimal
backwards compatibility impact. (Interestingly, that is actually the
only part of this stuff that is of any use to me right now).

cheers

andrew

Tom Lane wrote:

>"Andrew Dunstan" <andrew@dunslane.net> writes:
>
>
>>Of course, I could parse the string when setting up the buffer looking for
>>the number of expansions required. Instead I made the (I think reasonable)
>>assumption that each possible expansion would be wanted at most once.
>>
>>
>
>I think that's a reasonable assumption; the question was just about
>whether your code acts sanely if the assumption isn't true.
>
>            regards, tom lane
>
>
>

Re: logging enhancements, minor code cleanup

From

Bruce Momjian

Date:

11 August 2003, 21:06:38

Andrew Dunstan wrote:
>
> Answer = sane == 'fill buffer, don't overfill buffer' ? 'yes' : 'no';
>
> :-)
>
> Seriously, I will add comments when I submit the revised patch to
> demonstrate the loop invariants etc. so nobody need get worried when
> reading the code.
>
> As for session end logging, I'm leaning in favor of a new
> log_session_end or log_connection_end boolean, so that there is minimal
> backwards compatibility impact. (Interestingly, that is actually the
> only part of this stuff that is of any use to me right now).

Agreed.  A separate boolean is more self-documenting than 0/1/2.

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

Re: logging enhancements, minor code cleanup

From

Bruce Momjian

Date:

11 August 2003, 21:11:29

Would you add remote hostname and source port so we then have all
connection parameters available for line output.

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

Andrew Dunstan wrote:
>
> The attached patch does 3 things:
>
> . logs connection ends if log_connections = true
> . provides a new option "log_line_format" which allows addition of extra
> information on a log line before the keyword. Currently supported are
> user name and database name, but it is easily extensible. The string is
> in the flavor of a printf format, where "%U" means user name, "%D" means
> database name, "%%" means "%" and anything else means itself, literally.
> . minor code cleanup for consistency in calling gettimeofday().
>
> cheers
>
> andrew

> Index: 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
> *** backend/commands/vacuum.c    4 Aug 2003 02:39:58 -0000    1.259
> --- backend/commands/vacuum.c    9 Aug 2003 21:17:11 -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: backend/postmaster/postmaster.c
> ===================================================================
> RCS file: /projects/cvsroot/pgsql-server/src/backend/postmaster/postmaster.c,v
> retrieving revision 1.340
> diff -c -w -r1.340 postmaster.c
> *** backend/postmaster/postmaster.c    4 Aug 2003 02:40:02 -0000    1.340
> --- backend/postmaster/postmaster.c    9 Aug 2003 21:17:13 -0000
> ***************
> *** 995,1004 ****
>       int            nSockets;
>       struct timeval now,
>                   later;
> -     struct timezone tz;
>       int            i;
>
> !     gettimeofday(&now, &tz);
>
>       nSockets = initMasks(&readmask);
>
> --- 995,1003 ----
>       int            nSockets;
>       struct timeval now,
>                   later;
>       int            i;
>
> !     gettimeofday(&now, NULL);
>
>       nSockets = initMasks(&readmask);
>
> ***************
> *** 1080,1086 ****
>            */
>           while (random_seed == 0)
>           {
> !             gettimeofday(&later, &tz);
>
>               /*
>                * We are not sure how much precision is in tv_usec, so we
> --- 1079,1085 ----
>            */
>           while (random_seed == 0)
>           {
> !             gettimeofday(&later, NULL);
>
>               /*
>                * We are not sure how much precision is in tv_usec, so we
> ***************
> *** 2302,2308 ****
>       int            i;
>       int            status;
>       struct timeval now;
> -     struct timezone tz;
>       char        remote_host[NI_MAXHOST];
>       char        remote_port[NI_MAXSERV];
>
> --- 2301,2306 ----
> ***************
> *** 2324,2332 ****
>       /* 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();
>
> --- 2322,2327 ----
> ***************
> *** 2398,2403 ****
> --- 2393,2405 ----
>           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).
>        */
> ***************
> *** 2438,2444 ****
>        * start a new random sequence in the random() library function.
>        */
>       random_seed = 0;
> !     gettimeofday(&now, &tz);
>       srandom((unsigned int) now.tv_usec);
>
>       /* ----------------
> --- 2440,2446 ----
>        * start a new random sequence in the random() library function.
>        */
>       random_seed = 0;
> !     gettimeofday(&now, NULL);
>       srandom((unsigned int) now.tv_usec);
>
>       /* ----------------
> ***************
> *** 2521,2526 ****
> --- 2523,2536 ----
>       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: backend/tcop/postgres.c
> ===================================================================
> RCS file: /projects/cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
> retrieving revision 1.357
> diff -c -w -r1.357 postgres.c
> *** backend/tcop/postgres.c    6 Aug 2003 17:46:45 -0000    1.357
> --- backend/tcop/postgres.c    9 Aug 2003 21:17:13 -0000
> ***************
> *** 68,73 ****
> --- 68,74 ----
>   extern int    optind;
>   extern char *optarg;
>
> + extern bool Log_connections;
>
>   /* ----------------
>    *        global variables
> ***************
> *** 150,155 ****
> --- 151,157 ----
>   static void finish_xact_command(void);
>   static void SigHupHandler(SIGNAL_ARGS);
>   static void FloatExceptionHandler(SIGNAL_ARGS);
> + static void log_session_end(void);
>
>
>   /* ----------------------------------------------------------------
> ***************
> *** 2453,2458 ****
> --- 2455,2465 ----
>               gucopts = lnext(gucopts);
>               SetConfigOption(name, value, PGC_BACKEND, PGC_S_CLIENT);
>           }
> +        /*
> +         * set up handler to log session end.
> +         */
> +         if (IsUnderPostmaster && Log_connections)
> +             on_proc_exit(log_session_end,0);
>       }
>
>       /*
> ***************
> *** 3190,3193 ****
> --- 3197,3243 ----
>                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];
> +
> +     snprintf(uname, sizeof(uname)," user=%s",port->user_name);
> +     snprintf(dbname, sizeof(dbname)," database=%s",port->database_name);
> +
> +
> +     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;
> +
> +     snprintf(session_time, sizeof(session_time),"%d:%02d:%02d.%02ld",
> +              hours, minutes, seconds,
> +              end.tv_usec/10000);
> +
> +     ereport(LOG,
> +             (errmsg("session ended: duration: %s%s%s",
> +                     session_time,uname,dbname)));
> +
>   }
> Index: 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
> *** backend/utils/adt/nabstime.c    4 Aug 2003 02:40:05 -0000    1.113
> --- backend/utils/adt/nabstime.c    9 Aug 2003 21:17:13 -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: 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
> *** backend/utils/error/elog.c    8 Aug 2003 21:42:11 -0000    1.119
> --- backend/utils/error/elog.c    9 Aug 2003 21:17:14 -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,1089 ----
>   }
>   #endif   /* HAVE_SYSLOG */
>
> + /*
> +  * Formatted extra info for log if option is set and we have a data,
> +  * or empty string otherwise.
> +  */
> + static const char *
> + log_line_extra(void)
> + {
> +     /* space for option string + 2 identifiers */
> +     /* Note: if more identifers are built in this will have to increase */
> +     static char *result = NULL;
> +     int flen = strlen(Log_line_format_str);
> +     int i,j;
> +     int tlen = 2*NAMEDATALEN + flen +3 ;
> +     if (result == NULL)
> +         result = malloc(tlen);
> +     result[0] = '\0';
> +
> +     if (flen > 0 && MyProcPort)
> +     {
> +         char * dbname = MyProcPort->database_name;
> +         char * username = MyProcPort->user_name;
> +         if (dbname == NULL)
> +             dbname="";
> +         if (username == NULL)
> +             username = "";
> +         j = 0;
> +         for (i = 0; i < flen && j < tlen-1; i++)
> +         {
> +             if(Log_line_format_str[i] != '%')
> +             {
> +                 result[j]=Log_line_format_str[i];
> +                 j++;
> +                 result[j] = '\0';
> +                 continue;
> +             }
> +             else if (i == flen - 1)
> +             {
> +                 /* format error - just skip it */
> +                 continue;
> +             }
> +             i++;
> +             switch (Log_line_format_str[i])
> +             {
> +                 case 'U':
> +                     j += snprintf(result+j,tlen-j,"%s",username);
> +                     break;
> +                 case 'D':
> +                     j += snprintf(result+j,tlen-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)
>       {
> --- 1093,1105 ----
>   {
>       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);
>           }
>       }
> --- 1131,1157 ----
>       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);
>
>
> --- 1163,1170 ----
>        * improve?
>        */
>       if (edata->elevel >= log_min_error_statement && debug_query_string != NULL)
> !         appendStringInfo(&buf, gettext("%sSTATEMENT:  %s\n"),
> !                          extra_info,
>                            debug_query_string);
>
>
> Index: backend/utils/misc/guc.c
> ===================================================================
> RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
> retrieving revision 1.148
> diff -c -w -r1.148 guc.c
> *** backend/utils/misc/guc.c    4 Aug 2003 23:59:39 -0000    1.148
> --- backend/utils/misc/guc.c    9 Aug 2003 21:17:15 -0000
> ***************
> *** 1334,1339 ****
> --- 1334,1348 ----
>           },
>           &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: 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
> *** backend/utils/misc/postgresql.conf.sample    29 Jul 2003 00:03:18 -0000    1.87
> --- backend/utils/misc/postgresql.conf.sample    9 Aug 2003 21:17:15 -0000
> ***************
> *** 173,178 ****
> --- 173,179 ----
>   #log_connections = false
>   #log_duration = false
>   #log_pid = false
> + #log_line_format = '<%U~%D>'     # %U=username %D=databasename %%=%
>   #log_statement = false
>   #log_timestamp = false
>   #log_hostname = false
> Index: 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
> *** include/libpq/libpq-be.h    4 Aug 2003 02:40:13 -0000    1.37
> --- include/libpq/libpq-be.h    9 Aug 2003 21:17:15 -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: 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
> *** include/utils/elog.h    8 Aug 2003 21:42:55 -0000    1.63
> --- include/utils/elog.h    9 Aug 2003 21:17:15 -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 1: subscribe and unsubscribe commands go to majordomo@postgresql.org

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

Re: logging enhancements, minor code cleanup

From

Andrew Dunstan

Date:

11 August 2003, 21:19:12

Good catch - I meant to do that.

cheers

andrew

Bruce Momjian wrote:

>Would you add remote hostname and source port so we then have all
>connection parameters available for line output.
>
>
>

logging enhancements, minor code cleanup (retry)

From

Andrew Dunstan

Date:

13 August 2003, 21:08:00

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;

Re: logging enhancements, minor code cleanup (retry)

From

Bruce Momjian

Date:

17 August 2003, 06:14:01

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