log_line_info - Mailing list pgsql-patches

From Andrew Dunstan
Subject log_line_info
Date
Msg-id 40422AE9.7030009@dunslane.net
Whole thread Raw
Responses Re: log_line_info  (Jon Jensen <jon@endpoint.com>)
Re: log_line_info  (Bruce Momjian <pgman@candle.pha.pa.us>)
Re: log_line_info  (Bruce Momjian <pgman@candle.pha.pa.us>)
List pgsql-patches
I think this is now ready for application, unless someone objects.

Since the last patch I posted, I have done the following:

. changed the escapes to lower case, as Peter prefers. This is also in
line with what Apache does, which is the nearest equivalent I can think of.
. added 2 new escapes: %r = remote host and port and %x says "postmaster
and friends stop here".  Postmaster and friends will also ignore any
escapes they see that don't make sense (specifically %u %d %i %r %s and
%c). However, they no longer ignore the whole facility. This means we
can use it for logging (for example) timestamps and pids in all cases.
. added docco
. changed source port reporting from host:port to host(port) to avoid
IP6 address ambiguity.

If someone wants to monkey with the name of the facility, it shouldn't
be hard. I don't like plain "log_line", though. "log_line_prefix" or
"log_line_tag" both seem to me better alternatives.

After this is applied (fingers crossed) and everyone is happy, I will
submit a patch to remove log_timestamp, log_pid and (if we are agreed on
it) log_source_port.

cheers

andrew

Index: doc/src/sgml/runtime.sgml
===================================================================
RCS file: /projects/cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v
retrieving revision 1.242
diff -c -r1.242 runtime.sgml
*** doc/src/sgml/runtime.sgml    23 Feb 2004 20:45:58 -0000    1.242
--- doc/src/sgml/runtime.sgml    29 Feb 2004 17:49:04 -0000
***************
*** 1966,1971 ****
--- 1966,2063 ----
       </varlistentry>

       <varlistentry>
+       <term><varname>log_line_info</varname> (<type>string</type>)</term>
+       <listitem>
+        <para>
+      This is a <literal>printf</> type string that is output before the
+      beginning of each log line. The default is an empty string.
+      Any recognised escape is replaced as set
+      out below - anything else that looks like an escape is ignored. Other
+      characters are copied straight to the log line. Some escapes are
+      only recognised by session processes, and do not apply to other
+      processes not controlling sessions. Syslog produces its own
+      timestamp and process ID information, so you probably do not want to
+      use those escapes if you are using Syslog.
+      <informaltable>
+       <tgroup cols="3">
+        <thead>
+         <row>
+          <entry>Escape</entry>
+          <entry>Effect</entry>
+          <entry>Session only</entry>
+          </row>
+         </thead>
+        <tbody>
+         <row>
+          <entry><literal>%t</literal></entry>
+          <entry>Timestamp</entry>
+          <entry>No</entry>
+         </row>
+         <row>
+          <entry><literal>%p</literal></entry>
+          <entry>Process ID</entry>
+          <entry>No</entry>
+         </row>
+         <row>
+          <entry><literal>%%</literal></entry>
+          <entry>literal <literal>%</></entry>
+          <entry>No</entry>
+         </row>
+         <row>
+          <entry><literal>%l</literal></entry>
+          <entry>Number of the log line for each process,
+           starting at 1</entry>
+          <entry>No</entry>
+         </row>
+         <row>
+          <entry><literal>%x</literal></entry>
+          <entry>Does not produce any output, but tells non-session
+          processes to stop at this point in the string. Ignored by
+          session backends.</entry>
+          <entry>No</entry>
+         </row>
+         <row>
+          <entry><literal>%u</literal></entry>
+          <entry>User Name</entry>
+          <entry>Yes</entry>
+         </row>
+         <row>
+          <entry><literal>%d</literal></entry>
+          <entry>Database Name</entry>
+          <entry>Yes</entry>
+         </row>
+         <row>
+          <entry><literal>%s</literal></entry>
+          <entry>Session Start Timestamp</entry>
+          <entry>Yes</entry>
+         </row>
+         <row>
+          <entry><literal>%c</literal></entry>
+          <entry>Session Cookie. A unique identifier for each session.
+          It is just 2 hexadecimal numbers separated by a dot. The numbers
+          are the Session Start Time and the Process ID, so this can also
+          be used as a space saving way of printing these items.</entry>
+          <entry>Yes</entry>
+         </row>
+         <row>
+          <entry><literal>%i</literal></entry>
+          <entry>Command Tag. This is the context in which the log
+           line was generated.</entry>
+          <entry>Yes</entry>
+         </row>
+         <row>
+          <entry><literal>%r</literal></entry>
+          <entry>Remote Hostname or IP address, and Remote Port</entry>
+          <entry>Yes</entry>
+         </row>
+        </tbody>
+       </tgroup>
+      </informaltable>
+        </para>
+       </listitem>
+      </varlistentry>
+
+      <varlistentry>
        <term><varname>log_pid</varname> (<type>boolean</type>)</term>
        <listitem>
         <para>
