From: Ronan Dunklau <ronan.dunklau@aiven.io>
To: pgsql-hackers@lists.postgresql.org
Subject: Proposal: More structured logging
Date: Fri, 13 Aug 2021 15:23:03 +0200
Message-ID: <3207907.AWbSqkKDnR@aivenronan>
Organization: aiven
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="nextPart2291991.NPU9q4DvIS"
Content-Transfer-Encoding: 7Bit
Archived-At: 
 <https://www.postgresql.org/message-id/3207907.AWbSqkKDnR%40aivenronan>
Precedence: bulk

This is a multi-part message in MIME format.

--nextPart2291991.NPU9q4DvIS
Content-Transfer-Encoding: 7Bit
Content-Type: text/plain; charset="us-ascii"

Hello,

The logging system already captures a lot of information in the ErrorData. But 
at present there is no way for a log message authors to include more metadata 
about the log outside of the log message itself. For example, including the 
extension name which can be useful for filtering / dispatching log messages.
This can be done in the log message itself, but that requires specialized 
parsing in the log output. 

Even though among the available loggers in core, only the csv logger would be 
able to make sense of it, I feel it would be beneficial to add a tagging system 
to logs, by adding different (tag, value) combinations to a log entry, with an 
API similar to what we do for other ErrorData fields:

ereport(NOTICE,
 (errmsg("My log message")),
 (errtag("EMITTER", "MYEXTENSION")),
 (errtag("MSG-ID", "%d", error_message_id))
);

Please find attached a very small POC patch to better demonstrate what I 
propose.  

Third party logging hooks could then exploit those values to output them 
correctly. For example the json loggger written by Michael Paquier here: 
https://github.com/michaelpq/pg_plugins/tree/master/jsonlog, or  the 
seeminlgy-abandonned journald hook here: https://github.com/intgr/pg_journal 
could add those information in a structured way.

I think the pgaudit extension (or something similar) could also make good use 
of such a feature instead of dumping a CSV entry in the log file. 

As for Postgres own log messages, I'm sure we could find practical use cases 
for tagging messages like this.

On a related note, the only structured logger we have in-core is the CSV 
logger. Many users nowadays end up feeding the logs to journald either by 
capturing the stderr output with systemd, or by having syslog implemented by 
journald itself. Would there be any interest in having native journald support 
as a logging_destination ?

Best regards,

-- 
Ronan Dunklau
--nextPart2291991.NPU9q4DvIS
Content-Disposition: attachment; filename="v1-0001-Add-ErrorTag-support.patch"
Content-Transfer-Encoding: 7Bit
Content-Type: text/x-patch; charset="UTF-8";
 name="v1-0001-Add-ErrorTag-support.patch"

From 270ffc5ed2fbe5f5076bddee14c5fb3555b87e4f Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Fri, 13 Aug 2021 15:03:18 +0200
Subject: [PATCH v1 1/2] Add ErrorTag support

---
 src/backend/utils/error/elog.c | 48 ++++++++++++++++++++++++++++++++++
 src/include/utils/elog.h       | 10 +++++++
 2 files changed, 58 insertions(+)

diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index a3e1c59a82..5b9b1b8a72 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -465,6 +465,7 @@ errstart(int elevel, const char *domain)
 		edata->sqlerrcode = ERRCODE_SUCCESSFUL_COMPLETION;
 	/* errno is saved here so that error parameter eval can't change it */
 	edata->saved_errno = errno;
+	edata->tags = NIL;
 
 	/*
 	 * Any allocations for this error state level should go into ErrorContext
@@ -516,6 +517,7 @@ errfinish(const char *filename, int lineno, const char *funcname)
 	int			elevel;
 	MemoryContext oldcontext;
 	ErrorContextCallback *econtext;
+	ListCell   *lc;
 
 	recursion_depth++;
 	CHECK_STACK_DEPTH();
@@ -621,7 +623,18 @@ errfinish(const char *filename, int lineno, const char *funcname)
 		pfree(edata->constraint_name);
 	if (edata->internalquery)
 		pfree(edata->internalquery);
+	/* Every tag should have been palloc'ed */
+	if (edata->tags != NIL)
+	{
+		foreach(lc, edata->tags)
+		{
+			ErrorTag   *tag = (ErrorTag *) lfirst(lc);
 
+			pfree(tag->tagvalue);
+			pfree(tag);
+		}
+		pfree(edata->tags);
+	}
 	errordata_stack_depth--;
 
 	/* Exit error-handling context */
@@ -1192,6 +1205,41 @@ errhint_plural(const char *fmt_singular, const char *fmt_plural,
 	return 0;					/* return value does not matter */
 }
 
+int
+errtag(const char *tag, const char *fmt_value,...)
+{
+	ErrorData  *edata = &errordata[errordata_stack_depth];
+	ErrorTag   *etag;
+	MemoryContext oldcontext;
+	StringInfoData buf;
+
+	recursion_depth++;
+	CHECK_STACK_DEPTH();
+	oldcontext = MemoryContextSwitchTo(edata->assoc_context);
+	etag = palloc(sizeof(ErrorTag));
+	etag->tagname = tag;
+	initStringInfo(&buf);
+	for (;;)
+	{
+		va_list		args;
+		int			needed;
+
+		errno = edata->saved_errno;
+		va_start(args, fmt_value);
+		needed = appendStringInfoVA(&buf, fmt_value, args);
+		va_end(args);
+		if (needed == 0)
+			break;
+		enlargeStringInfo(&buf, needed);
+	}
+	etag->tagvalue = pstrdup(buf.data);
+	edata->tags = lappend(edata->tags, etag);
+	pfree(buf.data);
+	MemoryContextSwitchTo(oldcontext);
+	recursion_depth--;
+	return 0;
+}
+
 
 /*
  * errcontext_msg --- add a context error message text to the current error
diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
index f53607e12e..1c490d1b11 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -15,6 +15,7 @@
 #define ELOG_H
 
 #include <setjmp.h>
+#include "nodes/pg_list.h"
 
 /* Error level codes */
 #define DEBUG5		10			/* Debugging messages, in categories of
@@ -193,6 +194,8 @@ extern int	errhint(const char *fmt,...) pg_attribute_printf(1, 2);
 extern int	errhint_plural(const char *fmt_singular, const char *fmt_plural,
 						   unsigned long n,...) pg_attribute_printf(1, 4) pg_attribute_printf(2, 4);
 
+extern int	errtag(const char *tag, const char *fmt_value,...) pg_attribute_printf(2, 3);
+
 /*
  * errcontext() is typically called in error context callback functions, not
  * within an ereport() invocation. The callback function can be in a different
@@ -395,11 +398,18 @@ typedef struct ErrorData
 	int			internalpos;	/* cursor index into internalquery */
 	char	   *internalquery;	/* text of internally-generated query */
 	int			saved_errno;	/* errno at entry */
+	List	   *tags;			/* List of error tags */
 
 	/* context containing associated non-constant strings */
 	struct MemoryContextData *assoc_context;
 } ErrorData;
 
+typedef struct ErrorTag
+{
+	const char *tagname;
+	char	   *tagvalue;
+} ErrorTag;
+
 extern void EmitErrorReport(void);
 extern ErrorData *CopyErrorData(void);
 extern void FreeErrorData(ErrorData *edata);
-- 
2.32.0


--nextPart2291991.NPU9q4DvIS--