Thread: Re: WIP CSV logs
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.
cheers
andrew
Index: src/backend/postmaster/postmaster.c
===================================================================
RCS file: /projects/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 01:42:29 -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];
***************
*** 1225,1231 ****
}
/* If we have lost the system logger, try to start a new one */
! if (SysLoggerPID == 0 && Redirect_stderr)
SysLoggerPID = SysLogger_Start();
/*
--- 1227,1234 ----
}
/* 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 ****
--- 1778,1795 ----
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 ****
--- 3971,3977 ----
#endif
memcpy(¶m->syslogPipe, &syslogPipe, sizeof(syslogPipe));
+ memcpy(¶m->csvlogPipe, &csvlogPipe, sizeof(csvlogPipe));
strlcpy(param->my_exec_path, my_exec_path, MAXPGPATH);
***************
*** 4161,4166 ****
--- 4173,4179 ----
#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: /projects/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 01:42:30 -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;
***************
*** 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);
--- 185,191 ----
* 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 ****
--- 211,237 ----
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 */
--- 274,299 ----
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 ****
--- 314,320 ----
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)
{
--- 376,389 ----
* 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 */
--- 392,458 ----
(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 ****
--- 467,482 ----
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;
/*
--- 498,509 ----
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
--- 518,579 ----
* 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()))
--- 584,620 ----
* 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);
--- 648,654 ----
/* 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;
}
--- 682,696 ----
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";
--- 709,719 ----
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 ****
--- 726,736 ----
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 ****
--- 738,749 ----
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
--- 767,773 ----
{
int fd;
! Assert(argc == 6);
argv += 3;
#ifndef WIN32
***************
*** 624,629 ****
--- 778,790 ----
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 ****
--- 797,813 ----
}
}
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))
--- 842,857 ----
* 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
--- 915,921 ----
* 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);
}
}
--- 942,955 ----
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;
}
--- 975,981 ----
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++)
--- 994,1009 ----
* 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);
}
--- 1011,1017 ----
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
*
--- 1021,1031 ----
* 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 */
--- 1034,1072 ----
* 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))
--- 1086,1107 ----
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);
}
}
--- 1119,1125 ----
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)
--- 1127,1167 ----
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 ****
--- 1177,1212 ----
*/
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;
--- 1241,1270 ----
/* 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 ****
--- 1289,1301 ----
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: /projects/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 01:42:32 -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,137 ----
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);
+ static size_t escape_string_literal(char *to, const char *from);
/*
* 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':
{
--- 1500,1506 ----
appendStringInfo(buf, "%ld", log_line_number);
break;
case 'm':
! get_timestamp(buf);
break;
case 't':
{
***************
*** 1635,1640 ****
--- 1607,1613 ----
{
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');
--- 1616,1623 ----
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
--- 1732,1739 ----
#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
--- 1745,1752 ----
* 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);
}
--- 1755,1768 ----
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 ****
--- 2174,2483 ----
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, char* data)
+ {
+ 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);
+ }
+
+ 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);
+ }
+
+ /*
+ * Escapes special characters in the string to conform
+ * with the csv type output.
+ * Replaces " with "", since that is the PostgreSQL default for QUOTE/ESCAPE
+ */
+ static size_t
+ escape_string_literal(char *to, const char *from)
+ {
+ const char *source = from;
+ char *target = to;
+ size_t remaining = 0;
+ int client_encoding = 0;
+
+ if (from == NULL)
+ return remaining;
+
+ remaining = strlen(from);
+
+ while (remaining > 0 && *source != '\0')
+ {
+ char c = *source;
+ int len;
+ int i;
+
+ /* Apply quoting if needed */
+ if (c == '"')
+ *target++ = c;
+ /* Copy the character */
+ *target++ = c;
+ source++;
+ remaining--;
+ }
+
+ /* Write the terminating NUL character. */
+ *target = '\0';
+
+ return target - to;
+ }
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/utils/misc/guc.c,v
retrieving revision 1.402
diff -c -r1.402 guc.c
*** src/backend/utils/misc/guc.c 21 Jun 2007 22:59:12 -0000 1.402
--- src/backend/utils/misc/guc.c 29 Jun 2007 01:42:36 -0000
***************
*** 2212,2218 ****
{
{"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
},
--- 2212,2218 ----
{
{"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
},
***************
*** 6279,6284 ****
--- 6279,6286 ----
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: /projects/cvsroot/pgsql/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.216
diff -c -r1.216 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample 3 Jun 2007 17:08:15 -0000 1.216
--- src/backend/utils/misc/postgresql.conf.sample 29 Jun 2007 01:42:37 -0000
***************
*** 227,233 ****
# - 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:
--- 227,233 ----
# - 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:
***************
*** 235,241 ****
# 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.
--- 235,241 ----
# 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/postmaster/syslogger.h
===================================================================
RCS file: /projects/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 01:42:37 -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: /projects/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 01:42:38 -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);
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);
Andrew Dunstan wrote: > > 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. I'm not going to be able to look at this before Monday I'm afraid. Not sure if Magnus has more time before then. Regards, Dave.