Index: src/backend/postmaster/postmaster.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/postmaster/postmaster.c,v
retrieving revision 1.369
diff -c -r1.369 postmaster.c
*** src/backend/postmaster/postmaster.c    25 Feb 2004 19:41:22 -0000    1.369
--- src/backend/postmaster/postmaster.c    29 Feb 2004 17:49:05 -0000
***************
*** 2437,2442 ****
--- 2437,2443 ----
      /* set these to empty in case they are needed before we set them up */
      port->remote_host = "";
      port->remote_port = "";
+     port->commandTag = "";

      /* Save port etc. for ps status */
      MyProcPort = port;
***************
*** 2489,2495 ****
          /* modify remote_host for use in ps status */
          char        tmphost[NI_MAXHOST];

!         snprintf(tmphost, sizeof(tmphost), "%s:%s", remote_host, remote_port);
          StrNCpy(remote_host, tmphost, sizeof(remote_host));
      }

--- 2490,2496 ----
          /* modify remote_host for use in ps status */
          char        tmphost[NI_MAXHOST];

!         snprintf(tmphost, sizeof(tmphost), "%s(%s)", remote_host, remote_port);
          StrNCpy(remote_host, tmphost, sizeof(remote_host));
      }

Index: src/backend/utils/error/elog.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/error/elog.c,v
retrieving revision 1.126
diff -c -r1.126 elog.c
*** src/backend/utils/error/elog.c    29 Nov 2003 19:52:01 -0000    1.126
--- src/backend/utils/error/elog.c    29 Feb 2004 17:49:05 -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_info = ""; /* format for extra log line info */

  #ifdef HAVE_SYSLOG
  /*
***************
*** 146,152 ****
  static const char *print_timestamp(void);
  static const char *print_pid(void);
  static void append_with_tabs(StringInfo buf, const char *str);
!

  /*
   * errstart --- begin an error-reporting cycle
--- 147,153 ----
  static const char *print_timestamp(void);
  static const char *print_pid(void);
  static void append_with_tabs(StringInfo buf, const char *str);
! static const char *log_line_info(void);

  /*
   * errstart --- begin an error-reporting cycle
***************
*** 1022,1027 ****
--- 1023,1160 ----
  }
  #endif   /* HAVE_SYSLOG */

