Re: WIP CSV logs - Mailing list pgsql-patches

From Andrew Dunstan
Subject Re: WIP CSV logs
Date
Msg-id 46851BF8.6020005@dunslane.net
Whole thread Raw
In response to Re: WIP CSV logs  (Andrew Dunstan <andrew@dunslane.net>)
Responses Re: WIP CSV logs
List pgsql-patches

Andrew Dunstan wrote:
>
>
> Andrew Dunstan wrote:
>>
>> Here is a WIP patch of the CSV logs work brought up to date with CVS
>> HEAD.  One large change I made was to multiplex the selects on the
>> pipes - previously it waited on one then the other - this seems
>> almost to defeat the purpose of using select() :-)
>>
>> It seems to work well on Unix - I will test later on Windows, which
>> I'm slightly worried about.
>>
>> I also want to get an id for non-session processes. I think this can
>> just be start-time+pid, just like for session processes, but we'll
>> need to stash it somewhere (just for those cases). If we do that we
>> will be able to set a primary key on the log table when we read the
>> data in, which Greg Smith was worried about.
>>
>> I hope to get this polished off in the next 15 hours or so - after
>> that I'm away for 12 days.
>>
>>
>
> Here is a slightly updated version. It compiles on Windows, but it
> doesn't work - the CSV log file gets created but doesn't get any
> content. Dave, Magnus - can you see what I've done wrong? The strange
> thing is that I tried to do exactly the same thing for CSV as for
> stderr, and the stderr file gets content just fine.
>
>

Further update attached. Includes some code cleanup, and now sets up a
session-id for all processes, including postmaster, syslogger etc, so we
can make a primary key on the log table of (session_id, line_number).

TODOs: fix on Windows, docs.

cheers

andrew
Index: src/backend/postmaster/autovacuum.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/autovacuum.c,v
retrieving revision 1.51
diff -c -r1.51 autovacuum.c
*** src/backend/postmaster/autovacuum.c    25 Jun 2007 16:09:03 -0000    1.51
--- src/backend/postmaster/autovacuum.c    29 Jun 2007 14:33:40 -0000
***************
*** 386,391 ****
--- 386,393 ----
      /* reset MyProcPid */
      MyProcPid = getpid();

+     MyStartTime = time(NULL);       /* get start time for logger session id */
+
      /* Identify myself via ps */
      init_ps_display("autovacuum launcher process", "", "", "");

***************
*** 1399,1404 ****
--- 1401,1408 ----
      /* reset MyProcPid */
      MyProcPid = getpid();

+     MyStartTime = time(NULL);       /* get start time for logger session id */
+
      /* Identify myself via ps */
      init_ps_display("autovacuum worker process", "", "", "");

Index: src/backend/postmaster/pgarch.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/pgarch.c,v
retrieving revision 1.29
diff -c -r1.29 pgarch.c
*** src/backend/postmaster/pgarch.c    10 Feb 2007 14:58:54 -0000    1.29
--- src/backend/postmaster/pgarch.c    29 Jun 2007 14:33:40 -0000
***************
*** 223,228 ****
--- 223,230 ----

      MyProcPid = getpid();        /* reset MyProcPid */

+     MyStartTime = time(NULL);       /* get start time for logger session id */
+
      /*
       * If possible, make this process a group leader, so that the postmaster
       * can signal any child processes too.
Index: src/backend/postmaster/pgstat.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/pgstat.c,v
retrieving revision 1.160
diff -c -r1.160 pgstat.c
*** src/backend/postmaster/pgstat.c    28 Jun 2007 00:02:38 -0000    1.160
--- src/backend/postmaster/pgstat.c    29 Jun 2007 14:33:42 -0000
***************
*** 2163,2168 ****
--- 2163,2170 ----

      MyProcPid = getpid();        /* reset MyProcPid */

+     MyStartTime = time(NULL);       /* get start time for logger session id */
+
      /*
       * If possible, make this process a group leader, so that the postmaster
       * can signal any child processes too.  (pgstat probably never has
Index: src/backend/postmaster/postmaster.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/postmaster.c,v
retrieving revision 1.528
diff -c -r1.528 postmaster.c
*** src/backend/postmaster/postmaster.c    25 Jun 2007 16:09:03 -0000    1.528
--- src/backend/postmaster/postmaster.c    29 Jun 2007 14:33:44 -0000
***************
*** 336,343 ****
--- 336,345 ----
      HANDLE        PostmasterHandle;
      HANDLE        initial_signal_pipe;
      HANDLE        syslogPipe[2];
+     HANDLE        csvlogPipe[2];
  #else
      int            syslogPipe[2];
+     int            csvlogPipe[2];
  #endif
      char        my_exec_path[MAXPGPATH];
      char        pkglib_path[MAXPGPATH];
***************
*** 381,386 ****
--- 383,390 ----

      MyProcPid = PostmasterPid = getpid();

+     MyStartTime = time(NULL);       /* get start time for logger session id */
+
      IsPostmasterEnvironment = true;

      /*
***************
*** 1225,1231 ****
          }

          /* If we have lost the system logger, try to start a new one */
!         if (SysLoggerPID == 0 && Redirect_stderr)
              SysLoggerPID = SysLogger_Start();

          /*
--- 1229,1236 ----
          }

          /* If we have lost the system logger, try to start a new one */
!         if ( SysLoggerPID == 0 &&
!              (Redirect_stderr || (Log_destination & LOG_DESTINATION_CSVLOG) ) )
              SysLoggerPID = SysLogger_Start();

          /*
***************
*** 1775,1784 ****
--- 1780,1797 ----
          if (syslogPipe[0] >= 0)
              close(syslogPipe[0]);
          syslogPipe[0] = -1;
+
+         if (csvlogPipe[0] >= 0)
+             close(csvlogPipe[0]);
+         csvlogPipe[0] = -1;
  #else
          if (syslogPipe[0])
              CloseHandle(syslogPipe[0]);
          syslogPipe[0] = 0;
+
+         if (csvlogPipe[0])
+             CloseHandle(csvlogPipe[0]);
+         csvlogPipe[0] = 0;
  #endif
      }
  }
***************
*** 3960,3965 ****
--- 3973,3979 ----
  #endif

      memcpy(¶m->syslogPipe, &syslogPipe, sizeof(syslogPipe));
+     memcpy(¶m->csvlogPipe, &csvlogPipe, sizeof(csvlogPipe));

      strlcpy(param->my_exec_path, my_exec_path, MAXPGPATH);

***************
*** 4161,4166 ****
--- 4175,4181 ----
  #endif

      memcpy(&syslogPipe, ¶m->syslogPipe, sizeof(syslogPipe));
+     memcpy(&csvlogPipe, ¶m->csvlogPipe, sizeof(csvlogPipe));

      strlcpy(my_exec_path, param->my_exec_path, MAXPGPATH);

Index: src/backend/postmaster/syslogger.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/syslogger.c,v
retrieving revision 1.32
diff -c -r1.32 syslogger.c
*** src/backend/postmaster/syslogger.c    14 Jun 2007 01:48:51 -0000    1.32
--- src/backend/postmaster/syslogger.c    29 Jun 2007 14:33:45 -0000
***************
*** 85,91 ****
  static pg_time_t next_rotation_time;
  static bool redirection_done = false;
  static bool pipe_eof_seen = false;
! static FILE *syslogFile = NULL;
  static char *last_file_name = NULL;

  /*
--- 85,91 ----
  static pg_time_t next_rotation_time;
  static bool redirection_done = false;
  static bool pipe_eof_seen = false;
! static FILE *syslogFile = NULL, *csvlogFile = NULL;
  static char *last_file_name = NULL;

  /*
***************
*** 103,120 ****
  } save_buffer;

  #define CHUNK_SLOTS 20
! static save_buffer saved_chunks[CHUNK_SLOTS];

  /* These must be exported for EXEC_BACKEND case ... annoying */
  #ifndef WIN32
  int            syslogPipe[2] = {-1, -1};
  #else
  HANDLE        syslogPipe[2] = {0, 0};
  #endif

  #ifdef WIN32
