logging enhancements, minor code cleanup - Mailing list pgsql-patches

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;