Subject: Re: backtrace_on_internal_error

From: Peter Eisentraut <[email-masked]>
Date: Thu, 7 Dec 2023 11:00:11 +0100

On 05.12.23 11:55, Peter Eisentraut wrote:
> I think the implementation would be very simple, something like
> 
> diff --git a/src/backend/utils/error/elog.c 
> b/src/backend/utils/error/elog.c
> index 6aeb855e49..45d40abe92 100644
> --- a/src/backend/utils/error/elog.c
> +++ b/src/backend/utils/error/elog.c
> @@ -498,9 +498,11 @@ errfinish(const char *filename, int lineno, const 
> char *funcname)
> 
>      /* Collect backtrace, if enabled and we didn't already */
>      if (!edata->backtrace &&
> -       edata->funcname &&
> -       backtrace_functions &&
> -       matches_backtrace_functions(edata->funcname))
> +       ((edata->funcname &&
> +         backtrace_functions &&
> +         matches_backtrace_functions(edata->funcname)) ||
> +        (edata->sqlerrcode == ERRCODE_INTERNAL_ERROR &&
> +         backtrace_on_internal_error)))
>          set_backtrace(edata, 2);
> 
>      /*
> 
> where backtrace_on_internal_error would be a GUC variable.

It looks like many people found this idea worthwhile.

Several people asked for a way to set the minimum log level for this 
treatment.

Something else to note:  I wrote the above code to check the error code; 
it doesn't check whether the original code write elog() or ereport(). 
There are some internal errors that are written as ereport() now. 
Others might be changed from time to time; until now there would have 
been no external effect from this.  I think it would be weird to 
introduce a difference between these forms now.

But then, elog() only uses the error code ERRCODE_INTERNAL_ERROR if the 
error level is >=ERROR.  So this already excludes everything below.

Do people want a way to distinguish ERROR/FATAL/PANIC?

Or do people want a way to enable backtraces for elog(LOG)?  This didn't 
look too interesting to me.  (Many current elog(LOG) calls are behind 
additional guards like TRACE_SORT or LOCK_DEBUG.)

If neither of these two are very interesting, then the above code would 
already appear to do what was asked.

---

From: Tom Lane <[email-masked]>
Date: Thu, 07 Dec 2023 09:22:10 -0500

> introduce a difference between these forms now.

Yeah, that was bothering me too.  IIRC, elog is already documented
as being *exactly equivalent* to ereport with a minimal set of
options.  I don't think we should break that equivalence.  So I
agree with driving this off the stated-or-imputed errcode rather
than which function is called.

> Or do people want a way to enable backtraces for elog(LOG)?

Personally I don't see a need for either.

			regards, tom lane

---

From: Peter Eisentraut <[email-masked]>
Date: Fri, 8 Dec 2023 14:21:32 +0100

Here is a patch to play with.

I also found a related typo.

One possible question for discussion is whether the default for this 
should be off, on, or possibly something like on-in-assert-builds. 
(Personally, I'm happy to turn it on myself at run time, but everyone 
has different workflows.)

From 2e01ee20358df323170fbfef6dc01f684371d873 Mon Sep 17 00:00:00 2001
From: Peter Eisentraut <[email-masked]>
Date: Fri, 8 Dec 2023 13:30:55 +0100
Subject: [PATCH v1 1/2] Fix variable name and comment

---
 src/backend/utils/error/elog.c | 12 ++++++------
 1 file changed, 6 insertions(+), 6 deletions(-)

diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 6aeb855e49..ecacba4ee1 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -115,8 +115,8 @@ char	   *Log_destination_string = NULL;
 bool		syslog_sequence_numbers = true;
 bool		syslog_split_messages = true;
 
-/* Processed form of backtrace_symbols GUC */
-static char *backtrace_symbol_list;
+/* Processed form of backtrace_functions GUC */
+static char *backtrace_function_list;
 
 #ifdef HAVE_SYSLOG
 