! static HANDLE threadHandle = 0;
! static CRITICAL_SECTION sysfileSection;
  #endif

  /*
--- 103,123 ----
  } save_buffer;

  #define CHUNK_SLOTS 20
! static save_buffer stderr_saved_chunks[CHUNK_SLOTS];
! static save_buffer csvlog_saved_chunks[CHUNK_SLOTS];

  /* These must be exported for EXEC_BACKEND case ... annoying */
  #ifndef WIN32
  int            syslogPipe[2] = {-1, -1};
+ int            csvlogPipe[2] = {-1, -1};
  #else
  HANDLE        syslogPipe[2] = {0, 0};
+ HANDLE        csvlogPipe[2] = {0, 0};
  #endif

  #ifdef WIN32
! static HANDLE stderrThreadHandle = 0, csvThreadHandle = 0;
! static CRITICAL_SECTION sysfileSection, csvfileSection;
  #endif

  /*
***************
*** 129,142 ****
  static pid_t syslogger_forkexec(void);
  static void syslogger_parseArgs(int argc, char *argv[]);
  #endif
! static void process_pipe_input(char *logbuffer, int *bytes_in_logbuffer);
! static void flush_pipe_input(char *logbuffer, int *bytes_in_logbuffer);

  #ifdef WIN32
  static unsigned int __stdcall pipeThread(void *arg);
  #endif
  static void logfile_rotate(bool time_based_rotation);
! static char *logfile_getname(pg_time_t timestamp);
  static void set_next_rotation_time(void);
  static void sigHupHandler(SIGNAL_ARGS);
  static void sigUsr1Handler(SIGNAL_ARGS);
--- 132,149 ----
  static pid_t syslogger_forkexec(void);
  static void syslogger_parseArgs(int argc, char *argv[]);
  #endif
! static void process_pipe_input(char *logbuffer, int *bytes_in_logbuffer,
!                                int log_type);
! static void flush_pipe_input(char *logbuffer, int *bytes_in_logbuffer,
!                              int log_type);

  #ifdef WIN32
  static unsigned int __stdcall pipeThread(void *arg);
  #endif
  static void logfile_rotate(bool time_based_rotation);
! static char *logfile_getname(pg_time_t timestamp, int log_type);
! static void logfile_rotate_worker(bool overwrite_logfile, int log_type,
!                                   char* filename, FILE **dest_file);
  static void set_next_rotation_time(void);
  static void sigHupHandler(SIGNAL_ARGS);
  static void sigUsr1Handler(SIGNAL_ARGS);
***************
*** 150,157 ****
  SysLoggerMain(int argc, char *argv[])
  {
  #ifndef WIN32
!     char        logbuffer[READ_BUF_SIZE];
!     int            bytes_in_logbuffer = 0;
  #endif
      char       *currentLogDir;
      char       *currentLogFilename;
--- 157,166 ----
  SysLoggerMain(int argc, char *argv[])
  {
  #ifndef WIN32
!     char        stderr_logbuffer[READ_BUF_SIZE], csv_logbuffer[READ_BUF_SIZE];
!     int            bytes_in_stderr_logbuffer = 0, bytes_in_csv_logbuffer = 0;
!     int         maxfd = 0;
!
  #endif
      char       *currentLogDir;
      char       *currentLogFilename;
***************
*** 161,166 ****
--- 170,177 ----

      MyProcPid = getpid();        /* reset MyProcPid */

+     MyStartTime = time(NULL);       /* get start time for logger session id */
+
  #ifdef EXEC_BACKEND
      syslogger_parseArgs(argc, argv);
  #endif   /* EXEC_BACKEND */
***************
*** 176,182 ****
       * assumes that all interesting messages generated in the syslogger will
       * come through elog.c and will be sent to write_syslogger_file.
       */
!     if (redirection_done)
      {
          int            fd = open(NULL_DEV, O_WRONLY, 0);

--- 187,193 ----
       * assumes that all interesting messages generated in the syslogger will
       * come through elog.c and will be sent to write_syslogger_file.
       */
!     if (Redirect_stderr && redirection_done)
      {
          int            fd = open(NULL_DEV, O_WRONLY, 0);

***************
*** 202,211 ****
--- 213,239 ----
      if (syslogPipe[1] >= 0)
          close(syslogPipe[1]);
      syslogPipe[1] = -1;
+
+     if (csvlogPipe[1] >= 0)
+         close(csvlogPipe[1]);
+     csvlogPipe[1] = -1;
+
+     /* also set the max fd number for non-windows select use */
+     if (Redirect_stderr)
+         maxfd = syslogPipe[0];
+
+     if ((Log_destination & LOG_DESTINATION_CSVLOG) &&
+         (maxfd < csvlogPipe[0]))
+         maxfd = csvlogPipe[0];
+
  #else
      if (syslogPipe[1])
          CloseHandle(syslogPipe[1]);
      syslogPipe[1] = 0;
+
+     if (csvlogPipe[1])
+         CloseHandle(csvlogPipe[1]);
+     csvlogPipe[1] = 0;
  #endif

      /*
***************
*** 248,260 ****
      PG_SETMASK(&UnBlockSig);

  #ifdef WIN32
!     /* Fire up separate data transfer thread */
!     InitializeCriticalSection(&sysfileSection);

      {
          unsigned int tid;

!         threadHandle = (HANDLE) _beginthreadex(0, 0, pipeThread, 0, 0, &tid);
      }
  #endif   /* WIN32 */

--- 276,301 ----
      PG_SETMASK(&UnBlockSig);

  #ifdef WIN32
!     /* Fire up separate data transfer thread for syslog*/
!     if (Redirect_stderr)
!     {
!         unsigned int tid;
!         int logtype = STDERR_LOGFILE;

+         InitializeCriticalSection(&sysfileSection);
+         stderrThreadHandle = (HANDLE) _beginthreadex(0, 0, pipeThread,
+                                 &logtype, 0, &tid);
+     }
+
+     /* Fire up separate data transfer thread for csvlog*/
+     if (Log_destination & LOG_DESTINATION_CSVLOG)
      {
          unsigned int tid;
+         int logtype = CSV_LOGFILE;

!         InitializeCriticalSection(&csvfileSection);
!         csvThreadHandle = (HANDLE) _beginthreadex(0, 0, pipeThread,
!                                 &logtype, 0, &tid);
      }
  #endif   /* WIN32 */

***************
*** 275,280 ****
--- 316,322 ----
          int            rc;
          fd_set        rfds;
          struct timeval timeout;
+
  #endif

          if (got_SIGHUP)
***************
*** 336,346 ****
           * Wait for some data, timing out after 1 second
           */
          FD_ZERO(&rfds);
!         FD_SET(syslogPipe[0], &rfds);
          timeout.tv_sec = 1;
          timeout.tv_usec = 0;

!         rc = select(syslogPipe[0] + 1, &rfds, NULL, NULL, &timeout);

          if (rc < 0)
          {
--- 378,391 ----
           * Wait for some data, timing out after 1 second
           */
          FD_ZERO(&rfds);
!         if (Redirect_stderr)
!             FD_SET(syslogPipe[0], &rfds);
!         if (Log_destination & LOG_DESTINATION_CSVLOG)
!             FD_SET(csvlogPipe[0], &rfds);
          timeout.tv_sec = 1;
          timeout.tv_usec = 0;

!         rc = select(maxfd + 1, &rfds, NULL, NULL, &timeout);

          if (rc < 0)
          {
***************
*** 349,384 ****
                          (errcode_for_socket_access(),
                           errmsg("select() failed in logger process: %m")));
          }
!         else if (rc > 0 && FD_ISSET(syslogPipe[0], &rfds))
          {
!             bytesRead = piperead(syslogPipe[0],
!                                  logbuffer + bytes_in_logbuffer,
!                                  sizeof(logbuffer) - bytes_in_logbuffer);
!             if (bytesRead < 0)
              {
!                 if (errno != EINTR)
!                     ereport(LOG,
!                             (errcode_for_socket_access(),
!                              errmsg("could not read from logger pipe: %m")));
!             }
!             else if (bytesRead > 0)
!             {
!                 bytes_in_logbuffer += bytesRead;
!                 process_pipe_input(logbuffer, &bytes_in_logbuffer);
!                 continue;
              }
!             else
              {
!                 /*
!                  * Zero bytes read when select() is saying read-ready means
!                  * EOF on the pipe: that is, there are no longer any processes
!                  * with the pipe write end open.  Therefore, the postmaster
!                  * and all backends are shut down, and we are done.
!                  */
!                 pipe_eof_seen = true;

!                 /* if there's any data left then force it out now */
!                 flush_pipe_input(logbuffer, &bytes_in_logbuffer);
              }
          }
  #else                            /* WIN32 */
--- 394,460 ----
                          (errcode_for_socket_access(),
                           errmsg("select() failed in logger process: %m")));
          }
