From: Ronan Dunklau <ronan.dunklau@aiven.io>
To: Justin Pryzby <pryzby@telsasoft.com>
Cc: Alvaro Herrera <alvherre@alvh.no-ip.org>, pgsql-hackers@lists.postgresql.org
Subject: Re: Proposal: More structured logging
Date: Tue, 11 Jan 2022 11:05:26 +0100
Message-ID: <10995044.nUPlyArG6x@aivenronan>
Organization: aiven
In-Reply-To: <20211229135916.GN24477@telsasoft.com>
References: <202108191304.u7g5wwuepwpe@alvherre.pgsql> <3358218.yRJqF8fxcQ@aivenronan> <20211229135916.GN24477@telsasoft.com>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="nextPart3149575.iZASKD2KPV"
Content-Transfer-Encoding: 7Bit
Archived-At: <https://www.postgresql.org/message-id/10995044.nUPlyArG6x%40aivenronan>
Precedence: bulk

This is a multi-part message in MIME format.

--nextPart3149575.iZASKD2KPV
Content-Transfer-Encoding: quoted-printable
Content-Type: text/plain; charset="iso-8859-1"

Le mercredi 29 d=E9cembre 2021, 14:59:16 CET Justin Pryzby a =E9crit :
> > Subject: [PATCH v3 2/3] Add test module for the new tag functionality.
>=20
> ...
>=20
> > +test_logging(PG_FUNCTION_ARGS)
> > +{
>=20
> ...
>=20
> > +	 (errmsg("%s", message),
> > +	  ({
> > +		forboth(lk, keys, lv, values)
> > +		{
> > +			(errtag(lfirst(lk), "%s", (char *)=20
lfirst(lv)));
> > +		}})
> > +	));
>=20
> 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.157=
923

Thank you. I switched to an explicit sequence of errstart / errfinish to av=
oid =20
putting too much things in nested macro calls. As I don't have any Windows=
=20
knowledge, I am very grateful for the new cirrus-ci integration which allow=
ed=20
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
> >=20
> >    backend_type text,
> >    leader_pid integer,
> >    query_id bigint,
> >=20
> > +  tags jsonb
> >=20
> >    PRIMARY KEY (session_id, session_line_num)
> > =20
> >  );
> >  </programlisting>
>=20
> That's invalid sql due to missing a trailing ",".

Thanks, fixed.

>=20
> You should also update file-fdw.sgml - which I only think of since we for=
got
> 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,

=2D-=20
Ronan Dunklau
--nextPart3149575.iZASKD2KPV
Content-Disposition: attachment; filename="v4-0004-Add-comment-in-config.sgml-as-a-reminder-to-also-.patch"
Content-Transfer-Encoding: 7Bit
Content-Type: text/x-patch; charset="UTF-8"; name="v4-0004-Add-comment-in-config.sgml-as-a-reminder-to-also-.patch"

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


--nextPart3149575.iZASKD2KPV
Content-Disposition: attachment; filename="v4-0003-Output-error-tags-in-CSV-logs.patch"
Content-Transfer-Encoding: 7Bit
Content-Type: text/x-patch; charset="UTF-8"; name="v4-0003-Output-error-tags-in-CSV-logs.patch"

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


--nextPart3149575.iZASKD2KPV
Content-Disposition: attachment; filename="v4-0002-Add-test-module-for-the-new-tag-functionality.patch"
Content-Transfer-Encoding: 7Bit
Content-Type: text/x-patch; charset="UTF-8"; name="v4-0002-Add-test-module-for-the-new-tag-functionality.patch"

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


--nextPart3149575.iZASKD2KPV
Content-Disposition: attachment; filename="v4-0001-Add-ErrorTag-support.patch"
Content-Transfer-Encoding: 7Bit
Content-Type: text/x-patch; charset="UTF-8"; name="v4-0001-Add-ErrorTag-support.patch"

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


--nextPart3149575.iZASKD2KPV--