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
>From 8071760e2a826b4ec88d2580c7bfc76e9bd2ff6e Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunk...@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
>From 872770026fd9037f87728865f4bab49e8b64fcf9 Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunk...@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
>From 3c5c23cb33ef0ca07ce61ddd4983acc08cc8e81d Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunk...@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
>From 560a02687ed354a17601125c3341147ee8ebcf42 Mon Sep 17 00:00:00 2001
From: Ronan Dunklau <ronan.dunk...@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