!         else if (rc > 0)
          {
!             if (Redirect_stderr && FD_ISSET(syslogPipe[0], &rfds))
              {
!                 bytesRead = piperead(syslogPipe[0],
!                              stderr_logbuffer + bytes_in_stderr_logbuffer,
!                              sizeof(stderr_logbuffer) - bytes_in_stderr_logbuffer);
!                 if (bytesRead < 0)
!                 {
!                 if (errno != EINTR)
!                     ereport(LOG,
!                             (errcode_for_socket_access(),
!                              errmsg("could not read from stderr logger pipe: %m")));
!                 }
!                 else if (bytesRead > 0)
!                 {
!                     bytes_in_stderr_logbuffer += bytesRead;
!                     process_pipe_input(stderr_logbuffer,
!                                        &bytes_in_stderr_logbuffer,
!                                        STDERR_LOGFILE);
!                     continue;
!                 }
!                 else
!                 {
!                     /*
!                      * Zero bytes read when select() is saying read-ready means
!                      * EOF on the pipe: that is, there are no longer any processes
!                      * with the pipe write end open.  Therefore, the postmaster
!                      * and all backends are shut down, and we are done.
!                      */
!                     pipe_eof_seen = true;
!
!                 }
              }
!
!             if ((Log_destination & LOG_DESTINATION_CSVLOG) &&
!                 FD_ISSET(csvlogPipe[0], &rfds))
              {
!                 bytesRead = piperead(csvlogPipe[0],
!                              csv_logbuffer + bytes_in_csv_logbuffer,
!                              sizeof(csv_logbuffer) - bytes_in_csv_logbuffer);
!                 if (bytesRead < 0)
!                 {
!                 if (errno != EINTR)
!                     ereport(LOG,
!                             (errcode_for_socket_access(),
!                              errmsg("could not read from CSV logger pipe: %m")));
!                 }
!                 else if (bytesRead > 0)
!                 {
!                     bytes_in_csv_logbuffer += bytesRead;
!                     process_pipe_input(csv_logbuffer,
!                                        &bytes_in_csv_logbuffer,
!                                        CSV_LOGFILE);
!                     continue;
!                 }
!                 else
!                 {
!                     pipe_eof_seen = true;

!                 }
              }
          }
  #else                            /* WIN32 */
***************
*** 393,398 ****
--- 469,484 ----

          if (pipe_eof_seen)
          {
+
+ #ifndef WIN32
+             /* if there's any data left then force it out now */
+             if (Redirect_stderr)
+                 flush_pipe_input(stderr_logbuffer, &bytes_in_stderr_logbuffer, STDERR_LOGFILE);
+
+             if (Log_destination & LOG_DESTINATION_CSVLOG)
+                 flush_pipe_input(csv_logbuffer, &bytes_in_csv_logbuffer, CSV_LOGFILE);
+
+ #endif
              ereport(LOG,
                      (errmsg("logger shutting down")));

***************
*** 414,423 ****
  int
  SysLogger_Start(void)
  {
      pid_t        sysloggerPid;
-     char       *filename;

!     if (!Redirect_stderr)
          return 0;

      /*
--- 500,511 ----
  int
  SysLogger_Start(void)
  {
+     char    *csv_filename;
+     char    *stderr_filename;
+
      pid_t        sysloggerPid;

!     if ( (!Redirect_stderr) && (!(Log_destination & LOG_DESTINATION_CSVLOG)) )
          return 0;

      /*
***************
*** 432,460 ****
       * pipe open, so we can pass it down to the reincarnated syslogger. This
       * is a bit klugy but we have little choice.
       */
! #ifndef WIN32
!     if (syslogPipe[0] < 0)
      {
!         if (pgpipe(syslogPipe) < 0)
!             ereport(FATAL,
!                     (errcode_for_socket_access(),
!                      (errmsg("could not create pipe for syslog: %m"))));
!     }
  #else
!     if (!syslogPipe[0])
!     {
!         SECURITY_ATTRIBUTES sa;
!
!         memset(&sa, 0, sizeof(SECURITY_ATTRIBUTES));
!         sa.nLength = sizeof(SECURITY_ATTRIBUTES);
!         sa.bInheritHandle = TRUE;

!         if (!CreatePipe(&syslogPipe[0], &syslogPipe[1], &sa, 32768))
!             ereport(FATAL,
!                     (errcode_for_file_access(),
!                      (errmsg("could not create pipe for syslog: %m"))));
      }
  #endif

      /*
       * Create log directory if not present; ignore errors
--- 520,581 ----
       * pipe open, so we can pass it down to the reincarnated syslogger. This
       * is a bit klugy but we have little choice.
       */
!
!     /* Create the syslog pipe only if we need to redirect stderr */
!     if (Redirect_stderr)
      {
! #ifndef WIN32
!         if (syslogPipe[0] < 0)
!         {
!             if (pgpipe(syslogPipe) < 0)
!                 ereport(FATAL,
!                         (errcode_for_socket_access(),
!                          (errmsg("could not create pipe for syslog: %m"))));
!         }
  #else
!         if (!syslogPipe[0])
!         {
!             SECURITY_ATTRIBUTES sa;

!             memset(&sa, 0, sizeof(SECURITY_ATTRIBUTES));
!             sa.nLength = sizeof(SECURITY_ATTRIBUTES);
!             sa.bInheritHandle = TRUE;
!
!             if (!CreatePipe(&syslogPipe[0], &syslogPipe[1], &sa, LOG_BUFFER_SIZE))
!                 ereport(FATAL,
!                         (errcode_for_file_access(),
!                          (errmsg("could not create pipe for syslog: %m"))));
!         }
! #endif
      }
+
+     /* Create the csv log pipe if we need csv type log output */
+     if (Log_destination & LOG_DESTINATION_CSVLOG)
+     {
+ #ifndef WIN32
+         if (csvlogPipe[0] < 0)
+         {
+             if (pgpipe(csvlogPipe) < 0)
+                 ereport(FATAL,
+                         (errcode_for_socket_access(),
+                         (errmsg("could not create pipe for csvlog: %m"))));
+         }
+ #else
+         if (!csvlogPipe[0])
+         {
+             SECURITY_ATTRIBUTES sa;
+
+             memset(&sa, 0, sizeof(SECURITY_ATTRIBUTES));
+             sa.nLength = sizeof(SECURITY_ATTRIBUTES);
+             sa.bInheritHandle = TRUE;
+
+             if (!CreatePipe(&csvlogPipe[0], &csvlogPipe[1], &sa, LOG_BUFFER_SIZE))
+                 ereport(FATAL,
+                         (errcode_for_file_access(),
+                         (errmsg("could not create pipe for csvlog: %m"))));
+         }
  #endif
+     }

      /*
       * Create log directory if not present; ignore errors
***************
*** 465,483 ****
       * The initial logfile is created right in the postmaster, to verify that
       * the Log_directory is writable.
       */
!     filename = logfile_getname(time(NULL));

!     syslogFile = fopen(filename, "a");

!     if (!syslogFile)
!         ereport(FATAL,
                  (errcode_for_file_access(),
                   (errmsg("could not create log file \"%s\": %m",
!                          filename))));

-     setvbuf(syslogFile, NULL, LBF_MODE, 0);

-     pfree(filename);

  #ifdef EXEC_BACKEND
      switch ((sysloggerPid = syslogger_forkexec()))
--- 586,622 ----
       * The initial logfile is created right in the postmaster, to verify that
       * the Log_directory is writable.
       */
!     if (Redirect_stderr)
!     {
!         stderr_filename = logfile_getname(time(NULL), STDERR_LOGFILE);

!         syslogFile = fopen(stderr_filename, "a");
!         if (!syslogFile)
!             ereport(FATAL,
!                 (errcode_for_file_access(),
!                  (errmsg("could not create log file \"%s\": %m",
!                              stderr_filename))));

!         setvbuf(syslogFile, NULL, LBF_MODE, 0);
!         pfree(stderr_filename);
!     }
!
!     if (Log_destination & LOG_DESTINATION_CSVLOG)
!     {
!         csv_filename = logfile_getname(time(NULL), CSV_LOGFILE);
!
!         csvlogFile = fopen(csv_filename, "a");
!         if (!csvlogFile)
!             ereport(FATAL,
                  (errcode_for_file_access(),
                   (errmsg("could not create log file \"%s\": %m",
!                             csv_filename))));
!
!         setvbuf(csvlogFile, NULL, LBF_MODE, 0);
!         pfree(csv_filename);
!     }



  #ifdef EXEC_BACKEND
      switch ((sysloggerPid = syslogger_forkexec()))
***************
*** 511,517 ****
              /* success, in postmaster */

              /* now we redirect stderr, if not done already */
!             if (!redirection_done)
              {
  #ifndef WIN32
                  fflush(stdout);
--- 650,656 ----
              /* success, in postmaster */

              /* now we redirect stderr, if not done already */
!             if (Redirect_stderr && !redirection_done)
              {
  #ifndef WIN32
                  fflush(stdout);
***************
*** 545,553 ****
                  redirection_done = true;
              }

!             /* postmaster will never write the file; close it */
!             fclose(syslogFile);
              syslogFile = NULL;
              return (int) sysloggerPid;
      }

--- 684,698 ----
                  redirection_done = true;
              }

!             /* postmaster will never write the files; close it */
!             if (syslogFile)
!                 fclose(syslogFile);
              syslogFile = NULL;
+
+             if (csvlogFile)
+                 fclose(csvlogFile);
+             csvlogFile = NULL;
+
              return (int) sysloggerPid;
      }

