From: Andrew Dunstan Date: Sun, 19 Aug 2007 01:41:25 +0000 (+0000) Subject: Provide for logfiles in machine readable CSV format. In consequence, rename X-Git-Tag: REL9_0_0~5199 X-Git-Url: http://git.osdn.net/view?a=commitdiff_plain;h=fd801f4faa8e0f00bc314b16549e3d8e8aa1b653;p=pg-rex%2Fsyncrep.git Provide for logfiles in machine readable CSV format. In consequence, rename redirect_stderr to logging_collector. Original patch from Arul Shaji, subsequently modified by Greg Smith, and then heavily modified by me. --- diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 0259e4c31f..1f0e2005c0 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -1,4 +1,4 @@ - + Server Configuration @@ -2261,7 +2261,7 @@ SELECT * FROM parent WHERE key = 2400; PostgreSQL supports several methods for logging server messages, including - stderr and + stderr, csvlog and syslog. On Windows, eventlog is also supported. Set this parameter to a list of desired log destinations separated by @@ -2270,17 +2270,24 @@ SELECT * FROM parent WHERE key = 2400; This parameter can only be set in the postgresql.conf file or on the server command line. + If log_destination is set to csvlog, + the log is output as comma seperated values. The format is: + timestamp with milliseconds, username, database name, session id, host:port number, + process id, per process line number, command tag, session start time, transaction id, + error severity, SQL state code, statement/error message. + - - redirect_stderr (boolean) + + logging_collector (boolean) - redirect_stderr configuration parameter + logging_collector configuration parameter - This parameter allows messages sent to stderr to be + This parameter allows messages sent to stderr, + and CSV logs, to be captured and redirected into log files. This method, in combination with logging to stderr, is often more useful than @@ -2288,6 +2295,8 @@ SELECT * FROM parent WHERE key = 2400; might not appear in syslog output (a common example is dynamic-linker failure messages). This parameter can only be set at server start. + start_log_collector must be enabled to generate + CSV logs. @@ -2299,8 +2308,8 @@ SELECT * FROM parent WHERE key = 2400; - When redirect_stderr is enabled, this parameter - determines the directory in which log files will be created. + When logging_collector is enabled, + this parameter determines the directory in which log files will be created. It can be specified as an absolute path, or relative to the cluster data directory. This parameter can only be set in the postgresql.conf @@ -2316,8 +2325,8 @@ SELECT * FROM parent WHERE key = 2400; - When redirect_stderr is enabled, this parameter - sets the file names of the created log files. The value + When logging_collector is enabled, + this parameter sets the file names of the created log files. The value is treated as a strftime pattern, so %-escapes can be used to specify time-varying file names. (Note that if there are @@ -2332,6 +2341,14 @@ SELECT * FROM parent WHERE key = 2400; This parameter can only be set in the postgresql.conf file or on the server command line. + + If log_destination is set to csvlog, + .csv will be appended to the timestamped + log_filename to create the final log file name. + (If log_filename ends in .log, the suffix is overwritten.) + In the case of the example above, the + file name will be server_log.1093827753.csv + @@ -2342,8 +2359,8 @@ SELECT * FROM parent WHERE key = 2400; - When redirect_stderr is enabled, this parameter - determines the maximum lifetime of an individual log file. + When logging_collector is enabled, + this parameter determines the maximum lifetime of an individual log file. After this many minutes have elapsed, a new log file will be created. Set to zero to disable time-based creation of new log files. @@ -2360,8 +2377,8 @@ SELECT * FROM parent WHERE key = 2400; - When redirect_stderr is enabled, this parameter - determines the maximum size of an individual log file. + When logging_collector is enabled, + this parameter determines the maximum size of an individual log file. After this many kilobytes have been emitted into a log file, a new log file will be created. Set to zero to disable size-based creation of new log files. @@ -2378,8 +2395,8 @@ SELECT * FROM parent WHERE key = 2400; - When redirect_stderr is enabled, this parameter will cause - PostgreSQL to truncate (overwrite), + When logging_collector is enabled, + this parameter will cause PostgreSQL to truncate (overwrite), rather than append to, any existing log file of the same name. However, truncation will occur only when a new file is being opened due to time-based rotation, not during server startup or size-based @@ -2599,7 +2616,7 @@ SELECT * FROM parent WHERE key = 2400; The server's standard output and standard error are redirected to /dev/null, so any messages sent to them will be lost. Unless syslog logging is selected or - redirect_stderr is enabled, using this parameter + start_log_collector is enabled, using this parameter is discouraged because it makes it impossible to see error messages. This parameter can only be set at server start. @@ -3067,6 +3084,94 @@ SELECT * FROM parent WHERE key = 2400; + + Using the csvlog + + + Including csvlog in the log_destination list + provides a convenient way to import log files into a database table. + Here is a sample table definition for storing csvlog output: + + + +CREATE TABLE postgres_log +( + log_time timestamp, + username text, + database_name text, + sessionid text not null, + connection_from text, + process_id text, + process_line_num int not null, + command_tag text, + session_start_time timestamp, + transaction_id int, + error_severity text, + sql_state_code text, + statement text, + PRIMARY KEY (sessionid, process_line_num) +); + + + + + In order to import into this table, use the COPY FROM command: + + + +COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv; + + + + There are a few things you need to import csvlog files easily and + automatically: + + + + + Use a consistant, predictable naming scheme for your log files + with log_filename. This lets you predict what +the file name will be when it is ready to be imported. +guess what + the file name will be and know when an individual log file is + complete and therefore ready to be imported. + + + + + + Set log_rotation_size to 0 to disable + size-based log rotation, as it makes the log filename difficult + to predict. + + + + + + Set log_truncate_on_rotate = on so that old + log data isn't mixed with the new in the same file. + + + + + + The example above includes a useful primary key on the log + file data, which will protect against accidentally importing + the same information twice. The COPY command commits all of + the data it imports at one time, and any single error will + cause the entire import to fail. + If you import a partial log file and later import the file again + when it is complete, the primary key violation will cause the + import to fail. Wait until the log is complete and closed before + import. This will also protect against accidently importing a + partial line that hasn't been completely written, which would + also cause the COPY to fail. + + + + + + diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml index 52858efc60..97b7160113 100644 --- a/doc/src/sgml/func.sgml +++ b/doc/src/sgml/func.sgml @@ -1,4 +1,4 @@ - + Functions and Operators @@ -11254,9 +11254,9 @@ SELECT set_config('log_statement_stats', 'off', false); pg_rotate_logfile signals the log-file manager to switch - to a new output file immediately. This works only when - redirect_stderr is used for logging, since otherwise there - is no log-file manager subprocess. + to a new output file immediately. This works only when the built-in + log collector if running, since otherwise there is no log-file manager + subprocess. diff --git a/doc/src/sgml/maintenance.sgml b/doc/src/sgml/maintenance.sgml index 40e9527d0c..8090bbe838 100644 --- a/doc/src/sgml/maintenance.sgml +++ b/doc/src/sgml/maintenance.sgml @@ -1,4 +1,4 @@ - + Routine Database Maintenance Tasks @@ -691,10 +691,11 @@ analyze threshold = analyze base threshold + analyze scale factor * number of tu A better approach is to send the server's stderr output to some type of log rotation program. There is a built-in log rotation program, which you can use by - setting the configuration parameter redirect_stderr to + setting the configuration parameter logging_collector to true in postgresql.conf. The control parameters for this program are described in . + linkend="runtime-config-logging-where">. You can also use this approach + to capture the log data in machine readable CSV format. diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c index 621b38c270..ab039f0b41 100644 --- a/src/backend/postmaster/postmaster.c +++ b/src/backend/postmaster/postmaster.c @@ -37,7 +37,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/postmaster/postmaster.c,v 1.540 2007/08/09 01:18:43 tgl Exp $ + * $PostgreSQL: pgsql/src/backend/postmaster/postmaster.c,v 1.541 2007/08/19 01:41:24 adunstan Exp $ * * NOTES * @@ -1282,8 +1282,8 @@ ServerLoop(void) } } - /* If we have lost the system logger, try to start a new one */ - if (SysLoggerPID == 0 && Redirect_stderr) + /* If we have lost the log collector, try to start a new one */ + if (SysLoggerPID == 0 && Logging_collector) SysLoggerPID = SysLogger_Start(); /* diff --git a/src/backend/postmaster/syslogger.c b/src/backend/postmaster/syslogger.c index cd3793497b..4e75e8d6d6 100644 --- a/src/backend/postmaster/syslogger.c +++ b/src/backend/postmaster/syslogger.c @@ -18,7 +18,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/postmaster/syslogger.c,v 1.36 2007/08/04 01:26:53 tgl Exp $ + * $PostgreSQL: pgsql/src/backend/postmaster/syslogger.c,v 1.37 2007/08/19 01:41:24 adunstan Exp $ * *------------------------------------------------------------------------- */ @@ -64,10 +64,10 @@ /* - * GUC parameters. Redirect_stderr cannot be changed after postmaster + * GUC parameters. Logging_collector cannot be changed after postmaster * start, but the rest can change at SIGHUP. */ -bool Redirect_stderr = false; +bool Logging_collector = false; int Log_RotationAge = HOURS_PER_DAY * MINS_PER_HOUR; int Log_RotationSize = 10 * 1024; char *Log_directory = NULL; @@ -87,7 +87,9 @@ extern bool redirection_done; static pg_time_t next_rotation_time; static bool pipe_eof_seen = false; static FILE *syslogFile = NULL; +static FILE *csvlogFile = NULL; static char *last_file_name = NULL; +static char *last_csvfile_name = NULL; /* * Buffers for saving partial messages from different backends. We don't expect @@ -132,12 +134,13 @@ 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); +static void open_csvlogfile(void); #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 logfile_rotate(bool time_based_rotation, int size_rotation_for); +static char *logfile_getname(pg_time_t timestamp, char * suffix); static void set_next_rotation_time(void); static void sigHupHandler(SIGNAL_ARGS); static void sigUsr1Handler(SIGNAL_ARGS); @@ -281,7 +284,7 @@ SysLoggerMain(int argc, char *argv[]) for (;;) { bool time_based_rotation = false; - + int size_rotation_for = 0; #ifndef WIN32 int bytesRead; int rc; @@ -336,11 +339,20 @@ SysLoggerMain(int argc, char *argv[]) { /* Do a rotation if file is too big */ if (ftell(syslogFile) >= Log_RotationSize * 1024L) + { + rotation_requested = true; + size_rotation_for |= LOG_DESTINATION_STDERR; + } + if (csvlogFile != NULL && ftell(csvlogFile) >= Log_RotationSize * 1024L) + { rotation_requested = true; + size_rotation_for |= LOG_DESTINATION_CSVLOG; + } + } if (rotation_requested) - logfile_rotate(time_based_rotation); + logfile_rotate(time_based_rotation, size_rotation_for); #ifndef WIN32 @@ -405,7 +417,10 @@ SysLoggerMain(int argc, char *argv[]) if (pipe_eof_seen) { - ereport(LOG, + /* seeing this message on the real stderr is annoying - so we + * make it DEBUG1 to suppress in normal use. + */ + ereport(DEBUG1, (errmsg("logger shutting down"))); /* @@ -429,7 +444,7 @@ SysLogger_Start(void) pid_t sysloggerPid; char *filename; - if (!Redirect_stderr) + if (!Logging_collector) return 0; /* @@ -477,7 +492,7 @@ SysLogger_Start(void) * The initial logfile is created right in the postmaster, to verify that * the Log_directory is writable. */ - filename = logfile_getname(time(NULL)); + filename = logfile_getname(time(NULL), NULL); syslogFile = fopen(filename, "a"); @@ -688,6 +703,7 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer) { char *cursor = logbuffer; int count = *bytes_in_logbuffer; + int dest = LOG_DESTINATION_STDERR; /* While we have enough for a header, process data... */ while (count >= (int) sizeof(PipeProtoHeader)) @@ -700,7 +716,8 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer) if (p.nuls[0] == '\0' && p.nuls[1] == '\0' && p.len > 0 && p.len <= PIPE_MAX_PAYLOAD && p.pid != 0 && - (p.is_last == 't' || p.is_last == 'f')) + (p.is_last == 't' || p.is_last == 'f' || + p.is_last == 'T' || p.is_last == 'F' )) { chunklen = PIPE_HEADER_SIZE + p.len; @@ -708,7 +725,10 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer) if (count < chunklen) break; - if (p.is_last == 'f') + dest = (p.is_last == 'T' || p.is_last == 'F' ) ? + LOG_DESTINATION_CSVLOG : LOG_DESTINATION_STDERR; + + if (p.is_last == 'f' || p.is_last == 'F') { /* * Save a complete non-final chunk in the per-pid buffer @@ -751,7 +771,8 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer) * 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); + write_syslogger_file(cursor + PIPE_HEADER_SIZE, p.len, + dest); } } else @@ -778,14 +799,15 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer) appendBinaryStringInfo(str, cursor + PIPE_HEADER_SIZE, p.len); - write_syslogger_file(str->data, str->len); + write_syslogger_file(str->data, str->len, dest); saved_chunks[existing_slot].pid = 0; pfree(str->data); } else { /* The whole message was one chunk, evidently. */ - write_syslogger_file(cursor + PIPE_HEADER_SIZE, p.len); + write_syslogger_file(cursor + PIPE_HEADER_SIZE, p.len, + dest); } } @@ -811,7 +833,8 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer) if (cursor[chunklen] == '\0') break; } - write_syslogger_file(cursor, chunklen); + /* fall back on the stderr log as the destination */ + write_syslogger_file(cursor, chunklen, LOG_DESTINATION_STDERR); cursor += chunklen; count -= chunklen; } @@ -841,7 +864,7 @@ flush_pipe_input(char *logbuffer, int *bytes_in_logbuffer) if (saved_chunks[i].pid != 0) { str = &(saved_chunks[i].data); - write_syslogger_file(str->data, str->len); + write_syslogger_file(str->data, str->len, LOG_DESTINATION_STDERR); saved_chunks[i].pid = 0; pfree(str->data); } @@ -851,7 +874,8 @@ flush_pipe_input(char *logbuffer, int *bytes_in_logbuffer) * remove any protocol headers that may exist in it. */ if (*bytes_in_logbuffer > 0) - write_syslogger_file(logbuffer, *bytes_in_logbuffer); + write_syslogger_file(logbuffer, *bytes_in_logbuffer, + LOG_DESTINATION_STDERR); *bytes_in_logbuffer = 0; } @@ -869,15 +893,21 @@ flush_pipe_input(char *logbuffer, int *bytes_in_logbuffer) * even though its stderr does not point at the syslog pipe. */ void -write_syslogger_file(const char *buffer, int count) +write_syslogger_file(const char *buffer, int count, int destination) { int rc; + FILE * logfile; + + if (destination == LOG_DESTINATION_CSVLOG && csvlogFile == NULL) + open_csvlogfile(); + + logfile = destination == LOG_DESTINATION_CSVLOG ? csvlogFile : syslogFile ; #ifndef WIN32 - rc = fwrite(buffer, 1, count, syslogFile); + rc = fwrite(buffer, 1, count, logfile); #else EnterCriticalSection(&sysfileSection); - rc = fwrite(buffer, 1, count, syslogFile); + rc = fwrite(buffer, 1, count, logfile); LeaveCriticalSection(&sysfileSection); #endif @@ -939,12 +969,45 @@ pipeThread(void *arg) #endif /* WIN32 */ /* + * open the csv log file - we do this opportunistically, because + * we don't know if CSV logging will be wanted. + */ +static void +open_csvlogfile(void) +{ + char *filename; + FILE *fh; + + filename = logfile_getname(time(NULL),".csv"); + + fh = fopen(filename, "a"); + + if (!fh) + ereport(FATAL, + (errcode_for_file_access(), + (errmsg("could not create log file \"%s\": %m", + filename)))); + + setvbuf(fh, NULL, LBF_MODE, 0); + +#ifdef WIN32 + _setmode(_fileno(fh), _O_TEXT); /* use CRLF line endings on Windows */ +#endif + + csvlogFile = fh; + + pfree(filename); + +} + +/* * perform logfile rotation */ static void -logfile_rotate(bool time_based_rotation) +logfile_rotate(bool time_based_rotation, int size_rotation_for) { char *filename; + char *csvfilename; FILE *fh; rotation_requested = false; @@ -955,9 +1018,17 @@ logfile_rotate(bool time_based_rotation) * file name when we don't do the rotation immediately. */ if (time_based_rotation) - filename = logfile_getname(next_rotation_time); + { + filename = logfile_getname(next_rotation_time, NULL); + if (csvlogFile != NULL) + csvfilename = logfile_getname(next_rotation_time, ".csv"); + } else - filename = logfile_getname(time(NULL)); + { + filename = logfile_getname(time(NULL), NULL); + if (csvlogFile != NULL) + csvfilename = logfile_getname(time(NULL), ".csv"); + } /* * Decide whether to overwrite or append. We can overwrite if (a) @@ -970,61 +1041,132 @@ logfile_rotate(bool time_based_rotation) * postmaster because it ain't gonna work in the EXEC_BACKEND case.) So we * will always append in that situation, even though truncating would * usually be safe. + * + * For consistency, we treat CSV logs the same even though they aren't + * opened in the postmaster. */ - if (Log_truncate_on_rotation && time_based_rotation && - last_file_name != NULL && strcmp(filename, last_file_name) != 0) - fh = fopen(filename, "w"); - else - fh = fopen(filename, "a"); - - if (!fh) + if (time_based_rotation || (size_rotation_for & LOG_DESTINATION_STDERR)) { - int saveerrno = errno; + if (Log_truncate_on_rotation && time_based_rotation && + last_file_name != NULL && strcmp(filename, last_file_name) != 0) + fh = fopen(filename, "w"); + else + fh = fopen(filename, "a"); - ereport(LOG, - (errcode_for_file_access(), - errmsg("could not open new log file \"%s\": %m", - filename))); - - /* - * ENFILE/EMFILE are not too surprising on a busy system; just keep - * using the old file till we manage to get a new one. Otherwise, - * assume something's wrong with Log_directory and stop trying to - * create files. - */ - if (saveerrno != ENFILE && saveerrno != EMFILE) + if (!fh) { + int saveerrno = errno; + ereport(LOG, - (errmsg("disabling automatic rotation (use SIGHUP to reenable)"))); - Log_RotationAge = 0; - Log_RotationSize = 0; + (errcode_for_file_access(), + errmsg("could not open new log file \"%s\": %m", + filename))); + + /* + * ENFILE/EMFILE are not too surprising on a busy system; just keep + * using the old file till we manage to get a new one. Otherwise, + * assume something's wrong with Log_directory and stop trying to + * create files. + */ + if (saveerrno != ENFILE && saveerrno != EMFILE) + { + ereport(LOG, + (errmsg("disabling automatic rotation (use SIGHUP to reenable)"))); + Log_RotationAge = 0; + Log_RotationSize = 0; + } + pfree(filename); + return; } - pfree(filename); - return; + + setvbuf(fh, NULL, LBF_MODE, 0); + +#ifdef WIN32 + _setmode(_fileno(fh), _O_TEXT); /* use CRLF line endings on Windows */ +#endif + + /* On Windows, need to interlock against data-transfer thread */ +#ifdef WIN32 + EnterCriticalSection(&sysfileSection); +#endif + fclose(syslogFile); + syslogFile = fh; +#ifdef WIN32 + LeaveCriticalSection(&sysfileSection); +#endif + + /* instead of pfree'ing filename, remember it for next time */ + if (last_file_name != NULL) + pfree(last_file_name); + last_file_name = filename; + + } - setvbuf(fh, NULL, LBF_MODE, 0); + /* same as above, but for csv file. */ + + if (csvlogFile != NULL && ( + time_based_rotation || + (size_rotation_for & LOG_DESTINATION_STDERR))) + { + if (Log_truncate_on_rotation && time_based_rotation && + last_csvfile_name != NULL && + strcmp(csvfilename, last_csvfile_name) != 0) + + fh = fopen(csvfilename, "w"); + else + fh = fopen(csvfilename, "a"); + + if (!fh) + { + int saveerrno = errno; + + ereport(LOG, + (errcode_for_file_access(), + errmsg("could not open new log file \"%s\": %m", + csvfilename))); + + /* + * ENFILE/EMFILE are not too surprising on a busy system; just keep + * using the old file till we manage to get a new one. Otherwise, + * assume something's wrong with Log_directory and stop trying to + * create files. + */ + if (saveerrno != ENFILE && saveerrno != EMFILE) + { + ereport(LOG, + (errmsg("disabling automatic rotation (use SIGHUP to reenable)"))); + Log_RotationAge = 0; + Log_RotationSize = 0; + } + pfree(csvfilename); + return; + } + + setvbuf(fh, NULL, LBF_MODE, 0); #ifdef WIN32 - _setmode(_fileno(fh), _O_TEXT); /* use CRLF line endings on Windows */ + _setmode(_fileno(fh), _O_TEXT); /* use CRLF line endings on Windows */ #endif - /* On Windows, need to interlock against data-transfer thread */ + /* On Windows, need to interlock against data-transfer thread */ #ifdef WIN32 - EnterCriticalSection(&sysfileSection); + EnterCriticalSection(&sysfileSection); #endif - fclose(syslogFile); - syslogFile = fh; + fclose(csvlogFile); + syslogFile = fh; #ifdef WIN32 - LeaveCriticalSection(&sysfileSection); + LeaveCriticalSection(&sysfileSection); #endif + /* instead of pfree'ing filename, remember it for next time */ + if (last_csvfile_name != NULL) + pfree(last_csvfile_name); + last_csvfile_name = filename; + } + set_next_rotation_time(); - /* instead of pfree'ing filename, remember it for next time */ - if (last_file_name != NULL) - pfree(last_file_name); - last_file_name = filename; } @@ -1034,7 +1176,7 @@ logfile_rotate(bool time_based_rotation) * Result is palloc'd. */ static char * -logfile_getname(pg_time_t timestamp) +logfile_getname(pg_time_t timestamp, char * suffix) { char *filename; int len; @@ -1058,6 +1200,14 @@ logfile_getname(pg_time_t timestamp) Log_filename, (unsigned long) timestamp); } + if (suffix != NULL) + { + len = strlen(filename); + if (len > 4 && (strcmp(filename+(len-4),".log") == 0)) + len -= 4; + strncpy(filename + len, suffix, MAXPGPATH - len); + } + return filename; } diff --git a/src/backend/utils/adt/misc.c b/src/backend/utils/adt/misc.c index 992f7889a2..9683579436 100644 --- a/src/backend/utils/adt/misc.c +++ b/src/backend/utils/adt/misc.c @@ -8,7 +8,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/utils/adt/misc.c,v 1.56 2007/01/05 22:19:41 momjian Exp $ + * $PostgreSQL: pgsql/src/backend/utils/adt/misc.c,v 1.57 2007/08/19 01:41:25 adunstan Exp $ * *------------------------------------------------------------------------- */ @@ -144,10 +144,10 @@ pg_rotate_logfile(PG_FUNCTION_ARGS) (errcode(ERRCODE_INSUFFICIENT_PRIVILEGE), (errmsg("must be superuser to rotate log files")))); - if (!Redirect_stderr) + if (!Logging_collector) { ereport(WARNING, - (errmsg("rotation not possible because log redirection not active"))); + (errmsg("rotation not possible because log collection not active"))); PG_RETURN_BOOL(false); } diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c index 44d0275208..12c9c935de 100644 --- a/src/backend/utils/error/elog.c +++ b/src/backend/utils/error/elog.c @@ -42,7 +42,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/utils/error/elog.c,v 1.193 2007/08/04 19:29:25 tgl Exp $ + * $PostgreSQL: pgsql/src/backend/utils/error/elog.c,v 1.194 2007/08/19 01:41:25 adunstan Exp $ * *------------------------------------------------------------------------- */ @@ -104,6 +104,14 @@ static int errordata_stack_depth = -1; /* index of topmost active frame */ static int recursion_depth = 0; /* to detect actual recursion */ +/* buffers for formatted timestamps that might be used by both + * log_line_prefix and csv logs. + */ + +#define FORMATTED_TS_LEN 128 +static char formatted_start_time[FORMATTED_TS_LEN]; +static char formatted_log_time[FORMATTED_TS_LEN]; + /* Macro for checking errordata_stack_depth is reasonable */ #define CHECK_STACK_DEPTH() \ @@ -124,8 +132,8 @@ static const char *useful_strerror(int errnum); static const char *error_severity(int elevel); static void append_with_tabs(StringInfo buf, const char *str); static bool is_log_level_output(int elevel, int log_min_level); -static void write_pipe_chunks(int fd, char *data, int len); - +static void write_pipe_chunks(char *data, int len, int dest); +static void get_error_message(StringInfo buf, ErrorData *edata); /* * errstart --- begin an error-reporting cycle @@ -1434,12 +1442,14 @@ log_line_prefix(StringInfo buf) /* * 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. + * MyProcPid changes. MyStartTime also changes when MyProcPid does, so + * reset the formatted start timestamp too. */ if (log_my_pid != MyProcPid) { log_line_number = 0; log_my_pid = MyProcPid; + formatted_start_time[0] = '\0'; } log_line_number++; @@ -1498,8 +1508,7 @@ log_line_prefix(StringInfo buf) struct timeval tv; pg_time_t stamp_time; pg_tz *tz; - char strfbuf[128], - msbuf[8]; + char msbuf[8]; gettimeofday(&tv, NULL); stamp_time = (pg_time_t) tv.tv_sec; @@ -1512,16 +1521,16 @@ log_line_prefix(StringInfo buf) */ tz = log_timezone ? log_timezone : gmt_timezone; - pg_strftime(strfbuf, sizeof(strfbuf), + pg_strftime(formatted_log_time, FORMATTED_TS_LEN, /* leave room for milliseconds... */ "%Y-%m-%d %H:%M:%S %Z", pg_localtime(&stamp_time, tz)); /* 'paste' milliseconds into place... */ sprintf(msbuf, ".%03d", (int) (tv.tv_usec / 1000)); - strncpy(strfbuf + 19, msbuf, 4); + strncpy(formatted_log_time + 19, msbuf, 4); - appendStringInfoString(buf, strfbuf); + appendStringInfoString(buf, formatted_log_time); } break; case 't': @@ -1539,18 +1548,18 @@ log_line_prefix(StringInfo buf) } break; case 's': + if (formatted_start_time[0] == '\0') { pg_time_t stamp_time = (pg_time_t) MyStartTime; pg_tz *tz; - char strfbuf[128]; tz = log_timezone ? log_timezone : gmt_timezone; - pg_strftime(strfbuf, sizeof(strfbuf), + pg_strftime(formatted_start_time, FORMATTED_TS_LEN, "%Y-%m-%d %H:%M:%S %Z", pg_localtime(&stamp_time, tz)); - appendStringInfoString(buf, strfbuf); } + appendStringInfoString(buf, formatted_start_time); break; case 'i': if (MyProcPort) @@ -1596,6 +1605,245 @@ log_line_prefix(StringInfo buf) } } + +/* + * append a CSV'd version of a string to a StringInfo + * We use the PostgreSQL defaults for CSV, i.e. quote = escape = '"' + */ + +static inline void +appendCSVLiteral(StringInfo buf, const char* data) +{ + const char * p = data; + char c; + + appendStringInfoCharMacro(buf, '"'); + while ( (c = *p++) != '\0' ) + { + if (c == '"') + appendStringInfoCharMacro(buf, '"'); + appendStringInfoCharMacro(buf, c); + } + appendStringInfoCharMacro(buf, '"'); +} + +/* + * Constructs the error message, depending on the Errordata it gets, + * in CSV (comma seperated values) format. The COPY command + * can then be used to load the messages into a table. + */ + +static void +write_csvlog(ErrorData *edata) +{ + StringInfoData msgbuf; + StringInfoData buf; + + /* static counter for line numbers */ + static long log_line_number = 0; + + /* has counter been reset in current process? */ + static int log_my_pid = 0; + + /* + * This is one of the few places where we'd rather not inherit a static + * variable's value from the postmaster. But since we will, reset it when + * MyProcPid changes. + */ + if (log_my_pid != MyProcPid) + { + log_line_number = 0; + log_my_pid = MyProcPid; + formatted_start_time[0] = '\0'; + } + log_line_number++; + + initStringInfo(&msgbuf); + initStringInfo(&buf); + + /* + * The format of the log output in CSV format: + * timestamp with milliseconds, username, databasename, session id, + * host and port number, process id, process line number, command tag, + * session start time, transaction id, error severity, sql state code, + * statement or error message. + */ + + /* timestamp_with_milliseconds */ + /* + * Check if the timestamp is already calculated for the syslog message, + * if it is, then no need to calculate it again, will use the same, + * else get the current timestamp. This is done to put same timestamp + * in both syslog and csvlog messages. + */ + if (formatted_log_time[0] == '\0') + { + struct timeval tv; + pg_time_t stamp_time; + pg_tz *tz; + char msbuf[8]; + + gettimeofday(&tv, NULL); + stamp_time = (pg_time_t) tv.tv_sec; + + /* + * Normally we print log timestamps in log_timezone, but + * during startup we could get here before that's set. + * If so, fall back to gmt_timezone (which guc.c ensures + * is set up before Log_line_prefix can become nonempty). + */ + tz = log_timezone ? log_timezone : gmt_timezone; + + pg_strftime(formatted_log_time, FORMATTED_TS_LEN, + /* leave room for milliseconds... */ + "%Y-%m-%d %H:%M:%S %Z", + pg_localtime(&stamp_time, tz)); + + /* 'paste' milliseconds into place... */ + sprintf(msbuf, ".%03d", (int) (tv.tv_usec / 1000)); + strncpy(formatted_log_time + 19, msbuf, 4); + } + appendStringInfoString(&buf, formatted_log_time); + appendStringInfoChar(&buf, ','); + + /* username */ + if (MyProcPort) + { + const char *username = MyProcPort->user_name; + if (username == NULL || *username == '\0') + username = _("[unknown]"); + + appendCSVLiteral(&buf, username); + } + appendStringInfoChar(&buf, ','); + + /* databasename */ + if (MyProcPort) + { + const char *dbname = MyProcPort->database_name; + + if (dbname == NULL || *dbname == '\0') + dbname = _("[unknown]"); + + appendCSVLiteral(&buf, dbname); + } + appendStringInfoChar(&buf, ','); + + /* session id */ + appendStringInfo(&buf, "%lx.%x", + (long) MyStartTime, MyProcPid); + appendStringInfoChar(&buf, ','); + + /* Remote host and port */ + if (MyProcPort && MyProcPort->remote_host) + { + appendStringInfo(&buf, "%s", MyProcPort->remote_host); + if (MyProcPort->remote_port && MyProcPort->remote_port[0] != '\0') + appendStringInfo(&buf, ":%s", MyProcPort->remote_port); + } + + appendStringInfoChar(&buf, ','); + + /* Process id */ + if (MyProcPid != 0) + appendStringInfo(&buf, "%d", MyProcPid); + + appendStringInfoChar(&buf, ','); + + /* Line number */ + appendStringInfo(&buf, "%ld", log_line_number); + + appendStringInfoChar(&buf, ','); + + /* PS display */ + if (MyProcPort) + { + const char *psdisp; + int displen; + + psdisp = get_ps_display(&displen); + appendStringInfo(&msgbuf, "%.*s", displen, psdisp); + appendCSVLiteral(&buf, msgbuf.data); + resetStringInfo(&msgbuf); + } + + appendStringInfoChar(&buf, ','); + + /* session start timestamp */ + if (formatted_start_time[0] == '\0') + { + pg_time_t stamp_time = (pg_time_t) MyStartTime; + pg_tz *tz; + + tz = log_timezone ? log_timezone : gmt_timezone; + + pg_strftime(formatted_start_time, FORMATTED_TS_LEN, + "%Y-%m-%d %H:%M:%S %Z", + pg_localtime(&stamp_time, tz)); + } + appendStringInfoString(&buf, formatted_start_time); + appendStringInfoChar(&buf, ','); + + + /* Transaction id */ + if (MyProcPort) + { + if (IsTransactionState()) + appendStringInfo(&buf, "%u", GetTopTransactionId()); + else + appendStringInfo(&buf, "%u", InvalidTransactionId); + } + + appendStringInfoChar(&buf, ','); + + /* Error severity */ + if (error_severity(edata->elevel) != NULL) + appendStringInfo(&buf, "%s,", error_severity(edata->elevel)); + else + appendStringInfoString(&buf, ","); + + /* SQL state code */ + if (Log_error_verbosity >= PGERROR_VERBOSE) + appendStringInfo(&buf, "%s", + unpack_sql_state(edata->sqlerrcode)); + appendStringInfoChar(&buf, ','); + + /* Error message and cursor position if any */ + get_error_message(&msgbuf, edata); + + appendCSVLiteral(&buf, msgbuf.data); + + appendStringInfoChar(&buf, '\n'); + + /* If in the syslogger process, try to write messages direct to file */ + if (am_syslogger) + write_syslogger_file(buf.data, buf.len, LOG_DESTINATION_CSVLOG); + else + write_pipe_chunks(buf.data, buf.len, LOG_DESTINATION_CSVLOG); + + pfree(msgbuf.data); + pfree(buf.data); +} + +/* + * Appends the buffer with the error message and the cursor position. + */ +static void +get_error_message(StringInfo buf, ErrorData *edata) +{ + if (edata->message) + appendStringInfo(buf, "%s", edata->message); + else + appendStringInfo(buf, "%s", _("missing error text")); + + if (edata->cursorpos > 0) + appendStringInfo(buf, _(" at character %d"), + edata->cursorpos); + else if (edata->internalpos > 0) + appendStringInfo(buf, _(" at character %d"), + edata->internalpos); +} + /* * Unpack MAKE_SQLSTATE code. Note that this returns a pointer to a * static buffer. @@ -1627,6 +1875,8 @@ send_message_to_server_log(ErrorData *edata) initStringInfo(&buf); + formatted_log_time[0] = '\0'; + log_line_prefix(&buf); appendStringInfo(&buf, "%s: ", error_severity(edata->elevel)); @@ -1766,7 +2016,7 @@ send_message_to_server_log(ErrorData *edata) * syslogger. Otherwise, just do a vanilla write to stderr. */ if (redirection_done && !am_syslogger) - write_pipe_chunks(fileno(stderr), buf.data, buf.len); + write_pipe_chunks(buf.data, buf.len, LOG_DESTINATION_STDERR); #ifdef WIN32 /* * In a win32 service environment, there is no usable stderr. Capture @@ -1782,9 +2032,31 @@ send_message_to_server_log(ErrorData *edata) write(fileno(stderr), buf.data, buf.len); } + if (Log_destination & LOG_DESTINATION_CSVLOG) + { + if (redirection_done || am_syslogger) + { + /* send CSV data if it's safe to do so (syslogger doesn't need + * the pipe) + */ + write_csvlog(edata); + } + else + { + char * msg = _("Not safe to send CSV data\n"); + write(fileno(stderr),msg,strlen(msg)); + if ( ! (Log_destination & LOG_DESTINATION_STDERR) && + whereToSendOutput != DestDebug) + { + /* write message to stderr unless we just sent it above */ + write(fileno(stderr), buf.data, buf.len); + } + } + } + /* If in the syslogger process, try to write messages direct to file */ if (am_syslogger) - write_syslogger_file(buf.data, buf.len); + write_syslogger_file(buf.data, buf.len, LOG_DESTINATION_STDERR); pfree(buf.data); } @@ -1793,10 +2065,12 @@ send_message_to_server_log(ErrorData *edata) * Send data to the syslogger using the chunked protocol */ static void -write_pipe_chunks(int fd, char *data, int len) +write_pipe_chunks(char *data, int len, int dest) { PipeProtoChunk p; + int fd = fileno(stderr); + Assert(len > 0); p.proto.nuls[0] = p.proto.nuls[1] = '\0'; @@ -1805,7 +2079,7 @@ write_pipe_chunks(int fd, char *data, int len) /* write all but the last chunk */ while (len > PIPE_MAX_PAYLOAD) { - p.proto.is_last = 'f'; + p.proto.is_last = (dest == LOG_DESTINATION_CSVLOG ? 'F' : 'f'); p.proto.len = PIPE_MAX_PAYLOAD; memcpy(p.proto.data, data, PIPE_MAX_PAYLOAD); write(fd, &p, PIPE_HEADER_SIZE + PIPE_MAX_PAYLOAD); @@ -1814,7 +2088,7 @@ write_pipe_chunks(int fd, char *data, int len) } /* write the last chunk */ - p.proto.is_last = 't'; + p.proto.is_last = (dest == LOG_DESTINATION_CSVLOG ? 'T' : 't'); p.proto.len = len; memcpy(p.proto.data, data, len); write(fd, &p, PIPE_HEADER_SIZE + len); diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c index 0f2b479bf9..a05b3be393 100644 --- a/src/backend/utils/misc/guc.c +++ b/src/backend/utils/misc/guc.c @@ -10,7 +10,7 @@ * Written by Peter Eisentraut . * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/utils/misc/guc.c,v 1.412 2007/08/13 19:27:11 tgl Exp $ + * $PostgreSQL: pgsql/src/backend/utils/misc/guc.c,v 1.413 2007/08/19 01:41:25 adunstan Exp $ * *-------------------------------------------------------------------- */ @@ -968,11 +968,11 @@ static struct config_bool ConfigureNamesBool[] = false, NULL, NULL }, { - {"redirect_stderr", PGC_POSTMASTER, LOGGING_WHERE, - gettext_noop("Start a subprocess to capture stderr output into log files."), + {"logging_collector", PGC_POSTMASTER, LOGGING_WHERE, + gettext_noop("Start a subprocess to capture stderr output and/or csvlogs into log files."), NULL }, - &Redirect_stderr, + &Logging_collector, false, NULL, NULL }, { @@ -2241,7 +2241,7 @@ static struct config_string ConfigureNamesString[] = {"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."), + " \"csvlog\" and \"eventlog\", depending on the platform."), GUC_LIST_INPUT }, &log_destination_string, @@ -6313,6 +6313,8 @@ assign_log_destination(const char *value, bool doit, GucSource source) 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; diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index ef6cae299c..8720d18c55 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -229,15 +229,16 @@ # - Where to Log - #log_destination = 'stderr' # Valid values are combinations of - # stderr, syslog and eventlog, + # stderr, csvlog, syslog and eventlog, # depending on platform. + # csvlog requires logging_collector to be on # This is used when logging to stderr: -#redirect_stderr = off # Enable capturing of stderr into log - # files +#logging_collector = off # Enable capturing of stderr and csvlog + # into log files. Required to be on for csvlogs. # (change requires restart) -# These are only used if redirect_stderr is on: +# These are only used if logging_collector 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. diff --git a/src/include/postmaster/syslogger.h b/src/include/postmaster/syslogger.h index 535e4392c4..36125ac5e2 100644 --- a/src/include/postmaster/syslogger.h +++ b/src/include/postmaster/syslogger.h @@ -5,7 +5,7 @@ * * Copyright (c) 2004-2007, PostgreSQL Global Development Group * - * $PostgreSQL: pgsql/src/include/postmaster/syslogger.h,v 1.10 2007/07/25 12:22:53 mha Exp $ + * $PostgreSQL: pgsql/src/include/postmaster/syslogger.h,v 1.11 2007/08/19 01:41:25 adunstan Exp $ * *------------------------------------------------------------------------- */ @@ -24,9 +24,9 @@ * also cope with non-protocol data coming down the pipe, though we cannot * guarantee long strings won't get split apart. * - * We use 't' or 'f' instead of a bool for is_last to make the protocol a tiny - * bit more robust against finding a false double nul byte prologue. But we - * still might find it in the len and/or pid bytes unless we're careful. + * We use non-nul bytes in is_last to make the protocol a tiny bit + * more robust against finding a false double nul byte prologue. But + * we still might find it in the len and/or pid bytes unless we're careful. */ #ifdef PIPE_BUF @@ -46,7 +46,9 @@ typedef struct char nuls[2]; /* always \0\0 */ uint16 len; /* size of this chunk (counts data only) */ int32 pid; /* writer's pid */ - char is_last; /* last chunk of message? 't' or 'f' */ + char is_last; /* last chunk of message? 't' or 'f' + * ('T' or 'F' for CSV case) + */ char data[1]; /* data payload starts here */ } PipeProtoHeader; @@ -61,7 +63,7 @@ typedef union /* GUC options */ -extern bool Redirect_stderr; +extern bool Logging_collector; extern int Log_RotationAge; extern int Log_RotationSize; extern PGDLLIMPORT char *Log_directory; @@ -79,7 +81,7 @@ extern HANDLE syslogPipe[2]; extern int SysLogger_Start(void); -extern void write_syslogger_file(const char *buffer, int count); +extern void write_syslogger_file(const char *buffer, int count, int dest); #ifdef EXEC_BACKEND extern void SysLoggerMain(int argc, char *argv[]); diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h index 0ad41c65b3..6edc02c233 100644 --- a/src/include/utils/elog.h +++ b/src/include/utils/elog.h @@ -7,7 +7,7 @@ * Portions Copyright (c) 1996-2007, PostgreSQL Global Development Group * Portions Copyright (c) 1994, Regents of the University of California * - * $PostgreSQL: pgsql/src/include/utils/elog.h,v 1.87 2007/07/25 12:22:54 mha Exp $ + * $PostgreSQL: pgsql/src/include/utils/elog.h,v 1.88 2007/08/19 01:41:25 adunstan Exp $ * *------------------------------------------------------------------------- */ @@ -291,6 +291,7 @@ extern int Log_destination; #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); diff --git a/src/test/bench/runwisc.sh b/src/test/bench/runwisc.sh index 4a2e237bd7..0012958b48 100755 --- a/src/test/bench/runwisc.sh +++ b/src/test/bench/runwisc.sh @@ -1,5 +1,5 @@ #!/bin/sh -# $PostgreSQL: pgsql/src/test/bench/runwisc.sh,v 1.9 2007/08/01 22:24:32 momjian Exp $ +# $PostgreSQL: pgsql/src/test/bench/runwisc.sh,v 1.10 2007/08/19 01:41:25 adunstan Exp $ if [ ! -d $1 ]; then echo " you must specify a valid data directory " >&2 @@ -14,4 +14,4 @@ echo =============== vacuuming benchmark database... ================= >&2 echo "vacuum" | postgres -D"$1" bench > /dev/null echo =============== running benchmark... ================= >&2 -time postgres -D"$1" -texecutor -tplanner -c log_min_messages=log -c log_destination=stderr -c redirect_stderr=off bench < bench.sql 2>&1 +time postgres -D"$1" -texecutor -tplanner -c log_min_messages=log -c log_destination=stderr -c start_log_collector=off bench < bench.sql 2>&1