@@ -831,13 +831,13 @@ matches_backtrace_functions(const char *funcname)
 {
 	const char *p;
 
-	if (!backtrace_symbol_list || funcname == NULL || funcname[0] == '\0')
+	if (!backtrace_function_list || funcname == NULL || funcname[0] == '\0')
 		return false;
 
-	p = backtrace_symbol_list;
+	p = backtrace_function_list;
 	for (;;)
 	{
-		if (*p == '\0')			/* end of backtrace_symbol_list */
+		if (*p == '\0')			/* end of backtrace_function_list */
 			break;
 
 		if (strcmp(funcname, p) == 0)
@@ -2180,7 +2180,7 @@ check_backtrace_functions(char **newval, void **extra, GucSource source)
 void
 assign_backtrace_functions(const char *newval, void *extra)
 {
-	backtrace_symbol_list = (char *) extra;
+	backtrace_function_list = (char *) extra;
 }
 
 /*

base-commit: 7db01fbcefbd95a7c97afa128fab59f4a09b3ff1
-- 
2.43.0

From 06beed94067efaf5b93da5041048347fa22a4290 Mon Sep 17 00:00:00 2001
From: Peter Eisentraut <[email-masked]>
Date: Fri, 8 Dec 2023 14:04:53 +0100
Subject: [PATCH v1 2/2] Add GUC backtrace_on_internal_error

---
 doc/src/sgml/config.sgml            | 27 +++++++++++++++++++++++++++
 src/backend/utils/error/elog.c      |  8 +++++---
 src/backend/utils/misc/guc_tables.c | 16 ++++++++++++++++
 src/include/utils/guc.h             |  1 +
 4 files changed, 49 insertions(+), 3 deletions(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 94d1eb2b81..b830539b9a 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -11027,6 +11027,33 @@ <title>Developer Options</title>
       </listitem>
      </varlistentry>
 
+     <varlistentry id="guc-backtrace-on-internal-error" xreflabel="backtrace_on_internal_error">
+      <term><varname>backtrace_on_internal_error</varname> (<type>boolean</type>)
+      <indexterm>
+        <primary><varname>backtrace_on_internal_error</varname> configuration parameter</primary>
+      </indexterm>
+      </term>
+      <listitem>
+       <para>
+        If this parameter is on and an error with error code XX000 (internal
+        error; see also <xref linkend="errcodes-appendix"/>) is raised, then a
+        backtrace is written to the server log together with the error
+        message.  This can be used to debug such internal errors (which should
+        normally not happen in production).  The default is off.
+       </para>
+
+       <para>
+        Backtrace support is not available on all platforms, and the quality
+        of the backtraces depends on compilation options.
+       </para>
+
+       <para>
+        Only superusers and users with the appropriate <literal>SET</literal>
+        privilege can change this setting.
+       </para>
+      </listitem>
+     </varlistentry>
+
      <varlistentry id="guc-debug-discard-caches" xreflabel="debug_discard_caches">
       <term><varname>debug_discard_caches</varname> (<type>integer</type>)
       <indexterm>
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index ecacba4ee1..6a7a487323 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -498,9 +498,11 @@ errfinish(const char *filename, int lineno, const char *funcname)

 	/*
diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c
index 6474e35ec0..73252d4864 100644
--- a/src/backend/utils/misc/guc_tables.c
+++ b/src/backend/utils/misc/guc_tables.c
@@ -527,6 +527,7 @@ double		log_statement_sample_rate = 1.0;
 double		log_xact_sample_rate = 0;
 int			trace_recovery_messages = LOG;
 char	   *backtrace_functions;
+bool		backtrace_on_internal_error = false;
 
 int			temp_file_limit = -1;
 
@@ -810,6 +811,21 @@ StaticAssertDecl(lengthof(config_type_names) == (PGC_ENUM + 1),
 
 struct config_bool ConfigureNamesBool[] =
 {
+	{
+		{"backtrace_on_internal_error", PGC_SUSET, DEVELOPER_OPTIONS,
+			gettext_noop("Log backtrace for any error with error code XX000 (internal error)."),
+			NULL,
+			GUC_NOT_IN_SAMPLE
+		},
+		&backtrace_on_internal_error,
+
+		/*
+		 * TODO: Discussion: Could default to true unconditionally or in
+		 * assert builds?
+		 */
+		false,
+		NULL, NULL, NULL
+	},
 	{
 		{"enable_seqscan", PGC_USERSET, QUERY_TUNING_METHOD,
 			gettext_noop("Enables the planner's use of sequential-scan plans."),
diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h
index 20fe13702b..b4df0b6678 100644
--- a/src/include/utils/guc.h
+++ b/src/include/utils/guc.h
@@ -264,6 +264,7 @@ extern PGDLLIMPORT int log_temp_files;
 extern PGDLLIMPORT double log_statement_sample_rate;
 extern PGDLLIMPORT double log_xact_sample_rate;
 extern PGDLLIMPORT char *backtrace_functions;
+extern PGDLLIMPORT bool backtrace_on_internal_error;
 
 extern PGDLLIMPORT int temp_file_limit;
 
-- 
2.43.0

---

From: Tom Lane <[email-masked]>
Date: Fri, 08 Dec 2023 10:05:09 -0500

> Here is a patch to play with.

Didn't read the patch yet, but ...

> has different workflows.)

... there was already opinion upthread that this should be on by
default, which I agree with.  You shouldn't be hitting cases like
this commonly (if so, they're bugs to fix or the errcode should be
rethought), and the failure might be pretty hard to reproduce.

I'm not really sold that we even need YA GUC, for that matter.
How about committing the behavior without a GUC, and then
back-filling one if we get pushback?

			regards, tom lane

---

From: Andres Freund <[email-masked]>
Date: Fri, 8 Dec 2023 10:14:51 -0800

Hi,

> rethought), and the failure might be pretty hard to reproduce.

FWIW, I did some analysis on aggregated logs on a larger number of machines,
and it does look like that'd be a measurable increase in log volume. There are
a few voluminous internal errors in core, but the bigger issue is
extensions. They are typically much less disciplined about assigning error
codes than core PG is.

I've been wondering about doing some macro hackery to inform elog.c about
whether a log message is from core or an extension. It might even be possible
to identify the concrete extension, e.g. by updating the contents of
PG_MODULE_MAGIC during module loading, and referencing that.

Based on the aforementioned data, the most common, in-core, log messages
without assigned error codes are:

could not accept SSL connection: %m - with zero errno
archive command was terminated by signal %d: %s
could not send data to client: %m - with zero errno
cache lookup failed for type %u
archive command failed with exit code %d
tuple concurrently updated
could not restore file "%s" from archive: %s
archive command was terminated by signal %d: %s
%s at file "%s" line %u
invalid memory alloc request size %zu
could not send data to client: %m
could not open directory "%s": %m - errno indicating ENOMEM
could not write init file
out of relcache_callback_list slots
online backup was canceled, recovery cannot continue
requested timeline %u does not contain minimum recovery point %X/%X on timeline %u

There were a lot more in older PG versions, I tried to filter those out.

I'm a bit confused about the huge number of "could not accept SSL connection:
%m" with a zero errno. I guess we must be clearing errno somehow, but I don't
immediately see where. Or perhaps we need to actually look at what
SSL_get_error() returns?

Greetings,

Andres Freund

---

From: Peter Eisentraut <[email-masked]>
Date: Mon, 11 Dec 2023 10:29:26 +0100

> extensions. They are typically much less disciplined about assigning error

Good point.  Also, during development, I often just put elog(ERROR, 
"real error later").