***************
*** 566,576 ****
  static pid_t
  syslogger_forkexec(void)
  {
!     char       *av[10];
!     int            ac = 0,
!                 bufc = 0,
!                 i;
!     char        numbuf[2][32];

      av[ac++] = "postgres";
      av[ac++] = "--forklog";
--- 711,721 ----
  static pid_t
  syslogger_forkexec(void)
  {
!     char    *av[11];
!     int    ac = 0,
!         bufc = 0,
!         i;
!     char    numbuf[3][32];

      av[ac++] = "postgres";
      av[ac++] = "--forklog";
***************
*** 583,588 ****
--- 728,738 ----
      else
          strcpy(numbuf[bufc++], "-1");
      snprintf(numbuf[bufc++], 32, "%d", (int) redirection_done);
+
+     if (csvlogFile != NULL)
+         snprintf(numbuf[bufc++], 32, "%d", fileno(csvlogFile));
+     else
+         strcpy(numbuf[bufc++], "-1");
  #else                            /* WIN32 */
      if (syslogFile != NULL)
          snprintf(numbuf[bufc++], 32, "%ld",
***************
*** 590,595 ****
--- 740,751 ----
      else
          strcpy(numbuf[bufc++], "0");
      snprintf(numbuf[bufc++], 32, "%d", (int) redirection_done);
+
+     if (csvlogFile != NULL)
+         snprintf(numbuf[bufc++], 32, "%ld",
+                  _get_osfhandle(_fileno(csvlogFile)));
+     else
+         strcpy(numbuf[bufc++], "0");
  #endif   /* WIN32 */

      /* Add to the arg list */
***************
*** 613,619 ****
  {
      int            fd;

!     Assert(argc == 5);
      argv += 3;

  #ifndef WIN32
--- 769,775 ----
  {
      int            fd;

!     Assert(argc == 6);
      argv += 3;

  #ifndef WIN32
***************
*** 624,629 ****
--- 780,792 ----
          setvbuf(syslogFile, NULL, LBF_MODE, 0);
      }
      redirection_done = (bool) atoi(*argv++);
+
+     fd = atoi(*argv++);
+     if (fd != -1)
+     {
+         csvlogFile = fdopen(fd, "a");
+         setvbuf(csvlogFile, NULL, LBF_MODE, 0);
+     }
  #else                            /* WIN32 */
      fd = atoi(*argv++);
      if (fd != 0)
***************
*** 636,641 ****
--- 799,815 ----
          }
      }
      redirection_done = (bool) atoi(*argv++);
+
+     fd = atoi(*argv++);
+     if (fd != 0)
+     {
+         fd = _open_osfhandle(fd, _O_APPEND);
+         if (fd > 0)
+         {
+             csvlogFile = fdopen(fd, "a");
+             setvbuf(csvlogFile, NULL, LBF_MODE, 0);
+         }
+     }
  #endif   /* WIN32 */
  }
  #endif   /* EXEC_BACKEND */
***************
*** 670,679 ****
   * logbuffer, and *bytes_in_logbuffer is updated.
   */
  static void
! process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
  {
      char   *cursor = logbuffer;
      int        count = *bytes_in_logbuffer;

      /* While we have enough for a header, process data... */
      while (count >= (int) sizeof(PipeProtoHeader))
--- 844,859 ----
   * logbuffer, and *bytes_in_logbuffer is updated.
   */
  static void
! process_pipe_input(char *logbuffer, int *bytes_in_logbuffer, int log_type)
  {
      char   *cursor = logbuffer;
      int        count = *bytes_in_logbuffer;
+     save_buffer *saved_chunks;
+
+     saved_chunks = log_type == CSV_LOGFILE ?
+         csvlog_saved_chunks :
+         stderr_saved_chunks;
+

      /* While we have enough for a header, process data... */
      while (count >= (int) sizeof(PipeProtoHeader))
***************
*** 737,743 ****
                       * chances and write out a partial message and hope that
                       * it's not followed by something from another pid.
                       */
!                     write_syslogger_file(cursor + PIPE_HEADER_SIZE, p.len);
                  }
              }
              else
--- 917,923 ----
                       * chances and write out a partial message and hope that
                       * it's not followed by something from another pid.
                       */
!                     write_syslogger_file(cursor + PIPE_HEADER_SIZE, p.len, log_type);
                  }
              }
              else
***************
*** 764,777 ****
                      appendBinaryStringInfo(str,
                                             cursor + PIPE_HEADER_SIZE,
                                             p.len);
!                     write_syslogger_file(str->data, str->len);
                      saved_chunks[existing_slot].pid = 0;
                      pfree(str->data);
                  }
                  else
                  {
                      /* The whole message was one chunk, evidently. */
!                     write_syslogger_file(cursor + PIPE_HEADER_SIZE, p.len);
                  }
              }

--- 944,957 ----
                      appendBinaryStringInfo(str,
                                             cursor + PIPE_HEADER_SIZE,
                                             p.len);
!                     write_syslogger_file(str->data, str->len, log_type);
                      saved_chunks[existing_slot].pid = 0;
                      pfree(str->data);
                  }
                  else
                  {
                      /* The whole message was one chunk, evidently. */
!                     write_syslogger_file(cursor + PIPE_HEADER_SIZE, p.len, log_type);
                  }
              }

***************
*** 797,803 ****
                  if (cursor[chunklen] == '\0')
                      break;
              }
!             write_syslogger_file(cursor, chunklen);
              cursor += chunklen;
              count -= chunklen;
          }
