Support a wildcard in backtrace_functions

On 20 Dec 2023, at 12:23, Jelte Fennema-Nio <me@jeltef.nl> wrote:

Attached is a trivial patch that starts supporting
backtrace_functions='*'. By setting that in postgresql.conf for my dev
environment it starts logging backtraces always.

I happened to implement pretty much the same diff today during a debugging
session, and then stumbled across this when searching the archives, so count me
in for +1 on the concept.

The main problem it currently has is that it adds backtraces to all
LOG level logs too. So probably we want to make backtrace_functions
only log backtraces for ERROR and up (or maybe WARNING/NOTICE and up),
or add a backtrace_functions_level GUC too control this behaviour.

A wildcard should IMO only apply for ERROR (and higher) so I've hacked that up
in the attached v2. I was thinking about WARNING as well but opted against it.

The docs of backtrace_functions currently heavily suggest that it should
only be logging backtraces for errors, so either we actually start
doing that or we should clarify the docs

I think we should keep the current functionality and instead adjust the docs.
This has already been shipped like this, and restricting it now without a clear
usecase for doing so seems invasive (and someone might very well be using
this). 0001 in the attached adjusts this.

--
Daniel Gustafsson

On Mon, 12 Feb 2024 at 14:14, Daniel Gustafsson <daniel@yesql.se> wrote:

The main problem it currently has is that it adds backtraces to all
LOG level logs too. So probably we want to make backtrace_functions
only log backtraces for ERROR and up (or maybe WARNING/NOTICE and up),
or add a backtrace_functions_level GUC too control this behaviour.

A wildcard should IMO only apply for ERROR (and higher) so I've hacked that up
in the attached v2. I was thinking about WARNING as well but opted against it.

Fine by me patch looks good. Although I think I'd slightly prefer
having a backtrace_functions_level GUC, so that we can get this same
benefit for non wildcard backtrace_functions and so we keep the
behaviour between the two consistent.

I think we should keep the current functionality and instead adjust the docs.
This has already been shipped like this, and restricting it now without a clear
usecase for doing so seems invasive (and someone might very well be using
this). 0001 in the attached adjusts this.

Would a backtrace_functions_level GUC that would default to ERROR be
acceptable in this case? It's slight behaviour break, but you would be
able to get the previous behaviour very easily. And honestly wanting
to get backtraces for non-ERROR log entries seems quite niche to me,
which to me makes it a weird default.

+ If an log entry is raised and the name of the internal C function where

s/an log entry/a log entry

On 12.02.24 14:27, Jelte Fennema-Nio wrote:

And honestly wanting
to get backtraces for non-ERROR log entries seems quite niche to me,
which to me makes it a weird default.

I think one reason for this is that non-ERRORs are fairly unique in
their wording, so you don't have to isolate them by function name.

On Mon, 12 Feb 2024 at 14:27, Jelte Fennema-Nio <me@jeltef.nl> wrote:

Would a backtrace_functions_level GUC that would default to ERROR be
acceptable in this case?

I implemented it this way in the attached patchset.

On 27 Feb 2024, at 18:03, Jelte Fennema-Nio <me@jeltef.nl> wrote:

On Mon, 12 Feb 2024 at 14:27, Jelte Fennema-Nio <me@jeltef.nl> wrote:

Would a backtrace_functions_level GUC that would default to ERROR be
acceptable in this case?

I implemented it this way in the attached patchset.

I'm not excited about adding even more GUCs but maybe it's the least bad option
here.

+        If a log entry is raised with a level higher than
+        <xref linkend="guc-backtrace-functions-min-level"/> and the name of the
This should be "equal to or higher" right?

--
Daniel Gustafsson

On Wed, 28 Feb 2024 at 19:04, Daniel Gustafsson <daniel@yesql.se> wrote:

This should be "equal to or higher" right?

Correct, nicely spotted. Fixed that. I also updated the docs for the
new backtrace_functions_min_level GUC itself too, as well as creating
a dedicated options array for the GUC. Because when updating its docs
I realized that none of the existing level arrays matched what we
wanted.

On 28 Feb 2024, at 19:50, Jelte Fennema-Nio <me@jeltef.nl> wrote:

On Wed, 28 Feb 2024 at 19:04, Daniel Gustafsson <daniel@yesql.se> wrote:

This should be "equal to or higher" right?

Correct, nicely spotted. Fixed that. I also updated the docs for the
new backtrace_functions_min_level GUC itself too, as well as creating
a dedicated options array for the GUC. Because when updating its docs
I realized that none of the existing level arrays matched what we
wanted.

Looks good, I'm marking this ready for committer for now. I just have a few
small comments:

+        A single <literal>*</literal> character is interpreted as a wildcard and
+        will cause all errors in the log to contain backtraces.
This should mention that it's all error matching the level (or higher) of the
newly introduced GUC.

+ gettext_noop("Sets the message levels that create backtraces when backtrace_functions is configured"),
I think we should add the same "Each level includes.." long_desc, and the
short_desc should end with period.

+       <para>
+        Backtrace support is not available on all platforms, and the quality
+        of the backtraces depends on compilation options.
+       </para>
I don't think we need to duplicate this para here, having it on
backtrace_functions suffice.

--
Daniel Gustafsson

On 2024-Feb-28, Jelte Fennema-Nio wrote:

diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 699d9d0a241..553e4785520 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -843,6 +843,8 @@ matches_backtrace_functions(const char *funcname)
if (*p == '\0')			/* end of backtrace_function_list */
break;

+ if (strcmp("*", p) == 0)
+ return true;
if (strcmp(funcname, p) == 0)
return true;
p += strlen(p) + 1;

Hmm, so if I write "foo,*" this will work but check all function names
first and on the second entry. But if I write "foo*" the GUC value will
be accepted but match nothing (as will "*foo" or "foo*bar"). I don't
like either of these behaviors. I think we should tighten this up: an
asterisk should be allowed only if it appears alone in the string
(short-circuiting check_backtrace_functions before strspn); and let's
leave the strspn() call alone.

--
Álvaro Herrera 48°01'N 7°57'E — https://www.EnterpriseDB.com/
Bob [Floyd] used to say that he was planning to get a Ph.D. by the "green
stamp method," namely by saving envelopes addressed to him as 'Dr. Floyd'.
After collecting 500 such letters, he mused, a university somewhere in
Arizona would probably grant him a degree. (Don Knuth)

On Thu, Feb 29, 2024 at 4:05 PM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:

Hmm, so if I write "foo,*" this will work but check all function names
first and on the second entry. But if I write "foo*" the GUC value will
be accepted but match nothing (as will "*foo" or "foo*bar"). I don't
like either of these behaviors. I think we should tighten this up: an
asterisk should be allowed only if it appears alone in the string
(short-circuiting check_backtrace_functions before strspn); and let's
leave the strspn() call alone.

+1 for disallowing *foo or foo* or foo*bar etc. combinations. I think
we need to go a bit further and convert backtrace_functions of type
GUC_LIST_INPUT so that check_backtrace_functions can just use
SplitIdentifierString to parse the list of identifiers. Then, the
strspn can just be something like below for each token:

validlen = strspn(*tok,
"0123456789_"
"abcdefghijklmnopqrstuvwxyz"
"ABCDEFGHIJKLMNOPQRSTUVWXYZ");

Does anyone see a problem with it?

FWIW, I've recently noticed for my work on
https://commitfest.postgresql.org/47/2863/ that there isn't any test
covering all the backtrace related code - backtrace_functions GUC,
backtrace_on_internal_error GUC, set_backtrace(), backtrace(),
backtrace_symbols(). I came up with a test module covering these areas
https://commitfest.postgresql.org/47/4823/. I could make the TAP tests
pass on all the CF bot animals. Interestingly, the new code that gets
added for this thread can also be covered with it. Any thoughts are
welcome.

--
Bharath Rupireddy
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

On 2024-Mar-06, Bharath Rupireddy wrote:

+1 for disallowing *foo or foo* or foo*bar etc. combinations.

Cool.

I think we need to go a bit further and convert backtrace_functions of
type GUC_LIST_INPUT so that check_backtrace_functions can just use
SplitIdentifierString to parse the list of identifiers. Then, the
strspn can just be something like below for each token:

validlen = strspn(*tok,
"0123456789_"
"abcdefghijklmnopqrstuvwxyz"
"ABCDEFGHIJKLMNOPQRSTUVWXYZ");

Does anyone see a problem with it?

IIRC the reason it's coded as it is, is so that we have a single palloc
chunk of memory to free when the value changes; we purposefully stayed
away from SplitIdentifierString and the like. What problem do you see
with the idea I proposed? That was:

On Thu, Feb 29, 2024 at 4:05 PM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:

I think we should tighten this up: an asterisk should be allowed
only if it appears alone in the string (short-circuiting
check_backtrace_functions before strspn); and let's leave the
strspn() call alone.

That means, just add something like this at the top of
check_backtrace_functions and don't do anything to this function
otherwise (untested code):

if (newval[0] == '*' && newval[1] == '\0')
{
someval = guc_malloc(ERROR, 2);
if (someval == NULL)
return false;
someval[0] = '*';
someval[1] = '\0';
*extra = someval;
return true;
}

(Not sure if a second trailing \0 is necessary.)

--
Álvaro Herrera Breisgau, Deutschland — https://www.EnterpriseDB.com/
Voy a acabar con todos los humanos / con los humanos yo acabaré
voy a acabar con todos (bis) / con todos los humanos acabaré ¡acabaré! (Bender)

On Wed, Mar 6, 2024 at 12:41 AM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:

I think we need to go a bit further and convert backtrace_functions of
type GUC_LIST_INPUT so that check_backtrace_functions can just use
SplitIdentifierString to parse the list of identifiers. Then, the
strspn can just be something like below for each token:

validlen = strspn(*tok,
"0123456789_"
"abcdefghijklmnopqrstuvwxyz"
"ABCDEFGHIJKLMNOPQRSTUVWXYZ");

Does anyone see a problem with it?

IIRC the reason it's coded as it is, is so that we have a single palloc
chunk of memory to free when the value changes; we purposefully stayed
away from SplitIdentifierString and the like.

Why do we even need to prepare another list backtrace_function_list
from the parsed identifiers? Why can't we just do something like
v4-0003? Existing logic looks a bit complicated to me personally.

I still don't understand why we can't just turn backtrace_functions to
GUC_LIST_INPUT and use SplitIdentifierString? I see a couple of
advantages with this approach:
1. It simplifies the backtrace_functions GUC related code a lot.
2. We don't need assign_backtrace_functions() and a separate variable
backtrace_function_list, we can just rely on the GUC value
backtrace_functions.
3. All we do now in check_backtrace_functions() is just parse the user
entered backtrace_functions value, and quickly exit if we have found
'*'.
4. In matches_backtrace_functions(), we iterate over the list as we
already do right now.

With the v4-0003, all of the below test cases work:

ALTER SYSTEM SET backtrace_functions = 'pg_terminate_backend,
pg_create_restore_point';
SELECT pg_reload_conf();
SHOW backtrace_functions;

-- Must see backtrace
SELECT pg_create_restore_point(repeat('A', 1024));

-- Must see backtrace
SELECT pg_terminate_backend(1234, -1);

ALTER SYSTEM SET backtrace_functions = '*, pg_create_restore_point';
SELECT pg_reload_conf();
SHOW backtrace_functions;

-- Must see backtrace as * is specified
SELECT pg_terminate_backend(1234, -1);

-- Must see an error as * is specified in between the identifier name
ALTER SYSTEM SET backtrace_functions = 'pg*_create_restore_point';
ERROR: invalid value for parameter "backtrace_functions":
"pg*_create_restore_point"
DETAIL: Invalid character

What problem do you see with the idea I proposed? That was:

On Thu, Feb 29, 2024 at 4:05 PM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:

I think we should tighten this up: an asterisk should be allowed
only if it appears alone in the string (short-circuiting
check_backtrace_functions before strspn); and let's leave the
strspn() call alone.

That means, just add something like this at the top of
check_backtrace_functions and don't do anything to this function
otherwise (untested code):

if (newval[0] == '*' && newval[1] == '\0')
{
someval = guc_malloc(ERROR, 2);
if (someval == NULL)
return false;
someval[0] = '*';
someval[1] = '\0';
*extra = someval;
return true;
}