+ /*
+  * Format tag info for log lines
+  */
+ static const char *
+ log_line_info(void)
+ {
+
+     /* static accumulator for line numbers */
+     static int log_line_number = 0;
+
+     /* space for option string + one of each option, plus some room to spare */
+     /* Note: if more identifiers are built in this will have to increase */
+     static char *result = NULL;
+     int format_len = strlen(Log_line_info);
+     int result_len = 2*NAMEDATALEN + format_len +120 ;
+
+     if (result == NULL)
+         result = malloc(result_len);
+     result[0] = '\0';
+
+     if (format_len > 0)
+     {
+         int i,j;
+         char * dbname = NULL;
+         char * username = NULL;
+         time_t stamp_time;
+         log_line_number++;
+         if (MyProcPort != NULL)
+         {
+             dbname  = MyProcPort->database_name;
+             username = MyProcPort->user_name;
+             if (dbname == NULL || *dbname == '\0')
+                 dbname = gettext("[unknown]");
+             if (username == NULL || *username == '\0')
+                 username = gettext("[unknown]");
+         }
+
+         /*
+          * 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_info[i] != '%')
+             {
+                 /* literal char, just copy */
+                 result[j]=Log_line_info[i];
+                 j++;
+                 result[j] = '\0';
+                 continue;
+             }
+             else if (i == format_len - 1)
+             {
+                 /* format error - skip it */
+                 continue;
+             }
+
+             /* go to char after '%' */
+             i++;
+
+             /* in postmaster and friends, skip non-applicable options,
+              * stop if %x is seen
+              */
+             if (MyProcPort == NULL)
+             {
+                 if (Log_line_info[i] == 'x')
+                     break;
+                 if (strchr("udcsir",Log_line_info[i]) != NULL)
+                     continue;
+             }
+
+             /* process the option */
+             switch (Log_line_info[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 'c':
+                     j += snprintf(result+j,result_len-j,"%lx.%lx",
+                                   (long)(MyProcPort->session_start.tv_sec),
+                                   (long)MyProcPid);
+                     break;
+                 case 'p':
+                     j += snprintf(result+j,result_len-j,"%ld",(long)MyProcPid);
+                     break;
+                 case 'l':
+                     j += snprintf(result+j,result_len-j,"%d",log_line_number);
+                     break;
+                 case 't':
+                     stamp_time = time(NULL);
+                     j += strftime(result+j, result_len-j, "%Y-%m-%d %H:%M:%S",
+                              localtime(&stamp_time));
+                     break;
+                 case 's':
+                     j += strftime(result+j, result_len-j, "%Y-%m-%d %H:%M:%S",
+                              localtime(&(MyProcPort->session_start.tv_sec)));
+                     break;
+                 case 'i':
+                     j += snprintf(result+j,result_len-j,"%s",
+                                   MyProcPort->commandTag);
+                     break;
+                 case 'r':
+                     j += snprintf(result+j,result_len-j,"%s",
+                                   MyProcPort->remote_host);
+                     if (!LogSourcePort && strlen(MyProcPort->remote_port))
+                         j += snprintf(result+j,result_len-j,"(%s)",
+                                       MyProcPort->remote_port);
+                     break;
+                 case 'x':
+                     /* non-postmaster case - just ignore */
+                     break;
+                 case '%':
+                     result[j] = '%';
+                     j++;
+                     result[j] = '\0';
+                     break;
+                 default:
+                     /* format error - skip it */
+                     break;
+             }
+         }
+     }
+     return result;
+ }
+

  /*
   * Write error report to server's log
***************
*** 1033,1039 ****

      initStringInfo(&buf);

!     appendStringInfo(&buf, "%s:  ", error_severity(edata->elevel));

      if (Log_error_verbosity >= PGERROR_VERBOSE)
      {
--- 1166,1173 ----

      initStringInfo(&buf);

!     appendStringInfo(&buf, "%s%s:  ",
!                      log_line_info(), error_severity(edata->elevel));

      if (Log_error_verbosity >= PGERROR_VERBOSE)
      {
***************
*** 1066,1083 ****
--- 1200,1220 ----
      {
          if (edata->detail)
          {
+             appendStringInfoString(&buf, log_line_info() );
              appendStringInfoString(&buf, gettext("DETAIL:  "));
              append_with_tabs(&buf, edata->detail);
              appendStringInfoChar(&buf, '\n');
          }
          if (edata->hint)
          {
+             appendStringInfoString(&buf, log_line_info() );
              appendStringInfoString(&buf, gettext("HINT:  "));
              append_with_tabs(&buf, edata->hint);
              appendStringInfoChar(&buf, '\n');
          }
          if (edata->context)
          {
+             appendStringInfoString(&buf, log_line_info() );
              appendStringInfoString(&buf, gettext("CONTEXT:  "));
              append_with_tabs(&buf, edata->context);
              appendStringInfoChar(&buf, '\n');
***************
*** 1086,1096 ****
          {
              /* assume no newlines in funcname or filename... */
              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);
          }
      }
--- 1223,1235 ----
          {
              /* assume no newlines in funcname or filename... */
              if (edata->funcname && edata->filename)
!                 appendStringInfo(&buf, gettext("%sLOCATION:  %s, %s:%d\n"),
!                                  log_line_info(),
                                   edata->funcname, edata->filename,
                                   edata->lineno);
              else if (edata->filename)
!                 appendStringInfo(&buf, gettext("%sLOCATION:  %s:%d\n"),
!                                  log_line_info(),
                                   edata->filename, edata->lineno);
          }
      }