--- 977,983 ----
                  if (cursor[chunklen] == '\0')
                      break;
              }
!             write_syslogger_file(cursor, chunklen, log_type);
              cursor += chunklen;
              count -= chunklen;
          }
***************
*** 816,825 ****
   * useful at other times, so it is careful to leave things in a clean state.
   */
  static void
! flush_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
  {
      int i;
      StringInfo str;

      /* Dump any incomplete protocol messages */
      for (i = 0; i < CHUNK_SLOTS; i++)
--- 996,1011 ----
   * useful at other times, so it is careful to leave things in a clean state.
   */
  static void
! flush_pipe_input(char *logbuffer, int *bytes_in_logbuffer, int log_type)
  {
      int i;
      StringInfo str;
+     save_buffer *saved_chunks;
+
+     saved_chunks = log_type == CSV_LOGFILE ?
+         csvlog_saved_chunks :
+         stderr_saved_chunks;
+

      /* Dump any incomplete protocol messages */
      for (i = 0; i < CHUNK_SLOTS; i++)
***************
*** 827,833 ****
          if (saved_chunks[i].pid != 0)
          {
              str = &(saved_chunks[i].data);
!             write_syslogger_file(str->data, str->len);
              saved_chunks[i].pid = 0;
              pfree(str->data);
          }
--- 1013,1019 ----
          if (saved_chunks[i].pid != 0)
          {
              str = &(saved_chunks[i].data);
!             write_syslogger_file(str->data, str->len, log_type);
              saved_chunks[i].pid = 0;
              pfree(str->data);
          }
***************
*** 837,852 ****
       * remove any protocol headers that may exist in it.
       */
      if (*bytes_in_logbuffer > 0)
!         write_syslogger_file(logbuffer, *bytes_in_logbuffer);
      *bytes_in_logbuffer = 0;
  }


- /* --------------------------------
-  *        logfile routines
-  * --------------------------------
-  */
-
  /*
   * Write text to the currently open logfile
   *
--- 1023,1033 ----
       * remove any protocol headers that may exist in it.
       */
      if (*bytes_in_logbuffer > 0)
!         write_syslogger_file(logbuffer, *bytes_in_logbuffer, log_type);
      *bytes_in_logbuffer = 0;
  }


  /*
   * Write text to the currently open logfile
   *
***************
*** 855,870 ****
   * even though its stderr does not point at the syslog pipe.
   */
  void
