Here's my latest WIP patch for COPYable CSV logs. I think I addresses
all (or most :-) ) of the concerns Dave and Tom had. It's a whole lot
simpler than before (no extra pipe).
I have not yet tested this on Windows, but given that it now contains
almost no Windows-specific code I'm not so worried about it - will
test when I get a chance.
Windows tests (make installcheck-parallel with csv logs turned on)
seem to work just fine.
updated in attached to fix a couple of small logic bugs in picking the
destination file.
I think this is close to ready for documentation and application.
cheers
andrew
Index: src/backend/postmaster/syslogger.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/syslogger.c,v
retrieving revision 1.36
diff -c -r1.36 syslogger.c
*** src/backend/postmaster/syslogger.c 4 Aug 2007 01:26:53 -0000 1.36
--- src/backend/postmaster/syslogger.c 8 Aug 2007 16:32:19 -0000
***************
*** 87,93 ****
--- 87,95 ----
static pg_time_t next_rotation_time;
static bool pipe_eof_seen = false;
static FILE *syslogFile = NULL;
+ static FILE *csvlogFile = NULL;
static char *last_file_name = NULL;
+ static char *last_csvfile_name = NULL;
/*
* Buffers for saving partial messages from different backends. We don't expect
***************
*** 132,143 ****
#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);
--- 134,146 ----
#endif
static void process_pipe_input(char *logbuffer, int *bytes_in_logbuffer);
static void flush_pipe_input(char *logbuffer, int *bytes_in_logbuffer);
+ static void open_csvlogfile(void);
#ifdef WIN32
static unsigned int __stdcall pipeThread(void *arg);
#endif
! static void logfile_rotate(bool time_based_rotation, int size_rotation_for);
! static char *logfile_getname(pg_time_t timestamp, char * suffix);
static void set_next_rotation_time(void);
static void sigHupHandler(SIGNAL_ARGS);
static void sigUsr1Handler(SIGNAL_ARGS);
***************
*** 281,287 ****
for (;;)
{
bool time_based_rotation = false;
!
#ifndef WIN32
int bytesRead;
int rc;
--- 284,290 ----
for (;;)
{
bool time_based_rotation = false;
! int size_rotation_for = 0;
#ifndef WIN32
int bytesRead;
int rc;
***************
*** 336,346 ****
{
/* Do a rotation if file is too big */
if (ftell(syslogFile) >= Log_RotationSize * 1024L)
rotation_requested = true;
}
if (rotation_requested)
! logfile_rotate(time_based_rotation);
#ifndef WIN32
--- 339,358 ----
{
/* Do a rotation if file is too big */
if (ftell(syslogFile) >= Log_RotationSize * 1024L)
+ {
+ rotation_requested = true;
+ size_rotation_for |= LOG_DESTINATION_STDERR;
+ }
+ if (csvlogFile != NULL && ftell(csvlogFile) >= Log_RotationSize * 1024L)
+ {
rotation_requested = true;
+ size_rotation_for |= LOG_DESTINATION_CSVLOG;
+ }
+
}
if (rotation_requested)
! logfile_rotate(time_based_rotation, size_rotation_for);
#ifndef WIN32
***************
*** 405,411 ****
if (pipe_eof_seen)
{
! ereport(LOG,
(errmsg("logger shutting down")));
/*
--- 417,426 ----
if (pipe_eof_seen)
{
! /* seeing this message on the real stderr is annoying - so we
! * make it DEBUG1 to suppress in normal use.
! */
! ereport(DEBUG1,
(errmsg("logger shutting down")));
/*
***************
*** 477,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");
--- 492,498 ----
* The initial logfile is created right in the postmaster, to verify that
* the Log_directory is writable.
*/
! filename = logfile_getname(time(NULL), NULL);
syslogFile = fopen(filename, "a");
***************
*** 688,693 ****
--- 703,709 ----
{
char *cursor = logbuffer;
int count = *bytes_in_logbuffer;
+ int dest = LOG_DESTINATION_STDERR;
/* While we have enough for a header, process data... */
while (count >= (int) sizeof(PipeProtoHeader))
***************
*** 700,706 ****
if (p.nuls[0] == '\0' && p.nuls[1] == '\0' &&
p.len > 0 && p.len <= PIPE_MAX_PAYLOAD &&
p.pid != 0 &&
! (p.is_last == 't' || p.is_last == 'f'))
{
chunklen = PIPE_HEADER_SIZE + p.len;
--- 716,723 ----
if (p.nuls[0] == '\0' && p.nuls[1] == '\0' &&
p.len > 0 && p.len <= PIPE_MAX_PAYLOAD &&
p.pid != 0 &&
! (p.is_last == 't' || p.is_last == 'f' ||
! p.is_last == 'T' || p.is_last == 'F' ))
{
chunklen = PIPE_HEADER_SIZE + p.len;
***************
*** 708,714 ****
if (count < chunklen)
break;
! if (p.is_last == 'f')
{
/*
* Save a complete non-final chunk in the per-pid buffer
--- 725,734 ----
if (count < chunklen)
break;
! dest = (p.is_last == 'T' || p.is_last == 'F' ) ?
! LOG_DESTINATION_CSVLOG : LOG_DESTINATION_STDERR;
!
! if (p.is_last == 'f' || p.is_last == 'F')
{
/*
* Save a complete non-final chunk in the per-pid buffer
***************
*** 751,757 ****
* 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
--- 771,778 ----
* 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,
! dest);
}
}
else
***************
*** 778,791 ****
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);
}
}
--- 799,813 ----
appendBinaryStringInfo(str,
cursor + PIPE_HEADER_SIZE,
p.len);
! write_syslogger_file(str->data, str->len, dest);
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,
! dest);
}
}
***************
*** 811,817 ****
if (cursor[chunklen] == '\0')
break;
}
! write_syslogger_file(cursor, chunklen);
cursor += chunklen;
count -= chunklen;
}
--- 833,840 ----
if (cursor[chunklen] == '\0')
break;
}
! /* fall back on the stderr log as the destination */
! write_syslogger_file(cursor, chunklen, LOG_DESTINATION_STDERR);
cursor += chunklen;
count -= chunklen;
}
***************
*** 841,847 ****
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);
}
--- 864,870 ----
if (saved_chunks[i].pid != 0)
{
str = &(saved_chunks[i].data);
! write_syslogger_file(str->data, str->len, LOG_DESTINATION_STDERR);
saved_chunks[i].pid = 0;
pfree(str->data);
}
***************
*** 851,857 ****
* 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;
}
--- 874,881 ----
* remove any protocol headers that may exist in it.
*/
if (*bytes_in_logbuffer > 0)
! write_syslogger_file(logbuffer, *bytes_in_logbuffer,
! LOG_DESTINATION_STDERR);
*bytes_in_logbuffer = 0;
}
***************
*** 869,883 ****
* 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
--- 893,913 ----
* even though its stderr does not point at the syslog pipe.
*/
void
! write_syslogger_file(const char *buffer, int count, int destination)
{
int rc;
+ FILE * logfile;
+
+ if (destination == LOG_DESTINATION_CSVLOG && csvlogFile == NULL)
+ open_csvlogfile();
+
+ logfile = destination == LOG_DESTINATION_CSVLOG ? csvlogFile : syslogFile ;
#ifndef WIN32
! rc = fwrite(buffer, 1, count, logfile);
#else
EnterCriticalSection(&sysfileSection);
! rc = fwrite(buffer, 1, count, logfile);
LeaveCriticalSection(&sysfileSection);
#endif
***************
*** 939,950 ****
#endif /* WIN32 */
/*
* perform logfile rotation
*/
static void
! logfile_rotate(bool time_based_rotation)
{
char *filename;
FILE *fh;
rotation_requested = false;
--- 969,1013 ----
#endif /* WIN32 */
/*
+ * open the csv log file - we do this opportunistically, because
+ * we don't know if CSV logging will be wanted.
+ */
+ static void
+ open_csvlogfile(void)
+ {
+ char *filename;
+ FILE *fh;
+
+ filename = logfile_getname(time(NULL),".csv");
+
+ fh = fopen(filename, "a");
+
+ if (!fh)
+ ereport(FATAL,
+ (errcode_for_file_access(),
+ (errmsg("could not create log file \"%s\": %m",
+ filename))));
+
+ setvbuf(fh, NULL, LBF_MODE, 0);
+
+ #ifdef WIN32
+ _setmode(_fileno(fh), _O_TEXT); /* use CRLF line endings on Windows */
+ #endif
+
+ csvlogFile = fh;
+
+ pfree(filename);
+
+ }
+
+ /*
* perform logfile rotation
*/
static void
! logfile_rotate(bool time_based_rotation, int size_rotation_for)
{
char *filename;
+ char *csvfilename;
FILE *fh;
rotation_requested = false;
***************
*** 955,963 ****
* 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)
--- 1018,1034 ----
* file name when we don't do the rotation immediately.
*/
if (time_based_rotation)
! {
! filename = logfile_getname(next_rotation_time, NULL);
! if (csvlogFile != NULL)
! csvfilename = logfile_getname(next_rotation_time, ".csv");
! }
else
! {
! filename = logfile_getname(time(NULL), NULL);
! if (csvlogFile != NULL)
! csvfilename = logfile_getname(time(NULL), ".csv");
! }
/*
* Decide whether to overwrite or append. We can overwrite if (a)
***************
*** 970,1030 ****
* postmaster because it ain't gonna work in the EXEC_BACKEND case.) So we
* will always append in that situation, even though truncating would
* usually be safe.
*/
! if (Log_truncate_on_rotation && time_based_rotation &&
! last_file_name != NULL && strcmp(filename, last_file_name) != 0)
! fh = fopen(filename, "w");
! else
! fh = fopen(filename, "a");
!
! if (!fh)
{
! int saveerrno = errno;
!
! ereport(LOG,
! (errcode_for_file_access(),
! errmsg("could not open new log file \"%s\": %m",
! filename)));
! /*
! * ENFILE/EMFILE are not too surprising on a busy system; just keep
! * using the old file till we manage to get a new one. Otherwise,
! * assume something's wrong with Log_directory and stop trying to
! * create files.
! */
! if (saveerrno != ENFILE && saveerrno != EMFILE)
{
ereport(LOG,
! (errmsg("disabling automatic rotation (use SIGHUP to reenable)")));
! Log_RotationAge = 0;
! Log_RotationSize = 0;
}
! pfree(filename);
! return;
}
! setvbuf(fh, NULL, LBF_MODE, 0);
#ifdef WIN32
! _setmode(_fileno(fh), _O_TEXT); /* use CRLF line endings on Windows */
#endif
! /* 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;
}
--- 1041,1172 ----
* postmaster because it ain't gonna work in the EXEC_BACKEND case.) So we
* will always append in that situation, even though truncating would
* usually be safe.
+ *
+ * For consistency, we treat CSV logs the same even though they aren't
+ * opened in the postmaster.
*/
! if (time_based_rotation || (size_rotation_for & LOG_DESTINATION_STDERR))
{
! if (Log_truncate_on_rotation && time_based_rotation &&
! last_file_name != NULL && strcmp(filename, last_file_name) != 0)
! fh = fopen(filename, "w");
! else
! fh = fopen(filename, "a");
! if (!fh)
{
+ int saveerrno = errno;
+
ereport(LOG,
! (errcode_for_file_access(),
! errmsg("could not open new log file \"%s\": %m",
! filename)));
!
! /*
! * ENFILE/EMFILE are not too surprising on a busy system; just keep
! * using the old file till we manage to get a new one. Otherwise,
! * assume something's wrong with Log_directory and stop trying to
! * create files.
! */
! if (saveerrno != ENFILE && saveerrno != EMFILE)
! {
! ereport(LOG,
! (errmsg("disabling automatic rotation (use SIGHUP to reenable)")));
! Log_RotationAge = 0;
! Log_RotationSize = 0;
! }
! pfree(filename);
! return;
}
!
! setvbuf(fh, NULL, LBF_MODE, 0);
!
! #ifdef WIN32
! _setmode(_fileno(fh), _O_TEXT); /* use CRLF line endings on Windows */
! #endif
!
! /* On Windows, need to interlock against data-transfer thread */
! #ifdef WIN32
! EnterCriticalSection(&sysfileSection);
! #endif
! fclose(syslogFile);
! syslogFile = fh;
! #ifdef WIN32
! LeaveCriticalSection(&sysfileSection);
! #endif
!
! /* instead of pfree'ing filename, remember it for next time */
! if (last_file_name != NULL)
! pfree(last_file_name);
! last_file_name = filename;
!
!
}
! /* same as above, but for csv file. */
!
! if (csvlogFile != NULL && (
! time_based_rotation ||
! (size_rotation_for & LOG_DESTINATION_STDERR)))
! {
! if (Log_truncate_on_rotation && time_based_rotation &&
! last_csvfile_name != NULL &&
! strcmp(csvfilename, last_csvfile_name) != 0)
!
! fh = fopen(csvfilename, "w");
! else
! fh = fopen(csvfilename, "a");
!
! if (!fh)
! {
! int saveerrno = errno;
!
! ereport(LOG,
! (errcode_for_file_access(),
! errmsg("could not open new log file \"%s\": %m",
! csvfilename)));
!
! /*
! * ENFILE/EMFILE are not too surprising on a busy system; just keep
! * using the old file till we manage to get a new one. Otherwise,
! * assume something's wrong with Log_directory and stop trying to
! * create files.
! */
! if (saveerrno != ENFILE && saveerrno != EMFILE)
! {
! ereport(LOG,
! (errmsg("disabling automatic rotation (use SIGHUP to reenable)")));
! Log_RotationAge = 0;
! Log_RotationSize = 0;
! }
! pfree(csvfilename);
! return;
! }
!
! setvbuf(fh, NULL, LBF_MODE, 0);
#ifdef WIN32
! _setmode(_fileno(fh), _O_TEXT); /* use CRLF line endings on Windows */
#endif
! /* On Windows, need to interlock against data-transfer thread */
#ifdef WIN32
! EnterCriticalSection(&sysfileSection);
#endif
! fclose(csvlogFile);
! syslogFile = fh;
#ifdef WIN32
! LeaveCriticalSection(&sysfileSection);
#endif
+ /* instead of pfree'ing filename, remember it for next time */
+ if (last_csvfile_name != NULL)
+ pfree(last_csvfile_name);
+ last_csvfile_name = filename;
+ }
+
set_next_rotation_time();
}
***************
*** 1034,1040 ****
* Result is palloc'd.
*/
static char *
! logfile_getname(pg_time_t timestamp)
{
char *filename;
int len;
--- 1176,1182 ----
* Result is palloc'd.
*/
static char *
! logfile_getname(pg_time_t timestamp, char * suffix)
{
char *filename;
int len;
***************
*** 1058,1063 ****
--- 1200,1215 ----
Log_filename, (unsigned long) timestamp);
}
+ if (suffix != NULL)
+ {
+ len = strlen(filename);
+ if (len > 4 && (strcmp(filename+(len-4),".log") == 0))
+ {
+ len -= 4;
+ }
+ strncpy(filename + len, suffix, MAXPGPATH - len);
+ }
+
return filename;
}
Index: src/backend/utils/error/elog.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/error/elog.c,v
retrieving revision 1.193
diff -c -r1.193 elog.c
*** src/backend/utils/error/elog.c 4 Aug 2007 19:29:25 -0000 1.193
--- src/backend/utils/error/elog.c 8 Aug 2007 16:32:20 -0000
***************
*** 104,109 ****
--- 104,117 ----
static int recursion_depth = 0; /* to detect actual recursion */
+ /* buffers for formatted timestamps that might be used by both
+ * log_line_prefix and csv logs.
+ */
+
+ #define FORMATTED_TS_LEN 128
+ static char formatted_start_time[FORMATTED_TS_LEN];
+ static char formatted_log_time[FORMATTED_TS_LEN];
+
/* Macro for checking errordata_stack_depth is reasonable */
#define CHECK_STACK_DEPTH() \
***************
*** 124,131 ****
static const char *error_severity(int elevel);
static void append_with_tabs(StringInfo buf, const char *str);
static bool is_log_level_output(int elevel, int log_min_level);
! static void write_pipe_chunks(int fd, char *data, int len);
!
/*
* errstart --- begin an error-reporting cycle
--- 132,139 ----
static const char *error_severity(int elevel);
static void append_with_tabs(StringInfo buf, const char *str);
static bool is_log_level_output(int elevel, int log_min_level);
! static void write_pipe_chunks(char *data, int len, int dest);
! static void get_error_message(StringInfo buf, ErrorData *edata);
/*
* errstart --- begin an error-reporting cycle
***************
*** 1434,1445 ****
/*
* 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++;
--- 1442,1455 ----
/*
* 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. MyStartTime also changes when MyProcPid does, so
! * reset the formatted start timestamp too.
*/
if (log_my_pid != MyProcPid)
{
log_line_number = 0;
log_my_pid = MyProcPid;
+ formatted_start_time[0] = '\0';
}
log_line_number++;
***************
*** 1498,1505 ****
struct timeval tv;
pg_time_t stamp_time;
pg_tz *tz;
! char strfbuf[128],
! msbuf[8];
gettimeofday(&tv, NULL);
stamp_time = (pg_time_t) tv.tv_sec;
--- 1508,1514 ----
struct timeval tv;
pg_time_t stamp_time;
pg_tz *tz;
! char msbuf[8];
gettimeofday(&tv, NULL);
stamp_time = (pg_time_t) tv.tv_sec;
***************
*** 1512,1527 ****
*/
tz = log_timezone ? log_timezone : gmt_timezone;
! pg_strftime(strfbuf, sizeof(strfbuf),
/* leave room for milliseconds... */
"%Y-%m-%d %H:%M:%S %Z",
pg_localtime(&stamp_time, tz));
/* 'paste' milliseconds into place... */
sprintf(msbuf, ".%03d", (int) (tv.tv_usec / 1000));
! strncpy(strfbuf + 19, msbuf, 4);
! appendStringInfoString(buf, strfbuf);
}
break;
case 't':
--- 1521,1536 ----
*/
tz = log_timezone ? log_timezone : gmt_timezone;
! pg_strftime(formatted_log_time, FORMATTED_TS_LEN,
/* leave room for milliseconds... */
"%Y-%m-%d %H:%M:%S %Z",
pg_localtime(&stamp_time, tz));
/* 'paste' milliseconds into place... */
sprintf(msbuf, ".%03d", (int) (tv.tv_usec / 1000));
! strncpy(formatted_log_time + 19, msbuf, 4);
! appendStringInfoString(buf, formatted_log_time);
}
break;
case 't':
***************
*** 1539,1556 ****
}
break;
case 's':
{
pg_time_t stamp_time = (pg_time_t) MyStartTime;
pg_tz *tz;
- char strfbuf[128];
tz = log_timezone ? log_timezone : gmt_timezone;
! pg_strftime(strfbuf, sizeof(strfbuf),
"%Y-%m-%d %H:%M:%S %Z",
pg_localtime(&stamp_time, tz));
- appendStringInfoString(buf, strfbuf);
}
break;
case 'i':
if (MyProcPort)
--- 1548,1565 ----
}
break;
case 's':
+ if (formatted_start_time[0] == '\0')
{
pg_time_t stamp_time = (pg_time_t) MyStartTime;
pg_tz *tz;
tz = log_timezone ? log_timezone : gmt_timezone;
! pg_strftime(formatted_start_time, FORMATTED_TS_LEN,
"%Y-%m-%d %H:%M:%S %Z",
pg_localtime(&stamp_time, tz));
}
+ appendStringInfoString(buf, formatted_start_time);
break;
case 'i':
if (MyProcPort)
***************
*** 1596,1601 ****
--- 1605,1849 ----
}
}
+
+ /*
+ * 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;
+ formatted_start_time[0] = '\0';
+ }
+ 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 (formatted_log_time[0] == '\0')
+ {
+ struct timeval tv;
+ pg_time_t stamp_time;
+ pg_tz *tz;
+ char msbuf[8];
+
+ gettimeofday(&tv, NULL);
+ stamp_time = (pg_time_t) tv.tv_sec;
+
+ /*
+ * Normally we print log timestamps in log_timezone, but
+ * during startup we could get here before that's set.
+ * If so, fall back to gmt_timezone (which guc.c ensures
+ * is set up before Log_line_prefix can become nonempty).
+ */
+ tz = log_timezone ? log_timezone : gmt_timezone;
+
+ pg_strftime(formatted_log_time, FORMATTED_TS_LEN,
+ /* leave room for milliseconds... */
+ "%Y-%m-%d %H:%M:%S %Z",
+ pg_localtime(&stamp_time, tz));
+
+ /* 'paste' milliseconds into place... */
+ sprintf(msbuf, ".%03d", (int) (tv.tv_usec / 1000));
+ strncpy(formatted_log_time + 19, msbuf, 4);
+ }
+ appendStringInfoString(&buf, formatted_log_time);
+ 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 */
+ 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, ',');
+
+ /* PS display */
+ if (MyProcPort)
+ {
+ const char *psdisp;
+ int displen;
+
+ psdisp = get_ps_display(&displen);
+ appendStringInfo(&msgbuf, "%.*s", displen, psdisp);
+ appendCSVLiteral(&buf, msgbuf.data);
+ resetStringInfo(&msgbuf);
+ }
+
+ appendStringInfoChar(&buf, ',');
+
+ /* session start timestamp */
+ if (formatted_start_time[0] == '\0')
+ {
+ pg_time_t stamp_time = (pg_time_t) MyStartTime;
+ pg_tz *tz;
+
+ tz = log_timezone ? log_timezone : gmt_timezone;
+
+ pg_strftime(formatted_start_time, FORMATTED_TS_LEN,
+ "%Y-%m-%d %H:%M:%S %Z",
+ pg_localtime(&stamp_time, tz));
+ }
+ appendStringInfoString(&buf, formatted_start_time);
+ 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, LOG_DESTINATION_CSVLOG);
+ else
+ write_pipe_chunks(buf.data, buf.len, LOG_DESTINATION_CSVLOG);
+
+ 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)
+ {
+ if (edata->message)
+ appendStringInfo(buf, "%s", edata->message);
+ else
+ appendStringInfo(buf, "%s", _("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);
+ }
+
/*
* Unpack MAKE_SQLSTATE code. Note that this returns a pointer to a
* static buffer.
***************
*** 1627,1632 ****
--- 1875,1882 ----
initStringInfo(&buf);
+ formatted_log_time[0] = '\0';
+
log_line_prefix(&buf);
appendStringInfo(&buf, "%s: ", error_severity(edata->elevel));
***************
*** 1766,1772 ****
* syslogger. Otherwise, just do a vanilla write to stderr.
*/
if (redirection_done && !am_syslogger)
! write_pipe_chunks(fileno(stderr), buf.data, buf.len);
#ifdef WIN32
/*
* In a win32 service environment, there is no usable stderr. Capture
--- 2016,2022 ----
* syslogger. Otherwise, just do a vanilla write to stderr.
*/
if (redirection_done && !am_syslogger)
! write_pipe_chunks(buf.data, buf.len, LOG_DESTINATION_STDERR);
#ifdef WIN32
/*
* In a win32 service environment, there is no usable stderr. Capture
***************
*** 1782,1790 ****
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);
}
--- 2032,2062 ----
write(fileno(stderr), buf.data, buf.len);
}
+ if (Log_destination & LOG_DESTINATION_CSVLOG)
+ {
+ if (redirection_done || am_syslogger)
+ {
+ /* send CSV data if it's safe to do so (syslogger doesn't need
+ * the pipe)
+ */
+ write_csvlog(edata);
+ }
+ else
+ {
+ char * msg = _("Not safe to send CSV data\n");
+ write(fileno(stderr),msg,strlen(msg));
+ if ( ! (Log_destination & LOG_DESTINATION_STDERR) &&
+ whereToSendOutput != DestDebug)
+ {
+ /* write message to stderr unless we just sent it above */
+ 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, LOG_DESTINATION_STDERR);
pfree(buf.data);
}
***************
*** 1793,1802 ****
* Send data to the syslogger using the chunked protocol
*/
static void
! write_pipe_chunks(int fd, char *data, int len)
{
PipeProtoChunk p;
Assert(len > 0);
p.proto.nuls[0] = p.proto.nuls[1] = '\0';
--- 2065,2076 ----
* Send data to the syslogger using the chunked protocol
*/
static void
! write_pipe_chunks(char *data, int len, int dest)
{
PipeProtoChunk p;
+ int fd = fileno(stderr);
+
Assert(len > 0);
p.proto.nuls[0] = p.proto.nuls[1] = '\0';
***************
*** 1805,1811 ****
/* write all but the last chunk */
while (len > PIPE_MAX_PAYLOAD)
{
! p.proto.is_last = 'f';
p.proto.len = PIPE_MAX_PAYLOAD;
memcpy(p.proto.data, data, PIPE_MAX_PAYLOAD);
write(fd, &p, PIPE_HEADER_SIZE + PIPE_MAX_PAYLOAD);
--- 2079,2085 ----
/* write all but the last chunk */
while (len > PIPE_MAX_PAYLOAD)
{
! p.proto.is_last = (dest == LOG_DESTINATION_CSVLOG ? 'F' : 'f');
p.proto.len = PIPE_MAX_PAYLOAD;
memcpy(p.proto.data, data, PIPE_MAX_PAYLOAD);
write(fd, &p, PIPE_HEADER_SIZE + PIPE_MAX_PAYLOAD);
***************
*** 1814,1820 ****
}
/* write the last chunk */
! p.proto.is_last = 't';
p.proto.len = len;
memcpy(p.proto.data, data, len);
write(fd, &p, PIPE_HEADER_SIZE + len);
--- 2088,2094 ----
}
/* write the last chunk */
! p.proto.is_last = (dest == LOG_DESTINATION_CSVLOG ? 'T' : 't');
p.proto.len = len;
memcpy(p.proto.data, data, len);
write(fd, &p, PIPE_HEADER_SIZE + len);
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/misc/guc.c,v
retrieving revision 1.411
diff -c -r1.411 guc.c
*** src/backend/utils/misc/guc.c 8 Aug 2007 16:00:46 -0000 1.411
--- src/backend/utils/misc/guc.c 8 Aug 2007 16:32:24 -0000
***************
*** 2240,2246 ****
{"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
},
&log_destination_string,
--- 2240,2246 ----
{"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
},
&log_destination_string,
***************
*** 6312,6317 ****
--- 6312,6319 ----
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.223
diff -c -r1.223 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample 4 Aug 2007 01:26:54 -0000 1.223
--- src/backend/utils/misc/postgresql.conf.sample 8 Aug 2007 16:32:24 -0000
***************
*** 229,236 ****
# - 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:
#redirect_stderr = off # Enable capturing of stderr into log
--- 229,237 ----
# - Where to Log -
#log_destination = 'stderr' # Valid values are combinations of
! # stderr, csvlog, syslog and eventlog,
# depending on platform.
+ # csvlog requires redirect_stderr to be on
# This is used when logging to stderr:
#redirect_stderr = off # Enable capturing of stderr into log
Index: src/include/postmaster/syslogger.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/postmaster/syslogger.h,v
retrieving revision 1.10
diff -c -r1.10 syslogger.h
*** src/include/postmaster/syslogger.h 25 Jul 2007 12:22:53 -0000 1.10
--- src/include/postmaster/syslogger.h 8 Aug 2007 16:32:25 -0000
***************
*** 24,32 ****
* also cope with non-protocol data coming down the pipe, though we cannot
* guarantee long strings won't get split apart.
*
! * We use 't' or 'f' instead of a bool for is_last to make the protocol a tiny
! * bit more robust against finding a false double nul byte prologue. But we
! * still might find it in the len and/or pid bytes unless we're careful.
*/
#ifdef PIPE_BUF
--- 24,32 ----
* also cope with non-protocol data coming down the pipe, though we cannot
* guarantee long strings won't get split apart.
*
! * We use non-nul bytes in is_last to make the protocol a tiny bit
! * more robust against finding a false double nul byte prologue. But
! * we still might find it in the len and/or pid bytes unless we're careful.
*/
#ifdef PIPE_BUF
***************
*** 46,52 ****
char nuls[2]; /* always \0\0 */
uint16 len; /* size of this chunk (counts data only) */
int32 pid; /* writer's pid */
! char is_last; /* last chunk of message? 't' or 'f' */
char data[1]; /* data payload starts here */
} PipeProtoHeader;
--- 46,54 ----
char nuls[2]; /* always \0\0 */
uint16 len; /* size of this chunk (counts data only) */
int32 pid; /* writer's pid */
! char is_last; /* last chunk of message? 't' or 'f'
! * ('T' or 'F' for CSV case)
! */
char data[1]; /* data payload starts here */
} PipeProtoHeader;
***************
*** 79,85 ****
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[]);
--- 81,87 ----
extern int SysLogger_Start(void);
! extern void write_syslogger_file(const char *buffer, int count, int dest);
#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.87
diff -c -r1.87 elog.h
*** src/include/utils/elog.h 25 Jul 2007 12:22:54 -0000 1.87
--- src/include/utils/elog.h 8 Aug 2007 16:32:25 -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);
---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?
http://www.postgresql.org/docs/faq