***************
*** 1100,1105 ****
--- 1239,1245 ----
       */
      if (edata->elevel >= log_min_error_statement && debug_query_string != NULL)
      {
+         appendStringInfoString(&buf, log_line_info() );
          appendStringInfoString(&buf, gettext("STATEMENT:  "));
          append_with_tabs(&buf, debug_query_string);
          appendStringInfoChar(&buf, '\n');
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.188
diff -c -r1.188 guc.c
*** src/backend/utils/misc/guc.c    23 Feb 2004 20:45:59 -0000    1.188
--- src/backend/utils/misc/guc.c    29 Feb 2004 17:49:06 -0000
***************
*** 1496,1501 ****
--- 1496,1511 ----
      },

      {
+         {"log_line_info", PGC_SIGHUP, LOGGING_WHAT,
+          gettext_noop("Controls extra information on each log line"),
+          gettext_noop("if blank no extra info is logged")
+         },
+         &Log_line_info,
+         "", NULL, NULL
+     },
+
+
+     {
          {"DateStyle", PGC_USERSET, CLIENT_CONN_LOCALE,
              gettext_noop("Sets the display format for date and time values."),
              gettext_noop("Also controls interpretation of ambiguous "
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.106
diff -c -r1.106 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample    17 Feb 2004 03:54:57 -0000    1.106
--- src/backend/utils/misc/postgresql.conf.sample    29 Feb 2004 17:49:06 -0000
***************
*** 185,190 ****
--- 185,196 ----
  #log_disconnections = false
  #log_duration = false
  #log_pid = false
+ #log_line_info = ''         # e.g. '<%u%%%d> '
+                             #  %u=username %d=databasename %c=sessionid
+                         #  %p=PID %t=timestamp %l=session line number
+                             #  %s=session start timestamp %i=command tag
+                             #  %%='%' %r=remote host and port
+                         #  %x=stop here in non-session processes
  #log_statement = false
  #log_timestamp = false
  #log_hostname = false
Index: src/backend/utils/misc/ps_status.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/misc/ps_status.c,v
retrieving revision 1.17
diff -c -r1.17 ps_status.c
*** src/backend/utils/misc/ps_status.c    22 Feb 2004 21:26:55 -0000    1.17
--- src/backend/utils/misc/ps_status.c    29 Feb 2004 17:49:06 -0000
***************
*** 276,285 ****
  void
  set_ps_display(const char *activity)
  {
! #ifndef PS_USE_NONE
      /* no ps display for stand-alone backend */
      if (!IsUnderPostmaster)
          return;

  #ifdef PS_USE_CLOBBER_ARGV
      /* If ps_buffer is a pointer, it might still be null */
--- 276,291 ----
  void
  set_ps_display(const char *activity)
  {
!
      /* no ps display for stand-alone backend */
      if (!IsUnderPostmaster)
          return;
+
+     /* save it for logging context */
+     if (MyProcPort)
+       MyProcPort->commandTag = (char *) activity;
+
+ #ifndef PS_USE_NONE

  #ifdef PS_USE_CLOBBER_ARGV
      /* If ps_buffer is a pointer, it might still be null */
Index: src/include/miscadmin.h
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/include/miscadmin.h,v
retrieving revision 1.153
diff -c -r1.153 miscadmin.h
*** src/include/miscadmin.h    10 Feb 2004 03:42:45 -0000    1.153
--- src/include/miscadmin.h    29 Feb 2004 17:49:07 -0000
***************
*** 24,29 ****
--- 24,31 ----
  #define MISCADMIN_H


+ #include "libpq/libpq-be.h"
+
  /*****************************************************************************
   *      System interrupt and critical section handling
   *
Index: src/include/libpq/libpq-be.h
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/include/libpq/libpq-be.h,v
retrieving revision 1.41
diff -c -r1.41 libpq-be.h
*** src/include/libpq/libpq-be.h    21 Feb 2004 06:29:58 -0000    1.41
--- src/include/libpq/libpq-be.h    29 Feb 2004 17:49:07 -0000
***************
*** 50,55 ****
--- 50,56 ----
      SockAddr    raddr;            /* remote addr (client) */
      char        *remote_host;   /* name (or ip addr) of remote host */
      char        *remote_port;   /* text rep of remote port */
+     char        *commandTag;    /* command tag for display in log lines */
      struct timeval  session_start;  /* for session duration logging */
      CAC_state    canAcceptConnections;    /* postmaster connection status */

Index: src/include/utils/elog.h
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/include/utils/elog.h,v
retrieving revision 1.64
diff -c -r1.64 elog.h
*** src/include/utils/elog.h    29 Nov 2003 22:41:15 -0000    1.64
--- src/include/utils/elog.h    29 Feb 2004 17:49:07 -0000
***************
*** 171,176 ****
--- 171,177 ----
  extern PGErrorVerbosity Log_error_verbosity;
  extern bool Log_timestamp;
  extern bool Log_pid;
+ extern char *Log_line_info;

  #ifdef HAVE_SYSLOG
  extern int    Use_syslog;

pgsql-patches by date:

Previous
From: Neil Conway
Date:
Subject: Re: enable jade warnings
Next
From: Fabien COELHO
Date:
Subject: "ALSO" keyword to "CREATE RULE" patch