! write_syslogger_file(const char *buffer, int count)
  {
!     int            rc;

  #ifndef WIN32
!     rc = fwrite(buffer, 1, count, syslogFile);
  #else
!     EnterCriticalSection(&sysfileSection);
!     rc = fwrite(buffer, 1, count, syslogFile);
!     LeaveCriticalSection(&sysfileSection);
  #endif

      /* can't use ereport here because of possible recursion */
--- 1036,1074 ----
   * even though its stderr does not point at the syslog pipe.
   */
  void
! write_syslogger_file(const char *buffer, int count, int log_type)
  {
!     int    rc;
!     FILE    **fh = NULL;
!
!     /* Select the file to write to based on the log_type. */
!     switch (log_type)
!     {
!         case STDERR_LOGFILE:
!             fh = (FILE **) &syslogFile;
!             break;
!         case CSV_LOGFILE:
!             fh = (FILE **) &csvlogFile;
!             break;
!         default:
!             return;
!     }

  #ifndef WIN32
!     rc = fwrite(buffer, 1, count, *fh);
  #else
!     if (log_type == STDERR_LOGFILE)
!     {
!         EnterCriticalSection(&sysfileSection);
!         rc = fwrite(buffer, 1, count, *fh);
!         LeaveCriticalSection(&sysfileSection);
!     }
!     else if (log_type == CSV_LOGFILE)
!     {
!         EnterCriticalSection(&csvfileSection);
!         rc = fwrite(buffer, 1, count, *fh);
!         LeaveCriticalSection(&csvfileSection);
!     }
  #endif

      /* can't use ereport here because of possible recursion */
***************
*** 884,897 ****
  static unsigned int __stdcall
  pipeThread(void *arg)
  {
      char        logbuffer[READ_BUF_SIZE];
      int            bytes_in_logbuffer = 0;

      for (;;)
      {
          DWORD        bytesRead;

!         if (!ReadFile(syslogPipe[0],
                        logbuffer + bytes_in_logbuffer,
                        sizeof(logbuffer) - bytes_in_logbuffer,
                        &bytesRead, 0))
--- 1088,1109 ----
  static unsigned int __stdcall
  pipeThread(void *arg)
  {
+
+     int         log_type = *(int *)arg;
      char        logbuffer[READ_BUF_SIZE];
      int            bytes_in_logbuffer = 0;
+     HANDLE      logpipe;
+
+     if (log_type == CSV_LOGFILE)
+         logpipe = csvlogPipe[0];
+     else
+         logpipe = syslogPipe[0];

      for (;;)
      {
          DWORD        bytesRead;

!         if (!ReadFile(logpipe,
                        logbuffer + bytes_in_logbuffer,
                        sizeof(logbuffer) - bytes_in_logbuffer,
                        &bytesRead, 0))
***************
*** 909,915 ****
          else if (bytesRead > 0)
          {
              bytes_in_logbuffer += bytesRead;
!             process_pipe_input(logbuffer, &bytes_in_logbuffer);
          }
      }

--- 1121,1127 ----
          else if (bytesRead > 0)
          {
              bytes_in_logbuffer += bytesRead;
!             process_pipe_input(logbuffer, &bytes_in_logbuffer, log_type);
          }
      }

***************
*** 917,949 ****
      pipe_eof_seen = true;

      /* if there's any data left then force it out now */
!     flush_pipe_input(logbuffer, &bytes_in_logbuffer);

      _endthread();
      return 0;
  }
  #endif   /* WIN32 */

  /*
!  * perform logfile rotation
   */
  static void
  logfile_rotate(bool time_based_rotation)
  {
!     char       *filename;
!     FILE       *fh;

      rotation_requested = false;

      /*
!      * When doing a time-based rotation, invent the new logfile name based on
!      * the planned rotation time, not current time, to avoid "slippage" in the
!      * file name when we don't do the rotation immediately.
       */
      if (time_based_rotation)
!         filename = logfile_getname(next_rotation_time);
!     else
!         filename = logfile_getname(time(NULL));

      /*
       * Decide whether to overwrite or append.  We can overwrite if (a)
--- 1129,1169 ----
      pipe_eof_seen = true;

      /* if there's any data left then force it out now */
!     flush_pipe_input(logbuffer, &bytes_in_logbuffer, log_type);

      _endthread();
      return 0;
  }
  #endif   /* WIN32 */

+
  /*
!  * Log file rotation controller. Decides the filename and which file needs
!  * to be rotated. The worker method below this does the actual rotation.
   */
  static void
  logfile_rotate(bool time_based_rotation)
  {
!     char    *filename;
!     char    *csv_filename;
!
!     pg_time_t timestamp;
!     bool overwrite_logfile;

      rotation_requested = false;

+     timestamp = time(NULL);
+     overwrite_logfile = false;
+
      /*
!      * When doing a time-based rotation, invent the new logfile name based
!      * on the planned rotation time, not current time, to avoid "slippage"
!      * in the file name when we don't do the rotation immediately.
       */
      if (time_based_rotation)
!         timestamp = next_rotation_time;
!
!     filename = logfile_getname(timestamp, STDERR_LOGFILE);

      /*
       * Decide whether to overwrite or append.  We can overwrite if (a)
***************
*** 959,964 ****
--- 1179,1214 ----
       */
      if (Log_truncate_on_rotation && time_based_rotation &&
          last_file_name != NULL && strcmp(filename, last_file_name) != 0)
+         overwrite_logfile = true;
+
+     if (Redirect_stderr)
+         logfile_rotate_worker(overwrite_logfile, STDERR_LOGFILE, filename,
+                         (FILE **) &syslogFile);
+
+     if (Log_destination & LOG_DESTINATION_CSVLOG)
+     {
+         csv_filename = logfile_getname(timestamp, CSV_LOGFILE);
+         logfile_rotate_worker(overwrite_logfile, CSV_LOGFILE, csv_filename,
+                         (FILE **) &csvlogFile);
+     }
+
+     set_next_rotation_time();
+
+     /* instead of pfree'ing filename, remember it for next time */
+     if (last_file_name != NULL)
+         pfree(last_file_name);
+     last_file_name = filename;
+ }
+
+ /*
+  * logfile rotation worker - Does the actual file rotation
+  */
+ static void
+ logfile_rotate_worker(bool overwrite_logfile, int log_type, char* filename, FILE **dest_file)
+ {
+     FILE       *fh;
+
+     if (overwrite_logfile)
          fh = fopen(filename, "w");
      else
          fh = fopen(filename, "a");
***************
*** 993,1022 ****

      /* On Windows, need to interlock against data-transfer thread */
  #ifdef WIN32
!     EnterCriticalSection(&sysfileSection);
  #endif
!     fclose(syslogFile);
!     syslogFile = fh;
  #ifdef WIN32
!     LeaveCriticalSection(&sysfileSection);
  #endif
-
-     set_next_rotation_time();
-
-     /* instead of pfree'ing filename, remember it for next time */
-     if (last_file_name != NULL)
-         pfree(last_file_name);
-     last_file_name = filename;
  }


  /*
!  * construct logfile name using timestamp information
   *
   * Result is palloc'd.
   */
  static char *
! logfile_getname(pg_time_t timestamp)
  {
      char       *filename;
      int            len;
--- 1243,1272 ----

      /* On Windows, need to interlock against data-transfer thread */
  #ifdef WIN32
!     if (log_type == STDERR_LOGFILE)
!         EnterCriticalSection(&sysfileSection);
!     else
!         EnterCriticalSection(&csvfileSection);
  #endif
!     fclose(*dest_file);
!     *dest_file = fh;
  #ifdef WIN32
!     if (log_type == STDERR_LOGFILE)
!         LeaveCriticalSection(&sysfileSection);
!     else
!         LeaveCriticalSection(&csvfileSection);
  #endif
  }


  /*
!  * construct logfile name using timestamp information. Adds a '.csv' as
!  * extension to csvlog files if enabled.
   *
   * Result is palloc'd.
   */
  static char *
! logfile_getname(pg_time_t timestamp, int log_type)
  {
      char       *filename;
      int            len;
***************
*** 1041,1046 ****
--- 1291,1303 ----
                   Log_filename, (unsigned long) timestamp);
      }

+     if (log_type == CSV_LOGFILE)
+     {
+         len = strlen(filename);
+         /* Append .csv to the new filename */
+         snprintf(filename + len, MAXPGPATH - len, ".csv");
+     }
+
      return filename;
  }

Index: src/backend/utils/error/elog.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/error/elog.c,v
retrieving revision 1.187
diff -c -r1.187 elog.c
*** src/backend/utils/error/elog.c    14 Jun 2007 01:48:51 -0000    1.187
--- src/backend/utils/error/elog.c    29 Jun 2007 14:33:47 -0000
***************
*** 78,83 ****
--- 78,85 ----

  extern pid_t SysLoggerPID;

+ char timestamp[128];
+
  /* GUC parameters */
  PGErrorVerbosity Log_error_verbosity = PGERROR_VERBOSE;
  char       *Log_line_prefix = NULL;        /* format for extra log line info */
***************
*** 126,131 ****
--- 128,136 ----
  static bool is_log_level_output(int elevel, int log_min_level);
  static void write_pipe_chunks(int fd, char *data, int len);

+ static void write_csvlog(ErrorData *edata);
+ static void get_error_message(StringInfo buf, ErrorData *edata);
+ static void get_timestamp(StringInfo buf);

  /*
   * errstart --- begin an error-reporting cycle
***************
*** 1494,1534 ****
                  appendStringInfo(buf, "%ld", log_line_number);
                  break;
              case 'm':
!                 {
!                     /*
!                      * Note: for %m, %t, and %s we deliberately use the C
!                      * library's strftime/localtime, and not the equivalent
!                      * functions from src/timezone.  This ensures that all
!                      * backends will report log entries in the same timezone,
!                      * namely whatever C-library setting they inherit from the
!                      * postmaster.    If we used src/timezone then local
!                      * settings of the TimeZone GUC variable would confuse the
!                      * log.
!                      */
!                     time_t        stamp_time;
!                     char        strfbuf[128],
!                                 msbuf[8];
!                     struct timeval tv;
!
!                     gettimeofday(&tv, NULL);
!                     stamp_time = tv.tv_sec;
!
!                     strftime(strfbuf, sizeof(strfbuf),
!                     /* leave room for milliseconds... */
!                     /* Win32 timezone names are too long so don't print them */
! #ifndef WIN32
!                              "%Y-%m-%d %H:%M:%S     %Z",
! #else
!                              "%Y-%m-%d %H:%M:%S     ",
! #endif
!                              localtime(&stamp_time));
!
!                     /* 'paste' milliseconds into place... */
!                     sprintf(msbuf, ".%03d", (int) (tv.tv_usec / 1000));
!                     strncpy(strfbuf + 19, msbuf, 4);
!
!                     appendStringInfoString(buf, strfbuf);
!                 }
                  break;
              case 't':
                  {
--- 1499,1505 ----
                  appendStringInfo(buf, "%ld", log_line_number);
                  break;
              case 'm':
!                 get_timestamp(buf);
                  break;
              case 't':
                  {
***************
*** 1635,1640 ****
--- 1606,1612 ----
  {
      StringInfoData buf;

+     memset(timestamp, '\0', sizeof(timestamp));
      initStringInfo(&buf);

      log_line_prefix(&buf);
***************
*** 1643,1659 ****
      if (Log_error_verbosity >= PGERROR_VERBOSE)
          appendStringInfo(&buf, "%s: ", unpack_sql_state(edata->sqlerrcode));

!     if (edata->message)
!         append_with_tabs(&buf, edata->message);
!     else
!         append_with_tabs(&buf, _("missing error text"));
!
!     if (edata->cursorpos > 0)
!         appendStringInfo(&buf, _(" at character %d"),
!                          edata->cursorpos);
!     else if (edata->internalpos > 0)
!         appendStringInfo(&buf, _(" at character %d"),
!                          edata->internalpos);

      appendStringInfoChar(&buf, '\n');

--- 1615,1622 ----
      if (Log_error_verbosity >= PGERROR_VERBOSE)
          appendStringInfo(&buf, "%s: ", unpack_sql_state(edata->sqlerrcode));

!     /* Get the error message and cursor position if any */
!     get_error_message(&buf, edata);

      appendStringInfoChar(&buf, '\n');

***************
*** 1768,1774 ****
  #endif   /* WIN32 */

      /* Write to stderr, if enabled */
!     if ((Log_destination & LOG_DESTINATION_STDERR) || whereToSendOutput == DestDebug)
      {
  #ifdef WIN32

--- 1731,1738 ----
  #endif   /* WIN32 */

      /* Write to stderr, if enabled */
!     if ((Log_destination & LOG_DESTINATION_STDERR) ||
!         whereToSendOutput == DestDebug)
      {
  #ifdef WIN32

***************
*** 1780,1786 ****
           * that's really a pipe to the syslogger process. Unless we're in the
           * postmaster, and the syslogger process isn't started yet.
           */
!         if ((!Redirect_stderr || am_syslogger || (!IsUnderPostmaster && SysLoggerPID==0)) && pgwin32_is_service())
              write_eventlog(edata->elevel, buf.data);
          else
  #endif
--- 1744,1751 ----
           * that's really a pipe to the syslogger process. Unless we're in the
           * postmaster, and the syslogger process isn't started yet.
           */
!         if ((!Redirect_stderr || am_syslogger ||
!              (!IsUnderPostmaster && SysLoggerPID==0)) && pgwin32_is_service())
              write_eventlog(edata->elevel, buf.data);
          else
  #endif
***************
*** 1789,1798 ****
              else
                  write(fileno(stderr), buf.data, buf.len);
      }
!
      /* If in the syslogger process, try to write messages direct to file */
      if (am_syslogger)
!         write_syslogger_file(buf.data, buf.len);

      pfree(buf.data);
  }
--- 1754,1767 ----
              else
                  write(fileno(stderr), buf.data, buf.len);
      }
!
!     /* Output log in csv format, if enabled */
!     if(Log_destination & LOG_DESTINATION_CSVLOG)
!         write_csvlog(edata);
!
      /* If in the syslogger process, try to write messages direct to file */
      if (am_syslogger)
!         write_syslogger_file(buf.data, buf.len, STDERR_LOGFILE);

      pfree(buf.data);
  }
***************
*** 2204,2206 ****
--- 2173,2448 ----

      return false;
  }
