WIP - syslogger infrastructure changes
I've been working on a restructure of some of the syslogger
infrastructure with Josh Tolley. Attached is the WIP patch that we
have so far.
First, the patch removes the logging_collector parameter and basically
assumes that logging_collector is always on. With that, it's no longer
necessary to restart your server just to reconfigure the logging, and
it also takes away a confusing parameter (really
"log_destination=stderr, logging_collector=on" is *not* a logical way
to say "log to file"). Instead, it adds a log_destination of "file"
that is the standard log to file. Given that the syslogger is now
always started, those that actually *want* logging to stderr (which I
claim is a low number of people, but that's a different story) will
have it go through the syslogger and then to the stderr of syslogger.
If syslogger is not used at all (say with syslog log target that goes
directly from backend), it'll just sit around doing nothing, and the
cost should be very close to zero.
Second, data transfer from the backends is now in the form of
structured data, and the actual logging message is put together in the
syslogger (today,it's put together in the backend and just sent as a
string to the syslogger). Yes, this means that we will likely send
more data than what's eventually going to be logged, since all fields
don't go out (except with CVS logging, I guess). But you usually don't
send *that* much data in the log. It *does* allow for us to properly
specify multiple log destinations, which we only "almost" can now. For
example, it allows a regular logfile and csvlog at the same time. And
since stderr actually means stderr, you can combine stderr and
logfile.
By putting more available data in the syslogger, this is also intended
to make it easier to make the syslogger functionality more advanced in
the future. This includes the kind of work that Itagaki Takahiro
submitted a patch around recently, and things like being able to write
different things to different logfiles.
As the name says, it's still a WIP, and the code contains both several
FIXME places, and some other non-finished parts so far, but we're
posting it to get comments on the general idea and method for doing
it.
--
Magnus Hagander
Me: http://www.hagander.net/
Work: http://www.redpill-linpro.com/
Attachments:
syslogger_infra.patchtext/x-diff; charset=US-ASCII; name=syslogger_infra.patchDownload
*** a/src/backend/postmaster/postmaster.c
--- b/src/backend/postmaster/postmaster.c
***************
*** 1410,1416 **** ServerLoop(void)
}
/* If we have lost the log collector, try to start a new one */
! if (SysLoggerPID == 0 && Logging_collector)
SysLoggerPID = SysLogger_Start();
/*
--- 1410,1416 ----
}
/* If we have lost the log collector, try to start a new one */
! if (SysLoggerPID == 0)
SysLoggerPID = SysLogger_Start();
/*
*** a/src/backend/postmaster/syslogger.c
--- b/src/backend/postmaster/syslogger.c
***************
*** 64,73 ****
/*
! * GUC parameters. Logging_collector cannot be changed after postmaster
! * start, but the rest can change at SIGHUP.
*/
- bool Logging_collector = false;
int Log_RotationAge = HOURS_PER_DAY * MINS_PER_HOUR;
int Log_RotationSize = 10 * 1024;
char *Log_directory = NULL;
--- 64,71 ----
/*
! * GUC parameters. All parameters can change at SIGHUP.
*/
int Log_RotationAge = HOURS_PER_DAY * MINS_PER_HOUR;
int Log_RotationSize = 10 * 1024;
char *Log_directory = NULL;
***************
*** 135,140 **** static void syslogger_parseArgs(int argc, char *argv[]);
--- 133,139 ----
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);
+ static void write_syslogger_message(char *buffer, int len, bool partial);
#ifdef WIN32
static unsigned int __stdcall pipeThread(void *arg);
***************
*** 454,462 **** SysLogger_Start(void)
pid_t sysloggerPid;
char *filename;
- if (!Logging_collector)
- return 0;
-
/*
* If first time through, create the pipe which will receive stderr
* output.
--- 453,458 ----
***************
*** 777,784 **** 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,
! dest);
}
}
else
--- 773,780 ----
* chances and write out a partial message and hope that
* it's not followed by something from another pid.
*/
! write_syslogger_message(cursor + PIPE_HEADER_SIZE, p.len,
! true);
}
}
else
***************
*** 805,819 **** process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
appendBinaryStringInfo(str,
cursor + PIPE_HEADER_SIZE,
p.len);
! write_syslogger_file(str->data, str->len, dest);
saved_chunks[existing_slot].pid = 0;
pfree(str->data);
}
else
{
/* The whole message was one chunk, evidently. */
! write_syslogger_file(cursor + PIPE_HEADER_SIZE, p.len,
! dest);
}
}
--- 801,815 ----
appendBinaryStringInfo(str,
cursor + PIPE_HEADER_SIZE,
p.len);
! write_syslogger_message(str->data, str->len, false);
saved_chunks[existing_slot].pid = 0;
pfree(str->data);
}
else
{
/* The whole message was one chunk, evidently. */
! write_syslogger_message(cursor + PIPE_HEADER_SIZE, p.len,
! false);
}
}
***************
*** 824,829 **** process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
--- 820,826 ----
else
{
/* Process non-protocol data */
+ StringInfo str;
/*
* Look for the start of a protocol header. If found, dump data
***************
*** 839,846 **** process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
if (cursor[chunklen] == '\0')
break;
}
! /* fall back on the stderr log as the destination */
! write_syslogger_file(cursor, chunklen, LOG_DESTINATION_STDERR);
cursor += chunklen;
count -= chunklen;
}
--- 836,853 ----
if (cursor[chunklen] == '\0')
break;
}
!
! /*
! * send non-protocol data through the error log system, so we can add log_line_prefix and such, and
! * get it send to all the required destinatinos.
! */
! str = makeStringInfo();
! appendBinaryStringInfo(str, cursor, chunklen);
! appendStringInfoChar(str, '\0'); /* ensure zero-termination to be sure */
! elog(WARNING, "Non protocol data: %s", str->data);
! pfree(str->data);
! pfree(str);
!
cursor += chunklen;
count -= chunklen;
}
***************
*** 870,876 **** 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, LOG_DESTINATION_STDERR);
saved_chunks[i].pid = 0;
pfree(str->data);
}
--- 877,883 ----
if (saved_chunks[i].pid != 0)
{
str = &(saved_chunks[i].data);
! write_syslogger_message(str->data, str->len, true);
saved_chunks[i].pid = 0;
pfree(str->data);
}
***************
*** 881,888 **** 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,
! LOG_DESTINATION_STDERR);
*bytes_in_logbuffer = 0;
}
--- 888,901 ----
* remove any protocol headers that may exist in it.
*/
if (*bytes_in_logbuffer > 0)
! {
! str = makeStringInfo();
! appendBinaryStringInfo(str, logbuffer, *bytes_in_logbuffer);
! appendStringInfoChar(str, '\0');
! elog(WARNING, "Unprocessed log data: %s", str->data);
! pfree(str->data);
! pfree(str);
! }
*bytes_in_logbuffer = 0;
}
***************
*** 894,927 **** flush_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
/*
* Write text to the currently open logfile
- *
- * This is exported so that elog.c can call it when am_syslogger is true.
- * This allows the syslogger process to record elog messages of its own,
- * even though its stderr does not point at the syslog pipe.
*/
void
! write_syslogger_file(const char *buffer, int count, int destination)
{
- int rc;
- FILE *logfile;
-
- if (destination == LOG_DESTINATION_CSVLOG && csvlogFile == NULL)
- open_csvlogfile();
-
#ifdef WIN32
EnterCriticalSection(&sysfileSection);
#endif
! logfile = destination == LOG_DESTINATION_CSVLOG ? csvlogFile : syslogFile;
! rc = fwrite(buffer, 1, count, logfile);
#ifdef WIN32
LeaveCriticalSection(&sysfileSection);
#endif
/* can't use ereport here because of possible recursion */
if (rc != count)
write_stderr("could not write to log file: %s\n", strerror(errno));
}
#ifdef WIN32
--- 907,988 ----
/*
* Write text to the currently open logfile
*/
void
! write_syslogger_file(const char *buffer)
{
#ifdef WIN32
EnterCriticalSection(&sysfileSection);
#endif
! fwrite(buffer, 1, strlen(buffer), syslogFile);
#ifdef WIN32
LeaveCriticalSection(&sysfileSection);
#endif
/* can't use ereport here because of possible recursion */
+ /* FIXME: need to look at this! */
+ /*
if (rc != count)
write_stderr("could not write to log file: %s\n", strerror(errno));
+ */
+ }
+
+ /*
+ * Write text to the currently open CSV log file
+ */
+ void
+ write_csvlogger_file(const char *buffer)
+ {
+ if (csvlogFile == NULL)
+ open_csvlogfile();
+
+ #ifdef WIN32
+ EnterCriticalSection(&sysfileSection);
+ #endif
+
+ fwrite(buffer, 1, strlen(buffer), csvlogFile);
+
+ #ifdef WIN32
+ LeaveCriticalSection(&sysfileSection);
+ #endif
+
+ /* FIXME: need an error check? */
+ }
+
+
+ void
+ write_syslogger_message(char *buffer, int count, bool partial)
+ {
+ /* Data always starts with a fixed chunk */
+ syslogger_header *header = (syslogger_header *)buffer;
+
+ /* string data */
+ syslogger_strings strings;
+
+ /* pointer to walk through the strings */
+ char *cp = buffer + sizeof(syslogger_header);
+
+ /* FIXME: overflow handling! */
+ #define NEXT_STRING(var) strings.var = cp; cp += strlen(cp)+1; if (strings.var[0] == '\0') strings.var=NULL;
+ NEXT_STRING(user_name);
+ NEXT_STRING(database_name);
+ NEXT_STRING(message);
+ NEXT_STRING(detail);
+ NEXT_STRING(hint);
+ NEXT_STRING(internalquery);
+ NEXT_STRING(context);
+ NEXT_STRING(debug_query_string);
+ NEXT_STRING(funcname);
+ NEXT_STRING(filename);
+
+ /*
+ * Any local destinations (syslog etc) have already received the log message from
+ * the backend process itself. Route the message to any remote destination, which are those
+ * that required the syslogger process in the first place.
+ */
+ route_log_message(header, &strings, Log_destination & LOG_DESTINATION_REMOTE_MASK);
}
#ifdef WIN32
*** a/src/backend/utils/adt/misc.c
--- b/src/backend/utils/adt/misc.c
***************
*** 146,158 **** pg_rotate_logfile(PG_FUNCTION_ARGS)
(errcode(ERRCODE_INSUFFICIENT_PRIVILEGE),
(errmsg("must be superuser to rotate log files"))));
- if (!Logging_collector)
- {
- ereport(WARNING,
- (errmsg("rotation not possible because log collection not active")));
- PG_RETURN_BOOL(false);
- }
-
SendPostmasterSignal(PMSIGNAL_ROTATE_LOGFILE);
PG_RETURN_BOOL(true);
}
--- 146,151 ----
*** a/src/backend/utils/error/elog.c
--- b/src/backend/utils/error/elog.c
***************
*** 144,150 **** static char formatted_log_time[FORMATTED_TS_LEN];
} while (0)
! static void log_line_prefix(StringInfo buf, ErrorData *edata);
static void send_message_to_server_log(ErrorData *edata);
static void send_message_to_frontend(ErrorData *edata);
static char *expand_fmt_string(const char *fmt, ErrorData *edata);
--- 144,150 ----
} while (0)
! static void log_line_prefix(StringInfo buf, const syslogger_header *header, const syslogger_strings *str);
static void send_message_to_server_log(ErrorData *edata);
static void send_message_to_frontend(ErrorData *edata);
static char *expand_fmt_string(const char *fmt, ErrorData *edata);
***************
*** 153,161 **** static const char *error_severity(int elevel);
static void append_with_tabs(StringInfo buf, const char *str);
static bool is_log_level_output(int elevel, int log_min_level);
static void write_pipe_chunks(char *data, int len, int dest);
! static void write_csvlog(ErrorData *edata);
! static void setup_formatted_log_time(void);
! static void setup_formatted_start_time(void);
/*
--- 153,161 ----
static void append_with_tabs(StringInfo buf, const char *str);
static bool is_log_level_output(int elevel, int log_min_level);
static void write_pipe_chunks(char *data, int len, int dest);
! static void write_csvlog(const syslogger_header *header, const syslogger_strings *str);
! static void setup_formatted_log_time(const pg_time_t *log_time);
! static void setup_formatted_start_time(const pg_time_t *start_time);
/*
***************
*** 1623,1637 **** write_eventlog(int level, const char *line)
* setup formatted_log_time, for consistent times between CSV and regular logs
*/
static void
! setup_formatted_log_time(void)
{
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
--- 1623,1644 ----
* setup formatted_log_time, for consistent times between CSV and regular logs
*/
static void
! setup_formatted_log_time(const pg_time_t *log_time)
{
struct timeval tv;
pg_time_t stamp_time;
pg_tz *tz;
char msbuf[8];
! if (log_time == NULL || 0==0)
! {
! gettimeofday(&tv, NULL);
! stamp_time = (pg_time_t) tv.tv_sec;
! }
! else
! {
! stamp_time = *log_time;
! }
/*
* Normally we print log timestamps in log_timezone, but during startup we
***************
*** 1655,1665 **** setup_formatted_log_time(void)
* setup formatted_start_time
*/
static void
! setup_formatted_start_time(void)
{
! pg_time_t stamp_time = (pg_time_t) MyStartTime;
pg_tz *tz;
/*
* 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
--- 1662,1676 ----
* setup formatted_start_time
*/
static void
! setup_formatted_start_time(const pg_time_t *start_time)
{
! pg_time_t stamp_time;
pg_tz *tz;
+ if (start_time == NULL)
+ stamp_time = (pg_time_t) MyStartTime;
+ else
+ stamp_time = *start_time;
/*
* 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
***************
*** 1677,1683 **** setup_formatted_start_time(void)
* Format tag info for log lines; append to the provided buffer.
*/
static void
! log_line_prefix(StringInfo buf, ErrorData *edata)
{
/* static counter for line numbers */
static long log_line_number = 0;
--- 1688,1694 ----
* Format tag info for log lines; append to the provided buffer.
*/
static void
! log_line_prefix(StringInfo buf, const syslogger_header *header, const syslogger_strings *str)
{
/* static counter for line numbers */
static long log_line_number = 0;
***************
*** 1724,1764 **** log_line_prefix(StringInfo buf, ErrorData *edata)
switch (Log_line_prefix[i])
{
case 'u':
! if (MyProcPort)
! {
! const char *username = MyProcPort->user_name;
!
! if (username == NULL || *username == '\0')
! username = _("[unknown]");
! appendStringInfo(buf, "%s", username);
! }
break;
case 'd':
! if (MyProcPort)
! {
! const char *dbname = MyProcPort->database_name;
!
! if (dbname == NULL || *dbname == '\0')
! dbname = _("[unknown]");
! appendStringInfo(buf, "%s", dbname);
! }
break;
case 'c':
! appendStringInfo(buf, "%lx.%x", (long) (MyStartTime), MyProcPid);
break;
case 'p':
! appendStringInfo(buf, "%d", MyProcPid);
break;
case 'l':
! appendStringInfo(buf, "%ld", log_line_number);
break;
case 'm':
! setup_formatted_log_time();
appendStringInfoString(buf, formatted_log_time);
break;
case 't':
{
! pg_time_t stamp_time = (pg_time_t) time(NULL);
pg_tz *tz;
char strfbuf[128];
--- 1735,1761 ----
switch (Log_line_prefix[i])
{
case 'u':
! appendStringInfo(buf, "%s", str->user_name?str->user_name:"[unknown]");
break;
case 'd':
! appendStringInfo(buf, "%s", str->database_name?str->database_name:"[unknown]");
break;
case 'c':
! appendStringInfo(buf, "%lx.%x", (long)header->starttime, header->pid);
break;
case 'p':
! appendStringInfo(buf, "%d", header->pid);
break;
case 'l':
! appendStringInfo(buf, "%ld", header->linenum);
break;
case 'm':
! setup_formatted_log_time(&header->timestamp);
appendStringInfoString(buf, formatted_log_time);
break;
case 't':
{
! pg_time_t stamp_time = header->timestamp;
pg_tz *tz;
char strfbuf[128];
***************
*** 1772,1781 **** log_line_prefix(StringInfo buf, ErrorData *edata)
break;
case 's':
if (formatted_start_time[0] == '\0')
! setup_formatted_start_time();
appendStringInfoString(buf, formatted_start_time);
break;
case 'i':
if (MyProcPort)
{
const char *psdisp;
--- 1769,1779 ----
break;
case 's':
if (formatted_start_time[0] == '\0')
! setup_formatted_start_time(&header->starttime);
appendStringInfoString(buf, formatted_start_time);
break;
case 'i':
+ /* FIXME */
if (MyProcPort)
{
const char *psdisp;
***************
*** 1786,1821 **** log_line_prefix(StringInfo buf, ErrorData *edata)
}
break;
case 'r':
! 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);
}
break;
case 'h':
! if (MyProcPort && MyProcPort->remote_host)
! appendStringInfo(buf, "%s", MyProcPort->remote_host);
break;
case 'q':
/* in postmaster and friends, stop if %q is seen */
/* in a backend, just ignore */
! if (MyProcPort == NULL)
i = format_len;
break;
case 'v':
/* keep VXID format in sync with lockfuncs.c */
if (MyProc != NULL && MyProc->backendId != InvalidBackendId)
appendStringInfo(buf, "%d/%u",
MyProc->backendId, MyProc->lxid);
break;
case 'x':
! appendStringInfo(buf, "%u", GetTopTransactionIdIfAny());
break;
case 'e':
! appendStringInfoString(buf, unpack_sql_state(edata->sqlerrcode));
break;
case '%':
appendStringInfoChar(buf, '%');
--- 1784,1820 ----
}
break;
case 'r':
! if (str->remote_host != NULL)
{
! appendStringInfo(buf, "%s", str->remote_host);
! if (str->remote_port &&
! str->remote_port[0] != '\0')
appendStringInfo(buf, "(%s)",
! str->remote_port);
}
break;
case 'h':
! if (str->remote_host)
! appendStringInfo(buf, "%s", str->remote_host);
break;
case 'q':
/* in postmaster and friends, stop if %q is seen */
/* in a backend, just ignore */
! if (str->remote_host == NULL)
i = format_len;
break;
case 'v':
+ /* FIXME */
/* keep VXID format in sync with lockfuncs.c */
if (MyProc != NULL && MyProc->backendId != InvalidBackendId)
appendStringInfo(buf, "%d/%u",
MyProc->backendId, MyProc->lxid);
break;
case 'x':
! appendStringInfo(buf, "%u", header->xid);
break;
case 'e':
! appendStringInfoString(buf, unpack_sql_state(header->sqlerrcode));
break;
case '%':
appendStringInfoChar(buf, '%');
***************
*** 1857,1863 **** appendCSVLiteral(StringInfo buf, const char *data)
* format which is described in doc/src/sgml/config.sgml.
*/
static void
! write_csvlog(ErrorData *edata)
{
StringInfoData buf;
bool print_stmt = false;
--- 1856,1862 ----
* format which is described in doc/src/sgml/config.sgml.
*/
static void
! write_csvlog(const syslogger_header *header, const syslogger_strings *str)
{
StringInfoData buf;
bool print_stmt = false;
***************
*** 1891,1917 **** write_csvlog(ErrorData *edata)
* to put same timestamp in both syslog and csvlog messages.
*/
if (formatted_log_time[0] == '\0')
! setup_formatted_log_time();
appendStringInfoString(&buf, formatted_log_time);
appendStringInfoChar(&buf, ',');
/* username */
! if (MyProcPort)
! appendCSVLiteral(&buf, MyProcPort->user_name);
appendStringInfoChar(&buf, ',');
/* database name */
! if (MyProcPort)
! appendCSVLiteral(&buf, MyProcPort->database_name);
appendStringInfoChar(&buf, ',');
/* Process id */
! if (MyProcPid != 0)
! appendStringInfo(&buf, "%d", MyProcPid);
appendStringInfoChar(&buf, ',');
/* Remote host and port */
if (MyProcPort && MyProcPort->remote_host)
{
appendStringInfoChar(&buf, '"');
--- 1890,1914 ----
* to put same timestamp in both syslog and csvlog messages.
*/
if (formatted_log_time[0] == '\0')
! setup_formatted_log_time(&header->timestamp);
appendStringInfoString(&buf, formatted_log_time);
appendStringInfoChar(&buf, ',');
/* username */
! appendCSVLiteral(&buf, str->user_name);
appendStringInfoChar(&buf, ',');
/* database name */
! appendCSVLiteral(&buf, str->database_name);
appendStringInfoChar(&buf, ',');
/* Process id */
! appendStringInfo(&buf, "%d", header->pid);
appendStringInfoChar(&buf, ',');
/* Remote host and port */
+ /* FIXME
if (MyProcPort && MyProcPort->remote_host)
{
appendStringInfoChar(&buf, '"');
***************
*** 1921,1929 **** write_csvlog(ErrorData *edata)
appendStringInfoChar(&buf, '"');
}
appendStringInfoChar(&buf, ',');
/* session id */
! appendStringInfo(&buf, "%lx.%x", (long) MyStartTime, MyProcPid);
appendStringInfoChar(&buf, ',');
/* Line number */
--- 1918,1927 ----
appendStringInfoChar(&buf, '"');
}
appendStringInfoChar(&buf, ',');
+ */
/* session id */
! appendStringInfo(&buf, "%lx.%x", (long) header->starttime, header->pid);
appendStringInfoChar(&buf, ',');
/* Line number */
***************
*** 1931,1936 **** write_csvlog(ErrorData *edata)
--- 1929,1935 ----
appendStringInfoChar(&buf, ',');
/* PS display */
+ /* FIXME
if (MyProcPort)
{
StringInfoData msgbuf;
***************
*** 1946,2014 **** write_csvlog(ErrorData *edata)
pfree(msgbuf.data);
}
appendStringInfoChar(&buf, ',');
/* session start timestamp */
if (formatted_start_time[0] == '\0')
! setup_formatted_start_time();
appendStringInfoString(&buf, formatted_start_time);
appendStringInfoChar(&buf, ',');
/* Virtual transaction id */
/* keep VXID format in sync with lockfuncs.c */
if (MyProc != NULL && MyProc->backendId != InvalidBackendId)
appendStringInfo(&buf, "%d/%u", MyProc->backendId, MyProc->lxid);
appendStringInfoChar(&buf, ',');
/* Transaction id */
appendStringInfo(&buf, "%u", GetTopTransactionIdIfAny());
appendStringInfoChar(&buf, ',');
/* Error severity */
! appendStringInfo(&buf, "%s", error_severity(edata->elevel));
appendStringInfoChar(&buf, ',');
/* SQL state code */
! appendStringInfo(&buf, "%s", unpack_sql_state(edata->sqlerrcode));
appendStringInfoChar(&buf, ',');
/* errmessage */
! appendCSVLiteral(&buf, edata->message);
appendStringInfoCharMacro(&buf, ',');
/* errdetail or errdetail_log */
! if (edata->detail_log)
! appendCSVLiteral(&buf, edata->detail_log);
! else
! appendCSVLiteral(&buf, edata->detail);
appendStringInfoCharMacro(&buf, ',');
/* errhint */
! appendCSVLiteral(&buf, edata->hint);
appendStringInfoCharMacro(&buf, ',');
/* internal query */
! appendCSVLiteral(&buf, edata->internalquery);
appendStringInfoCharMacro(&buf, ',');
/* if printed internal query, print internal pos too */
! if (edata->internalpos > 0 && edata->internalquery != NULL)
! appendStringInfo(&buf, "%d", edata->internalpos);
appendStringInfoCharMacro(&buf, ',');
/* errcontext */
! appendCSVLiteral(&buf, edata->context);
appendStringInfoCharMacro(&buf, ',');
/* user query --- only reported if not disabled by the caller */
! if (is_log_level_output(edata->elevel, log_min_error_statement) &&
! debug_query_string != NULL &&
! !edata->hide_stmt)
print_stmt = true;
if (print_stmt)
! appendCSVLiteral(&buf, debug_query_string);
appendStringInfoCharMacro(&buf, ',');
! if (print_stmt && edata->cursorpos > 0)
! appendStringInfo(&buf, "%d", edata->cursorpos);
appendStringInfoCharMacro(&buf, ',');
/* file error location */
--- 1945,2014 ----
pfree(msgbuf.data);
}
appendStringInfoChar(&buf, ',');
+ */
/* session start timestamp */
if (formatted_start_time[0] == '\0')
! setup_formatted_start_time(&header->starttime);
appendStringInfoString(&buf, formatted_start_time);
appendStringInfoChar(&buf, ',');
/* Virtual transaction id */
/* keep VXID format in sync with lockfuncs.c */
+ /* FIXME:
if (MyProc != NULL && MyProc->backendId != InvalidBackendId)
appendStringInfo(&buf, "%d/%u", MyProc->backendId, MyProc->lxid);
appendStringInfoChar(&buf, ',');
+ */
/* Transaction id */
+ /* FIXME
appendStringInfo(&buf, "%u", GetTopTransactionIdIfAny());
appendStringInfoChar(&buf, ',');
+ */
/* Error severity */
! appendStringInfo(&buf, "%s", error_severity(header->elevel));
appendStringInfoChar(&buf, ',');
/* SQL state code */
! appendStringInfo(&buf, "%s", unpack_sql_state(header->sqlerrcode));
appendStringInfoChar(&buf, ',');
/* errmessage */
! appendCSVLiteral(&buf, str->message);
appendStringInfoCharMacro(&buf, ',');
/* errdetail or errdetail_log */
! appendCSVLiteral(&buf, str->detail);
appendStringInfoCharMacro(&buf, ',');
/* errhint */
! appendCSVLiteral(&buf, str->hint);
appendStringInfoCharMacro(&buf, ',');
/* internal query */
! appendCSVLiteral(&buf, str->internalquery);
appendStringInfoCharMacro(&buf, ',');
/* if printed internal query, print internal pos too */
! if (header->internalpos > 0 && str->internalquery != NULL)
! appendStringInfo(&buf, "%d", header->internalpos);
appendStringInfoCharMacro(&buf, ',');
/* errcontext */
! appendCSVLiteral(&buf, str->context);
appendStringInfoCharMacro(&buf, ',');
/* user query --- only reported if not disabled by the caller */
! if (is_log_level_output(header->elevel, header->log_min_error_statement) &&
! str->debug_query_string != NULL)
print_stmt = true;
if (print_stmt)
! appendCSVLiteral(&buf, str->debug_query_string);
appendStringInfoCharMacro(&buf, ',');
! if (print_stmt && header->cursorpos > 0)
! appendStringInfo(&buf, "%d", header->cursorpos);
appendStringInfoCharMacro(&buf, ',');
/* file error location */
***************
*** 2018,2041 **** write_csvlog(ErrorData *edata)
initStringInfo(&msgbuf);
! if (edata->funcname && edata->filename)
appendStringInfo(&msgbuf, "%s, %s:%d",
! edata->funcname, edata->filename,
! edata->lineno);
! else if (edata->filename)
appendStringInfo(&msgbuf, "%s:%d",
! edata->filename, edata->lineno);
appendCSVLiteral(&buf, msgbuf.data);
pfree(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(buf.data);
}
--- 2018,2037 ----
initStringInfo(&msgbuf);
! if (str->funcname && str->filename)
appendStringInfo(&msgbuf, "%s, %s:%d",
! str->funcname, str->filename,
! header->error_lineno);
! else if (str->filename)
appendStringInfo(&msgbuf, "%s:%d",
! str->filename, header->error_lineno);
appendCSVLiteral(&buf, msgbuf.data);
pfree(msgbuf.data);
}
appendStringInfoChar(&buf, '\n');
! write_csvlogger_file(buf.data);
pfree(buf.data);
}
***************
*** 2062,2150 **** unpack_sql_state(int sql_state)
/*
! * Write error report to server's log
*/
static void
send_message_to_server_log(ErrorData *edata)
{
StringInfoData buf;
! initStringInfo(&buf);
! formatted_log_time[0] = '\0';
! log_line_prefix(&buf, edata);
! appendStringInfo(&buf, "%s: ", error_severity(edata->elevel));
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');
if (Log_error_verbosity >= PGERROR_DEFAULT)
{
! if (edata->detail_log)
{
! log_line_prefix(&buf, edata);
! appendStringInfoString(&buf, _("DETAIL: "));
! append_with_tabs(&buf, edata->detail_log);
! appendStringInfoChar(&buf, '\n');
}
! else if (edata->detail)
{
! log_line_prefix(&buf, edata);
! appendStringInfoString(&buf, _("DETAIL: "));
! append_with_tabs(&buf, edata->detail);
! appendStringInfoChar(&buf, '\n');
}
! if (edata->hint)
! {
! log_line_prefix(&buf, edata);
! appendStringInfoString(&buf, _("HINT: "));
! append_with_tabs(&buf, edata->hint);
! appendStringInfoChar(&buf, '\n');
! }
! if (edata->internalquery)
{
! log_line_prefix(&buf, edata);
! appendStringInfoString(&buf, _("QUERY: "));
! append_with_tabs(&buf, edata->internalquery);
! appendStringInfoChar(&buf, '\n');
}
! if (edata->context)
{
! log_line_prefix(&buf, edata);
! appendStringInfoString(&buf, _("CONTEXT: "));
! append_with_tabs(&buf, edata->context);
! appendStringInfoChar(&buf, '\n');
}
if (Log_error_verbosity >= PGERROR_VERBOSE)
{
/* assume no newlines in funcname or filename... */
! if (edata->funcname && edata->filename)
{
! log_line_prefix(&buf, edata);
! appendStringInfo(&buf, _("LOCATION: %s, %s:%d\n"),
! edata->funcname, edata->filename,
! edata->lineno);
}
! else if (edata->filename)
{
! log_line_prefix(&buf, edata);
! appendStringInfo(&buf, _("LOCATION: %s:%d\n"),
! edata->filename, edata->lineno);
}
}
}
--- 2058,2281 ----
/*
! * Write error report to pipe to syslogger
*/
+ #define EMPTY_STRING(x) ((x)?(x):"")
+ #define appendStringInfoVariable(n) do { appendStringInfoString(&buf, EMPTY_STRING(str.n));appendStringInfoChar(&buf,'\0'); } while (0);
static void
send_message_to_server_log(ErrorData *edata)
{
StringInfoData buf;
+ struct timeval tv;
! /* static counter for line numbers */
! static long log_line_number = 0;
!
! /* has counter been reset in current process? */
! static int log_my_pid = 0;
!
! /* header with fixed-size data to send */
! syslogger_header header;
! /* variable length strings */
! syslogger_strings str;
!
! /*
! * 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++;
! /* Get the current time for logging */
! gettimeofday(&tv, NULL);
! /* Set up all header values */
! memset(&header, 0, sizeof(header));
!
! header.pid = MyProcPid;
! header.timestamp = tv.tv_sec;
! header.starttime = MyStartTime;
! header.linenum = log_line_number;
! if (MyProc)
! {
! header.backendid = MyProc->backendId;
! header.lxid = MyProc->lxid;
! }
! header.xid = GetTopTransactionIdIfAny();
! header.elevel = edata->elevel;
! header.sqlerrcode = edata->sqlerrcode;
! header.internalpos = edata->internalpos;
! header.log_min_error_statement = log_min_error_statement;
! header.cursorpos = edata->cursorpos;
! header.error_lineno = edata->lineno;
!
! /* Set up strings to be sent */
! str.user_name = MyProcPort ? MyProcPort->user_name : "";
! str.database_name = MyProcPort ? MyProcPort->database_name : "";
! str.message = edata->message;
! str.detail = edata->detail_log ? edata->detail_log : edata->detail;
! str.hint = edata->hint;
! str.internalquery = edata->internalquery;
! str.context = edata->context;
! str.debug_query_string = edata->hide_stmt ? "" : debug_query_string;
! str.funcname = edata->funcname;
! str.filename = edata->filename;
! if (MyProcPort) {
! str.remote_host = MyProcPort->remote_host;
! if (MyProcPort->remote_port)
! str.remote_port = MyProcPort->remote_host;
! else
! str.remote_port = NULL;
! }
! else {
! str.remote_host = NULL;
! str.remote_port = NULL;
! }
!
! if (am_syslogger)
! {
! /*
! * Running in syslogger process, write data directly to the destination
! */
! route_log_message(&header, &str, Log_destination);
! }
! else
! {
! if (!redirection_done)
! {
! /*
! * If redirection hasn't been done yet, there is no way we can write any data
! * to the syslogger, so just skip sending to remote.
! * If any local destinations are configured, send there.
! * If there are no local destinations configured, send to stderr anyway,
! * so we don't loose the data.
! */
! if (Log_destination & LOG_DESTINATION_LOCAL_MASK)
! {
! route_log_message(&header, &str, Log_destination & LOG_DESTINATION_LOCAL_MASK);
! }
! else
! {
! route_log_message(&header, &str, LOG_DESTINATION_STDERR);
! }
! }
! else
! {
! /* Redirection has been done */
! if (Log_destination & LOG_DESTINATION_LOCAL_MASK)
! {
! /*
! * Log destination contains at least one destination that we write directly to,
! * bypassing the syslogger process.
! */
! route_log_message(&header, &str, Log_destination & LOG_DESTINATION_LOCAL_MASK);
! }
!
! if (Log_destination & LOG_DESTINATION_REMOTE_MASK)
! {
! /*
! * If our log destination contains any destination that requires the syslogger,
! * send the data there.
! */
!
! initStringInfo(&buf);
! appendBinaryStringInfo(&buf, (const char *)&header, sizeof(header));
! appendStringInfoVariable(user_name);
! appendStringInfoVariable(database_name);
! appendStringInfoVariable(message);
! appendStringInfoVariable(detail);
! appendStringInfoVariable(hint);
! appendStringInfoVariable(internalquery);
! appendStringInfoVariable(context);
! appendStringInfoVariable(debug_query_string);
! appendStringInfoVariable(funcname);
! appendStringInfoVariable(filename);
! appendStringInfoVariable(remote_host);
! appendStringInfoVariable(remote_port);
!
! /* Send the data off to the syslogger */
! write_pipe_chunks(buf.data, buf.len, LOG_DESTINATION_STDERR);
! }
! }
! }
! }
!
! /*
! * Format a log line
! */
! void
! format_log_line(StringInfoData *buf, const syslogger_header *header, const syslogger_strings *str)
! {
! log_line_prefix(buf, header, str);
! appendStringInfo(buf, "%s: ", error_severity(header->elevel));
if (Log_error_verbosity >= PGERROR_VERBOSE)
! appendStringInfo(buf, "%s: ", unpack_sql_state(header->sqlerrcode));
! if (str->message)
! append_with_tabs(buf, str->message);
else
! append_with_tabs(buf, _("missing error text"));
! if (header->cursorpos > 0)
! appendStringInfo(buf, _(" at character %d"),
! header->cursorpos);
! else if (header->internalpos > 0)
! appendStringInfo(buf, _(" at character %d"),
! header->internalpos);
! appendStringInfoChar(buf, '\n');
if (Log_error_verbosity >= PGERROR_DEFAULT)
{
! if (str->detail)
{
! log_line_prefix(buf, header, str);
! appendStringInfoString(buf, _("DETAIL: "));
! append_with_tabs(buf, str->detail);
! appendStringInfoChar(buf, '\n');
}
! if (str->hint)
{
! log_line_prefix(buf, header, str);
! appendStringInfoString(buf, _("HINT: "));
! append_with_tabs(buf, str->hint);
! appendStringInfoChar(buf, '\n');
}
! if (str->internalquery)
{
! log_line_prefix(buf, header, str);
! appendStringInfoString(buf, _("QUERY: "));
! append_with_tabs(buf, str->internalquery);
! appendStringInfoChar(buf, '\n');
}
! if (str->context)
{
! log_line_prefix(buf, header, str);
! appendStringInfoString(buf, _("CONTEXT: "));
! append_with_tabs(buf, str->context);
! appendStringInfoChar(buf, '\n');
}
if (Log_error_verbosity >= PGERROR_VERBOSE)
{
/* assume no newlines in funcname or filename... */
! if (str->funcname && str->filename)
{
! log_line_prefix(buf, header, str);
! appendStringInfo(buf, _("LOCATION: %s, %s:%d\n"),
! str->funcname, str->filename,
! header->error_lineno);
}
! else if (str->filename)
{
! log_line_prefix(buf, header, str);
! appendStringInfo(buf, _("LOCATION: %s:%d\n"),
! str->filename, header->error_lineno);
}
}
}
***************
*** 2152,2174 **** send_message_to_server_log(ErrorData *edata)
/*
* If the user wants the query that generated this error logged, do it.
*/
! if (is_log_level_output(edata->elevel, log_min_error_statement) &&
! debug_query_string != NULL &&
! !edata->hide_stmt)
{
! log_line_prefix(&buf, edata);
! appendStringInfoString(&buf, _("STATEMENT: "));
! append_with_tabs(&buf, debug_query_string);
! appendStringInfoChar(&buf, '\n');
}
#ifdef HAVE_SYSLOG
/* Write to syslog, if enabled */
! if (Log_destination & LOG_DESTINATION_SYSLOG)
{
int syslog_level;
! switch (edata->elevel)
{
case DEBUG5:
case DEBUG4:
--- 2283,2328 ----
/*
* If the user wants the query that generated this error logged, do it.
*/
! if (is_log_level_output(header->elevel, header->log_min_error_statement) &&
! str->debug_query_string != NULL)
{
! log_line_prefix(buf, header, str);
! appendStringInfoString(buf, _("STATEMENT: "));
! append_with_tabs(buf, str->debug_query_string);
! appendStringInfoChar(buf, '\n');
}
+ }
+
+ /*
+ * Route the log message to the proper destination. This can either be a local destination
+ * (syslog, stderr etc), or a remote one (the ones that require the syslogger process, such
+ * as logfile).
+ * For remote destinations, this function is only called inside the syslogger, so we write
+ * directly to the destination in this case as well.
+ */
+ void
+ route_log_message(const syslogger_header *header, const syslogger_strings *strings, int destinations)
+ {
+ StringInfoData buf;
+
+ /*
+ * If our destination needs a general format string, set it up here
+ */
+ if (destinations & (LOG_DESTINATION_SYSLOG | LOG_DESTINATION_EVENTLOG | LOG_DESTINATION_FILE | LOG_DESTINATION_STDERR))
+ {
+ initStringInfo(&buf);
+ format_log_line(&buf, header, strings);
+ }
+ else
+ buf.data = NULL;
#ifdef HAVE_SYSLOG
/* Write to syslog, if enabled */
! if (destinations & LOG_DESTINATION_SYSLOG)
{
int syslog_level;
! switch (header->elevel)
{
case DEBUG5:
case DEBUG4:
***************
*** 2204,2275 **** send_message_to_server_log(ErrorData *edata)
#ifdef WIN32
/* Write to eventlog, if enabled */
! if (Log_destination & LOG_DESTINATION_EVENTLOG)
{
! write_eventlog(edata->elevel, buf.data);
}
#endif /* WIN32 */
! /* Write to stderr, if enabled */
! if ((Log_destination & LOG_DESTINATION_STDERR) || whereToSendOutput == DestDebug)
{
! /*
! * Use the chunking protocol if we know the syslogger should be
! * catching stderr output, and we are not ourselves the syslogger.
! * Otherwise, just do a vanilla write to stderr.
! */
! if (redirection_done && !am_syslogger)
! write_pipe_chunks(buf.data, buf.len, LOG_DESTINATION_STDERR);
! #ifdef WIN32
!
! /*
! * In a win32 service environment, there is no usable stderr. Capture
! * anything going there and write it to the eventlog instead.
! *
! * If stderr redirection is active, it was OK to write to stderr above
! * because that's really a pipe to the syslogger process.
! */
! else if (pgwin32_is_service())
! write_eventlog(edata->elevel, buf.data);
! #endif
! 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, LOG_DESTINATION_STDERR);
/* Write to CSV log if enabled */
! 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). First get back the space in the message buffer.
! */
! pfree(buf.data);
! write_csvlog(edata);
! }
! else
! {
! const 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);
! }
! pfree(buf.data);
! }
}
! else
! {
pfree(buf.data);
- }
}
/*
--- 2358,2396 ----
#ifdef WIN32
/* Write to eventlog, if enabled */
! if (destinations & LOG_DESTINATION_EVENTLOG)
{
! write_eventlog(header->elevel, buf.data);
}
#endif /* WIN32 */
! /*
! * Write to stderr if enabled. We are called with this in two cases:
! * - in the syslogger, when configured to write to stderr
! * - in a backend, if the syslogger is not (yet) running. In this case,
! * just dumping the data right out on our local stderr is the best
! * thing we can do.
! */
! if (destinations & LOG_DESTINATION_STDERR)
{
! /* FIXME: don't ignore write()'s return value */
! write(fileno(stderr), buf.data, buf.len);
}
! /* Write to syslogger file, if enabled */
! if (destinations & LOG_DESTINATION_FILE)
! {
! write_syslogger_file(buf.data);
! }
/* Write to CSV log if enabled */
! if (destinations & LOG_DESTINATION_CSVLOG)
{
! write_csvlog(header, strings);
}
!
! if (buf.data)
pfree(buf.data);
}
/*
***************
*** 2293,2298 **** write_pipe_chunks(char *data, int len, int dest)
--- 2414,2420 ----
p.proto.is_last = (dest == LOG_DESTINATION_CSVLOG ? 'F' : 'f');
p.proto.len = PIPE_MAX_PAYLOAD;
memcpy(p.proto.data, data, PIPE_MAX_PAYLOAD);
+ /* FIXME: don't ignore write()'s return value */
write(fd, &p, PIPE_HEADER_SIZE + PIPE_MAX_PAYLOAD);
data += PIPE_MAX_PAYLOAD;
len -= PIPE_MAX_PAYLOAD;
***************
*** 2302,2307 **** write_pipe_chunks(char *data, int len, int dest)
--- 2424,2430 ----
p.proto.is_last = (dest == LOG_DESTINATION_CSVLOG ? 'T' : 't');
p.proto.len = len;
memcpy(p.proto.data, data, len);
+ /* FIXME: don't ignore write()'s return value */
write(fd, &p, PIPE_HEADER_SIZE + len);
}
*** a/src/backend/utils/misc/guc.c
--- b/src/backend/utils/misc/guc.c
***************
*** 1089,1102 **** static struct config_bool ConfigureNamesBool[] =
false, NULL, NULL
},
{
- {"logging_collector", PGC_POSTMASTER, LOGGING_WHERE,
- gettext_noop("Start a subprocess to capture stderr output and/or csvlogs into log files."),
- NULL
- },
- &Logging_collector,
- false, NULL, NULL
- },
- {
{"log_truncate_on_rotation", PGC_SIGHUP, LOGGING_WHERE,
gettext_noop("Truncate existing log files of same name during log rotation."),
NULL
--- 1089,1094 ----
***************
*** 7235,7240 **** assign_log_destination(const char *value, bool doit, GucSource source)
--- 7227,7234 ----
if (pg_strcasecmp(tok, "stderr") == 0)
newlogdest |= LOG_DESTINATION_STDERR;
+ else if (pg_strcasecmp(tok, "file") == 0)
+ newlogdest |= LOG_DESTINATION_FILE;
else if (pg_strcasecmp(tok, "csvlog") == 0)
newlogdest |= LOG_DESTINATION_CSVLOG;
#ifdef HAVE_SYSLOG
*** a/src/backend/utils/misc/postgresql.conf.sample
--- b/src/backend/utils/misc/postgresql.conf.sample
***************
*** 234,250 ****
# - Where to Log -
#log_destination = 'stderr' # Valid values are combinations of
! # stderr, csvlog, syslog and eventlog,
! # depending on platform. csvlog
! # requires logging_collector to be on.
!
! # This is used when logging to stderr:
! #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 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,
--- 234,243 ----
# - Where to Log -
#log_destination = 'stderr' # Valid values are combinations of
! # stderr, file, csvlog, syslog and eventlog,
! # depending on platform.
! # These are only used for file and csvlog destinations.
#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,
*** a/src/include/postmaster/syslogger.h
--- b/src/include/postmaster/syslogger.h
***************
*** 60,68 **** typedef union
#define PIPE_HEADER_SIZE offsetof(PipeProtoHeader, data)
#define PIPE_MAX_PAYLOAD ((int) (PIPE_CHUNK_SIZE - PIPE_HEADER_SIZE))
/* GUC options */
- extern bool Logging_collector;
extern int Log_RotationAge;
extern int Log_RotationSize;
extern PGDLLIMPORT char *Log_directory;
--- 60,102 ----
#define PIPE_HEADER_SIZE offsetof(PipeProtoHeader, data)
#define PIPE_MAX_PAYLOAD ((int) (PIPE_CHUNK_SIZE - PIPE_HEADER_SIZE))
+ /*
+ * header struct sent over pipe to syslogger
+ */
+ typedef struct
+ {
+ int pid;
+ pg_time_t timestamp;
+ pg_time_t starttime;
+ long int linenum;
+ int backendid;
+ LocalTransactionId lxid;
+ TransactionId xid;
+ int elevel;
+ int sqlerrcode;
+ int internalpos;
+ int log_min_error_statement;
+ int cursorpos;
+ int error_lineno;
+ } syslogger_header;
+
+ typedef struct
+ {
+ const char *user_name;
+ const char *database_name;
+ const char *message;
+ const char *detail;
+ const char *hint;
+ const char *internalquery;
+ const char *context;
+ const char *debug_query_string;
+ const char *funcname;
+ const char *filename;
+ const char *remote_host;
+ const char *remote_port;
+ } syslogger_strings;
/* GUC options */
extern int Log_RotationAge;
extern int Log_RotationSize;
extern PGDLLIMPORT char *Log_directory;
***************
*** 80,89 **** extern HANDLE syslogPipe[2];
extern int SysLogger_Start(void);
! extern void write_syslogger_file(const char *buffer, int count, int dest);
#ifdef EXEC_BACKEND
extern void SysLoggerMain(int argc, char *argv[]);
#endif
#endif /* _SYSLOGGER_H */
--- 114,128 ----
extern int SysLogger_Start(void);
! extern void route_log_message(const syslogger_header *header, const syslogger_strings *strings, int destinations);
! extern void write_syslogger_file(const char *buffer);
! extern void write_csvlogger_file(const char *buffer);
#ifdef EXEC_BACKEND
extern void SysLoggerMain(int argc, char *argv[]);
#endif
+ /* this is in elog.c, and probably shouldn't be! */
+ void format_log_line(StringInfoData *buf, const syslogger_header *header, const syslogger_strings *str);
+
#endif /* _SYSLOGGER_H */
*** a/src/include/utils/elog.h
--- b/src/include/utils/elog.h
***************
*** 337,342 **** extern int Log_destination;
--- 337,347 ----
#define LOG_DESTINATION_SYSLOG 2
#define LOG_DESTINATION_EVENTLOG 4
#define LOG_DESTINATION_CSVLOG 8
+ #define LOG_DESTINATION_FILE 16
+
+ /* Remote (=via syslogger) and local (directly from backend) destination masks */
+ #define LOG_DESTINATION_LOCAL_MASK (LOG_DESTINATION_SYSLOG | LOG_DESTINATION_EVENTLOG)
+ #define LOG_DESTINATION_REMOTE_MASK (~(LOG_DESTINATION_LOCAL_MASK))
/* Other exported functions */
extern void DebugFileOpen(void);
Hi Magnus,
On Mon, Sep 14, 2009 at 9:41 PM, Magnus Hagander <magnus@hagander.net> wrote:
First, the patch removes the logging_collector parameter and basically
assumes that logging_collector is always on.
Alvaro commited this a few days ago:
http://anoncvs.postgresql.org/cvsweb.cgi/pgsql/doc/src/sgml/config.sgml?r1=1.225&r2=1.226
Any consequence?
Second, data transfer from the backends is now in the form of
structured data, and the actual logging message is put together in the
syslogger (today,it's put together in the backend and just sent as a
string to the syslogger). Yes, this means that we will likely send
more data than what's eventually going to be logged, since all fields
don't go out (except with CVS logging, I guess). But you usually don't
send *that* much data in the log.
I don't know if it will make a real difference but some of us log
quite a lot of queries.
--
Guillaume
On Mon, Sep 14, 2009 at 21:56, Guillaume Smet <guillaume.smet@gmail.com> wrote:
Hi Magnus,
On Mon, Sep 14, 2009 at 9:41 PM, Magnus Hagander <magnus@hagander.net> wrote:
First, the patch removes the logging_collector parameter and basically
assumes that logging_collector is always on.Alvaro commited this a few days ago:
http://anoncvs.postgresql.org/cvsweb.cgi/pgsql/doc/src/sgml/config.sgml?r1=1.225&r2=1.226Any consequence?
At this point, not really. If you log to syslog, it still goes
directly to syslog, just like before, without passing the logging
collector. That is something worth considering inthe future, though.
Second, data transfer from the backends is now in the form of
structured data, and the actual logging message is put together in the
syslogger (today,it's put together in the backend and just sent as a
string to the syslogger). Yes, this means that we will likely send
more data than what's eventually going to be logged, since all fields
don't go out (except with CVS logging, I guess). But you usually don't
send *that* much data in the log.I don't know if it will make a real difference but some of us log
quite a lot of queries.
Yeah, one of the main reasons is to be able to do that using CSV (not
CVS, sorry about that typo) to stick it into logging parsers, and then
have the regular logfile available for DBA reading as well.
Anyway, we'll have to do some performance testing as well, obviously -
but I haven't done any of that yet.
--
Magnus Hagander
Me: http://www.hagander.net/
Work: http://www.redpill-linpro.com/
Magnus Hagander <magnus@hagander.net> writes:
First, the patch removes the logging_collector parameter and basically
assumes that logging_collector is always on.
I don't find that to be a good idea, and you certainly have not made
a case why we should change it. I can't see any reason why pushing
functionality out of backends and downstream to the syslogger process
is an improvement. What it's more likely to do is create a processing
bottleneck and a single point of failure.
... Given that the syslogger is now
always started, those that actually *want* logging to stderr (which I
claim is a low number of people, but that's a different story) will
have it go through the syslogger and then to the stderr of syslogger.
That design doesn't work because there is then *no* way to recover from
a syslogger crash. You no longer have access to the original stderr
file once the postmaster has redirected stderr to syslogger. We can
live with that so long as syslogger's stderr output isn't very
interesting, but not if it's going to be the main log channel.
regards, tom lane
Magnus Hagander <magnus@hagander.net> wrote:
Second, data transfer from the backends is now in the form of
structured data, and the actual logging message is put together in the
syslogger
I'd like to have an opposite approach -- per-backend log files.
Syslogger and appending logs at only one file will be a performance
bottleneck when we want write a lot of logs. Per-backend log files
like "postgres.<backend-id>.log" would be a help then.
Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center
On 15 sep 2009, at 07.21, Itagaki Takahiro <itagaki.takahiro@oss.ntt.co.jp
wrote:
Magnus Hagander <magnus@hagander.net> wrote:
Second, data transfer from the backends is now in the form of
structured data, and the actual logging message is put together in
the
sysloggerI'd like to have an opposite approach -- per-backend log files.
Syslogger and appending logs at only one file will be a performance
bottleneck when we want write a lot of logs. Per-backend log files
like "postgres.<backend-id>.log" would be a help then.
That would make the log more or less completely useless for any of the
situations I've been in.
I can see each backend writing it, certainly, but keeping it in
separate files makes it useless without post processing, which in most
vases means useless for day-to-day work.
/Magnus
Magnus Hagander <magnus@hagander.net> wrote:
On 15 sep 2009, at 07.21, Itagaki Takahiro <itagaki.takahiro@oss.ntt.co.jp
I'd like to have an opposite approach -- per-backend log files.
I can see each backend writing it, certainly, but keeping it in
separate files makes it useless without post processing, which in most
vases means useless for day-to-day work.
Sure. There should be a trade-off between performance and usability.
And that's is the reason I submitted per-destination or per-category
log filter. Log messages for "day-to-day work" should be written in
a single file (either text or syslog), but sql queries used only for
database auditing are acceptable even if written in separate files.
Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center
On Mon, Sep 14, 2009 at 4:14 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Magnus Hagander <magnus@hagander.net> writes:
First, the patch removes the logging_collector parameter and basically
assumes that logging_collector is always on.I don't find that to be a good idea, and you certainly have not made
a case why we should change it. I can't see any reason why pushing
functionality out of backends and downstream to the syslogger process
is an improvement. What it's more likely to do is create a processing
bottleneck and a single point of failure.
Hmm. I think the justification was supposed to be this part here:
$ With that, it's no longer necessary to restart your server just to
$ reconfigure the logging, and it also takes away a confusing parameter
$ (really "log_destination=stderr, logging_collector=on" is *not* a logical
$ way to say "log to file"). Instead, it adds a log_destination of "file" that
$ is the standard log to file."
Do we have any positive or negative experience with logging_collector
as a performance bottleneck? Are there people running with
logging_collector=off to avert disaster?
... Given that the syslogger is now
always started, those that actually *want* logging to stderr (which I
claim is a low number of people, but that's a different story) will
have it go through the syslogger and then to the stderr of syslogger.That design doesn't work because there is then *no* way to recover from
a syslogger crash. You no longer have access to the original stderr
file once the postmaster has redirected stderr to syslogger. We can
live with that so long as syslogger's stderr output isn't very
interesting, but not if it's going to be the main log channel.
I haven't read the patch yet, but this seems like it might be
surmountable by having the postmaster keep both file descriptors
around, and letting the children make appropriate calls to dup2() and
close() just after forking.
...Robert
On Fri, Sep 25, 2009 at 05:18, Robert Haas <robertmhaas@gmail.com> wrote:
On Mon, Sep 14, 2009 at 4:14 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Magnus Hagander <magnus@hagander.net> writes:
First, the patch removes the logging_collector parameter and basically
assumes that logging_collector is always on.I don't find that to be a good idea, and you certainly have not made
a case why we should change it. I can't see any reason why pushing
functionality out of backends and downstream to the syslogger process
is an improvement. What it's more likely to do is create a processing
bottleneck and a single point of failure.Hmm. I think the justification was supposed to be this part here:
$ With that, it's no longer necessary to restart your server just to
$ reconfigure the logging, and it also takes away a confusing parameter
$ (really "log_destination=stderr, logging_collector=on" is *not* a logical
$ way to say "log to file"). Instead, it adds a log_destination of "file" that
$ is the standard log to file."Do we have any positive or negative experience with logging_collector
as a performance bottleneck? Are there people running with
logging_collector=off to avert disaster?
I've never heard of that, so I'd be very interested in hearing if somebody did.
Actually, it's not starting the logging collector that's the issue.
It's the redirection.
So we could always start the logging collector, but not necessarily
redirect stderr. For those who then set logging to "file", it gets
passed to the logging collector. Those who set it to "stderr" just
have to deal with stderr somehow (pg_ctl -l for example). It's still
going to require a restart to change stderr, but that will only hit
those people who are actually having performance issues from it (and
want to switch to using stderr instead of logging collector).
Then we just send the data to the syslogger over a separate pipe. If
we keep the "endpoint" of this pipe in the postmaster, a new syslogger
could just "pick that up" after a crash, no? Data that goes on stderr
will still go to stderr and not be captured in this case, but normally
that would be no data at all, and if it did happen it'd be caught by
wherever you point pg_ctl -l at (which is the same place the early
startup messages goes, before the logger is running).
--
Magnus Hagander
Me: http://www.hagander.net/
Work: http://www.redpill-linpro.com/
Robert Haas escribi�:
$ With that, it's no longer necessary to restart your server just to
$ reconfigure the logging, and it also takes away a confusing parameter
$ (really "log_destination=stderr, logging_collector=on" is *not* a logical
$ way to say "log to file"). Instead, it adds a log_destination of "file" that
$ is the standard log to file."Do we have any positive or negative experience with logging_collector
as a performance bottleneck? Are there people running with
logging_collector=off to avert disaster?
The collector can be a bottleneck, yes, but for this to happen it needs
to be in active use. So if the collector is always running but the
messages are being sent to syslog, no harm is done.
(A customer of ours found the hard way that the collector can block
backends when things are tight. They have since switched to syslog.)
--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.
On Fri, Sep 25, 2009 at 4:13 PM, Magnus Hagander <magnus@hagander.net> wrote:
On Fri, Sep 25, 2009 at 05:18, Robert Haas <robertmhaas@gmail.com> wrote:
On Mon, Sep 14, 2009 at 4:14 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Magnus Hagander <magnus@hagander.net> writes:
First, the patch removes the logging_collector parameter and basically
assumes that logging_collector is always on.I don't find that to be a good idea, and you certainly have not made
a case why we should change it. I can't see any reason why pushing
functionality out of backends and downstream to the syslogger process
is an improvement. What it's more likely to do is create a processing
bottleneck and a single point of failure.Hmm. I think the justification was supposed to be this part here:
$ With that, it's no longer necessary to restart your server just to
$ reconfigure the logging, and it also takes away a confusing parameter
$ (really "log_destination=stderr, logging_collector=on" is *not* a logical
$ way to say "log to file"). Instead, it adds a log_destination of "file" that
$ is the standard log to file."Do we have any positive or negative experience with logging_collector
as a performance bottleneck? Are there people running with
logging_collector=off to avert disaster?I've never heard of that, so I'd be very interested in hearing if somebody did.
Actually, it's not starting the logging collector that's the issue.
It's the redirection.So we could always start the logging collector, but not necessarily
redirect stderr. For those who then set logging to "file", it gets
passed to the logging collector. Those who set it to "stderr" just
have to deal with stderr somehow (pg_ctl -l for example). It's still
going to require a restart to change stderr, but that will only hit
those people who are actually having performance issues from it (and
want to switch to using stderr instead of logging collector).Then we just send the data to the syslogger over a separate pipe. If
we keep the "endpoint" of this pipe in the postmaster, a new syslogger
could just "pick that up" after a crash, no? Data that goes on stderr
will still go to stderr and not be captured in this case, but normally
that would be no data at all, and if it did happen it'd be caught by
wherever you point pg_ctl -l at (which is the same place the early
startup messages goes, before the logger is running).
That doesn't sound horribly robust. I thought part of the point of
the design of the logging collector was that if random libraries
linked into the backend emit messages on stderr, we'll still capture
them and send them on to the appropriate place, even though we don't
really know what they are. Having such messages go off to some
probably-much-less-carefully-monitored logfile somewhere doesn't seem
good.
Could we handle this by allow the setting to be changed while the
system is up, but just have it take effect for any NEW backends? As
long as we keep the original stderr around in the postmaster, we ought
to be able to change how new backends are set up after the fact.
Anyone who really needs to make sure the setting gets changed, but
without shutting down the system, will just have to make sure to kill
off all their old backends after making the change.
...Robert
On Fri, Sep 25, 2009 at 22:26, Robert Haas <robertmhaas@gmail.com> wrote:
On Fri, Sep 25, 2009 at 4:13 PM, Magnus Hagander <magnus@hagander.net> wrote:
On Fri, Sep 25, 2009 at 05:18, Robert Haas <robertmhaas@gmail.com> wrote:
On Mon, Sep 14, 2009 at 4:14 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Magnus Hagander <magnus@hagander.net> writes:
First, the patch removes the logging_collector parameter and basically
assumes that logging_collector is always on.I don't find that to be a good idea, and you certainly have not made
a case why we should change it. I can't see any reason why pushing
functionality out of backends and downstream to the syslogger process
is an improvement. What it's more likely to do is create a processing
bottleneck and a single point of failure.Hmm. I think the justification was supposed to be this part here:
$ With that, it's no longer necessary to restart your server just to
$ reconfigure the logging, and it also takes away a confusing parameter
$ (really "log_destination=stderr, logging_collector=on" is *not* a logical
$ way to say "log to file"). Instead, it adds a log_destination of "file" that
$ is the standard log to file."Do we have any positive or negative experience with logging_collector
as a performance bottleneck? Are there people running with
logging_collector=off to avert disaster?I've never heard of that, so I'd be very interested in hearing if somebody did.
Actually, it's not starting the logging collector that's the issue.
It's the redirection.So we could always start the logging collector, but not necessarily
redirect stderr. For those who then set logging to "file", it gets
passed to the logging collector. Those who set it to "stderr" just
have to deal with stderr somehow (pg_ctl -l for example). It's still
going to require a restart to change stderr, but that will only hit
those people who are actually having performance issues from it (and
want to switch to using stderr instead of logging collector).Then we just send the data to the syslogger over a separate pipe. If
we keep the "endpoint" of this pipe in the postmaster, a new syslogger
could just "pick that up" after a crash, no? Data that goes on stderr
will still go to stderr and not be captured in this case, but normally
that would be no data at all, and if it did happen it'd be caught by
wherever you point pg_ctl -l at (which is the same place the early
startup messages goes, before the logger is running).That doesn't sound horribly robust. I thought part of the point of
the design of the logging collector was that if random libraries
linked into the backend emit messages on stderr, we'll still capture
them and send them on to the appropriate place, even though we don't
really know what they are. Having such messages go off to some
probably-much-less-carefully-monitored logfile somewhere doesn't seem
good.
Well, from how I read the first complaint here, running with
logging_collector on is simply broken from the crash perspective, no?
I mean, don't we have the same problem *today*, it's just that
logging_collector isn't on by default (in the source distribution that
is - on our most installed platform it is..)
Also, how often does it actually happen that "random libraries linked
into the backend emit messages on stderr"? Is this really something
that we need to pay so much attention to, rather than just let them go
on stderr and have them be redirected?
--
Magnus Hagander
Me: http://www.hagander.net/
Work: http://www.redpill-linpro.com/
Magnus Hagander <magnus@hagander.net> writes:
Well, from how I read the first complaint here, running with
logging_collector on is simply broken from the crash perspective, no?
I mean, don't we have the same problem *today*,
No, we don't. But we would if we accept the proposed patch.
regards, tom lane
[ argh, hit send a bit too fast ]
Magnus Hagander <magnus@hagander.net> writes:
Also, how often does it actually happen that "random libraries linked
into the backend emit messages on stderr"? Is this really something
that we need to pay so much attention to, rather than just let them go
on stderr and have them be redirected?
Yes, this is an ABSOLUTE deal-breaker. To name two reasons:
* glibc tells about various malloc-arena-corruption problems on stderr.
* On a lot of systems you will not find out anything useful about
dynamic-linker problems if you don't capture stderr.
regards, tom lane
On Fri, Sep 25, 2009 at 4:29 PM, Magnus Hagander <magnus@hagander.net> wrote:
On Fri, Sep 25, 2009 at 22:26, Robert Haas <robertmhaas@gmail.com> wrote:
On Fri, Sep 25, 2009 at 4:13 PM, Magnus Hagander <magnus@hagander.net> wrote:
On Fri, Sep 25, 2009 at 05:18, Robert Haas <robertmhaas@gmail.com> wrote:
On Mon, Sep 14, 2009 at 4:14 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Magnus Hagander <magnus@hagander.net> writes:
First, the patch removes the logging_collector parameter and basically
assumes that logging_collector is always on.I don't find that to be a good idea, and you certainly have not made
a case why we should change it. I can't see any reason why pushing
functionality out of backends and downstream to the syslogger process
is an improvement. What it's more likely to do is create a processing
bottleneck and a single point of failure.Hmm. I think the justification was supposed to be this part here:
$ With that, it's no longer necessary to restart your server just to
$ reconfigure the logging, and it also takes away a confusing parameter
$ (really "log_destination=stderr, logging_collector=on" is *not* a logical
$ way to say "log to file"). Instead, it adds a log_destination of "file" that
$ is the standard log to file."Do we have any positive or negative experience with logging_collector
as a performance bottleneck? Are there people running with
logging_collector=off to avert disaster?I've never heard of that, so I'd be very interested in hearing if somebody did.
Actually, it's not starting the logging collector that's the issue.
It's the redirection.So we could always start the logging collector, but not necessarily
redirect stderr. For those who then set logging to "file", it gets
passed to the logging collector. Those who set it to "stderr" just
have to deal with stderr somehow (pg_ctl -l for example). It's still
going to require a restart to change stderr, but that will only hit
those people who are actually having performance issues from it (and
want to switch to using stderr instead of logging collector).Then we just send the data to the syslogger over a separate pipe. If
we keep the "endpoint" of this pipe in the postmaster, a new syslogger
could just "pick that up" after a crash, no? Data that goes on stderr
will still go to stderr and not be captured in this case, but normally
that would be no data at all, and if it did happen it'd be caught by
wherever you point pg_ctl -l at (which is the same place the early
startup messages goes, before the logger is running).That doesn't sound horribly robust. I thought part of the point of
the design of the logging collector was that if random libraries
linked into the backend emit messages on stderr, we'll still capture
them and send them on to the appropriate place, even though we don't
really know what they are. Having such messages go off to some
probably-much-less-carefully-monitored logfile somewhere doesn't seem
good.Well, from how I read the first complaint here, running with
logging_collector on is simply broken from the crash perspective, no?
I mean, don't we have the same problem *today*, it's just that
logging_collector isn't on by default (in the source distribution that
is - on our most installed platform it is..)
AIUI the problem is that when logging_collector is on, we throw away
the original stderr. That's OK as long as you never try to switch
back to it.
Also, how often does it actually happen that "random libraries linked
into the backend emit messages on stderr"? Is this really something
that we need to pay so much attention to, rather than just let them go
on stderr and have them be redirected?
I think so. But I'm willing to be told I'm full of it.
...Robert
On Fri, Sep 25, 2009 at 5:22 PM, Robert Haas <robertmhaas@gmail.com> wrote:
AIUI the problem is that when logging_collector is on, we throw away
the original stderr. That's OK as long as you never try to switch
back to it.
BTW, this seems like it could be fixed with some appropriate file
descriptor management in postmaster. No?
Anyway, marking this Rejected for now, as that seems to be the consensus.
...Robert
Robert Haas <robertmhaas@gmail.com> writes:
On Fri, Sep 25, 2009 at 5:22 PM, Robert Haas <robertmhaas@gmail.com> wrote:
AIUI the problem is that when logging_collector is on, we throw away
the original stderr. �That's OK as long as you never try to switch
back to it.
BTW, this seems like it could be fixed with some appropriate file
descriptor management in postmaster. No?
Yeah, probably. In the current system design it didn't seem to be
necessary because collecting the collector process's own stderr output
is usually not all that critical. If we had the postmaster dup its
original stderr and the collector dup it back, that would be a more
complete but more complex solution. (dup2 works on Windows, no?)
regards, tom lane
On Sat, Sep 26, 2009 at 17:43, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Robert Haas <robertmhaas@gmail.com> writes:
On Fri, Sep 25, 2009 at 5:22 PM, Robert Haas <robertmhaas@gmail.com> wrote:
AIUI the problem is that when logging_collector is on, we throw away
the original stderr. That's OK as long as you never try to switch
back to it.BTW, this seems like it could be fixed with some appropriate file
descriptor management in postmaster. No?Yeah, probably. In the current system design it didn't seem to be
necessary because collecting the collector process's own stderr output
is usually not all that critical. If we had the postmaster dup its
original stderr and the collector dup it back, that would be a more
complete but more complex solution. (dup2 works on Windows, no?)
Yeah, they should.
Not sure how that works through process boundaries though, we do some
special fiddling for any handles that need to be inherited.
--
Magnus Hagander
Me: http://www.hagander.net/
Work: http://www.redpill-linpro.com/
On Sat, Sep 26, 2009 at 11:43:46AM -0400, Tom Lane wrote:
complete but more complex solution. (dup2 works on Windows, no?)
Unless I'm misreading syslogger.c, dup2() gets called on every platform.
I've started the wiki page in question:
http://wiki.postgresql.org/wiki/Logging_Brainstorm
It doesn't have anything linking to it right now, which might be a bad thing.
--
Joshua Tolley / eggyknap
End Point Corporation
http://www.endpoint.com
Joshua Tolley wrote:
On Sat, Sep 26, 2009 at 11:43:46AM -0400, Tom Lane wrote:
complete but more complex solution. (dup2 works on Windows, no?)
Unless I'm misreading syslogger.c, dup2() gets called on every platform.
Yes. Windows supports dup2(). See for example
<http://msdn.microsoft.com/en-us/library/8syseb29(VS.80).aspx>
cheers
andrew
On Sat, 2009-09-26 at 15:35 -0600, Joshua Tolley wrote:
On Sat, Sep 26, 2009 at 11:43:46AM -0400, Tom Lane wrote:
complete but more complex solution. (dup2 works on Windows, no?)
Unless I'm misreading syslogger.c, dup2() gets called on every platform.
I've started the wiki page in question:
http://wiki.postgresql.org/wiki/Logging_Brainstorm
Most of the items listed there you can already do with a sufficiently
non-ancient syslog implementation.
Has anyone ever actually tested rsyslog and syslog-ng for performance
and robustness with PostgreSQL? Half the ideas about on-disk queuing
and checkpointing and so on that have been mentioned recently seem to
come straight from their documentations.