This works only if '* 'is specified as the only one character in
backtrace_functions = '*', right? If yes, what if someone sets
backtrace_functions = 'foo, bar, *, baz'?

--
Bharath Rupireddy
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

On 2024-Mar-08, Bharath Rupireddy wrote:

This works only if '* 'is specified as the only one character in
backtrace_functions = '*', right? If yes, what if someone sets
backtrace_functions = 'foo, bar, *, baz'?

It throws an error, as expected. This is a useless waste of resources:
checking for "foo" and "bar" is pointless, since the * is going to give
a positive match anyway. And the "baz" is a waste of memory which is
never going to be checked.

--
Álvaro Herrera Breisgau, Deutschland — https://www.EnterpriseDB.com/
"I love the Postgres community. It's all about doing things _properly_. :-)"
(David Garamond)

On Fri, 8 Mar 2024 at 10:59, Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:

On 2024-Mar-08, Bharath Rupireddy wrote:

This works only if '* 'is specified as the only one character in
backtrace_functions = '*', right? If yes, what if someone sets
backtrace_functions = 'foo, bar, *, baz'?

It throws an error, as expected. This is a useless waste of resources:
checking for "foo" and "bar" is pointless, since the * is going to give
a positive match anyway. And the "baz" is a waste of memory which is
never going to be checked.

Makes sense. Attached is a new patchset that implements it that way.
I've not included Bharath his 0003 patch, since it's a much bigger
change than the others, and thus might need some more discussion.

On 8 Mar 2024, at 12:25, Jelte Fennema-Nio <me@jeltef.nl> wrote:

On Fri, 8 Mar 2024 at 10:59, Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:

On 2024-Mar-08, Bharath Rupireddy wrote:

This works only if '* 'is specified as the only one character in
backtrace_functions = '*', right? If yes, what if someone sets
backtrace_functions = 'foo, bar, *, baz'?

It throws an error, as expected. This is a useless waste of resources:
checking for "foo" and "bar" is pointless, since the * is going to give
a positive match anyway. And the "baz" is a waste of memory which is
never going to be checked.

Makes sense. Attached is a new patchset that implements it that way.

This version address the concerns raised by Alvaro, and even simplifies the
code over earlier revisions. My documentation comments from upthread still
stands, but other than those this version LGTM.

I've not included Bharath his 0003 patch, since it's a much bigger
change than the others, and thus might need some more discussion.

Agreed.

--
Daniel Gustafsson

On Fri, Mar 8, 2024 at 7:12 PM Daniel Gustafsson <daniel@yesql.se> wrote:

On 8 Mar 2024, at 12:25, Jelte Fennema-Nio <me@jeltef.nl> wrote:

On Fri, 8 Mar 2024 at 10:59, Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:

On 2024-Mar-08, Bharath Rupireddy wrote:

This works only if '* 'is specified as the only one character in
backtrace_functions = '*', right? If yes, what if someone sets
backtrace_functions = 'foo, bar, *, baz'?

It throws an error, as expected. This is a useless waste of resources:
checking for "foo" and "bar" is pointless, since the * is going to give
a positive match anyway. And the "baz" is a waste of memory which is
never going to be checked.

Makes sense. Attached is a new patchset that implements it that way.

This version address the concerns raised by Alvaro, and even simplifies the
code over earlier revisions. My documentation comments from upthread still
stands, but other than those this version LGTM.

So, to get backtraces of all functions at
backtrace_functions_min_level level, one has to specify
backtrace_functions = '*'; combining it with function names is not
allowed. This looks cleaner.

postgres=# ALTER SYSTEM SET backtrace_functions = '*, pg_create_restore_point';
ERROR: invalid value for parameter "backtrace_functions": "*,
pg_create_restore_point"
DETAIL: Invalid character

I have one comment on 0002, otherwise all looks good.

+       <para>
+        A single <literal>*</literal> character can be used instead of a list
+        of C functions. This <literal>*</literal> is interpreted as a wildcard
+        and will cause all errors in the log to contain backtraces.
+       </para>

It's not always the ERRORs for which backtraces get logged, it really
depends on the new GUC backtrace_functions_min_level. If my
understanding is right, can we specify that in the above note?

