Proposal: More structured logging

Started by Ronan Dunklauover 4 years ago26 messages
#1Ronan Dunklau
ronan.dunklau@aiven.io
1 attachment(s)

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

Attachments:

v1-0001-Add-ErrorTag-support.patchtext/x-patch; charset=UTF-8; name=v1-0001-Add-ErrorTag-support.patchDownload
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

#2Alvaro Herrera
alvherre@alvh.no-ip.org
In reply to: Ronan Dunklau (#1)
Re: Proposal: More structured logging

On 2021-Aug-13, Ronan Dunklau wrote:

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

Interesting idea. I agree this would be useful.

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

Seems like a good start. I think a further step towards a committable
patch would include a test module that uses the new tagging
functionality.

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 ?

I don't know anything about journald, but I agree that we sorely need
some better way to emit structured log entries.

--
Álvaro Herrera Valdivia, Chile — https://www.EnterpriseDB.com/
"The problem with the facetime model is not just that it's demoralizing, but
that the people pretending to work interrupt the ones actually working."
(Paul Graham)

#3Magnus Hagander
magnus@hagander.net
In reply to: Alvaro Herrera (#2)
Re: Proposal: More structured logging

On Thu, Aug 19, 2021 at 3:04 PM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:

On 2021-Aug-13, Ronan Dunklau wrote:

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

Interesting idea. I agree this would be useful.

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

Seems like a good start. I think a further step towards a committable
patch would include a test module that uses the new tagging
functionality.

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 ?

I don't know anything about journald, but I agree that we sorely need
some better way to emit structured log entries.

+1. I think having the ability to natively send structured data to
journald would be useful.

Another thing I've noticed in more and more other products is to be
able to log as json, which is then later thrown into a central logging
system somewhere. Basically like csv, but with the schema defined in
each row. Yes, a lot more overhead, but some systems really do like to
consume json.... So when we're on the topic of more structured
logging...

--
Magnus Hagander
Me: https://www.hagander.net/
Work: https://www.redpill-linpro.com/

#4Alvaro Herrera
alvherre@alvh.no-ip.org
In reply to: Magnus Hagander (#3)
Re: Proposal: More structured logging

On 2021-Aug-19, Magnus Hagander wrote:

Another thing I've noticed in more and more other products is to be
able to log as json, which is then later thrown into a central logging
system somewhere. Basically like csv, but with the schema defined in
each row. Yes, a lot more overhead, but some systems really do like to
consume json.... So when we're on the topic of more structured
logging...

Yeah, I was thinking in json logging too -- specifically thinking about
Fluentbit and similar tools.

--
Álvaro Herrera PostgreSQL Developer — https://www.EnterpriseDB.com/

#5Ronan Dunklau
ronan.dunklau@aiven.io
In reply to: Alvaro Herrera (#2)
2 attachment(s)
Re: Proposal: More structured logging

Le jeudi 19 août 2021, 15:04:30 CEST Alvaro Herrera a écrit :

On 2021-Aug-13, Ronan Dunklau wrote:

ereport(NOTICE,

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

);

Interesting idea. I agree this would be useful.

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

Seems like a good start. I think a further step towards a committable
patch would include a test module that uses the new tagging
functionality.

Please find attached the original patch + a new one adding a test module.
The test module exposes a function for generating logs with tags, and a log
hook which format the tags in the DETAIL field for easy regression testing.

Next step would be to emit those tags in the CSV logs. I'm not sure what
representation they should have though: a nested csv in it's own column ? A
key => value pairs list similar to hstore ? A json object ?

Also we should probably make this available to the client too, but once again
the format of the tag field needs to be defined. Any opinion ?

--
Ronan Dunklau

Attachments:

v2-0001-Add-ErrorTag-support.patchtext/x-patch; charset=UTF-8; name=v2-0001-Add-ErrorTag-support.patchDownload
From e5af5d1a07e65926eee90e0d18443a673d1fcba8 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 v2 1/3] 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

v2-0002-Add-test-module-for-the-new-tag-functionality.patchtext/x-patch; charset=UTF-8; name=v2-0002-Add-test-module-for-the-new-tag-functionality.patchDownload
From 2cee45f3a6273141c177dff7d869c66e6fad01e4 Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Fri, 20 Aug 2021 10:46:20 +0200
Subject: [PATCH v2 2/3] Add test module for the new tag functionality.

This test module consists of an extension exposing a function which just
logs things, and a hook which adds the tags to the detail field in order
to be tested in "regular" output.
---
 src/test/modules/test_logging/Makefile        |  20 +++
 .../test_logging/expected/test_logging.out    |  18 +++
 .../modules/test_logging/sql/test_logging.sql |   5 +
 .../test_logging/test_logging--1.0.sql        |   4 +
 src/test/modules/test_logging/test_logging.c  | 121 ++++++++++++++++++
 .../modules/test_logging/test_logging.control |   5 +
 6 files changed, 173 insertions(+)
 create mode 100644 src/test/modules/test_logging/Makefile
 create mode 100644 src/test/modules/test_logging/expected/test_logging.out
 create mode 100644 src/test/modules/test_logging/sql/test_logging.sql
 create mode 100644 src/test/modules/test_logging/test_logging--1.0.sql
 create mode 100644 src/test/modules/test_logging/test_logging.c
 create mode 100644 src/test/modules/test_logging/test_logging.control

diff --git a/src/test/modules/test_logging/Makefile b/src/test/modules/test_logging/Makefile
new file mode 100644
index 0000000000..1191886e43
--- /dev/null
+++ b/src/test/modules/test_logging/Makefile
@@ -0,0 +1,20 @@
+# src/test/modules/test_logging/Makefile
+
+MODULES = test_logging
+
+EXTENSION = test_logging
+DATA = test_logging--1.0.sql
+PGFILEDESC = "test_logging - simple log hook test"
+
+REGRESS = test_logging
+
+ifdef USE_PGXS
+PG_CONFIG = pg_config
+PGXS := $(shell $(PG_CONFIG) --pgxs)
+include $(PGXS)
+else
+subdir = src/test/modules/test_logging
+top_builddir = ../../../..
+include $(top_builddir)/src/Makefile.global
+include $(top_srcdir)/contrib/contrib-global.mk
+endif
diff --git a/src/test/modules/test_logging/expected/test_logging.out b/src/test/modules/test_logging/expected/test_logging.out
new file mode 100644
index 0000000000..41423da535
--- /dev/null
+++ b/src/test/modules/test_logging/expected/test_logging.out
@@ -0,0 +1,18 @@
+CREATE EXTENSION test_logging;
+SET log_min_messages = NOTICE;
+SELECT test_logging(18, 'This is a test message', NULL);
+NOTICE:  This is a test message
+DETAIL:  NB TAGS: 0 TAGS: 
+ test_logging 
+--------------
+ 
+(1 row)
+
+SELECT test_logging(18, 'This is a test message', '{"tag1": "value1", "tag2": "value2"}');
+NOTICE:  This is a test message
+DETAIL:  NB TAGS: 2 TAGS: tag1: value1 tag2: value2 
+ test_logging 
+--------------
+ 
+(1 row)
+
diff --git a/src/test/modules/test_logging/sql/test_logging.sql b/src/test/modules/test_logging/sql/test_logging.sql
new file mode 100644
index 0000000000..bb964b4b63
--- /dev/null
+++ b/src/test/modules/test_logging/sql/test_logging.sql
@@ -0,0 +1,5 @@
+CREATE EXTENSION test_logging;
+SET log_min_messages = NOTICE;
+SELECT test_logging(18, 'This is a test message', NULL);
+SELECT test_logging(18, 'This is a test message', '{"tag1": "value1", "tag2": "value2"}');
+
diff --git a/src/test/modules/test_logging/test_logging--1.0.sql b/src/test/modules/test_logging/test_logging--1.0.sql
new file mode 100644
index 0000000000..663af2db8f
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging--1.0.sql
@@ -0,0 +1,4 @@
+CREATE FUNCTION test_logging(level int, message text, tags jsonb)
+RETURNS VOID
+AS 'MODULE_PATHNAME'
+LANGUAGE C;
diff --git a/src/test/modules/test_logging/test_logging.c b/src/test/modules/test_logging/test_logging.c
new file mode 100644
index 0000000000..f92eff5150
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging.c
@@ -0,0 +1,121 @@
+/*--------------------------------------------------------------------------
+ *
+ * test_logging.c
+ *		Test logging functions
+ *
+ * Copyright (c) 2021, PostgreSQL Global Development Group
+ *
+ * IDENTIFICATION
+ *		src/test/modules/test_logging/test_logging.c
+ *
+ * -------------------------------------------------------------------------
+ */
+
+#include <unistd.h>
+#include "postgres.h"
+
+#include "fmgr.h"
+#include "utils/builtins.h"
+#include "utils/elog.h"
+#include "utils/jsonb.h"
+
+PG_MODULE_MAGIC;
+
+static emit_log_hook_type prev_log_hook = NULL;
+
+void		_PG_init(void);
+void		_PG_fini(void);
+
+static void move_tags_to_detail(ErrorData *edata);
+
+static char *
+jsonb_value_to_tagvalue(JsonbValue *v)
+{
+	switch (v->type)
+	{
+		case jbvNull:
+			return "";
+		case jbvString:
+			return pnstrdup(v->val.string.val, v->val.string.len);
+		default:
+			elog(ERROR, "jsonb type not allowed here: %d", (int) v->type);
+	}
+}
+
+static void
+jsonb_tags_to_key_value_text_pairs(Jsonb *tags, List **keys, List **values)
+{
+	JsonbValue	v;
+	JsonbIterator *it;
+	JsonbIteratorToken r;
+	bool		skipNested = false;
+
+	it = JsonbIteratorInit(&tags->root);
+	*keys = *values = NIL;
+	while ((r = JsonbIteratorNext(&it, &v, skipNested)) != WJB_DONE)
+	{
+		skipNested = true;
+		if (r == WJB_KEY)
+		{
+			*keys = lappend(*keys, pnstrdup(v.val.string.val, v.val.string.len));
+			r = JsonbIteratorNext(&it, &v, skipNested);
+			Assert(r != WJB_DONE);
+			*values = lappend(*values, jsonb_value_to_tagvalue(&v));
+		}
+	}
+}
+
+PG_FUNCTION_INFO_V1(test_logging);
+Datum
+test_logging(PG_FUNCTION_ARGS)
+{
+	int			level = PG_GETARG_INT32(0);
+	char	   *message = "";
+	List	   *keys = NIL,
+			   *values = NIL;
+	ListCell   *lk,
+			   *lv;
+
+	if (!PG_ARGISNULL(1))
+	{
+		message = text_to_cstring(PG_GETARG_TEXT_PP(1));
+	}
+	if (!PG_ARGISNULL(2))
+	{
+		jsonb_tags_to_key_value_text_pairs(PG_GETARG_JSONB_P(2), &keys, &values);
+	}
+	ereport(level,
+	 (errmsg("%s", message),
+	  ({
+		forboth(lk, keys, lv, values)
+		{
+			(errtag(lfirst(lk), "%s", (char *) lfirst(lv)));
+		}})
+	));
+
+	PG_RETURN_VOID();
+}
+
+void
+move_tags_to_detail(ErrorData *edata)
+{
+	StringInfoData buf;
+	ListCell   *lc;
+
+	initStringInfo(&buf);
+	foreach(lc, edata->tags)
+	{
+		ErrorTag   *tag = (ErrorTag *) lfirst(lc);
+
+		appendStringInfo(&buf, "%s: %s ", tag->tagname, tag->tagvalue);
+	}
+	errdetail("NB TAGS: %d TAGS: %s", list_length(edata->tags), buf.data);
+	pfree(buf.data);
+}
+
+void
+_PG_init(void)
+{
+	prev_log_hook = emit_log_hook;
+	emit_log_hook = move_tags_to_detail;
+}
diff --git a/src/test/modules/test_logging/test_logging.control b/src/test/modules/test_logging/test_logging.control
new file mode 100644
index 0000000000..b1596b4b1d
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging.control
@@ -0,0 +1,5 @@
+# test_logging extension
+comment = 'test_logging - simple extension for emitting logs'
+default_version = '1.0'
+module_pathname = '$libdir/test_logging'
+relocatable = true
-- 
2.32.0

#6Ronan Dunklau
ronan.dunklau@aiven.io
In reply to: Alvaro Herrera (#4)
Re: Proposal: More structured logging

Le jeudi 19 août 2021, 16:50:10 CEST Alvaro Herrera a écrit :

On 2021-Aug-19, Magnus Hagander wrote:

Another thing I've noticed in more and more other products is to be
able to log as json, which is then later thrown into a central logging
system somewhere. Basically like csv, but with the schema defined in
each row. Yes, a lot more overhead, but some systems really do like to
consume json.... So when we're on the topic of more structured
logging...

Yeah, I was thinking in json logging too -- specifically thinking about
Fluentbit and similar tools.

Michael, your jsonlog module already fullfills this need. Is it something that
should be merged into our tree ?

--
Ronan Dunklau

#7Michael Paquier
michael@paquier.xyz
In reply to: Ronan Dunklau (#6)
Re: Proposal: More structured logging

On Fri, Aug 20, 2021 at 11:35:29AM +0200, Ronan Dunklau wrote:

Michael, your jsonlog module already fullfills this need. Is it something that
should be merged into our tree ?

Yes, there is nothing technically preventing to have this stuff in
core, of course, and that would even take care of the issues in
detecting if the piping protocol should be used or not.

Now, the last time this was proposed, there was a lot of drawback
because the presence of the JSON keys increases significantly the size
of the logs compared to CSV, and usually users care a lot about the
size of the log files. I would support the presence of JSON format
for the logs in core, FWIW.

The module is here, for reference:
https://github.com/michaelpq/pg_plugins/tree/master/jsonlog
--
Michael

#8Ronan Dunklau
ronan.dunklau@aiven.io
In reply to: Ronan Dunklau (#5)
3 attachment(s)
Re: Proposal: More structured logging

Le vendredi 20 août 2021, 11:31:21 CEST Ronan Dunklau a écrit :

Le jeudi 19 août 2021, 15:04:30 CEST Alvaro Herrera a écrit :

On 2021-Aug-13, Ronan Dunklau wrote:

ereport(NOTICE,

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

);

Interesting idea. I agree this would be useful.

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

Seems like a good start. I think a further step towards a committable
patch would include a test module that uses the new tagging
functionality.

Please find attached the original patch + a new one adding a test module.
The test module exposes a function for generating logs with tags, and a log
hook which format the tags in the DETAIL field for easy regression testing.

Next step would be to emit those tags in the CSV logs. I'm not sure what
representation they should have though: a nested csv in it's own column ? A
key => value pairs list similar to hstore ? A json object ?

I opted for a JSON representation in the CSV logs, please find attached v3
which is the same thing as v2 with another patch for CSV log output.

Also we should probably make this available to the client too, but once
again the format of the tag field needs to be defined. Any opinion ?

--
Ronan Dunklau

Attachments:

v3-0001-Add-ErrorTag-support.patchtext/x-patch; charset=UTF-8; name=v3-0001-Add-ErrorTag-support.patchDownload
From e5af5d1a07e65926eee90e0d18443a673d1fcba8 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 v3 1/3] 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

v3-0002-Add-test-module-for-the-new-tag-functionality.patchtext/x-patch; charset=UTF-8; name=v3-0002-Add-test-module-for-the-new-tag-functionality.patchDownload
From 2cee45f3a6273141c177dff7d869c66e6fad01e4 Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Fri, 20 Aug 2021 10:46:20 +0200
Subject: [PATCH v3 2/3] Add test module for the new tag functionality.

This test module consists of an extension exposing a function which just
logs things, and a hook which adds the tags to the detail field in order
to be tested in "regular" output.
---
 src/test/modules/test_logging/Makefile        |  20 +++
 .../test_logging/expected/test_logging.out    |  18 +++
 .../modules/test_logging/sql/test_logging.sql |   5 +
 .../test_logging/test_logging--1.0.sql        |   4 +
 src/test/modules/test_logging/test_logging.c  | 121 ++++++++++++++++++
 .../modules/test_logging/test_logging.control |   5 +
 6 files changed, 173 insertions(+)
 create mode 100644 src/test/modules/test_logging/Makefile
 create mode 100644 src/test/modules/test_logging/expected/test_logging.out
 create mode 100644 src/test/modules/test_logging/sql/test_logging.sql
 create mode 100644 src/test/modules/test_logging/test_logging--1.0.sql
 create mode 100644 src/test/modules/test_logging/test_logging.c
 create mode 100644 src/test/modules/test_logging/test_logging.control

diff --git a/src/test/modules/test_logging/Makefile b/src/test/modules/test_logging/Makefile
new file mode 100644
index 0000000000..1191886e43
--- /dev/null
+++ b/src/test/modules/test_logging/Makefile
@@ -0,0 +1,20 @@
+# src/test/modules/test_logging/Makefile
+
+MODULES = test_logging
+
+EXTENSION = test_logging
+DATA = test_logging--1.0.sql
+PGFILEDESC = "test_logging - simple log hook test"
+
+REGRESS = test_logging
+
+ifdef USE_PGXS
+PG_CONFIG = pg_config
+PGXS := $(shell $(PG_CONFIG) --pgxs)
+include $(PGXS)
+else
+subdir = src/test/modules/test_logging
+top_builddir = ../../../..
+include $(top_builddir)/src/Makefile.global
+include $(top_srcdir)/contrib/contrib-global.mk
+endif
diff --git a/src/test/modules/test_logging/expected/test_logging.out b/src/test/modules/test_logging/expected/test_logging.out
new file mode 100644
index 0000000000..41423da535
--- /dev/null
+++ b/src/test/modules/test_logging/expected/test_logging.out
@@ -0,0 +1,18 @@
+CREATE EXTENSION test_logging;
+SET log_min_messages = NOTICE;
+SELECT test_logging(18, 'This is a test message', NULL);
+NOTICE:  This is a test message
+DETAIL:  NB TAGS: 0 TAGS: 
+ test_logging 
+--------------
+ 
+(1 row)
+
+SELECT test_logging(18, 'This is a test message', '{"tag1": "value1", "tag2": "value2"}');
+NOTICE:  This is a test message
+DETAIL:  NB TAGS: 2 TAGS: tag1: value1 tag2: value2 
+ test_logging 
+--------------
+ 
+(1 row)
+
diff --git a/src/test/modules/test_logging/sql/test_logging.sql b/src/test/modules/test_logging/sql/test_logging.sql
new file mode 100644
index 0000000000..bb964b4b63
--- /dev/null
+++ b/src/test/modules/test_logging/sql/test_logging.sql
@@ -0,0 +1,5 @@
+CREATE EXTENSION test_logging;
+SET log_min_messages = NOTICE;
+SELECT test_logging(18, 'This is a test message', NULL);
+SELECT test_logging(18, 'This is a test message', '{"tag1": "value1", "tag2": "value2"}');
+
diff --git a/src/test/modules/test_logging/test_logging--1.0.sql b/src/test/modules/test_logging/test_logging--1.0.sql
new file mode 100644
index 0000000000..663af2db8f
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging--1.0.sql
@@ -0,0 +1,4 @@
+CREATE FUNCTION test_logging(level int, message text, tags jsonb)
+RETURNS VOID
+AS 'MODULE_PATHNAME'
+LANGUAGE C;
diff --git a/src/test/modules/test_logging/test_logging.c b/src/test/modules/test_logging/test_logging.c
new file mode 100644
index 0000000000..f92eff5150
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging.c
@@ -0,0 +1,121 @@
+/*--------------------------------------------------------------------------
+ *
+ * test_logging.c
+ *		Test logging functions
+ *
+ * Copyright (c) 2021, PostgreSQL Global Development Group
+ *
+ * IDENTIFICATION
+ *		src/test/modules/test_logging/test_logging.c
+ *
+ * -------------------------------------------------------------------------
+ */
+
+#include <unistd.h>
+#include "postgres.h"
+
+#include "fmgr.h"
+#include "utils/builtins.h"
+#include "utils/elog.h"
+#include "utils/jsonb.h"
+
+PG_MODULE_MAGIC;
+
+static emit_log_hook_type prev_log_hook = NULL;
+
+void		_PG_init(void);
+void		_PG_fini(void);
+
+static void move_tags_to_detail(ErrorData *edata);
+
+static char *
+jsonb_value_to_tagvalue(JsonbValue *v)
+{
+	switch (v->type)
+	{
+		case jbvNull:
+			return "";
+		case jbvString:
+			return pnstrdup(v->val.string.val, v->val.string.len);
+		default:
+			elog(ERROR, "jsonb type not allowed here: %d", (int) v->type);
+	}
+}
+
+static void
+jsonb_tags_to_key_value_text_pairs(Jsonb *tags, List **keys, List **values)
+{
+	JsonbValue	v;
+	JsonbIterator *it;
+	JsonbIteratorToken r;
+	bool		skipNested = false;
+
+	it = JsonbIteratorInit(&tags->root);
+	*keys = *values = NIL;
+	while ((r = JsonbIteratorNext(&it, &v, skipNested)) != WJB_DONE)
+	{
+		skipNested = true;
+		if (r == WJB_KEY)
+		{
+			*keys = lappend(*keys, pnstrdup(v.val.string.val, v.val.string.len));
+			r = JsonbIteratorNext(&it, &v, skipNested);
+			Assert(r != WJB_DONE);
+			*values = lappend(*values, jsonb_value_to_tagvalue(&v));
+		}
+	}
+}
+
+PG_FUNCTION_INFO_V1(test_logging);
+Datum
+test_logging(PG_FUNCTION_ARGS)
+{
+	int			level = PG_GETARG_INT32(0);
+	char	   *message = "";
+	List	   *keys = NIL,
+			   *values = NIL;
+	ListCell   *lk,
+			   *lv;
+
+	if (!PG_ARGISNULL(1))
+	{
+		message = text_to_cstring(PG_GETARG_TEXT_PP(1));
+	}
+	if (!PG_ARGISNULL(2))
+	{
+		jsonb_tags_to_key_value_text_pairs(PG_GETARG_JSONB_P(2), &keys, &values);
+	}
+	ereport(level,
+	 (errmsg("%s", message),
+	  ({
+		forboth(lk, keys, lv, values)
+		{
+			(errtag(lfirst(lk), "%s", (char *) lfirst(lv)));
+		}})
+	));
+
+	PG_RETURN_VOID();
+}
+
+void
+move_tags_to_detail(ErrorData *edata)
+{
+	StringInfoData buf;
+	ListCell   *lc;
+
+	initStringInfo(&buf);
+	foreach(lc, edata->tags)
+	{
+		ErrorTag   *tag = (ErrorTag *) lfirst(lc);
+
+		appendStringInfo(&buf, "%s: %s ", tag->tagname, tag->tagvalue);
+	}
+	errdetail("NB TAGS: %d TAGS: %s", list_length(edata->tags), buf.data);
+	pfree(buf.data);
+}
+
+void
+_PG_init(void)
+{
+	prev_log_hook = emit_log_hook;
+	emit_log_hook = move_tags_to_detail;
+}
diff --git a/src/test/modules/test_logging/test_logging.control b/src/test/modules/test_logging/test_logging.control
new file mode 100644
index 0000000000..b1596b4b1d
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging.control
@@ -0,0 +1,5 @@
+# test_logging extension
+comment = 'test_logging - simple extension for emitting logs'
+default_version = '1.0'
+module_pathname = '$libdir/test_logging'
+relocatable = true
-- 
2.32.0

v3-0003-Output-error-tags-in-CSV-logs.patchtext/x-patch; charset=UTF-8; name=v3-0003-Output-error-tags-in-CSV-logs.patchDownload
From be7fe7bbca9740c390a2a96b985c28d964bd1ef8 Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Fri, 13 Aug 2021 15:03:32 +0200
Subject: [PATCH v3 3/3] Output error tags in CSV logs

---
 doc/src/sgml/config.sgml       |  4 +++-
 src/backend/utils/error/elog.c | 25 ++++++++++++++++++++++++-
 2 files changed, 27 insertions(+), 2 deletions(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 2c31c35a6b..4ef59b32e9 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7338,7 +7338,8 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
         location of the error in the PostgreSQL source code
         (if <varname>log_error_verbosity</varname> is set to <literal>verbose</literal>),
         application name, backend type, process ID of parallel group leader,
-        and query id.
+        query id,
+        and optional tags added by the logger as JSON.
         Here is a sample table definition for storing CSV-format log output:
 
 <programlisting>
@@ -7370,6 +7371,7 @@ CREATE TABLE postgres_log
   backend_type text,
   leader_pid integer,
   query_id bigint,
+  tags jsonb
   PRIMARY KEY (session_id, session_line_num)
 );
 </programlisting>
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 5b9b1b8a72..4737054b87 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -80,6 +80,7 @@
 #include "storage/proc.h"
 #include "tcop/tcopprot.h"
 #include "utils/guc.h"
+#include "utils/json.h"
 #include "utils/memutils.h"
 #include "utils/ps_status.h"
 
@@ -3013,10 +3014,32 @@ write_csvlog(ErrorData *edata)
 			appendStringInfo(&buf, "%d", leader->pid);
 	}
 	appendStringInfoChar(&buf, ',');
-
 	/* query id */
 	appendStringInfo(&buf, "%lld", (long long) pgstat_get_my_query_id());
+	appendStringInfoChar(&buf, ',');
+	if (edata->tags != NIL)
+	{
+		StringInfoData tagbuf;
+		ListCell   *lc;
+		bool		first = true;
 
+		initStringInfo(&tagbuf);
+		appendStringInfoChar(&tagbuf, '{');
+		foreach(lc, edata->tags)
+		{
+			ErrorTag   *etag = lfirst(lc);
+
+			if (!first)
+				appendStringInfoChar(&tagbuf, ',');
+			escape_json(&tagbuf, etag->tagname);
+			appendStringInfoChar(&tagbuf, ':');
+			escape_json(&tagbuf, etag->tagvalue);
+			first = false;
+		}
+		appendStringInfoChar(&tagbuf, '}');
+		appendCSVLiteral(&buf, tagbuf.data);
+		pfree(tagbuf.data);
+	}
 	appendStringInfoChar(&buf, '\n');
 
 	/* If in the syslogger process, try to write messages direct to file */
-- 
2.32.0

#9Magnus Hagander
magnus@hagander.net
In reply to: Michael Paquier (#7)
Re: Proposal: More structured logging

On Sat, Aug 21, 2021 at 2:37 AM Michael Paquier <michael@paquier.xyz> wrote:

On Fri, Aug 20, 2021 at 11:35:29AM +0200, Ronan Dunklau wrote:

Michael, your jsonlog module already fullfills this need. Is it something that
should be merged into our tree ?

Yes, there is nothing technically preventing to have this stuff in
core, of course, and that would even take care of the issues in
detecting if the piping protocol should be used or not.

Now, the last time this was proposed, there was a lot of drawback
because the presence of the JSON keys increases significantly the size
of the logs compared to CSV, and usually users care a lot about the
size of the log files. I would support the presence of JSON format
for the logs in core, FWIW.

As long as it's optional, I don't think that drawback holds as an
argument. The same argument could be made against the cvs logs in the
first place -- they add information to every row that a lot of people
don't need. But it's optional. Leaving it up to the administrator to
choose whether they prefer the verbose-and-easier-to-parse-maybe
format or the more compact format seems like the right path for that.
I bet quite a few would actually choose json -- easier to integrate
with other systems (because newer systems love json), and unless
you're actually logging a lot of queries (which many people don't),
the size of the logfile is often not a concern at all.

In short, I would also support the presence of JSON log format in
core. (but as a proper log_destination of course -- or if it's time to
actually split that into a separaet thing, being one parameter for
log_destination and another for log_format)

--
Magnus Hagander
Me: https://www.hagander.net/
Work: https://www.redpill-linpro.com/

#10Michael Paquier
michael@paquier.xyz
In reply to: Magnus Hagander (#9)
Re: Proposal: More structured logging

On Mon, Aug 23, 2021 at 11:33:09AM +0200, Magnus Hagander wrote:

As long as it's optional, I don't think that drawback holds as an
argument. The same argument could be made against the cvs logs in the
first place -- they add information to every row that a lot of people
don't need. But it's optional. Leaving it up to the administrator to
choose whether they prefer the verbose-and-easier-to-parse-maybe
format or the more compact format seems like the right path for that.

From a code perspective, and while on it, we could split a bit elog.c
and move the log entries generated for each format into their own
file. That would be cleaner for CSV and JSON. As a whole I don't
have an objection with moving the JSON format into core. If one
proposes a patch, feel free to reuse the code from the module I have
released.

I bet quite a few would actually choose json -- easier to integrate
with other systems (because newer systems love json), and unless
you're actually logging a lot of queries (which many people don't),
the size of the logfile is often not a concern at all.

The module I publish on github to do this work is the most popular
thing of my plugin repo, FWIW. It even gets bug reports, sometimes.

In short, I would also support the presence of JSON log format in
core. (but as a proper log_destination of course -- or if it's time to
actually split that into a separaet thing, being one parameter for
log_destination and another for log_format)

What would you gain with a new parameter here? I think that this
would be rather confusing and log_destination has been around for
years.
--
Michael

#11Sehrope Sarkuni
sehrope@jackdb.com
In reply to: Michael Paquier (#10)
Re: Proposal: More structured logging

On Tue, Aug 24, 2021 at 7:22 PM Michael Paquier <michael@paquier.xyz> wrote:

From a code perspective, and while on it, we could split a bit elog.c
and move the log entries generated for each format into their own
file. That would be cleaner for CSV and JSON. As a whole I don't
have an objection with moving the JSON format into core. If one
proposes a patch, feel free to reuse the code from the module I have
released.

I had a patch that does exactly this from a few years ago. It started off
copying a bunch out of your json logging module and adds it as a new
"jsonlog" destination.

It needed some cleanup due to bit rot, but it now builds and works atop
master. I'll post it in its own thread.

Regards,
-- Sehrope Sarkuni
Founder & CEO | JackDB, Inc. | https://www.jackdb.com/

#12Michael Paquier
michael@paquier.xyz
In reply to: Sehrope Sarkuni (#11)
Re: Proposal: More structured logging

On Tue, Aug 31, 2021 at 10:46:30AM -0400, Sehrope Sarkuni wrote:

It needed some cleanup due to bit rot, but it now builds and works atop
master. I'll post it in its own thread.

Thanks.
--
Michael

#13Peter Eisentraut
peter.eisentraut@enterprisedb.com
In reply to: Magnus Hagander (#9)
Re: Proposal: More structured logging

On 23.08.21 11:33, Magnus Hagander wrote:

In short, I would also support the presence of JSON log format in
core. (but as a proper log_destination of course -- or if it's time to
actually split that into a separaet thing, being one parameter for
log_destination and another for log_format)

It would be useful if there was some kind of standardized schema for
JSON logging, meaning what the keys should be named etc. Then we don't
need to make this all up from scratch, and there could be some
integration with existing log analysis tools.

#14Peter Eisentraut
peter.eisentraut@enterprisedb.com
In reply to: Ronan Dunklau (#1)
Re: Proposal: More structured logging

On 13.08.21 15:23, Ronan Dunklau wrote:

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))
);

What are some more examples of where this could be used? The extension
name could be added more or less automatically to ereport() calls. I
don't know what the MSG-ID is supposed to be. Are there other use cases?

#15Ronan Dunklau
ronan.dunklau@aiven.io
In reply to: Peter Eisentraut (#14)
Re: Proposal: More structured logging

Le mercredi 1 septembre 2021, 09:36:50 CEST Peter Eisentraut a écrit :

On 13.08.21 15:23, Ronan Dunklau wrote:

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))

);

What are some more examples of where this could be used? The extension
name could be added more or less automatically to ereport() calls. I
don't know what the MSG-ID is supposed to be. Are there other use cases?

Adding it automatically would be nice, but how would you go about that ?

In-core it would open up the possibility to split log messages into different
fields, for example the different statistics reported in the logs by VACUUM /
ANALYZE VERBOSE and make it easier to consume the output without having to
parse the message. Parsing the message also means that any tool parsing it
needs to either be aware of the locale, or to force the user to use a specific
one.

Out-of-core, the same things could be done for extensions like pg_audit which
logs structured information into the message itself, leaving the message
format to be parsed at a later time.

--
Ronan Dunklau

#16Peter Eisentraut
peter.eisentraut@enterprisedb.com
In reply to: Ronan Dunklau (#15)
Re: Proposal: More structured logging

On 01.09.21 10:00, Ronan Dunklau wrote:

In-core it would open up the possibility to split log messages into different
fields, for example the different statistics reported in the logs by VACUUM /
ANALYZE VERBOSE and make it easier to consume the output without having to
parse the message. Parsing the message also means that any tool parsing it
needs to either be aware of the locale, or to force the user to use a specific
one.

I think those messages would themselves have substructure. For example,
the current message

"I/O timings: read: %.3f ms, write: %.3f ms\n"

might be

{"I/O timings": {"read": ..., "write": ...}}

and that in turn is already part of a larger message.

So just having a single level of tags wouldn't really work for this.

#17Ronan Dunklau
ronan.dunklau@aiven.io
In reply to: Peter Eisentraut (#16)
Re: Proposal: More structured logging

Le mercredi 8 septembre 2021, 11:51:31 CEST Peter Eisentraut a écrit :

On 01.09.21 10:00, Ronan Dunklau wrote:

In-core it would open up the possibility to split log messages into
different fields, for example the different statistics reported in the
logs by VACUUM / ANALYZE VERBOSE and make it easier to consume the output
without having to parse the message. Parsing the message also means that
any tool parsing it needs to either be aware of the locale, or to force
the user to use a specific one.

I think those messages would themselves have substructure. For example,
the current message

"I/O timings: read: %.3f ms, write: %.3f ms\n"

might be

{"I/O timings": {"read": ..., "write": ...}}

and that in turn is already part of a larger message.

So just having a single level of tags wouldn't really work for this.

I agree having a nested structure may feel more natural, but I don't think it
would matter too much if we standardize on ini-style property names (ie,
iotimings.read, iotimings.write and so on...)

Regards,

--
Ronan Dunklau

#18Justin Pryzby
pryzby@telsasoft.com
In reply to: Ronan Dunklau (#8)
Re: Proposal: More structured logging

Subject: [PATCH v3 2/3] Add test module for the new tag functionality.

...

+test_logging(PG_FUNCTION_ARGS)
+{

...

+	 (errmsg("%s", message),
+	  ({
+		forboth(lk, keys, lv, values)
+		{
+			(errtag(lfirst(lk), "%s", (char *) lfirst(lv)));
+		}})
+	));

The windows build fails with that syntax.
http://cfbot.cputube.org/ronan-dunklau.html
https://ci.appveyor.com/project/postgresql-cfbot/postgresql/build/1.0.157923

Subject: [PATCH v3 3/3] Output error tags in CSV logs
+++ b/doc/src/sgml/config.sgml
@@ -7370,6 +7371,7 @@ CREATE TABLE postgres_log
backend_type text,
leader_pid integer,
query_id bigint,
+  tags jsonb
PRIMARY KEY (session_id, session_line_num)
);
</programlisting>

That's invalid sql due to missing a trailing ",".

You should also update file-fdw.sgml - which I only think of since we forgot in
to update it before e568ed0eb and 0830d21f5. config.sgml should have a comment
as a reminder to do that.

--
Justin

#19Ronan Dunklau
ronan.dunklau@aiven.io
In reply to: Justin Pryzby (#18)
4 attachment(s)
Re: Proposal: More structured logging

Le mercredi 29 décembre 2021, 14:59:16 CET Justin Pryzby a écrit :

Subject: [PATCH v3 2/3] Add test module for the new tag functionality.

...

+test_logging(PG_FUNCTION_ARGS)
+{

...

+	 (errmsg("%s", message),
+	  ({
+		forboth(lk, keys, lv, values)
+		{
+			(errtag(lfirst(lk), "%s", (char *) 

lfirst(lv)));

+ }})
+ ));

The windows build fails with that syntax.
http://cfbot.cputube.org/ronan-dunklau.html
https://ci.appveyor.com/project/postgresql-cfbot/postgresql/build/1.0.157923

Thank you. I switched to an explicit sequence of errstart / errfinish to avoid
putting too much things in nested macro calls. As I don't have any Windows
knowledge, I am very grateful for the new cirrus-ci integration which allowed
me to build on Windows without hassle.

Subject: [PATCH v3 3/3] Output error tags in CSV logs
+++ b/doc/src/sgml/config.sgml
@@ -7370,6 +7371,7 @@ CREATE TABLE postgres_log

backend_type text,
leader_pid integer,
query_id bigint,

+ tags jsonb

PRIMARY KEY (session_id, session_line_num)

);
</programlisting>

That's invalid sql due to missing a trailing ",".

Thanks, fixed.

You should also update file-fdw.sgml - which I only think of since we forgot
in to update it before e568ed0eb and 0830d21f5. config.sgml should have a
comment as a reminder to do that.

Done, and I added anoher commit per your suggestion to add this comment.

Thank you for this review.

Regards,

--
Ronan Dunklau

Attachments:

v4-0004-Add-comment-in-config.sgml-as-a-reminder-to-also-.patchtext/x-patch; charset=UTF-8; name=v4-0004-Add-comment-in-config.sgml-as-a-reminder-to-also-.patchDownload
From 487c34465b34ef6ef8cb466247cbaaa8cf4bc534 Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Tue, 11 Jan 2022 10:16:53 +0100
Subject: [PATCH v4 4/4] Add comment in config.sgml as a reminder to also
 update file_fdw.sgml

---
 doc/src/sgml/config.sgml | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 4df79fcbcc..d4c20f40ac 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7375,7 +7375,7 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
         query id,
         and optional tags added by the logger as JSON.
         Here is a sample table definition for storing CSV-format log output:
-
+<!-- Don't forget to also update file_fdw.sgml if you change this table definition -->
 <programlisting>
 CREATE TABLE postgres_log
 (
-- 
2.34.1

v4-0003-Output-error-tags-in-CSV-logs.patchtext/x-patch; charset=UTF-8; name=v4-0003-Output-error-tags-in-CSV-logs.patchDownload
From a1c4ae874bf156a05da436838d6b2b73f6621905 Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Fri, 13 Aug 2021 15:03:32 +0200
Subject: [PATCH v4 3/4] Output error tags in CSV logs

---
 doc/src/sgml/config.sgml       |  4 +++-
 doc/src/sgml/file-fdw.sgml     |  1 +
 src/backend/utils/error/elog.c | 25 ++++++++++++++++++++++++-
 3 files changed, 28 insertions(+), 2 deletions(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index afbb6c35e3..4df79fcbcc 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7372,7 +7372,8 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
         location of the error in the PostgreSQL source code
         (if <varname>log_error_verbosity</varname> is set to <literal>verbose</literal>),
         application name, backend type, process ID of parallel group leader,
-        and query id.
+        query id,
+        and optional tags added by the logger as JSON.
         Here is a sample table definition for storing CSV-format log output:
 
 <programlisting>
@@ -7404,6 +7405,7 @@ CREATE TABLE postgres_log
   backend_type text,
   leader_pid integer,
   query_id bigint,
+  tags jsonb,
   PRIMARY KEY (session_id, session_line_num)
 );
 </programlisting>
diff --git a/doc/src/sgml/file-fdw.sgml b/doc/src/sgml/file-fdw.sgml
index 5b98782064..ccb4e9d8dd 100644
--- a/doc/src/sgml/file-fdw.sgml
+++ b/doc/src/sgml/file-fdw.sgml
@@ -268,6 +268,7 @@ CREATE FOREIGN TABLE pglog (
   backend_type text,
   leader_pid integer,
   query_id bigint
+  tags jsonb,
 ) SERVER pglog
 OPTIONS ( filename 'log/pglog.csv', format 'csv' );
 </programlisting>
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index d43e1c2c31..1e6c7222c3 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -80,6 +80,7 @@
 #include "storage/proc.h"
 #include "tcop/tcopprot.h"
 #include "utils/guc.h"
+#include "utils/json.h"
 #include "utils/memutils.h"
 #include "utils/ps_status.h"
 
@@ -3013,10 +3014,32 @@ write_csvlog(ErrorData *edata)
 			appendStringInfo(&buf, "%d", leader->pid);
 	}
 	appendStringInfoChar(&buf, ',');
-
 	/* query id */
 	appendStringInfo(&buf, "%lld", (long long) pgstat_get_my_query_id());
+	appendStringInfoChar(&buf, ',');
+	if (edata->tags != NIL)
+	{
+		StringInfoData tagbuf;
+		ListCell   *lc;
+		bool		first = true;
 
+		initStringInfo(&tagbuf);
+		appendStringInfoChar(&tagbuf, '{');
+		foreach(lc, edata->tags)
+		{
+			ErrorTag   *etag = lfirst(lc);
+
+			if (!first)
+				appendStringInfoChar(&tagbuf, ',');
+			escape_json(&tagbuf, etag->tagname);
+			appendStringInfoChar(&tagbuf, ':');
+			escape_json(&tagbuf, etag->tagvalue);
+			first = false;
+		}
+		appendStringInfoChar(&tagbuf, '}');
+		appendCSVLiteral(&buf, tagbuf.data);
+		pfree(tagbuf.data);
+	}
 	appendStringInfoChar(&buf, '\n');
 
 	/* If in the syslogger process, try to write messages direct to file */
-- 
2.34.1

v4-0002-Add-test-module-for-the-new-tag-functionality.patchtext/x-patch; charset=UTF-8; name=v4-0002-Add-test-module-for-the-new-tag-functionality.patchDownload
From 0b77633a524fa670601a1b49d0122d2e85c6bb70 Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Fri, 20 Aug 2021 10:46:20 +0200
Subject: [PATCH v4 2/4] Add test module for the new tag functionality.

This test module consists of an extension exposing a function which just
logs things, and a hook which adds the tags to the detail field in order
to be tested in "regular" output.
---
 src/test/modules/test_logging/Makefile        |  20 +++
 .../test_logging/expected/test_logging.out    |  18 +++
 .../modules/test_logging/sql/test_logging.sql |   5 +
 .../test_logging/test_logging--1.0.sql        |   4 +
 src/test/modules/test_logging/test_logging.c  | 120 ++++++++++++++++++
 .../modules/test_logging/test_logging.control |   5 +
 6 files changed, 172 insertions(+)
 create mode 100644 src/test/modules/test_logging/Makefile
 create mode 100644 src/test/modules/test_logging/expected/test_logging.out
 create mode 100644 src/test/modules/test_logging/sql/test_logging.sql
 create mode 100644 src/test/modules/test_logging/test_logging--1.0.sql
 create mode 100644 src/test/modules/test_logging/test_logging.c
 create mode 100644 src/test/modules/test_logging/test_logging.control

diff --git a/src/test/modules/test_logging/Makefile b/src/test/modules/test_logging/Makefile
new file mode 100644
index 0000000000..1191886e43
--- /dev/null
+++ b/src/test/modules/test_logging/Makefile
@@ -0,0 +1,20 @@
+# src/test/modules/test_logging/Makefile
+
+MODULES = test_logging
+
+EXTENSION = test_logging
+DATA = test_logging--1.0.sql
+PGFILEDESC = "test_logging - simple log hook test"
+
+REGRESS = test_logging
+
+ifdef USE_PGXS
+PG_CONFIG = pg_config
+PGXS := $(shell $(PG_CONFIG) --pgxs)
+include $(PGXS)
+else
+subdir = src/test/modules/test_logging
+top_builddir = ../../../..
+include $(top_builddir)/src/Makefile.global
+include $(top_srcdir)/contrib/contrib-global.mk
+endif
diff --git a/src/test/modules/test_logging/expected/test_logging.out b/src/test/modules/test_logging/expected/test_logging.out
new file mode 100644
index 0000000000..41423da535
--- /dev/null
+++ b/src/test/modules/test_logging/expected/test_logging.out
@@ -0,0 +1,18 @@
+CREATE EXTENSION test_logging;
+SET log_min_messages = NOTICE;
+SELECT test_logging(18, 'This is a test message', NULL);
+NOTICE:  This is a test message
+DETAIL:  NB TAGS: 0 TAGS: 
+ test_logging 
+--------------
+ 
+(1 row)
+
+SELECT test_logging(18, 'This is a test message', '{"tag1": "value1", "tag2": "value2"}');
+NOTICE:  This is a test message
+DETAIL:  NB TAGS: 2 TAGS: tag1: value1 tag2: value2 
+ test_logging 
+--------------
+ 
+(1 row)
+
diff --git a/src/test/modules/test_logging/sql/test_logging.sql b/src/test/modules/test_logging/sql/test_logging.sql
new file mode 100644
index 0000000000..bb964b4b63
--- /dev/null
+++ b/src/test/modules/test_logging/sql/test_logging.sql
@@ -0,0 +1,5 @@
+CREATE EXTENSION test_logging;
+SET log_min_messages = NOTICE;
+SELECT test_logging(18, 'This is a test message', NULL);
+SELECT test_logging(18, 'This is a test message', '{"tag1": "value1", "tag2": "value2"}');
+
diff --git a/src/test/modules/test_logging/test_logging--1.0.sql b/src/test/modules/test_logging/test_logging--1.0.sql
new file mode 100644
index 0000000000..663af2db8f
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging--1.0.sql
@@ -0,0 +1,4 @@
+CREATE FUNCTION test_logging(level int, message text, tags jsonb)
+RETURNS VOID
+AS 'MODULE_PATHNAME'
+LANGUAGE C;
diff --git a/src/test/modules/test_logging/test_logging.c b/src/test/modules/test_logging/test_logging.c
new file mode 100644
index 0000000000..18cd39b8e2
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging.c
@@ -0,0 +1,120 @@
+/*--------------------------------------------------------------------------
+ *
+ * test_logging.c
+ *		Test logging functions
+ *
+ * Copyright (c) 2021, PostgreSQL Global Development Group
+ *
+ * IDENTIFICATION
+ *		src/test/modules/test_logging/test_logging.c
+ *
+ * -------------------------------------------------------------------------
+ */
+
+#include <unistd.h>
+#include "postgres.h"
+
+#include "fmgr.h"
+#include "utils/builtins.h"
+#include "utils/elog.h"
+#include "utils/jsonb.h"
+
+PG_MODULE_MAGIC;
+
+static emit_log_hook_type prev_log_hook = NULL;
+
+void		_PG_init(void);
+void		_PG_fini(void);
+
+static void move_tags_to_detail(ErrorData *edata);
+
+static char *
+jsonb_value_to_tagvalue(JsonbValue *v)
+{
+	switch (v->type)
+	{
+		case jbvNull:
+			return "";
+		case jbvString:
+			return pnstrdup(v->val.string.val, v->val.string.len);
+		default:
+			elog(ERROR, "jsonb type not allowed here: %d", (int) v->type);
+	}
+}
+
+static void
+jsonb_tags_to_key_value_text_pairs(Jsonb *tags, List **keys, List **values)
+{
+	JsonbValue	v;
+	JsonbIterator *it;
+	JsonbIteratorToken r;
+	bool		skipNested = false;
+
+	it = JsonbIteratorInit(&tags->root);
+	*keys = *values = NIL;
+	while ((r = JsonbIteratorNext(&it, &v, skipNested)) != WJB_DONE)
+	{
+		skipNested = true;
+		if (r == WJB_KEY)
+		{
+			*keys = lappend(*keys, pnstrdup(v.val.string.val, v.val.string.len));
+			r = JsonbIteratorNext(&it, &v, skipNested);
+			Assert(r != WJB_DONE);
+			*values = lappend(*values, jsonb_value_to_tagvalue(&v));
+		}
+	}
+}
+
+PG_FUNCTION_INFO_V1(test_logging);
+Datum
+test_logging(PG_FUNCTION_ARGS)
+{
+	int			level = PG_GETARG_INT32(0);
+	char	   *message = "";
+	List	   *keys = NIL,
+			   *values = NIL;
+	ListCell   *lk,
+			   *lv;
+
+	if (!PG_ARGISNULL(1))
+	{
+		message = text_to_cstring(PG_GETARG_TEXT_PP(1));
+	}
+	if (!PG_ARGISNULL(2))
+	{
+		jsonb_tags_to_key_value_text_pairs(PG_GETARG_JSONB_P(2), &keys, &values);
+	}
+	errstart(level, TEXTDOMAIN);
+	errmsg("%s", message);
+	forboth(lk, keys, lv, values)
+	{
+		errtag(lfirst(lk), "%s", (char *) lfirst(lv));
+	}
+	errfinish(__FILE__, __LINE__, PG_FUNCNAME_MACRO);
+
+	PG_RETURN_VOID();
+}
+
+void
+move_tags_to_detail(ErrorData *edata)
+{
+	StringInfoData buf;
+	ListCell   *lc;
+
+	initStringInfo(&buf);
+	foreach(lc, edata->tags)
+	{
+		ErrorTag   *tag = (ErrorTag *) lfirst(lc);
+
+		appendStringInfo(&buf, "%s: %s ", tag->tagname, tag->tagvalue);
+	}
+	errdetail("NB TAGS: %d TAGS: %s", list_length(edata->tags), buf.data);
+	pfree(buf.data);
+}
+
+void
+_PG_init(void)
+{
+	prev_log_hook = emit_log_hook;
+	emit_log_hook = move_tags_to_detail;
+}
diff --git a/src/test/modules/test_logging/test_logging.control b/src/test/modules/test_logging/test_logging.control
new file mode 100644
index 0000000000..b1596b4b1d
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging.control
@@ -0,0 +1,5 @@
+# test_logging extension
+comment = 'test_logging - simple extension for emitting logs'
+default_version = '1.0'
+module_pathname = '$libdir/test_logging'
+relocatable = true
-- 
2.34.1

v4-0001-Add-ErrorTag-support.patchtext/x-patch; charset=UTF-8; name=v4-0001-Add-ErrorTag-support.patchDownload
From 459ad0f31be11889d0027be69fe78937f3b01946 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 v4 1/4] 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 2f2c3ba41b..d43e1c2c31 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 8df2799dc2..49aa741eb5 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.34.1

#20Julien Rouhaud
rjuju123@gmail.com
In reply to: Ronan Dunklau (#19)
Re: Proposal: More structured logging

Hi,

On Tue, Jan 11, 2022 at 11:05:26AM +0100, Ronan Dunklau wrote:

Done, and I added anoher commit per your suggestion to add this comment.

The cfbot reports that the patchset doesn't apply anymore:

http://cfbot.cputube.org/patch_36_3293.log
=== Applying patches on top of PostgreSQL commit ID 43c2175121c829c8591fc5117b725f1f22bfb670 ===
[...]
=== applying patch ./v4-0003-Output-error-tags-in-CSV-logs.patch
[...]
patching file src/backend/utils/error/elog.c
Hunk #2 FAILED at 3014.
1 out of 2 hunks FAILED -- saving rejects to file src/backend/utils/error/elog.c.rej

Could you send a rebased version? In the meantime I will switch the cf entry
to Waiting on Author.

#21Ronan Dunklau
ronan.dunklau@aiven.io
In reply to: Julien Rouhaud (#20)
5 attachment(s)
Re: Proposal: More structured logging

Le samedi 15 janvier 2022, 07:09:59 CET Julien Rouhaud a écrit :

Hi,

On Tue, Jan 11, 2022 at 11:05:26AM +0100, Ronan Dunklau wrote:

Done, and I added anoher commit per your suggestion to add this comment.

The cfbot reports that the patchset doesn't apply anymore:

http://cfbot.cputube.org/patch_36_3293.log
=== Applying patches on top of PostgreSQL commit ID
43c2175121c829c8591fc5117b725f1f22bfb670 === [...]
=== applying patch ./v4-0003-Output-error-tags-in-CSV-logs.patch
[...]
patching file src/backend/utils/error/elog.c
Hunk #2 FAILED at 3014.
1 out of 2 hunks FAILED -- saving rejects to file
src/backend/utils/error/elog.c.rej

Could you send a rebased version? In the meantime I will switch the cf
entry to Waiting on Author.

Thank you for this notification !

The csvlog has been refactored since I wrote the patch, and the new jsonlog
destination has been introduced. I rebased to fix the first patch, and added a
new patch to add support for tags in jsonlog output.

Best regards,

--
Ronan Dunklau

Attachments:

v5-0001-Add-ErrorTag-support.patchtext/x-patch; charset=UTF-8; name=v5-0001-Add-ErrorTag-support.patchDownload
From 8071760e2a826b4ec88d2580c7bfc76e9bd2ff6e 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 v5 1/5] 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 7402696986..4fb4c67c3f 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -460,6 +460,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
@@ -511,6 +512,7 @@ errfinish(const char *filename, int lineno, const char *funcname)
 	int			elevel;
 	MemoryContext oldcontext;
 	ErrorContextCallback *econtext;
+	ListCell   *lc;
 
 	recursion_depth++;
 	CHECK_STACK_DEPTH();
@@ -616,7 +618,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 */
@@ -1187,6 +1200,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 3eb8de3966..615fae47ef 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.34.1

v5-0002-Add-test-module-for-the-new-tag-functionality.patchtext/x-patch; charset=UTF-8; name=v5-0002-Add-test-module-for-the-new-tag-functionality.patchDownload
From ca893c36fa4572c91c366280aa4fd5f17ebfe332 Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Fri, 20 Aug 2021 10:46:20 +0200
Subject: [PATCH v5 2/5] Add test module for the new tag functionality.

This test module consists of an extension exposing a function which just
logs things, and a hook which adds the tags to the detail field in order
to be tested in "regular" output.
---
 src/test/modules/test_logging/Makefile        |  20 +++
 .../test_logging/expected/test_logging.out    |  18 +++
 .../modules/test_logging/sql/test_logging.sql |   5 +
 .../test_logging/test_logging--1.0.sql        |   4 +
 src/test/modules/test_logging/test_logging.c  | 120 ++++++++++++++++++
 .../modules/test_logging/test_logging.control |   5 +
 6 files changed, 172 insertions(+)
 create mode 100644 src/test/modules/test_logging/Makefile
 create mode 100644 src/test/modules/test_logging/expected/test_logging.out
 create mode 100644 src/test/modules/test_logging/sql/test_logging.sql
 create mode 100644 src/test/modules/test_logging/test_logging--1.0.sql
 create mode 100644 src/test/modules/test_logging/test_logging.c
 create mode 100644 src/test/modules/test_logging/test_logging.control

diff --git a/src/test/modules/test_logging/Makefile b/src/test/modules/test_logging/Makefile
new file mode 100644
index 0000000000..1191886e43
--- /dev/null
+++ b/src/test/modules/test_logging/Makefile
@@ -0,0 +1,20 @@
+# src/test/modules/test_logging/Makefile
+
+MODULES = test_logging
+
+EXTENSION = test_logging
+DATA = test_logging--1.0.sql
+PGFILEDESC = "test_logging - simple log hook test"
+
+REGRESS = test_logging
+
+ifdef USE_PGXS
+PG_CONFIG = pg_config
+PGXS := $(shell $(PG_CONFIG) --pgxs)
+include $(PGXS)
+else
+subdir = src/test/modules/test_logging
+top_builddir = ../../../..
+include $(top_builddir)/src/Makefile.global
+include $(top_srcdir)/contrib/contrib-global.mk
+endif
diff --git a/src/test/modules/test_logging/expected/test_logging.out b/src/test/modules/test_logging/expected/test_logging.out
new file mode 100644
index 0000000000..41423da535
--- /dev/null
+++ b/src/test/modules/test_logging/expected/test_logging.out
@@ -0,0 +1,18 @@
+CREATE EXTENSION test_logging;
+SET log_min_messages = NOTICE;
+SELECT test_logging(18, 'This is a test message', NULL);
+NOTICE:  This is a test message
+DETAIL:  NB TAGS: 0 TAGS: 
+ test_logging 
+--------------
+ 
+(1 row)
+
+SELECT test_logging(18, 'This is a test message', '{"tag1": "value1", "tag2": "value2"}');
+NOTICE:  This is a test message
+DETAIL:  NB TAGS: 2 TAGS: tag1: value1 tag2: value2 
+ test_logging 
+--------------
+ 
+(1 row)
+
diff --git a/src/test/modules/test_logging/sql/test_logging.sql b/src/test/modules/test_logging/sql/test_logging.sql
new file mode 100644
index 0000000000..bb964b4b63
--- /dev/null
+++ b/src/test/modules/test_logging/sql/test_logging.sql
@@ -0,0 +1,5 @@
+CREATE EXTENSION test_logging;
+SET log_min_messages = NOTICE;
+SELECT test_logging(18, 'This is a test message', NULL);
+SELECT test_logging(18, 'This is a test message', '{"tag1": "value1", "tag2": "value2"}');
+
diff --git a/src/test/modules/test_logging/test_logging--1.0.sql b/src/test/modules/test_logging/test_logging--1.0.sql
new file mode 100644
index 0000000000..663af2db8f
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging--1.0.sql
@@ -0,0 +1,4 @@
+CREATE FUNCTION test_logging(level int, message text, tags jsonb)
+RETURNS VOID
+AS 'MODULE_PATHNAME'
+LANGUAGE C;
diff --git a/src/test/modules/test_logging/test_logging.c b/src/test/modules/test_logging/test_logging.c
new file mode 100644
index 0000000000..18cd39b8e2
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging.c
@@ -0,0 +1,120 @@
+/*--------------------------------------------------------------------------
+ *
+ * test_logging.c
+ *		Test logging functions
+ *
+ * Copyright (c) 2021, PostgreSQL Global Development Group
+ *
+ * IDENTIFICATION
+ *		src/test/modules/test_logging/test_logging.c
+ *
+ * -------------------------------------------------------------------------
+ */
+
+#include <unistd.h>
+#include "postgres.h"
+
+#include "fmgr.h"
+#include "utils/builtins.h"
+#include "utils/elog.h"
+#include "utils/jsonb.h"
+
+PG_MODULE_MAGIC;
+
+static emit_log_hook_type prev_log_hook = NULL;
+
+void		_PG_init(void);
+void		_PG_fini(void);
+
+static void move_tags_to_detail(ErrorData *edata);
+
+static char *
+jsonb_value_to_tagvalue(JsonbValue *v)
+{
+	switch (v->type)
+	{
+		case jbvNull:
+			return "";
+		case jbvString:
+			return pnstrdup(v->val.string.val, v->val.string.len);
+		default:
+			elog(ERROR, "jsonb type not allowed here: %d", (int) v->type);
+	}
+}
+
+static void
+jsonb_tags_to_key_value_text_pairs(Jsonb *tags, List **keys, List **values)
+{
+	JsonbValue	v;
+	JsonbIterator *it;
+	JsonbIteratorToken r;
+	bool		skipNested = false;
+
+	it = JsonbIteratorInit(&tags->root);
+	*keys = *values = NIL;
+	while ((r = JsonbIteratorNext(&it, &v, skipNested)) != WJB_DONE)
+	{
+		skipNested = true;
+		if (r == WJB_KEY)
+		{
+			*keys = lappend(*keys, pnstrdup(v.val.string.val, v.val.string.len));
+			r = JsonbIteratorNext(&it, &v, skipNested);
+			Assert(r != WJB_DONE);
+			*values = lappend(*values, jsonb_value_to_tagvalue(&v));
+		}
+	}
+}
+
+PG_FUNCTION_INFO_V1(test_logging);
+Datum
+test_logging(PG_FUNCTION_ARGS)
+{
+	int			level = PG_GETARG_INT32(0);
+	char	   *message = "";
+	List	   *keys = NIL,
+			   *values = NIL;
+	ListCell   *lk,
+			   *lv;
+
+	if (!PG_ARGISNULL(1))
+	{
+		message = text_to_cstring(PG_GETARG_TEXT_PP(1));
+	}
+	if (!PG_ARGISNULL(2))
+	{
+		jsonb_tags_to_key_value_text_pairs(PG_GETARG_JSONB_P(2), &keys, &values);
+	}
+	errstart(level, TEXTDOMAIN);
+	errmsg("%s", message);
+	forboth(lk, keys, lv, values)
+	{
+		errtag(lfirst(lk), "%s", (char *) lfirst(lv));
+	}
+	errfinish(__FILE__, __LINE__, PG_FUNCNAME_MACRO);
+
+	PG_RETURN_VOID();
+}
+
+void
+move_tags_to_detail(ErrorData *edata)
+{
+	StringInfoData buf;
+	ListCell   *lc;
+
+	initStringInfo(&buf);
+	foreach(lc, edata->tags)
+	{
+		ErrorTag   *tag = (ErrorTag *) lfirst(lc);
+
+		appendStringInfo(&buf, "%s: %s ", tag->tagname, tag->tagvalue);
+	}
+	errdetail("NB TAGS: %d TAGS: %s", list_length(edata->tags), buf.data);
+	pfree(buf.data);
+}
+
+void
+_PG_init(void)
+{
+	prev_log_hook = emit_log_hook;
+	emit_log_hook = move_tags_to_detail;
+}
diff --git a/src/test/modules/test_logging/test_logging.control b/src/test/modules/test_logging/test_logging.control
new file mode 100644
index 0000000000..b1596b4b1d
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging.control
@@ -0,0 +1,5 @@
+# test_logging extension
+comment = 'test_logging - simple extension for emitting logs'
+default_version = '1.0'
+module_pathname = '$libdir/test_logging'
+relocatable = true
-- 
2.34.1

v5-0003-Output-error-tags-in-CSV-logs.patchtext/x-patch; charset=UTF-8; name=v5-0003-Output-error-tags-in-CSV-logs.patchDownload
From bb746e18cb9ddb7a7c0928e3c3830fc94015bdcb Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Mon, 17 Jan 2022 08:26:46 +0100
Subject: [PATCH v5 3/5] Output error tags in CSV logs

---
 src/backend/utils/error/csvlog.c | 25 +++++++++++++++++++++++++
 1 file changed, 25 insertions(+)

diff --git a/src/backend/utils/error/csvlog.c b/src/backend/utils/error/csvlog.c
index 89f78b447d..999839713c 100644
--- a/src/backend/utils/error/csvlog.c
+++ b/src/backend/utils/error/csvlog.c
@@ -252,6 +252,31 @@ write_csvlog(ErrorData *edata)
 	/* query id */
 	appendStringInfo(&buf, "%lld", (long long) pgstat_get_my_query_id());
 
+	/* tags */
+	if (edata->tags != NIL)
+	{
+		StringInfoData tagbuf;
+		ListCell   *lc;
+		bool            first = true;
+
+		initStringInfo(&tagbuf);
+		appendStringInfoChar(&tagbuf, '{');
+		foreach(lc, edata->tags)
+		{
+			ErrorTag   *etag = lfirst(lc);
+
+			if (!first)
+				appendStringInfoChar(&tagbuf, ',');
+			escape_json(&tagbuf, etag->tagname);
+			appendStringInfoChar(&tagbuf, ':');
+			escape_json(&tagbuf, etag->tagvalue);
+			first = false;
+		}
+		appendStringInfoChar(&tagbuf, '}');
+		appendCSVLiteral(&buf, tagbuf.data);
+		pfree(tagbuf.data);
+	}
+
 	appendStringInfoChar(&buf, '\n');
 
 	/* If in the syslogger process, try to write messages direct to file */
-- 
2.34.1

v5-0005-Add-error-tags-to-json-output.patchtext/x-patch; charset=UTF-8; name=v5-0005-Add-error-tags-to-json-output.patchDownload
From aca65ffb8d1b1642884adb582730b06cc6be93fe Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Mon, 17 Jan 2022 08:56:30 +0100
Subject: [PATCH v5 5/5] Add error tags to json output

---
 src/backend/utils/error/jsonlog.c | 26 ++++++++++++++++++++++++++
 1 file changed, 26 insertions(+)

diff --git a/src/backend/utils/error/jsonlog.c b/src/backend/utils/error/jsonlog.c
index 843641c865..70a62c1ec6 100644
--- a/src/backend/utils/error/jsonlog.c
+++ b/src/backend/utils/error/jsonlog.c
@@ -289,6 +289,32 @@ write_jsonlog(ErrorData *edata)
 	appendJSONKeyValueFmt(&buf, "query_id", false, "%lld",
 						  (long long) pgstat_get_my_query_id());
 
+	/* tags */
+	if (edata->tags != NIL)
+	{
+		StringInfoData tagbuf;
+		ListCell   *lc;
+		bool            first = true;
+
+
+		initStringInfo(&tagbuf);
+		appendStringInfoChar(&tagbuf, '{');
+		foreach(lc, edata->tags)
+		{
+			ErrorTag   *etag = lfirst(lc);
+			if (!first)
+				appendStringInfoChar(&tagbuf, ',');
+			escape_json(&tagbuf, etag->tagname);
+			appendStringInfoChar(&tagbuf, ':');
+			escape_json(&tagbuf, etag->tagvalue);
+			first = false;
+		}
+		appendStringInfoChar(&tagbuf, '}');
+		appendJSONKeyValue(&buf, "tags", tagbuf.data, false);
+		pfree(tagbuf.data);
+	}
+
+
 	/* Finish string */
 	appendStringInfoChar(&buf, '}');
 	appendStringInfoChar(&buf, '\n');
-- 
2.34.1

v5-0004-Add-comment-in-config.sgml-as-a-reminder-to-also-.patchtext/x-patch; charset=UTF-8; name=v5-0004-Add-comment-in-config.sgml-as-a-reminder-to-also-.patchDownload
From 1db1172eb698c08504729c1f3a2e9685dab6a374 Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Tue, 11 Jan 2022 10:16:53 +0100
Subject: [PATCH v5 4/5] Add comment in config.sgml as a reminder to also
 update file_fdw.sgml

---
 doc/src/sgml/config.sgml | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 4cd9818acf..0ff358233f 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7392,7 +7392,7 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
         application name, backend type, process ID of parallel group leader,
         and query id.
         Here is a sample table definition for storing CSV-format log output:
-
+<!-- Don't forget to also update file_fdw.sgml if you change this table definition -->
 <programlisting>
 CREATE TABLE postgres_log
 (
-- 
2.34.1

#22Ronan Dunklau
ronan.dunklau@aiven.io
In reply to: Ronan Dunklau (#21)
5 attachment(s)
Re: Proposal: More structured logging

Le lundi 17 janvier 2022, 09:18:04 CET Ronan Dunklau a écrit :

Le samedi 15 janvier 2022, 07:09:59 CET Julien Rouhaud a écrit :

Hi,

On Tue, Jan 11, 2022 at 11:05:26AM +0100, Ronan Dunklau wrote:

Done, and I added anoher commit per your suggestion to add this comment.

The cfbot reports that the patchset doesn't apply anymore:

http://cfbot.cputube.org/patch_36_3293.log
=== Applying patches on top of PostgreSQL commit ID
43c2175121c829c8591fc5117b725f1f22bfb670 === [...]
=== applying patch ./v4-0003-Output-error-tags-in-CSV-logs.patch
[...]
patching file src/backend/utils/error/elog.c
Hunk #2 FAILED at 3014.
1 out of 2 hunks FAILED -- saving rejects to file
src/backend/utils/error/elog.c.rej

Could you send a rebased version? In the meantime I will switch the cf
entry to Waiting on Author.

Thank you for this notification !

The csvlog has been refactored since I wrote the patch, and the new jsonlog
destination has been introduced. I rebased to fix the first patch, and added
a new patch to add support for tags in jsonlog output.

Best regards,

Hum, there was a missing import in csvlog.c from the fix above. Sorry about
that.

--
Ronan Dunklau

Attachments:

v6-0001-Add-ErrorTag-support.patchtext/x-patch; charset=UTF-8; name=v6-0001-Add-ErrorTag-support.patchDownload
From 8071760e2a826b4ec88d2580c7bfc76e9bd2ff6e 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 v6 1/5] 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 7402696986..4fb4c67c3f 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -460,6 +460,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
@@ -511,6 +512,7 @@ errfinish(const char *filename, int lineno, const char *funcname)
 	int			elevel;
 	MemoryContext oldcontext;
 	ErrorContextCallback *econtext;
+	ListCell   *lc;
 
 	recursion_depth++;
 	CHECK_STACK_DEPTH();
@@ -616,7 +618,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 */
@@ -1187,6 +1200,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 3eb8de3966..615fae47ef 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.34.1

v6-0002-Add-test-module-for-the-new-tag-functionality.patchtext/x-patch; charset=UTF-8; name=v6-0002-Add-test-module-for-the-new-tag-functionality.patchDownload
From ca893c36fa4572c91c366280aa4fd5f17ebfe332 Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Fri, 20 Aug 2021 10:46:20 +0200
Subject: [PATCH v6 2/5] Add test module for the new tag functionality.

This test module consists of an extension exposing a function which just
logs things, and a hook which adds the tags to the detail field in order
to be tested in "regular" output.
---
 src/test/modules/test_logging/Makefile        |  20 +++
 .../test_logging/expected/test_logging.out    |  18 +++
 .../modules/test_logging/sql/test_logging.sql |   5 +
 .../test_logging/test_logging--1.0.sql        |   4 +
 src/test/modules/test_logging/test_logging.c  | 120 ++++++++++++++++++
 .../modules/test_logging/test_logging.control |   5 +
 6 files changed, 172 insertions(+)
 create mode 100644 src/test/modules/test_logging/Makefile
 create mode 100644 src/test/modules/test_logging/expected/test_logging.out
 create mode 100644 src/test/modules/test_logging/sql/test_logging.sql
 create mode 100644 src/test/modules/test_logging/test_logging--1.0.sql
 create mode 100644 src/test/modules/test_logging/test_logging.c
 create mode 100644 src/test/modules/test_logging/test_logging.control

diff --git a/src/test/modules/test_logging/Makefile b/src/test/modules/test_logging/Makefile
new file mode 100644
index 0000000000..1191886e43
--- /dev/null
+++ b/src/test/modules/test_logging/Makefile
@@ -0,0 +1,20 @@
+# src/test/modules/test_logging/Makefile
+
+MODULES = test_logging
+
+EXTENSION = test_logging
+DATA = test_logging--1.0.sql
+PGFILEDESC = "test_logging - simple log hook test"
+
+REGRESS = test_logging
+
+ifdef USE_PGXS
+PG_CONFIG = pg_config
+PGXS := $(shell $(PG_CONFIG) --pgxs)
+include $(PGXS)
+else
+subdir = src/test/modules/test_logging
+top_builddir = ../../../..
+include $(top_builddir)/src/Makefile.global
+include $(top_srcdir)/contrib/contrib-global.mk
+endif
diff --git a/src/test/modules/test_logging/expected/test_logging.out b/src/test/modules/test_logging/expected/test_logging.out
new file mode 100644
index 0000000000..41423da535
--- /dev/null
+++ b/src/test/modules/test_logging/expected/test_logging.out
@@ -0,0 +1,18 @@
+CREATE EXTENSION test_logging;
+SET log_min_messages = NOTICE;
+SELECT test_logging(18, 'This is a test message', NULL);
+NOTICE:  This is a test message
+DETAIL:  NB TAGS: 0 TAGS: 
+ test_logging 
+--------------
+ 
+(1 row)
+
+SELECT test_logging(18, 'This is a test message', '{"tag1": "value1", "tag2": "value2"}');
+NOTICE:  This is a test message
+DETAIL:  NB TAGS: 2 TAGS: tag1: value1 tag2: value2 
+ test_logging 
+--------------
+ 
+(1 row)
+
diff --git a/src/test/modules/test_logging/sql/test_logging.sql b/src/test/modules/test_logging/sql/test_logging.sql
new file mode 100644
index 0000000000..bb964b4b63
--- /dev/null
+++ b/src/test/modules/test_logging/sql/test_logging.sql
@@ -0,0 +1,5 @@
+CREATE EXTENSION test_logging;
+SET log_min_messages = NOTICE;
+SELECT test_logging(18, 'This is a test message', NULL);
+SELECT test_logging(18, 'This is a test message', '{"tag1": "value1", "tag2": "value2"}');
+
diff --git a/src/test/modules/test_logging/test_logging--1.0.sql b/src/test/modules/test_logging/test_logging--1.0.sql
new file mode 100644
index 0000000000..663af2db8f
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging--1.0.sql
@@ -0,0 +1,4 @@
+CREATE FUNCTION test_logging(level int, message text, tags jsonb)
+RETURNS VOID
+AS 'MODULE_PATHNAME'
+LANGUAGE C;
diff --git a/src/test/modules/test_logging/test_logging.c b/src/test/modules/test_logging/test_logging.c
new file mode 100644
index 0000000000..18cd39b8e2
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging.c
@@ -0,0 +1,120 @@
+/*--------------------------------------------------------------------------
+ *
+ * test_logging.c
+ *		Test logging functions
+ *
+ * Copyright (c) 2021, PostgreSQL Global Development Group
+ *
+ * IDENTIFICATION
+ *		src/test/modules/test_logging/test_logging.c
+ *
+ * -------------------------------------------------------------------------
+ */
+
+#include <unistd.h>
+#include "postgres.h"
+
+#include "fmgr.h"
+#include "utils/builtins.h"
+#include "utils/elog.h"
+#include "utils/jsonb.h"
+
+PG_MODULE_MAGIC;
+
+static emit_log_hook_type prev_log_hook = NULL;
+
+void		_PG_init(void);
+void		_PG_fini(void);
+
+static void move_tags_to_detail(ErrorData *edata);
+
+static char *
+jsonb_value_to_tagvalue(JsonbValue *v)
+{
+	switch (v->type)
+	{
+		case jbvNull:
+			return "";
+		case jbvString:
+			return pnstrdup(v->val.string.val, v->val.string.len);
+		default:
+			elog(ERROR, "jsonb type not allowed here: %d", (int) v->type);
+	}
+}
+
+static void
+jsonb_tags_to_key_value_text_pairs(Jsonb *tags, List **keys, List **values)
+{
+	JsonbValue	v;
+	JsonbIterator *it;
+	JsonbIteratorToken r;
+	bool		skipNested = false;
+
+	it = JsonbIteratorInit(&tags->root);
+	*keys = *values = NIL;
+	while ((r = JsonbIteratorNext(&it, &v, skipNested)) != WJB_DONE)
+	{
+		skipNested = true;
+		if (r == WJB_KEY)
+		{
+			*keys = lappend(*keys, pnstrdup(v.val.string.val, v.val.string.len));
+			r = JsonbIteratorNext(&it, &v, skipNested);
+			Assert(r != WJB_DONE);
+			*values = lappend(*values, jsonb_value_to_tagvalue(&v));
+		}
+	}
+}
+
+PG_FUNCTION_INFO_V1(test_logging);
+Datum
+test_logging(PG_FUNCTION_ARGS)
+{
+	int			level = PG_GETARG_INT32(0);
+	char	   *message = "";
+	List	   *keys = NIL,
+			   *values = NIL;
+	ListCell   *lk,
+			   *lv;
+
+	if (!PG_ARGISNULL(1))
+	{
+		message = text_to_cstring(PG_GETARG_TEXT_PP(1));
+	}
+	if (!PG_ARGISNULL(2))
+	{
+		jsonb_tags_to_key_value_text_pairs(PG_GETARG_JSONB_P(2), &keys, &values);
+	}
+	errstart(level, TEXTDOMAIN);
+	errmsg("%s", message);
+	forboth(lk, keys, lv, values)
+	{
+		errtag(lfirst(lk), "%s", (char *) lfirst(lv));
+	}
+	errfinish(__FILE__, __LINE__, PG_FUNCNAME_MACRO);
+
+	PG_RETURN_VOID();
+}
+
+void
+move_tags_to_detail(ErrorData *edata)
+{
+	StringInfoData buf;
+	ListCell   *lc;
+
+	initStringInfo(&buf);
+	foreach(lc, edata->tags)
+	{
+		ErrorTag   *tag = (ErrorTag *) lfirst(lc);
+
+		appendStringInfo(&buf, "%s: %s ", tag->tagname, tag->tagvalue);
+	}
+	errdetail("NB TAGS: %d TAGS: %s", list_length(edata->tags), buf.data);
+	pfree(buf.data);
+}
+
+void
+_PG_init(void)
+{
+	prev_log_hook = emit_log_hook;
+	emit_log_hook = move_tags_to_detail;
+}
diff --git a/src/test/modules/test_logging/test_logging.control b/src/test/modules/test_logging/test_logging.control
new file mode 100644
index 0000000000..b1596b4b1d
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging.control
@@ -0,0 +1,5 @@
+# test_logging extension
+comment = 'test_logging - simple extension for emitting logs'
+default_version = '1.0'
+module_pathname = '$libdir/test_logging'
+relocatable = true
-- 
2.34.1

v6-0003-Output-error-tags-in-CSV-logs.patchtext/x-patch; charset=UTF-8; name=v6-0003-Output-error-tags-in-CSV-logs.patchDownload
From 8d2d03f5f8efb7aa8bfa17e6205010b3d26e5cda Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Mon, 17 Jan 2022 08:26:46 +0100
Subject: [PATCH v6 3/5] Output error tags in CSV logs

---
 src/backend/utils/error/csvlog.c | 26 ++++++++++++++++++++++++++
 1 file changed, 26 insertions(+)

diff --git a/src/backend/utils/error/csvlog.c b/src/backend/utils/error/csvlog.c
index 89f78b447d..e84cd9c202 100644
--- a/src/backend/utils/error/csvlog.c
+++ b/src/backend/utils/error/csvlog.c
@@ -27,6 +27,7 @@
 #include "utils/backend_status.h"
 #include "utils/elog.h"
 #include "utils/guc.h"
+#include "utils/json.h"
 #include "utils/ps_status.h"
 
 
@@ -252,6 +253,31 @@ write_csvlog(ErrorData *edata)
 	/* query id */
 	appendStringInfo(&buf, "%lld", (long long) pgstat_get_my_query_id());
 
+	/* tags */
+	if (edata->tags != NIL)
+	{
+		StringInfoData tagbuf;
+		ListCell   *lc;
+		bool            first = true;
+
+		initStringInfo(&tagbuf);
+		appendStringInfoChar(&tagbuf, '{');
+		foreach(lc, edata->tags)
+		{
+			ErrorTag   *etag = lfirst(lc);
+
+			if (!first)
+				appendStringInfoChar(&tagbuf, ',');
+			escape_json(&tagbuf, etag->tagname);
+			appendStringInfoChar(&tagbuf, ':');
+			escape_json(&tagbuf, etag->tagvalue);
+			first = false;
+		}
+		appendStringInfoChar(&tagbuf, '}');
+		appendCSVLiteral(&buf, tagbuf.data);
+		pfree(tagbuf.data);
+	}
+
 	appendStringInfoChar(&buf, '\n');
 
 	/* If in the syslogger process, try to write messages direct to file */
-- 
2.34.1

v6-0004-Add-comment-in-config.sgml-as-a-reminder-to-also-.patchtext/x-patch; charset=UTF-8; name=v6-0004-Add-comment-in-config.sgml-as-a-reminder-to-also-.patchDownload
From 3606848935fb6d5f05e6c1e73a05a7de489c5ad8 Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Tue, 11 Jan 2022 10:16:53 +0100
Subject: [PATCH v6 4/5] Add comment in config.sgml as a reminder to also
 update file_fdw.sgml

---
 doc/src/sgml/config.sgml | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 4cd9818acf..0ff358233f 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7392,7 +7392,7 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
         application name, backend type, process ID of parallel group leader,
         and query id.
         Here is a sample table definition for storing CSV-format log output:
-
+<!-- Don't forget to also update file_fdw.sgml if you change this table definition -->
 <programlisting>
 CREATE TABLE postgres_log
 (
-- 
2.34.1

v6-0005-Add-error-tags-to-json-output.patchtext/x-patch; charset=UTF-8; name=v6-0005-Add-error-tags-to-json-output.patchDownload
From 9dad84190e1f7063e888e616143664e64403f476 Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Mon, 17 Jan 2022 08:56:30 +0100
Subject: [PATCH v6 5/5] Add error tags to json output

---
 src/backend/utils/error/jsonlog.c | 26 ++++++++++++++++++++++++++
 1 file changed, 26 insertions(+)

diff --git a/src/backend/utils/error/jsonlog.c b/src/backend/utils/error/jsonlog.c
index 843641c865..70a62c1ec6 100644
--- a/src/backend/utils/error/jsonlog.c
+++ b/src/backend/utils/error/jsonlog.c
@@ -289,6 +289,32 @@ write_jsonlog(ErrorData *edata)
 	appendJSONKeyValueFmt(&buf, "query_id", false, "%lld",
 						  (long long) pgstat_get_my_query_id());
 
+	/* tags */
+	if (edata->tags != NIL)
+	{
+		StringInfoData tagbuf;
+		ListCell   *lc;
+		bool            first = true;
+
+
+		initStringInfo(&tagbuf);
+		appendStringInfoChar(&tagbuf, '{');
+		foreach(lc, edata->tags)
+		{
+			ErrorTag   *etag = lfirst(lc);
+			if (!first)
+				appendStringInfoChar(&tagbuf, ',');
+			escape_json(&tagbuf, etag->tagname);
+			appendStringInfoChar(&tagbuf, ':');
+			escape_json(&tagbuf, etag->tagvalue);
+			first = false;
+		}
+		appendStringInfoChar(&tagbuf, '}');
+		appendJSONKeyValue(&buf, "tags", tagbuf.data, false);
+		pfree(tagbuf.data);
+	}
+
+
 	/* Finish string */
 	appendStringInfoChar(&buf, '}');
 	appendStringInfoChar(&buf, '\n');
-- 
2.34.1

#23Michael Paquier
michael@paquier.xyz
In reply to: Ronan Dunklau (#22)
Re: Proposal: More structured logging

On Tue, Jan 18, 2022 at 06:46:03AM +0100, Ronan Dunklau wrote:

Hum, there was a missing import in csvlog.c from the fix above. Sorry about
that.

+<!-- Don't forget to also update file_fdw.sgml if you change this
table definition -->
<programlisting>

You are also forgetting that the table listing all the jsonlog fields
needs a refresh with this new key called "tags", and that it has a
JSON object underneath.

If you want to test all the formats supported by logging_destination,
wouldn't this stuff be better if tested through TAP with
logging_destination set with csvlog, jsonlog and stderr? This is
lacking coverage for csvlog.c and jsonlog.c, paths touched by your
patch.
--
Michael

#24Ronan Dunklau
ronan.dunklau@aiven.io
In reply to: Michael Paquier (#23)
4 attachment(s)
Re: Proposal: More structured logging

Le jeudi 27 janvier 2022, 08:15:01 CET Michael Paquier a écrit :

On Tue, Jan 18, 2022 at 06:46:03AM +0100, Ronan Dunklau wrote:

Hum, there was a missing import in csvlog.c from the fix above. Sorry
about
that.

+<!-- Don't forget to also update file_fdw.sgml if you change this
table definition -->
<programlisting>

You are also forgetting that the table listing all the jsonlog fields
needs a refresh with this new key called "tags", and that it has a
JSON object underneath.

Done.

If you want to test all the formats supported by logging_destination,
wouldn't this stuff be better if tested through TAP with
logging_destination set with csvlog, jsonlog and stderr? This is
lacking coverage for csvlog.c and jsonlog.c, paths touched by your
patch.

Done, I also added coverage for log_verbosity = verbose while I was at it,
and fixed a bug I introduced in csvlog while rebasing...

--
Ronan Dunklau

Attachments:

v7-0001-Add-ErrorTag-support.patchtext/x-patch; charset=UTF-8; name=v7-0001-Add-ErrorTag-support.patchDownload
From 8071760e2a826b4ec88d2580c7bfc76e9bd2ff6e 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 v7 1/4] 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 7402696986..4fb4c67c3f 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -460,6 +460,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
@@ -511,6 +512,7 @@ errfinish(const char *filename, int lineno, const char *funcname)
 	int			elevel;
 	MemoryContext oldcontext;
 	ErrorContextCallback *econtext;
+	ListCell   *lc;
 
 	recursion_depth++;
 	CHECK_STACK_DEPTH();
@@ -616,7 +618,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 */
@@ -1187,6 +1200,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 3eb8de3966..615fae47ef 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.35.0

v7-0002-Output-error-tags-in-CSV-logs.patchtext/x-patch; charset=UTF-8; name=v7-0002-Output-error-tags-in-CSV-logs.patchDownload
From 872770026fd9037f87728865f4bab49e8b64fcf9 Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Mon, 17 Jan 2022 08:26:46 +0100
Subject: [PATCH v7 2/4] Output error tags in CSV logs

---
 doc/src/sgml/config.sgml         |  2 ++
 doc/src/sgml/file-fdw.sgml       |  3 ++-
 src/backend/utils/error/csvlog.c | 28 ++++++++++++++++++++++++++++
 3 files changed, 32 insertions(+), 1 deletion(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 4cd9818acf..d835d70660 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7393,6 +7393,7 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
         and query id.
         Here is a sample table definition for storing CSV-format log output:
 
+<!-- Don't forget to also update file_fdw.sgml if you change this table definition -->
 <programlisting>
 CREATE TABLE postgres_log
 (
@@ -7422,6 +7423,7 @@ CREATE TABLE postgres_log
   backend_type text,
   leader_pid integer,
   query_id bigint,
+  tags json,
   PRIMARY KEY (session_id, session_line_num)
 );
 </programlisting>
diff --git a/doc/src/sgml/file-fdw.sgml b/doc/src/sgml/file-fdw.sgml
index 5b98782064..1710189d31 100644
--- a/doc/src/sgml/file-fdw.sgml
+++ b/doc/src/sgml/file-fdw.sgml
@@ -267,7 +267,8 @@ CREATE FOREIGN TABLE pglog (
   application_name text,
   backend_type text,
   leader_pid integer,
-  query_id bigint
+  query_id bigint,
+  tags json
 ) SERVER pglog
 OPTIONS ( filename 'log/pglog.csv', format 'csv' );
 </programlisting>
diff --git a/src/backend/utils/error/csvlog.c b/src/backend/utils/error/csvlog.c
index 89f78b447d..c0e86955c3 100644
--- a/src/backend/utils/error/csvlog.c
+++ b/src/backend/utils/error/csvlog.c
@@ -27,6 +27,7 @@
 #include "utils/backend_status.h"
 #include "utils/elog.h"
 #include "utils/guc.h"
+#include "utils/json.h"
 #include "utils/ps_status.h"
 
 
@@ -252,6 +253,33 @@ write_csvlog(ErrorData *edata)
 	/* query id */
 	appendStringInfo(&buf, "%lld", (long long) pgstat_get_my_query_id());
 
+	appendStringInfoChar(&buf, ',');
+
+	/* tags */
+	if (edata->tags != NIL)
+	{
+		StringInfoData tagbuf;
+		ListCell   *lc;
+		bool            first = true;
+
+		initStringInfo(&tagbuf);
+		appendStringInfoChar(&tagbuf, '{');
+		foreach(lc, edata->tags)
+		{
+			ErrorTag   *etag = lfirst(lc);
+
+			if (!first)
+				appendStringInfoChar(&tagbuf, ',');
+			escape_json(&tagbuf, etag->tagname);
+			appendStringInfoChar(&tagbuf, ':');
+			escape_json(&tagbuf, etag->tagvalue);
+			first = false;
+		}
+		appendStringInfoChar(&tagbuf, '}');
+		appendCSVLiteral(&buf, tagbuf.data);
+		pfree(tagbuf.data);
+	}
+
 	appendStringInfoChar(&buf, '\n');
 
 	/* If in the syslogger process, try to write messages direct to file */
-- 
2.35.0

v7-0003-Add-error-tags-to-json-output.patchtext/x-patch; charset=UTF-8; name=v7-0003-Add-error-tags-to-json-output.patchDownload
From 3c5c23cb33ef0ca07ce61ddd4983acc08cc8e81d Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Mon, 17 Jan 2022 08:56:30 +0100
Subject: [PATCH v7 3/4] Add error tags to json output

---
 doc/src/sgml/config.sgml          |  5 +++++
 src/backend/utils/error/jsonlog.c | 26 ++++++++++++++++++++++++++
 2 files changed, 31 insertions(+)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index d835d70660..494eb67b89 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7664,6 +7664,11 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
          <entry>number</entry>
          <entry>Query ID</entry>
         </row>
+        <row>
+         <entry><literal>tags</literal></entry>
+         <entry>object</entry>
+         <entry>Additional error tags</entry>
+        </row>
        </tbody>
       </tgroup>
      </table>
diff --git a/src/backend/utils/error/jsonlog.c b/src/backend/utils/error/jsonlog.c
index 843641c865..70a62c1ec6 100644
--- a/src/backend/utils/error/jsonlog.c
+++ b/src/backend/utils/error/jsonlog.c
@@ -289,6 +289,32 @@ write_jsonlog(ErrorData *edata)
 	appendJSONKeyValueFmt(&buf, "query_id", false, "%lld",
 						  (long long) pgstat_get_my_query_id());
 
+	/* tags */
+	if (edata->tags != NIL)
+	{
+		StringInfoData tagbuf;
+		ListCell   *lc;
+		bool            first = true;
+
+
+		initStringInfo(&tagbuf);
+		appendStringInfoChar(&tagbuf, '{');
+		foreach(lc, edata->tags)
+		{
+			ErrorTag   *etag = lfirst(lc);
+			if (!first)
+				appendStringInfoChar(&tagbuf, ',');
+			escape_json(&tagbuf, etag->tagname);
+			appendStringInfoChar(&tagbuf, ':');
+			escape_json(&tagbuf, etag->tagvalue);
+			first = false;
+		}
+		appendStringInfoChar(&tagbuf, '}');
+		appendJSONKeyValue(&buf, "tags", tagbuf.data, false);
+		pfree(tagbuf.data);
+	}
+
+
 	/* Finish string */
 	appendStringInfoChar(&buf, '}');
 	appendStringInfoChar(&buf, '\n');
-- 
2.35.0

v7-0004-Add-test-module-for-the-new-tag-functionality.patchtext/x-patch; charset=UTF-8; name=v7-0004-Add-test-module-for-the-new-tag-functionality.patchDownload
From 560a02687ed354a17601125c3341147ee8ebcf42 Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunklau@aiven.io>
Date: Fri, 20 Aug 2021 10:46:20 +0200
Subject: [PATCH v7 4/4] Add test module for the new tag functionality.

This test module consists of an extension exposing a function which just
logs things, and a hook which adds the tags to the detail field in order
to be tested in "regular" output.
---
 src/test/modules/Makefile                     |   1 +
 src/test/modules/test_logging/Makefile        |  20 +++
 src/test/modules/test_logging/t/001_logger.pl |  59 +++++++++
 .../test_logging/test_logging--1.0.sql        |   4 +
 src/test/modules/test_logging/test_logging.c  | 120 ++++++++++++++++++
 .../modules/test_logging/test_logging.control |   5 +
 6 files changed, 209 insertions(+)
 create mode 100644 src/test/modules/test_logging/Makefile
 create mode 100644 src/test/modules/test_logging/t/001_logger.pl
 create mode 100644 src/test/modules/test_logging/test_logging--1.0.sql
 create mode 100644 src/test/modules/test_logging/test_logging.c
 create mode 100644 src/test/modules/test_logging/test_logging.control

diff --git a/src/test/modules/Makefile b/src/test/modules/Makefile
index dffc79b2d9..e933eb8ddb 100644
--- a/src/test/modules/Makefile
+++ b/src/test/modules/Makefile
@@ -19,6 +19,7 @@ SUBDIRS = \
 		  test_extensions \
 		  test_ginpostinglist \
 		  test_integerset \
+			test_logging \
 		  test_misc \
 		  test_parser \
 		  test_pg_dump \
diff --git a/src/test/modules/test_logging/Makefile b/src/test/modules/test_logging/Makefile
new file mode 100644
index 0000000000..af9177263b
--- /dev/null
+++ b/src/test/modules/test_logging/Makefile
@@ -0,0 +1,20 @@
+# src/test/modules/test_logging/Makefile
+
+MODULES = test_logging
+
+EXTENSION = test_logging
+DATA = test_logging--1.0.sql
+PGFILEDESC = "test_logging - simple log hook test"
+
+TAP_TESTS = 1
+
+ifdef USE_PGXS
+PG_CONFIG = pg_config
+PGXS := $(shell $(PG_CONFIG) --pgxs)
+include $(PGXS)
+else
+subdir = src/test/modules/test_logging
+top_builddir = ../../../..
+include $(top_builddir)/src/Makefile.global
+include $(top_srcdir)/contrib/contrib-global.mk
+endif
diff --git a/src/test/modules/test_logging/t/001_logger.pl b/src/test/modules/test_logging/t/001_logger.pl
new file mode 100644
index 0000000000..39277d6c14
--- /dev/null
+++ b/src/test/modules/test_logging/t/001_logger.pl
@@ -0,0 +1,59 @@
+
+# Copyright (c) 2021-2022, PostgreSQL Global Development Group
+
+use strict;
+use warnings;
+
+use Config;
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+use Test::More tests => 6;
+
+my $tempdir = PostgreSQL::Test::Utils::tempdir;
+
+my $node = PostgreSQL::Test::Cluster->new('testlogging');
+$node->init;
+$node->append_conf('postgresql.conf', qq{
+  log_destination = 'csvlog, jsonlog, stderr'
+  log_min_messages = NOTICE
+  log_directory = '$tempdir'
+  logging_collector = on
+  log_filename = 'postgresql.log'
+  log_error_verbosity = verbose
+});
+$node->start;
+
+$node->safe_psql('postgres',
+  'create extension test_logging;');
+$node->safe_psql('postgres',
+  "SELECT test_logging(18, 'This is a test message',
+  '{\"tag1\": \"value1\", \"tag2\": \"value2\"}');");
+
+my $logcontents;
+
+# Check the plaintext log file
+$logcontents = slurp_file($tempdir . '/' . 'postgresql.log');
+like($logcontents, qr/This is a test message/,
+  "Found expected message in log");
+like($logcontents, qr/DETAIL:  NB TAGS: 2 TAGS: tag1: value1 tag2: value2/,
+  "Found expected tags in log");
+
+# This is not optimal, but check the logs using regexpes to avoid
+# adding a dependency on Text::CSV and JSON::XS
+
+# Check the csv log file.
+$logcontents = slurp_file($tempdir . '/' . 'postgresql.csv');
+
+like($logcontents, qr/,"\{""tag1"":""value1"",""tag2"":""value2""}"/,
+  "CSV log contains tag");
+like($logcontents, qr/,,"test_logging, test_logging.c:\d+",/,
+  "CSV log contains filename and linenumber");
+
+# Check the json log file.
+$logcontents = slurp_file($tempdir . '/' . 'postgresql.json');
+like($logcontents, qr/,"tags":\{"tag1":"value1","tag2":"value2"}/,
+  "JSON log contains tags");
+like($logcontents, qr/,"file_name":"test_logging.c","file_line_num":\d+,/,
+  "JSON log contains filename and linenumber");
+
+$node->stop;
diff --git a/src/test/modules/test_logging/test_logging--1.0.sql b/src/test/modules/test_logging/test_logging--1.0.sql
new file mode 100644
index 0000000000..663af2db8f
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging--1.0.sql
@@ -0,0 +1,4 @@
+CREATE FUNCTION test_logging(level int, message text, tags jsonb)
+RETURNS VOID
+AS 'MODULE_PATHNAME'
+LANGUAGE C;
diff --git a/src/test/modules/test_logging/test_logging.c b/src/test/modules/test_logging/test_logging.c
new file mode 100644
index 0000000000..18cd39b8e2
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging.c
@@ -0,0 +1,120 @@
+/*--------------------------------------------------------------------------
+ *
+ * test_logging.c
+ *		Test logging functions
+ *
+ * Copyright (c) 2021, PostgreSQL Global Development Group
+ *
+ * IDENTIFICATION
+ *		src/test/modules/test_logging/test_logging.c
+ *
+ * -------------------------------------------------------------------------
+ */
+
+#include <unistd.h>
+#include "postgres.h"
+
+#include "fmgr.h"
+#include "utils/builtins.h"
+#include "utils/elog.h"
+#include "utils/jsonb.h"
+
+PG_MODULE_MAGIC;
+
+static emit_log_hook_type prev_log_hook = NULL;
+
+void		_PG_init(void);
+void		_PG_fini(void);
+
+static void move_tags_to_detail(ErrorData *edata);
+
+static char *
+jsonb_value_to_tagvalue(JsonbValue *v)
+{
+	switch (v->type)
+	{
+		case jbvNull:
+			return "";
+		case jbvString:
+			return pnstrdup(v->val.string.val, v->val.string.len);
+		default:
+			elog(ERROR, "jsonb type not allowed here: %d", (int) v->type);
+	}
+}
+
+static void
+jsonb_tags_to_key_value_text_pairs(Jsonb *tags, List **keys, List **values)
+{
+	JsonbValue	v;
+	JsonbIterator *it;
+	JsonbIteratorToken r;
+	bool		skipNested = false;
+
+	it = JsonbIteratorInit(&tags->root);
+	*keys = *values = NIL;
+	while ((r = JsonbIteratorNext(&it, &v, skipNested)) != WJB_DONE)
+	{
+		skipNested = true;
+		if (r == WJB_KEY)
+		{
+			*keys = lappend(*keys, pnstrdup(v.val.string.val, v.val.string.len));
+			r = JsonbIteratorNext(&it, &v, skipNested);
+			Assert(r != WJB_DONE);
+			*values = lappend(*values, jsonb_value_to_tagvalue(&v));
+		}
+	}
+}
+
+PG_FUNCTION_INFO_V1(test_logging);
+Datum
+test_logging(PG_FUNCTION_ARGS)
+{
+	int			level = PG_GETARG_INT32(0);
+	char	   *message = "";
+	List	   *keys = NIL,
+			   *values = NIL;
+	ListCell   *lk,
+			   *lv;
+
+	if (!PG_ARGISNULL(1))
+	{
+		message = text_to_cstring(PG_GETARG_TEXT_PP(1));
+	}
+	if (!PG_ARGISNULL(2))
+	{
+		jsonb_tags_to_key_value_text_pairs(PG_GETARG_JSONB_P(2), &keys, &values);
+	}
+	errstart(level, TEXTDOMAIN);
+	errmsg("%s", message);
+	forboth(lk, keys, lv, values)
+	{
+		errtag(lfirst(lk), "%s", (char *) lfirst(lv));
+	}
+	errfinish(__FILE__, __LINE__, PG_FUNCNAME_MACRO);
+
+	PG_RETURN_VOID();
+}
+
+void
+move_tags_to_detail(ErrorData *edata)
+{
+	StringInfoData buf;
+	ListCell   *lc;
+
+	initStringInfo(&buf);
+	foreach(lc, edata->tags)
+	{
+		ErrorTag   *tag = (ErrorTag *) lfirst(lc);
+
+		appendStringInfo(&buf, "%s: %s ", tag->tagname, tag->tagvalue);
+	}
+	errdetail("NB TAGS: %d TAGS: %s", list_length(edata->tags), buf.data);
+	pfree(buf.data);
+}
+
+void
+_PG_init(void)
+{
+	prev_log_hook = emit_log_hook;
+	emit_log_hook = move_tags_to_detail;
+}
diff --git a/src/test/modules/test_logging/test_logging.control b/src/test/modules/test_logging/test_logging.control
new file mode 100644
index 0000000000..b1596b4b1d
--- /dev/null
+++ b/src/test/modules/test_logging/test_logging.control
@@ -0,0 +1,5 @@
+# test_logging extension
+comment = 'test_logging - simple extension for emitting logs'
+default_version = '1.0'
+module_pathname = '$libdir/test_logging'
+relocatable = true
-- 
2.35.0

#25Greg Stark
stark@mit.edu
In reply to: Ronan Dunklau (#1)
Re: Proposal: More structured logging

1) I would like an interface which more or less guarantees that
*every* parameter of the log message is included in the structured
data. Ideally there should be no actual need to generate the formatted
messages for destinations like elastic search, just record the message
id and the parameters.

To that end I would thing something like:

ereport(DEBUG2,
(errmsg("table \"%s\": removed %lld dead item identifiers in %u pages",
vacrel->relname, (long long) index, vacuumed_pages)));

Would end up like:

ereport(DEBUG2,
(errmsg("table \"%s\": removed %lld dead item identifiers in %u pages",
errtag("relname", vacrel->relname),
errtag("dead_item_pointers", (long long) index),
errtag("vacuumed_pages", vacuumed_pages))));

And any untagged parameters could be included in the structured data
with unknown tag names. (Or perhaps some macro magic involving # but
I'm not sure that would be possible with va_args.)

2) I was kind of hoping we could have some sort of list of known tag
labels that could be used. So instead of an arbitrary string for the
label name you just referenced the known labels. Then we could
document that whenever "relid" appears as a tag id it's the oid of a
relation, for example.

This would help with things like "search elastic search for all log
entries for relid x, block p". Which wouldn't work if block is
sometimes "page" and sometimes "blocknum" and sometimes "block"....

So I was imagining something like

errtag(TAG_RELID, relid)

3) When it comes to things like queryid it would be helpful to be able
to inject tags from higher in the call stack so that invididual
ereport sites don't need to include it and we can decide to add new
things like it in the future. This will be useful for things like
distributed tracing tools who need to inject a span id into the every
log message.

I imagine it could also be useful more generally. Application
developers might want to inject things like a pipeline identifier from
their CI tools and then pull any logs with that identifier into their
CI reports.

Yes, they could be added as new columns in CSV and top level json
attributes but we may well have new tags that are not always there or
are even created on user request. Or we may have cases where there can
be more than one active at a time.

4) As far as code ... this is probably premature microoptimization but
I do find the tags all being individually palloced and all going
through string formatting seems like a lot of overhead. Like the
actual number of errtag() calls in the ereport is always going to be
the same and the values are probably always going to be a single
parameter, not really using the formatting functionality.

I don't necessarily have a better alternative though. The only thing I
can think of isn't really any better:

errtag_str(RELNAME, relname)
errtag_int(RELID, relid)

(possibly with some magic where there's an errtag() function that
looks up which data type to expect for a given tag id).

It looks strange to me that the errorTag struct has a "const char
*tagname" but a "char *tagvalue". I think this is a side effect of the
code and not actually a sensible way to define the struct. Surely they
should both be const?

#26Michael Paquier
michael@paquier.xyz
In reply to: Greg Stark (#25)
Re: Proposal: More structured logging

On Mon, Jan 31, 2022 at 05:46:29PM -0500, Greg Stark wrote:

It looks strange to me that the errorTag struct has a "const char
*tagname" but a "char *tagvalue". I think this is a side effect of the
code and not actually a sensible way to define the struct. Surely they
should both be const?

This review has not been answered, and it was around for two months
now. I am marking this patch as returned with feedback.
--
Michael