+
+
+ /*
+  * append a CSV'd version of a string to a StringInfo
+  * We use the PostgreSQL defaults for CSV, i.e. quote = escape = '"'
+  */
+
+ static inline void
+ appendCSVLiteral(StringInfo buf, const char* data)
+ {
+     const char * p = data;
+     char c;
+
+     appendStringInfoCharMacro(buf, '"');
+     while ( (c = *p++) != '\0' )
+     {
+         if (c == '"')
+             appendStringInfoCharMacro(buf, '"');
+         appendStringInfoCharMacro(buf, c);
+     }
+     appendStringInfoCharMacro(buf, '"');
+ }
+
+ /*
+  * Constructs the error message, depending on the Errordata it gets,
+  * in CSV (comma seperated values) format. The COPY command
+  * can then be used to load the messages into a table.
+  */
+ static void
+ write_csvlog(ErrorData *edata)
+ {
+     StringInfoData msgbuf;
+     StringInfoData buf;
+
+     /* static counter for line numbers */
+     static long log_line_number = 0;
+
+     /* has counter been reset in current process? */
+     static int  log_my_pid = 0;
+
+     /*
+      * This is one of the few places where we'd rather not inherit a static
+      * variable's value from the postmaster.  But since we will, reset it when
+      * MyProcPid changes.
+      */
+     if (log_my_pid != MyProcPid)
+     {
+         log_line_number = 0;
+         log_my_pid = MyProcPid;
+     }
+     log_line_number++;
+
+     initStringInfo(&msgbuf);
+     initStringInfo(&buf);
+
+     /*
+      * The format of the log output in CSV format:
+      * timestamp with milliseconds, username, databasename, session id,
+      * host and port number, process id, process line number, command tag,
+      * session start time, transaction id, error severity, sql state code,
+      * statement or error message.
+      */
+
+     /* timestamp_with_milliseconds */
+     /*
+      * Check if the timestamp is already calculated for the syslog message,
+      * if it is, then no need to calculate it again, will use the same,
+      * else get the current timestamp. This is done to put same timestamp
+      * in both syslog and csvlog messages.
+      */
+     if (timestamp[0] == '\0')
+         get_timestamp(&buf);
+     else
+         appendStringInfoString(&buf, timestamp);
+
+     appendStringInfoChar(&buf, ',');
+
+     /* username */
+     if (MyProcPort)
+     {
+         const char *username = MyProcPort->user_name;
+         if (username == NULL || *username == '\0')
+             username = _("[unknown]");
+
+         appendCSVLiteral(&buf, username);
+     }
+     appendStringInfoChar(&buf, ',');
+
+     /* databasename */
+     if (MyProcPort)
+     {
+         const char *dbname = MyProcPort->database_name;
+
+         if (dbname == NULL || *dbname == '\0')
+             dbname = _("[unknown]");
+
+         appendCSVLiteral(&buf, dbname);
+     }
+
+     appendStringInfoChar(&buf, ',');
+
+     /* session id */
+     if (MyProcPort)
+     {
+         appendStringInfo(&buf, "%lx.%x",
+                  (long) (MyProcPort->session_start), MyProcPid);
+     }
+     else
+     {
+         appendStringInfo(&buf, "%lx.%x", (long) MyStartTime, MyProcPid);
+     }
+
+     appendStringInfoChar(&buf, ',');
+
+     /* Remote host and port */
+     if (MyProcPort && MyProcPort->remote_host)
+     {
+             appendStringInfo(&buf, "%s", MyProcPort->remote_host);
+             if (MyProcPort->remote_port && MyProcPort->remote_port[0] != '\0')
+                 appendStringInfo(&buf, ":%s", MyProcPort->remote_port);
+     }
+
+     appendStringInfoChar(&buf, ',');
+
+     /* Process id  */
+     if (MyProcPid != 0)
+         appendStringInfo(&buf, "%d", MyProcPid);
+
+     appendStringInfoChar(&buf, ',');
+
+     /* Line number */
+     appendStringInfo(&buf, "%ld", log_line_number);
+
+     appendStringInfoChar(&buf, ',');
+
+     /* Command tag */
+     if (MyProcPort)
+     {
+         const char *psdisp;
+         int            displen;
+
+         psdisp = get_ps_display(&displen);
+         appendStringInfo(&buf, "%.*s", displen, psdisp);
+     }
+
+     appendStringInfoChar(&buf, ',');
+
+     /* session start timestamp */
+     if (MyProcPort)
+     {
+         char        strfbuf[128];
+
+         strftime(strfbuf, sizeof(strfbuf),
+         /* Win32 timezone names are too long so don't print them */
+ #ifndef WIN32
+              "%Y-%m-%d %H:%M:%S %Z",
+ #else
+              "%Y-%m-%d %H:%M:%S",
+ #endif
+         localtime(&MyProcPort->session_start));
+         appendStringInfoString(&buf, strfbuf);
+     }
+
+
+     appendStringInfoChar(&buf, ',');
+
+
+     /* Transaction id */
+     if (MyProcPort)
+     {
+         if (IsTransactionState())
+             appendStringInfo(&buf, "%u", GetTopTransactionId());
+         else
+             appendStringInfo(&buf, "%u", InvalidTransactionId);
+     }
+
+     appendStringInfoChar(&buf, ',');
+
+     /* Error severity */
+     if (error_severity(edata->elevel) != NULL)
+         appendStringInfo(&buf, "%s,", error_severity(edata->elevel));
+     else
+         appendStringInfoString(&buf, ",");
+
+     /* SQL state code */
+     if (Log_error_verbosity >= PGERROR_VERBOSE)
+         appendStringInfo(&buf, "%s",
+                  unpack_sql_state(edata->sqlerrcode));
+
+     appendStringInfoChar(&buf, ',');
+
+     /* Error message and cursor position if any */
+     get_error_message(&msgbuf, edata);
+
+     appendCSVLiteral(&buf, msgbuf.data);
+
+     appendStringInfoChar(&buf, '\n');
+
+     /* If in the syslogger process, try to write messages direct to file */
+     if (am_syslogger)
+         write_syslogger_file(buf.data, buf.len, CSV_LOGFILE);
+     else
+         write_pipe_chunks(csvlogPipe[1], buf.data, buf.len);
+
+     pfree(msgbuf.data);
+     pfree(buf.data);
+ }
+
+ /*
+  * Appends the buffer with the error message and the cursor position.
+  */
+ static void
+ get_error_message(StringInfo buf, ErrorData *edata)
+ {
+     StringInfoData msgbuf;
+
+     initStringInfo(&msgbuf);
+
+     if (edata->message)
+         append_with_tabs(&msgbuf, edata->message);
+     else
+         append_with_tabs(&msgbuf, _("missing error text"));
+
+     if (edata->cursorpos > 0)
+         appendStringInfo(&msgbuf, _(" at character %d"),
+                          edata->cursorpos);
+     else if (edata->internalpos > 0)
+         appendStringInfo(&msgbuf, _(" at character %d"),
+                          edata->internalpos);
+     appendStringInfo(buf, "%s", pstrdup(msgbuf.data));
+ }
+
+ /*
+  * Calculates the current timestamp. Appends the calculated timestamp
+  * to the buffer passed in.
+  */
+ static void
+ get_timestamp(StringInfo buf)
+ {
+     /*
+      * Note: for %m, %t, and %s we deliberately use the C
+      * library's strftime/localtime, and not the equivalent
+      * functions from src/timezone.  This ensures that all
+      * backends will report log entries in the same timezone,
+      * namely whatever C-library setting they inherit from the
+      * postmaster.    If we used src/timezone then local
+      * settings of the TimeZone GUC variable would confuse the
+      * log.
+      */
+     time_t        stamp_time;
+     char        msbuf[8];
+     struct timeval tv;
+
+     gettimeofday(&tv, NULL);
+     stamp_time = tv.tv_sec;
+
+     strftime(timestamp, sizeof(timestamp),
+     /* leave room for milliseconds... */
+     /* Win32 timezone names are too long so don't print them. */
+ #ifndef WIN32
+          "%Y-%m-%d %H:%M:%S     %Z",
+ #else
+          "%Y-%m-%d %H:%M:%S     ",
+ #endif
+     localtime(&stamp_time));
+
+     /* 'paste' milliseconds into place... */
+     sprintf(msbuf, ".%03d", (int) (tv.tv_usec / 1000));
+     strncpy(timestamp + 19, msbuf, 4);
+
+     appendStringInfoString(buf, timestamp);
+ }
+
Index: src/backend/utils/init/globals.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/init/globals.c,v
retrieving revision 1.101
diff -c -r1.101 globals.c
*** src/backend/utils/init/globals.c    16 Apr 2007 18:29:54 -0000    1.101
--- src/backend/utils/init/globals.c    29 Jun 2007 14:33:47 -0000
***************
*** 33,38 ****
--- 33,39 ----
  volatile uint32 CritSectionCount = 0;

  int            MyProcPid;
