From 3bf66d6f1c3a8d266c3e6ed939e763a001179faf Mon Sep 17 00:00:00 2001
From: Alvaro Herrera <alvherre@alvh.no-ip.org>
Date: Tue, 11 Dec 2007 15:19:05 +0000
Subject: [PATCH] Extend the format of CSV logs to include the additional
 information supplied with the logged event.  CSV logs are now a first-class
 citizen along plain text logs in that they carry much of the same
 information.

Per complaint from depesz on bug #3799.
---
 doc/src/sgml/config.sgml       |  18 +++-
 src/backend/utils/error/elog.c | 160 +++++++++++++++++----------------
 2 files changed, 100 insertions(+), 78 deletions(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index a2f95b209c6..4188c5ca776 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -1,4 +1,4 @@
-<!-- $PostgreSQL: pgsql/doc/src/sgml/config.sgml,v 1.158 2007/11/28 15:42:30 petere Exp $ -->
+<!-- $PostgreSQL: pgsql/doc/src/sgml/config.sgml,v 1.159 2007/12/11 15:19:05 alvherre Exp $ -->
 
 <chapter Id="runtime-config">
   <title>Server Configuration</title>
@@ -3169,7 +3169,13 @@ local0.*    /var/log/postgresql
         with these columns: timestamp with milliseconds, user name, database
         name, session ID, host:port number, process ID, per-process line
         number, command tag, session start time, virtual transaction ID,
-        regular transaction id, error severity, SQL state code, error message.
+        regular transaction id, error severity, SQL state code, error message,
+        error message detail, hint, internal query that led to the error (if
+        any), character count of the error position thereof, error context,
+        user query that led to the error (if any and enabled by
+        <varname>log_min_error_statement</>), character count of the error
+        position thereof, location of the error in the PostgreSQL source code
+        (if <varname>log_error_verbosity</> is set to <literal>verbose</>).
         Here is a sample table definition for storing CSV-format log output:
 
 <programlisting>
@@ -3189,6 +3195,14 @@ CREATE TABLE postgres_log
   error_severity text,
   sql_state_code text,
   message text,
+  detail text,
+  hint text,
+  internal_query text,
+  internal_query_pos integer,
+  context text,
+  query text,
+  query_pos integer,
+  location text,
   PRIMARY KEY (session_id, process_line_num)
 );
 </programlisting>
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index bb010162ba4..57bd3b5036f 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.198 2007/11/15 21:14:40 momjian Exp $
+ *	  $PostgreSQL: pgsql/src/backend/utils/error/elog.c,v 1.199 2007/12/11 15:19:05 alvherre Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -134,7 +134,6 @@ static const char *error_severity(int elevel);
 static void append_with_tabs(StringInfo buf, const char *str);
 static bool is_log_level_output(int elevel, int log_min_level);
 static void write_pipe_chunks(char *data, int len, int dest);
-static void get_csv_error_message(StringInfo buf, ErrorData *edata);
 static void write_csvlog(ErrorData *edata);
 
 /*
@@ -1612,18 +1611,21 @@ 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 = '"'
+ * If it's NULL, append nothing.
  */
