/*
* Force out any buffered data
*
* This is currently used only at syslogger shutdown, but could perhaps be
* useful at other times, so it is careful to leave things in a clean state.
*/
static void
flush_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
{
int i;
StringInfo str;
/* Dump any incomplete protocol messages */
for (i = 0; i < CHUNK_SLOTS; i++)
{
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);
}
}
/*
* Force out any remaining pipe data as-is; we don't bother trying to
* 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;
}
/*
* Process data received through the syslogger pipe.
*
* This routine interprets the log pipe protocol which sends log messages as
* (hopefully atomic) chunks - such chunks are detected and reassembled here.
*
* The protocol has a header that starts with two nul bytes, then has a 16 bit
* length, the pid of the sending process, and a flag to indicate if it is
* the last chunk in a message. Incomplete chunks are saved until we read some
* more, and non-final chunks are accumulated until we get the final chunk.
*
* All of this is to avoid 2 problems:
* . partial messages being written to logfiles (messes rotation), and
* . messages from different backends being interleaved (messages garbled).
*
* Any non-protocol messages are written out directly. These should only come
* from non-PostgreSQL sources, however (e.g. third party libraries writing to
* stderr).
*
* logbuffer is the data input buffer, and *bytes_in_logbuffer is the number
* of bytes present. On exit, any not-yet-eaten data is left-justified in
* logbuffer, and *bytes_in_logbuffer is updated.
*/
static void
process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
{
char *cursor = logbuffer;
int count = *bytes_in_logbuffer;
int dest = LOG_DESTINATION_STDERR;
/* While we have enough for a header, process data... */
while (count >= (int) sizeof(PipeProtoHeader))
{
PipeProtoHeader p;
int chunklen;
/* Do we have a valid header? */
memcpy(&p, cursor, sizeof(PipeProtoHeader));
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'))
{
List *buffer_list;
ListCell *cell;
save_buffer *existing_slot = NULL,
*free_slot = NULL;
StringInfo str;
chunklen = PIPE_HEADER_SIZE + p.len;
/* Fall out of loop if we don't have the whole chunk yet */
if (count < chunklen)
break;
dest = (p.is_last == 'T' || p.is_last == 'F') ?
LOG_DESTINATION_CSVLOG : LOG_DESTINATION_STDERR;
/* Locate any existing buffer for this source pid */
buffer_list = buffer_lists[p.pid % NBUFFER_LISTS];
foreach(cell, buffer_list)
{
save_buffer *buf = (save_buffer *) lfirst(cell);
if (buf->pid == p.pid)
{
existing_slot = buf;
break;
}
if (buf->pid == 0 && free_slot == NULL)
free_slot = buf;
}
if (p.is_last == 'f' || p.is_last == 'F')
{
/*
* Save a complete non-final chunk in a per-pid buffer
*/
if (existing_slot != NULL)
{
/* Add chunk to data from preceding chunks */
str = &(existing_slot->data);
appendBinaryStringInfo(str,
cursor + PIPE_HEADER_SIZE,
p.len);
}
else
{
/* First chunk of message, save in a new buffer */
if (free_slot == NULL)
{
/*
* Need a free slot, but there isn't one in the list,
* so create a new one and extend the list with it.
*/
free_slot = palloc(sizeof(save_buffer));
buffer_list = lappend(buffer_list, free_slot);
buffer_lists[p.pid % NBUFFER_LISTS] = buffer_list;
}
free_slot->pid = p.pid;
str = &(free_slot->data);
initStringInfo(str);
appendBinaryStringInfo(str,
cursor + PIPE_HEADER_SIZE,
p.len);
}
}
else
{
/*
* Final chunk --- add it to anything saved for that pid, and
* either way write the whole thing out.
*/
if (existing_slot != NULL)
{
str = &(existing_slot->data);
appendBinaryStringInfo(str,
cursor + PIPE_HEADER_SIZE,
p.len);
write_syslogger_file(str->data, str->len, dest);
/* Mark the buffer unused, and reclaim string storage */
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);
}
}
/* Finished processing this chunk */
cursor += chunklen;
count -= chunklen;
}
/*
* write_jsonlog
* Write logs in json format.
*/
static void
write_jsonlog(ErrorData *edata)
{
StringInfoData buf;
TransactionId txid = GetTopTransactionIdIfAny();
initStringInfo(&buf);
/* Initialize string */
appendStringInfoChar(&buf, '{');
/* Timestamp */
if (log_time[0] == '\0')
setup_formatted_log_time();
appendJSONLiteral(&buf, "timestamp", log_time, true);
/* Username */
if (MyProcPort)
appendJSONLiteral(&buf, "user", MyProcPort->user_name, true);
/* Database name */
if (MyProcPort)
appendJSONLiteral(&buf, "dbname", MyProcPort->database_name, true);
/* Process ID */
if (MyProcPid != 0)
appendStringInfo(&buf, "\"pid\":%d,", MyProcPid);
/* Remote host and port */
if (MyProcPort && MyProcPort->remote_host)
{
appendJSONLiteral(&buf, "remote_host",
MyProcPort->remote_host, true);
if (MyProcPort->remote_port && MyProcPort->remote_port[0] != '\0')
appendJSONLiteral(&buf, "remote_port",
MyProcPort->remote_port, true);
}
/* Session id */
if (MyProcPid != 0)
appendStringInfo(&buf, "\"session_id\":\"%lx.%x\",",
(long) MyStartTime, MyProcPid);
/* Virtual transaction id */
/* keep VXID format in sync with lockfuncs.c */
if (MyProc != NULL && MyProc->backendId != InvalidBackendId)
appendStringInfo(&buf, "\"vxid\":\"%d/%u\",",
MyProc->backendId, MyProc->lxid);
/* Transaction id */
if (txid != InvalidTransactionId)
appendStringInfo(&buf, "\"txid\":%u,", GetTopTransactionIdIfAny());
/* Error severity */
appendJSONLiteral(&buf, "error_severity",
(char *) error_severity(edata->elevel), true);
/* SQL state code */
if (edata->sqlerrcode != ERRCODE_SUCCESSFUL_COMPLETION)
appendJSONLiteral(&buf, "state_code",
unpack_sql_state(edata->sqlerrcode), true);
/* Error detail or Error detail log */
if (edata->detail_log)
appendJSONLiteral(&buf, "detail_log", edata->detail_log, true);
else if (edata->detail)
appendJSONLiteral(&buf, "detail", edata->detail, true);
/* Error hint */
if (edata->hint)
appendJSONLiteral(&buf, "hint", edata->hint, true);
/* Internal query */
if (edata->internalquery)
appendJSONLiteral(&buf, "internal_query",
edata->internalquery, true);
/* Error context */
if (edata->context)
appendJSONLiteral(&buf, "context", edata->context, true);
/* File error location */
if (Log_error_verbosity >= PGERROR_VERBOSE)
{
StringInfoData msgbuf;
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);
appendJSONLiteral(&buf, "file_location", msgbuf.data, true);
pfree(msgbuf.data);
}
/* Application name */
if (application_name && application_name[0] != '\0')
appendJSONLiteral(&buf, "application_name",
application_name, true);
/* Error message */
appendJSONLiteral(&buf, "message", edata->message, false);
/* Finish string */
appendStringInfoChar(&buf, '}');
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_STDERR);
else
write_pipe_chunks(buf.data, buf.len);
/* Cleanup */
pfree(buf.data);
/* Continue chain to previous hook */
if (prev_log_hook)
(*prev_log_hook) (edata);
}
/*
* Process data received through the syslogger pipe.
*
* This routine interprets the log pipe protocol which sends log messages as
* (hopefully atomic) chunks - such chunks are detected and reassembled here.
*
* The protocol has a header that starts with two nul bytes, then has a 16 bit
* length, the pid of the sending process, and a flag to indicate if it is
* the last chunk in a message. Incomplete chunks are saved until we read some
* more, and non-final chunks are accumulated until we get the final chunk.
*
* All of this is to avoid 2 problems:
* . partial messages being written to logfiles (messes rotation), and
* . messages from different backends being interleaved (messages garbled).
*
* Any non-protocol messages are written out directly. These should only come
* from non-PostgreSQL sources, however (e.g. third party libraries writing to
* stderr).
*
* logbuffer is the data input buffer, and *bytes_in_logbuffer is the number
* of bytes present. On exit, any not-yet-eaten data is left-justified in
* logbuffer, and *bytes_in_logbuffer is updated.
*/
static void
process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
{
char *cursor = logbuffer;
int count = *bytes_in_logbuffer;
int dest = LOG_DESTINATION_STDERR;
/* While we have enough for a header, process data... */
while (count >= (int) sizeof(PipeProtoHeader))
{
PipeProtoHeader p;
int chunklen;
/* Do we have a valid header? */
memcpy(&p, cursor, sizeof(PipeProtoHeader));
if (p.nuls[0] == '\0' && p.nuls[1] == '\0' &&
p.len > 0 && p.len <= PIPE_MAX_PAYLOAD &&
p.pid != 0 &&
(p.is_last == 't' || p.is_last == 'f' ||
p.is_last == 'T' || p.is_last == 'F'))
{
chunklen = PIPE_HEADER_SIZE + p.len;
/* Fall out of loop if we don't have the whole chunk yet */
if (count < chunklen)
break;
dest = (p.is_last == 'T' || p.is_last == 'F') ?
LOG_DESTINATION_CSVLOG : LOG_DESTINATION_STDERR;
if (p.is_last == 'f' || p.is_last == 'F')
{
/*
* Save a complete non-final chunk in the per-pid buffer if
* possible - if not just write it out.
*/
int free_slot = -1,
existing_slot = -1;
int i;
StringInfo str;
for (i = 0; i < CHUNK_SLOTS; i++)
{
if (saved_chunks[i].pid == p.pid)
{
existing_slot = i;
break;
}
if (free_slot < 0 && saved_chunks[i].pid == 0)
free_slot = i;
}
if (existing_slot >= 0)
{
str = &(saved_chunks[existing_slot].data);
appendBinaryStringInfo(str,
cursor + PIPE_HEADER_SIZE,
p.len);
}
else if (free_slot >= 0)
{
saved_chunks[free_slot].pid = p.pid;
str = &(saved_chunks[free_slot].data);
initStringInfo(str);
appendBinaryStringInfo(str,
cursor + PIPE_HEADER_SIZE,
p.len);
}
else
{
/*
* If there is no free slot we'll just have to take our
* 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
{
/*
* Final chunk --- add it to anything saved for that pid, and
* either way write the whole thing out.
*/
int existing_slot = -1;
int i;
StringInfo str;
for (i = 0; i < CHUNK_SLOTS; i++)
{
if (saved_chunks[i].pid == p.pid)
{
existing_slot = i;
break;
}
}
if (existing_slot >= 0)
{
str = &(saved_chunks[existing_slot].data);
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);
}
}
/* Finished processing this chunk */
cursor += chunklen;
count -= chunklen;
}
else
{
/* Process non-protocol data */
/*
* Look for the start of a protocol header. If found, dump data
* up to there and repeat the loop. Otherwise, dump it all and
* fall out of the loop. (Note: we want to dump it all if at all
* possible, so as to avoid dividing non-protocol messages across
* logfiles. We expect that in many scenarios, a non-protocol
* message will arrive all in one read(), and we want to respect
* the read() boundary if possible.)
*/
for (chunklen = 1; chunklen < count; chunklen++)
{
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;
}
}
/* We don't have a full chunk, so left-align what remains in the buffer */
if (count > 0 && cursor != logbuffer)
memmove(logbuffer, cursor, count);
*bytes_in_logbuffer = count;
}
/*
* write_jsonlog
* Write logs in json format.
*/
static void
write_jsonlog(ErrorData *edata)
{
StringInfoData buf;
TransactionId txid = GetTopTransactionIdIfAny();
/*
* Disable logs to server, we don't want duplicate entries in
* the server.
*/
edata->output_to_server = false;
/* Determine whether message is enabled for server log output */
if (!is_log_level_output(edata->elevel, log_min_messages))
return;
initStringInfo(&buf);
/* Initialize string */
appendStringInfoChar(&buf, '{');
/* Timestamp */
setup_formatted_log_time();
appendJSONLiteral(&buf, "timestamp", formatted_log_time, true);
/* Username */
if (MyProcPort && MyProcPort->user_name)
appendJSONLiteral(&buf, "user", MyProcPort->user_name, true);
/* Database name */
if (MyProcPort && MyProcPort->database_name)
appendJSONLiteral(&buf, "dbname", MyProcPort->database_name, true);
/* Process ID */
if (MyProcPid != 0)
appendStringInfo(&buf, "\"pid\":%d,", MyProcPid);
/* Remote host and port */
if (MyProcPort && MyProcPort->remote_host)
{
appendJSONLiteral(&buf, "remote_host",
MyProcPort->remote_host, true);
if (MyProcPort->remote_port && MyProcPort->remote_port[0] != '\0')
appendJSONLiteral(&buf, "remote_port",
MyProcPort->remote_port, true);
}
/* Session id */
if (MyProcPid != 0)
appendStringInfo(&buf, "\"session_id\":\"%lx.%x\",",
(long) MyStartTime, MyProcPid);
/* Virtual transaction id */
/* keep VXID format in sync with lockfuncs.c */
if (MyProc != NULL && MyProc->backendId != InvalidBackendId)
appendStringInfo(&buf, "\"vxid\":\"%d/%u\",",
MyProc->backendId, MyProc->lxid);
/* Transaction id */
if (txid != InvalidTransactionId)
appendStringInfo(&buf, "\"txid\":%u,", GetTopTransactionIdIfAny());
/* Error severity */
appendJSONLiteral(&buf, "error_severity",
(char *) error_severity(edata->elevel), true);
/* SQL state code */
if (edata->sqlerrcode != ERRCODE_SUCCESSFUL_COMPLETION)
appendJSONLiteral(&buf, "state_code",
unpack_sql_state(edata->sqlerrcode), true);
/* Error detail or Error detail log */
if (edata->detail_log)
appendJSONLiteral(&buf, "detail_log", edata->detail_log, true);
else if (edata->detail)
appendJSONLiteral(&buf, "detail", edata->detail, true);
/* Error hint */
if (edata->hint)
appendJSONLiteral(&buf, "hint", edata->hint, true);
/* Internal query */
if (edata->internalquery)
appendJSONLiteral(&buf, "internal_query",
edata->internalquery, true);
/* Error context */
if (edata->context)
appendJSONLiteral(&buf, "context", edata->context, true);
/* 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)
{
appendJSONLiteral(&buf, "statement", debug_query_string, true);
if (edata->cursorpos > 0)
appendStringInfo(&buf, "\"cursor_position\":%d,",
edata->cursorpos);
else if (edata->internalpos > 0)
appendStringInfo(&buf, "\"internal_position\":%d,",
edata->internalpos);
}
/* File error location */
if (Log_error_verbosity >= PGERROR_VERBOSE)
{
StringInfoData msgbuf;
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);
appendJSONLiteral(&buf, "file_location", msgbuf.data, true);
pfree(msgbuf.data);
}
/* Application name */
if (application_name && application_name[0] != '\0')
appendJSONLiteral(&buf, "application_name",
application_name, true);
/* Error message */
appendJSONLiteral(&buf, "message", edata->message, false);
/* Finish string */
appendStringInfoChar(&buf, '}');
appendStringInfoChar(&buf, '\n');
/* Write to stderr, if enabled */
if ((Log_destination & LOG_DESTINATION_STDERR) != 0)
{
if (Logging_collector && redirection_done && !am_syslogger)
write_pipe_chunks(buf.data, buf.len);
else
write_console(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);
/* Cleanup */
pfree(buf.data);
/* Continue chain to previous hook */
if (prev_log_hook)
(*prev_log_hook) (edata);
}