+ time_t            MyStartTime;
  struct Port *MyProcPort;
  long        MyCancelKey;

Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/misc/guc.c,v
retrieving revision 1.403
diff -c -r1.403 guc.c
*** src/backend/utils/misc/guc.c    28 Jun 2007 00:02:39 -0000    1.403
--- src/backend/utils/misc/guc.c    29 Jun 2007 14:33:51 -0000
***************
*** 2203,2209 ****
      {
          {"log_destination", PGC_SIGHUP, LOGGING_WHERE,
              gettext_noop("Sets the destination for server log output."),
!             gettext_noop("Valid values are combinations of \"stderr\", \"syslog\", "
                           "and \"eventlog\", depending on the platform."),
              GUC_LIST_INPUT
          },
--- 2203,2209 ----
      {
          {"log_destination", PGC_SIGHUP, LOGGING_WHERE,
              gettext_noop("Sets the destination for server log output."),
!             gettext_noop("Valid values are combinations of \"stderr\", \"syslog\", \"csvlog\","
                           "and \"eventlog\", depending on the platform."),
              GUC_LIST_INPUT
          },
***************
*** 6270,6275 ****
--- 6270,6277 ----

          if (pg_strcasecmp(tok, "stderr") == 0)
              newlogdest |= LOG_DESTINATION_STDERR;
+         else if (pg_strcasecmp(tok, "csvlog") == 0)
+             newlogdest |= LOG_DESTINATION_CSVLOG;
  #ifdef HAVE_SYSLOG
          else if (pg_strcasecmp(tok, "syslog") == 0)
              newlogdest |= LOG_DESTINATION_SYSLOG;
Index: src/backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.217
diff -c -r1.217 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample    28 Jun 2007 00:02:39 -0000    1.217
--- src/backend/utils/misc/postgresql.conf.sample    29 Jun 2007 14:33:51 -0000
***************
*** 226,232 ****
  # - Where to Log -

  #log_destination = 'stderr'        # Valid values are combinations of
!                     # stderr, syslog and eventlog,
                      # depending on platform.

  # This is used when logging to stderr:
--- 226,232 ----
  # - Where to Log -

  #log_destination = 'stderr'        # Valid values are combinations of
!                     # stderr, syslog, csvlog and eventlog,
                      # depending on platform.

  # This is used when logging to stderr:
***************
*** 234,240 ****
                      # files
                      # (change requires restart)

! # These are only used if redirect_stderr is on:
  #log_directory = 'pg_log'        # Directory where log files are written
                      # Can be absolute or relative to PGDATA
  #log_filename = 'postgresql-%Y-%m-%d_%H%M%S.log' # Log file name pattern.
--- 234,240 ----
                      # files
                      # (change requires restart)

! # These are only used if redirect_stderr is on, or if log_destination is csvlog:
  #log_directory = 'pg_log'        # Directory where log files are written
                      # Can be absolute or relative to PGDATA
  #log_filename = 'postgresql-%Y-%m-%d_%H%M%S.log' # Log file name pattern.
Index: src/include/miscadmin.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/miscadmin.h,v
retrieving revision 1.194
diff -c -r1.194 miscadmin.h
*** src/include/miscadmin.h    16 Apr 2007 18:29:56 -0000    1.194
--- src/include/miscadmin.h    29 Jun 2007 14:33:52 -0000
***************
*** 132,137 ****
--- 132,138 ----
  extern int    MaxConnections;

  extern DLLIMPORT int MyProcPid;
+ extern DLLIMPORT time_t MyStartTime;
  extern DLLIMPORT struct Port *MyProcPort;
  extern long MyCancelKey;

Index: src/include/postmaster/syslogger.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/postmaster/syslogger.h,v
retrieving revision 1.9
diff -c -r1.9 syslogger.h
*** src/include/postmaster/syslogger.h    14 Jun 2007 01:48:51 -0000    1.9
--- src/include/postmaster/syslogger.h    29 Jun 2007 14:33:52 -0000
***************
*** 60,65 ****
--- 60,71 ----
  #define PIPE_MAX_PAYLOAD  ((int) (PIPE_CHUNK_SIZE - PIPE_HEADER_SIZE))


+ #define LOG_BUFFER_SIZE    32768
+
+ #define STDERR_LOGFILE    1
+ #define CSV_LOGFILE    2
+
+
  /* GUC options */
  extern bool Redirect_stderr;
  extern int    Log_RotationAge;
***************
*** 72,85 ****

  #ifndef WIN32
  extern int    syslogPipe[2];
  #else
  extern HANDLE syslogPipe[2];
  #endif


  extern int    SysLogger_Start(void);

! extern void write_syslogger_file(const char *buffer, int count);

  #ifdef EXEC_BACKEND
  extern void SysLoggerMain(int argc, char *argv[]);
--- 78,93 ----

  #ifndef WIN32
  extern int    syslogPipe[2];
+ extern int    csvlogPipe[2];
  #else
  extern HANDLE syslogPipe[2];
+ extern HANDLE csvlogPipe[2];
  #endif


  extern int    SysLogger_Start(void);

! extern void write_syslogger_file(const char *buffer, int count, int log_type);

  #ifdef EXEC_BACKEND
  extern void SysLoggerMain(int argc, char *argv[]);
Index: src/include/utils/elog.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/utils/elog.h,v
retrieving revision 1.86
diff -c -r1.86 elog.h
*** src/include/utils/elog.h    4 May 2007 02:01:02 -0000    1.86
--- src/include/utils/elog.h    29 Jun 2007 14:33:53 -0000
***************
*** 291,296 ****
--- 291,297 ----
  #define LOG_DESTINATION_STDERR     1
  #define LOG_DESTINATION_SYSLOG     2
  #define LOG_DESTINATION_EVENTLOG 4
+ #define LOG_DESTINATION_CSVLOG    8

  /* Other exported functions */
  extern void DebugFileOpen(void);

pgsql-patches by date:

Previous
From: Patrick Welche
Date:
Subject: Re: configure.in / xml / quoting trouble
Next
From: Dave Page
Date:
Subject: Re: WIP CSV logs