-
 static inline void
 appendCSVLiteral(StringInfo buf, const char *data)
 {
 	const char *p = data;
 	char		c;
 
+	/* avoid confusing an empty string with NULL */
+	if (p == NULL)
+		return;
+
 	appendStringInfoCharMacro(buf, '"');
 	while ((c = *p++) != '\0')
 	{
@@ -1635,15 +1637,14 @@ appendCSVLiteral(StringInfo buf, const char *data)
 }
 
 /*
- * Constructs the error message, depending on the Errordata it gets,
- * in CSV (comma separated values) format. The COPY command
- * can then be used to load the messages into a table.
+ * Constructs the error message, depending on the Errordata it gets, in a CSV
+ * format which is described in doc/src/sgml/config.sgml.
  */
 static void
 write_csvlog(ErrorData *edata)
 {
-	StringInfoData msgbuf;
 	StringInfoData buf;
+	bool	print_stmt = false;
 
 	/* static counter for line numbers */
 	static long log_line_number = 0;
@@ -1664,24 +1665,15 @@ write_csvlog(ErrorData *edata)
 	}
 	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,
-	 * virtual transaction id, regular transaction id, error severity, sql
-	 * state code, 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.
+	 * timestamp with milliseconds
+	 *
+	 * Check if the timestamp is already calculated for the syslog message,
+	 * and use it if so.  Otherwise, get the current timestamp.  This is done
+	 * to put same timestamp in both syslog and csvlog messages.
 	 */
 	if (formatted_log_time[0] == '\0')
 	{
@@ -1715,38 +1707,26 @@ write_csvlog(ErrorData *edata)
 
 	/* username */
 	if (MyProcPort)
-	{
-		const char *username = MyProcPort->user_name;
-
-		if (username == NULL || *username == '\0')
-			username = _("[unknown]");
-
-		appendCSVLiteral(&buf, username);
-	}
+		appendCSVLiteral(&buf, MyProcPort->user_name);
 	appendStringInfoChar(&buf, ',');
 
-	/* databasename */
+	/* database name */
 	if (MyProcPort)
-	{
-		const char *dbname = MyProcPort->database_name;
-
-		if (dbname == NULL || *dbname == '\0')
-			dbname = _("[unknown]");
-
-		appendCSVLiteral(&buf, dbname);
-	}
+		appendCSVLiteral(&buf, MyProcPort->database_name);
 	appendStringInfoChar(&buf, ',');
 
 	/* session id */
 	appendStringInfo(&buf, "%lx.%x", (long) MyStartTime, MyProcPid);
 	appendStringInfoChar(&buf, ',');
 
-	/* Remote host and port (is it safe to not quote this?) */
+	/* Remote host and port */
 	if (MyProcPort && MyProcPort->remote_host)
 	{
+		appendStringInfoChar(&buf, '"');
 		appendStringInfo(&buf, "%s", MyProcPort->remote_host);
 		if (MyProcPort->remote_port && MyProcPort->remote_port[0] != '\0')
 			appendStringInfo(&buf, ":%s", MyProcPort->remote_port);
+		appendStringInfoChar(&buf, '"');
 	}
 	appendStringInfoChar(&buf, ',');
 
@@ -1762,13 +1742,17 @@ write_csvlog(ErrorData *edata)
 	/* PS display */
 	if (MyProcPort)
 	{
+		StringInfoData msgbuf;
 		const char *psdisp;
 		int			displen;
 
+		initStringInfo(&msgbuf);
+
 		psdisp = get_ps_display(&displen);
 		appendStringInfo(&msgbuf, "%.*s", displen, psdisp);
 		appendCSVLiteral(&buf, msgbuf.data);
-		resetStringInfo(&msgbuf);
+	
+		pfree(msgbuf.data);
 	}
 	appendStringInfoChar(&buf, ',');
 
@@ -1787,7 +1771,7 @@ write_csvlog(ErrorData *edata)
 
 	/* Virtual transaction id */
 	/* keep VXID format in sync with lockfuncs.c */
-	if (MyProc != NULL)
+	if (MyProc != NULL && MyProc->backendId != InvalidBackendId)
 		appendStringInfo(&buf, "%d/%u", MyProc->backendId, MyProc->lxid);
 	appendStringInfoChar(&buf, ',');
 
@@ -1796,53 +1780,77 @@ write_csvlog(ErrorData *edata)
 	appendStringInfoChar(&buf, ',');
 
 	/* Error severity */
-	appendStringInfo(&buf, "%s,", error_severity(edata->elevel));
+	appendStringInfo(&buf, "%s", error_severity(edata->elevel));
+	appendStringInfoChar(&buf, ',');
 
 	/* SQL state code */
-	appendStringInfo(&buf, "%s,", unpack_sql_state(edata->sqlerrcode));
+	appendStringInfo(&buf, "%s", unpack_sql_state(edata->sqlerrcode));
+	appendStringInfoChar(&buf, ',');
 
-	/* Error message and cursor position if any */
-	get_csv_error_message(&buf, edata);
+	/* errmessage */
+	appendCSVLiteral(&buf, edata->message);
+	appendStringInfoCharMacro(&buf, ',');
 
-	appendStringInfoChar(&buf, '\n');
+	/* errdetail */
+	appendCSVLiteral(&buf, edata->detail);
+	appendStringInfoCharMacro(&buf, ',');
 
-	/* 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);
+	/* errhint */
+	appendCSVLiteral(&buf, edata->hint);
+	appendStringInfoCharMacro(&buf, ',');
 
-	pfree(msgbuf.data);
-	pfree(buf.data);
-}
+	/* internal query */
+	appendCSVLiteral(&buf, edata->internalquery);
+	appendStringInfoCharMacro(&buf, ',');
 
-/*
- * Appends the buffer with the error message and the cursor position, all
- * CSV escaped.
- */
-static void
-get_csv_error_message(StringInfo buf, ErrorData *edata)
-{
-	char	   *msg = edata->message ? edata->message : _("missing error text");
-	char		c;
+	/* if printed internal query, print internal pos too */
+	if (edata->internalpos > 0 && edata->internalquery != NULL)
+		appendStringInfo(&buf, "%d", edata->internalpos);
+	appendStringInfoCharMacro(&buf, ',');
 
-	appendStringInfoCharMacro(buf, '"');
+	/* errcontext */
+	appendCSVLiteral(&buf, edata->context);
+	appendStringInfoCharMacro(&buf, ',');
 
-	while ((c = *msg++) != '\0')
+	/* 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 */
+	if (Log_error_verbosity >= PGERROR_VERBOSE)
 	{
-		if (c == '"')
-			appendStringInfoCharMacro(buf, '"');
-		appendStringInfoCharMacro(buf, c);
+		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);
+		appendCSVLiteral(&buf, msgbuf.data);
+		pfree(msgbuf.data);
 	}
 
-	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');
 
-	appendStringInfoCharMacro(buf, '"');
+	/* 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);
 }
 
 /*
-- 
GitLab