I've not included Bharath his 0003 patch, since it's a much bigger
change than the others, and thus might need some more discussion.

+1. I'll see if I can start a new thread for this.

--
Bharath Rupireddy
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

On 8 Mar 2024, at 15:01, Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com> wrote:

So, to get backtraces of all functions at
backtrace_functions_min_level level, one has to specify
backtrace_functions = '*'; combining it with function names is not
allowed. This looks cleaner.

postgres=# ALTER SYSTEM SET backtrace_functions = '*, pg_create_restore_point';
ERROR: invalid value for parameter "backtrace_functions": "*,
pg_create_restore_point"
DETAIL: Invalid character

If we want to be extra helpful here we could add something like the below to
give an errhint when a wildcard was found. Also, the errdetail should read
like a full sentence so it should be slightly expanded anyways.

diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index ca621ea3ff..7bc655ecd2 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -2151,7 +2151,9 @@ check_backtrace_functions(char **newval, void **extra, GucSource source)
                                          ", \n\t");
        if (validlen != newvallen)
        {
-               GUC_check_errdetail("Invalid character");
+               GUC_check_errdetail("Invalid character in function name.");
+               if ((*newval)[validlen] == '*')
+                       GUC_check_errhint("For wildcard matching, use a single \"*\" without any other function names.");
                return false;
        }

--
Daniel Gustafsson

On 08.03.24 12:25, Jelte Fennema-Nio wrote:

On Fri, 8 Mar 2024 at 10:59, Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:

On 2024-Mar-08, Bharath Rupireddy wrote:

This works only if '* 'is specified as the only one character in
backtrace_functions = '*', right? If yes, what if someone sets
backtrace_functions = 'foo, bar, *, baz'?

It throws an error, as expected. This is a useless waste of resources:
checking for "foo" and "bar" is pointless, since the * is going to give
a positive match anyway. And the "baz" is a waste of memory which is
never going to be checked.

Makes sense. Attached is a new patchset that implements it that way.
I've not included Bharath his 0003 patch, since it's a much bigger
change than the others, and thus might need some more discussion.

What is the relationship of these changes with the recently added
backtrace_on_internal_error? We had similar discussions there, I feel
like we are doing similar things here but slightly differently. Like,
shouldn't backtrace_functions_min_level also affect
backtrace_on_internal_error? Don't you really just want
backtrace_on_any_error? You are sneaking that in through the backdoor
via backtrace_functions. Can we somehow combine all these use cases
more elegantly? backtrace_on_error = {all|internal|none}?

Btw., your code/documentation sometimes writes "stack trace". Let's
stick to backtrace for consistency.

On Fri, 8 Mar 2024 at 14:42, Daniel Gustafsson <daniel@yesql.se> wrote:

My documentation comments from upthread still
stands, but other than those this version LGTM.

Ah yeah, I forgot about those. Fixed now.

On Fri, 8 Mar 2024 at 15:51, Peter Eisentraut <peter@eisentraut.org> wrote:

What is the relationship of these changes with the recently added
backtrace_on_internal_error?

I think that's a reasonable question. And the follow up ones too.

I think it all depends on how close we consider
backtrace_on_internal_error and backtrace_functions. While they
obviously have similar functionality, I feel like
backtrace_on_internal_error is probably a function that we'd want to
turn on by default in the future. While backtrace_functions seems like
it's mostly useful for developers. (i.e. the current grouping of
backtrace_on_internal_error under DEVELOPER_OPTIONS seems wrong to me)

shouldn't backtrace_functions_min_level also affect
backtrace_on_internal_error?

I guess that depends on the default behaviour that we want. Would we
want warnings with ERRCODE_INTERNAL_ERROR to be backtraced by default
or not. There is at least one example of such a warning in the
codebase:

ereport(WARNING,
errcode(ERRCODE_INTERNAL_ERROR),
errmsg_internal("could not parse XML declaration in stored value"),
errdetail_for_xml_code(res_code));

Btw., your code/documentation sometimes writes "stack trace". Let's
stick to backtrace for consistency.

Fixed that in the latest patset in the email I sent right before this one.