Re: Reducing the log spam

On Mon, 2024-06-17 at 16:40 -0500, Justin Pryzby wrote:

The feature will become much less useful if unique voilations keep getting logged.

Uh, to be clear, your patch is changing the *defaults*, which I found
surprising, even after reaading the thread. Evidently, the current
behavior is not what you want, and you want to change it, but I'm *sure*
that whatever default you want to use at your site/with your application
is going to make someone else unhappy. I surely want unique violations
to be logged, for example.

I was afraid that setting the default non-empty would cause objections.

+       <para>
+        This setting is useful to exclude error messages from the log that are
+        frequent but irrelevant.

I think you should phrase the feature as ".. *allow* skipping error
logging for messages ... that are frequent but irrelevant for a given
site/role/DB/etc."

I have reworded that part.

I suggest that this patch should not change the default behavior at all:
its default should be empty. That you, personally, would plan to
exclude this or that error code is pretty uninteresting. I think the
idea of changing the default behavior will kill the patch, and even if
you want to propose to do that, it should be a separate discussion.
Maybe you should make it an 002 patch.

I have attached a new version that leaves the parameter empty by default.

The patch is not motivated by my personal dislike of certain error messages.
A well-written application would not need that parameter at all.
The motivation for me is based on my dealing with customers' log files,
which are often full of messages that are only distracting from serious
problems and fill up the disk.

But you are probably right that it would be hard to find a default setting
that nobody has quibbles with, and the default can always be changed with
a future patch.

Yours,
Laurenz Albe

Hello Laurenz,

I liked the idea for this patch. I will also go for the default being
an empty string.
I went through this patch and have some comments on the code,

1. In general, I don't like the idea of goto, maybe we can have a
free_something function to call here.

2.
if (!SplitIdentifierString(new_copy, ',', &states))
{
GUC_check_errdetail("List syntax is invalid.");
goto failed;
}
Here, we don't need all that free-ing, we can just return false here.

3.
/*
* Check the the values are alphanumeric and convert them to upper case
* (SplitIdentifierString converted them to lower case).
*/
for (p = state; *p != '\0'; p++)
if (*p >= 'a' && *p <= 'z')
*p += 'A' - 'a';
else if (*p < '0' || *p > '9')
{
GUC_check_errdetail("error codes can only contain digits and ASCII letters.");
goto failed;
}
I was thinking, maybe we can use tolower() function here.

4.
list_free(states);
pfree(new_copy);

*extra = statelist;
return true;

failed:
list_free(states);
pfree(new_copy);
guc_free(statelist);
return false;

This looks like duplication that can be easily avoided.
You may have free_somthing function to do all free-ing stuff only and
its callee can then have a return statement.
e.g for here,
free_states(states, new_copy, statelist);
return true;

5. Also, for alphanumeric check, maybe we can have something like,
if (isalnum(*state) == 0)
{
GUC_check_errdetail("error codes can only contain digits and ASCII letters.");
goto failed;
}
and we can do this in the beginning after the len check.

On Tue, 18 Jun 2024 at 18:49, Laurenz Albe <laurenz.albe@cybertec.at> wrote:

On Mon, 2024-06-17 at 16:40 -0500, Justin Pryzby wrote:

The feature will become much less useful if unique voilations keep getting logged.

Uh, to be clear, your patch is changing the *defaults*, which I found
surprising, even after reaading the thread. Evidently, the current
behavior is not what you want, and you want to change it, but I'm *sure*
that whatever default you want to use at your site/with your application
is going to make someone else unhappy. I surely want unique violations
to be logged, for example.

I was afraid that setting the default non-empty would cause objections.

+       <para>
+        This setting is useful to exclude error messages from the log that are
+        frequent but irrelevant.

I think you should phrase the feature as ".. *allow* skipping error
logging for messages ... that are frequent but irrelevant for a given
site/role/DB/etc."

I have reworded that part.

I suggest that this patch should not change the default behavior at all:
its default should be empty. That you, personally, would plan to
exclude this or that error code is pretty uninteresting. I think the
idea of changing the default behavior will kill the patch, and even if
you want to propose to do that, it should be a separate discussion.
Maybe you should make it an 002 patch.

I have attached a new version that leaves the parameter empty by default.

The patch is not motivated by my personal dislike of certain error messages.
A well-written application would not need that parameter at all.
The motivation for me is based on my dealing with customers' log files,
which are often full of messages that are only distracting from serious
problems and fill up the disk.

But you are probably right that it would be hard to find a default setting
that nobody has quibbles with, and the default can always be changed with
a future patch.

Yours,
Laurenz Albe

--
Regards,
Rafia Sabih

Thanks for the review!

On Wed, 2024-07-24 at 15:27 +0200, Rafia Sabih wrote:

I liked the idea for this patch. I will also go for the default being
an empty string.
I went through this patch and have some comments on the code,

1. In general, I don't like the idea of goto, maybe we can have a
free_something function to call here.

The PostgreSQL code base has over 3000 goto's...

Sure, that can be factored out to a function (except the final "return"),
but I feel that a function for three "free" calls is code bloat.

Do you think that avoiding the goto and using a function would make the
code simpler and clearer?

2.
if (!SplitIdentifierString(new_copy, ',', &states))
{
GUC_check_errdetail("List syntax is invalid.");
goto failed;
}
Here, we don't need all that free-ing, we can just return false here.

I am OK with changing that; I had thought it was more clearer and more
foolproof to use the same pattern everywhere.

3.
/*
* Check the the values are alphanumeric and convert them to upper case
* (SplitIdentifierString converted them to lower case).
*/
for (p = state; *p != '\0'; p++)
if (*p >= 'a' && *p <= 'z')
*p += 'A' - 'a';
else if (*p < '0' || *p > '9')
{
GUC_check_errdetail("error codes can only contain digits and ASCII letters.");
goto failed;
}
I was thinking, maybe we can use tolower() function here.

That is a good idea, but these C library respect the current locale.
I would have to explicitly specify the C locale or switch the locale
temporarily.

Switching the locale seems clumsy, and I have no idea what I would have
to feed as second argument to toupper_l() or isalnum_l().
Do you have an idea?

4.
list_free(states);
pfree(new_copy);

*extra = statelist;
return true;

failed:
list_free(states);
pfree(new_copy);
guc_free(statelist);
return false;

This looks like duplication that can be easily avoided.
You may have free_somthing function to do all free-ing stuff only and
its callee can then have a return statement.
e.g for here,
free_states(states, new_copy, statelist);
return true;

That free_states() function would just contain two function calls.
I think that defining a special function for that is somewhat out of
proportion.

5. Also, for alphanumeric check, maybe we can have something like,
if (isalnum(*state) == 0)
{
GUC_check_errdetail("error codes can only contain digits and ASCII letters.");
goto failed;
}
and we can do this in the beginning after the len check.

isalnum() operates on a single character and depends on the current locale.
See my comments to 3. above.

Please let me know what you think, particularly about the locale problem.

Yours,
Laurenz Albe

On Thu, 25 Jul 2024 at 18:03, Laurenz Albe <laurenz.albe@cybertec.at> wrote:

Thanks for the review!

On Wed, 2024-07-24 at 15:27 +0200, Rafia Sabih wrote:

I liked the idea for this patch. I will also go for the default being
an empty string.
I went through this patch and have some comments on the code,

1. In general, I don't like the idea of goto, maybe we can have a
free_something function to call here.

The PostgreSQL code base has over 3000 goto's...

Sure, that can be factored out to a function (except the final "return"),
but I feel that a function for three "free" calls is code bloat.

On a detailed look over this, you are right Laurenz about this.

Do you think that avoiding the goto and using a function would make the
code simpler and clearer?

2.
if (!SplitIdentifierString(new_copy, ',', &states))
{
GUC_check_errdetail("List syntax is invalid.");
goto failed;
}
Here, we don't need all that free-ing, we can just return false here.

I am OK with changing that; I had thought it was more clearer and more
foolproof to use the same pattern everywhere.

3.
/*
* Check the the values are alphanumeric and convert them to upper case
* (SplitIdentifierString converted them to lower case).
*/
for (p = state; *p != '\0'; p++)
if (*p >= 'a' && *p <= 'z')
*p += 'A' - 'a';
else if (*p < '0' || *p > '9')
{
GUC_check_errdetail("error codes can only contain digits and ASCII

letters.");

goto failed;
}
I was thinking, maybe we can use tolower() function here.

That is a good idea, but these C library respect the current locale.
I would have to explicitly specify the C locale or switch the locale
temporarily.

Hmm. actually I don't have any good answers to this locale issue.

Switching the locale seems clumsy, and I have no idea what I would have
to feed as second argument to toupper_l() or isalnum_l().
Do you have an idea?

4.
list_free(states);
pfree(new_copy);

*extra = statelist;
return true;

failed:
list_free(states);
pfree(new_copy);
guc_free(statelist);
return false;

This looks like duplication that can be easily avoided.
You may have free_somthing function to do all free-ing stuff only and
its callee can then have a return statement.
e.g for here,
free_states(states, new_copy, statelist);
return true;

That free_states() function would just contain two function calls.
I think that defining a special function for that is somewhat out of
proportion.

5. Also, for alphanumeric check, maybe we can have something like,
if (isalnum(*state) == 0)
{
GUC_check_errdetail("error codes can only contain digits and ASCII

letters.");

goto failed;
}
and we can do this in the beginning after the len check.

isalnum() operates on a single character and depends on the current locale.
See my comments to 3. above.

Please let me know what you think, particularly about the locale problem.

Yours,
Laurenz Albe

--
Regards,
Rafia Sabih

Hi Laurenz

On 18.06.24 18:49, Laurenz Albe wrote:

I have attached a new version that leaves the parameter empty by default.

I've tested this patch and for the most part it works as intended. For
convenience, I wrote a small function to simulate the exceptions using a
given errcode:

CREATE OR REPLACE FUNCTION raise_sqlstate(state text)
RETURNS VOID AS $$
BEGIN
  RAISE EXCEPTION 'exception sqlstate = %',
    state USING ERRCODE = state;
END;
$$ LANGUAGE plpgsql;

== specific errcodes ==

SET log_suppress_errcodes TO '23505,3D000,42601';
SHOW log_suppress_errcodes;

SELECT raise_sqlstate('23505'); -- must be suppressed
SELECT raise_sqlstate('3D000'); -- must be suppressed
SELECT raise_sqlstate('42601'); -- must be suppressed
SELECT raise_sqlstate('42P01');

log entries:
2025-03-07 14:23:30.688 CET [3266008] ERROR:  exception sqlstate = 42P01
2025-03-07 14:23:30.688 CET [3266008] CONTEXT:  PL/pgSQL function
raise_sqlstate(text) line 3 at RAISE
2025-03-07 14:23:30.688 CET [3266008] STATEMENT:  SELECT
raise_sqlstate('42P01');

== errcode classes ==

SET log_suppress_errcodes TO '23000,3D000';
SHOW log_suppress_errcodes;

SELECT raise_sqlstate('23505'); -- must be suppressed
SELECT raise_sqlstate('42P01');

log entries:
2025-03-07 14:24:40.023 CET [3268343] ERROR:  exception sqlstate = 42P01
2025-03-07 14:24:40.023 CET [3268343] CONTEXT:  PL/pgSQL function
raise_sqlstate(text) line 3 at RAISE
2025-03-07 14:24:40.023 CET [3268343] STATEMENT:  SELECT
raise_sqlstate('42P01');

There are a few issues though ...

1) Invalid codes aren't rejected. Is there any way to validate them?

postgres=# SET log_suppress_errcodes TO '0foo1'; SHOW log_suppress_errcodes;
SET
 log_suppress_errcodes
-----------------------
 0foo1
(1 row)

2) No duplication check (not critical IMO)

postgres=# SET log_suppress_errcodes TO '3F000,3F000'; SHOW
log_suppress_errcodes;
SET
 log_suppress_errcodes
-----------------------
 3F000,3F000
(1 row)

3) errcodes are not trimmed (also not critical..  just doesn't look nice)

postgres=# SET log_suppress_errcodes TO '               3F000, 42P01';
SHOW log_suppress_errcodes;
SET
    log_suppress_errcodes    
-----------------------------
                3F000, 42P01
(1 row)

4) SHOW log_suppress_errcodes displays an invalid value if we set it
twice to an empty string

$ /usr/local/postgres-dev/bin/psql postgres
psql (18devel)
Type "help" for help.

postgres=# SET log_suppress_errcodes TO ''; SHOW log_suppress_errcodes;
SET log_suppress_errcodes TO ''; SHOW log_suppress_errcodes;
SET
 log_suppress_errcodes
-----------------------
 
(1 row)

SET
 log_suppress_errcodes
-----------------------
 wV
(1 row)

5) The system crashes if we set log_suppress_errcodesto an empty string
and then set it back to comma separated values

$ /usr/local/postgres-dev/bin/psql postgres
psql (18devel)
Type "help" for help.

postgres=# SET log_suppress_errcodes TO '3F000,42883'; SHOW
log_suppress_errcodes;
SET log_suppress_errcodes TO ''; SHOW log_suppress_errcodes;
SET log_suppress_errcodes TO '42P01,23505'; SHOW log_suppress_errcodes;
SET log_suppress_errcodes TO '3D000,42704'; SHOW log_suppress_errcodes;
SET
 log_suppress_errcodes
-----------------------
 3F000,42883
(1 row)

SET
 log_suppress_errcodes
-----------------------
 
(1 row)

SET
 log_suppress_errcodes
-----------------------
 42P01,23505
(1 row)

server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
The connection to the server was lost. Attempting reset: Failed.
The connection to the server was lost. Attempting reset: Failed.
You are currently not connected to a database.

!?>

Best regards, Jim

On Fri, 2025-03-07 at 20:38 +0100, Jim Jones wrote:

I've tested this patch and for the most part it works as intended.

Thanks for the thorough test!

There are a few issues though ...

1) Invalid codes aren't rejected. Is there any way to validate them?

postgres=# SET log_suppress_errcodes TO '0foo1'; SHOW log_suppress_errcodes;
SET
 log_suppress_errcodes
-----------------------
 0foo1
(1 row)

That is intentional. I only test that the SQLSTATE is 5 characters long
and contains only ASCII letters and numbers. I looked at the SQL standard,
and while it defines the meaning of certain SQLSTATEs, it allows for
custom defined states.

Nothing bad can happen from setting an unused SQLSTATE; it just won't
suppress anything.

2) No duplication check (not critical IMO)

postgres=# SET log_suppress_errcodes TO '3F000,3F000'; SHOW
log_suppress_errcodes;
SET
 log_suppress_errcodes
-----------------------
 3F000,3F000
(1 row)

3) errcodes are not trimmed (also not critical..  just doesn't look nice)

postgres=# SET log_suppress_errcodes TO '               3F000, 42P01';
SHOW log_suppress_errcodes;
SET
    log_suppress_errcodes    
-----------------------------
                3F000, 42P01
(1 row)

These two are mostly cosmetic issues.

I originally thought it best to leave the parameter the way the user
entered it, but in the attached version I revised that by reassembling
the parameter string from the parsed SQLSTATEs, so that spaces and
duplicates will vanish and everything is converted to upper case.

So these complaints should be addressed.

4) SHOW log_suppress_errcodes displays an invalid value if we set it
twice to an empty string

$ /usr/local/postgres-dev/bin/psql postgres
psql (18devel)
Type "help" for help.

postgres=# SET log_suppress_errcodes TO ''; SHOW log_suppress_errcodes;
SET log_suppress_errcodes TO ''; SHOW log_suppress_errcodes;
SET
 log_suppress_errcodes
-----------------------
 
(1 row)

SET
 log_suppress_errcodes
-----------------------
 wV
(1 row)

5) The system crashes if we set log_suppress_errcodesto an empty string
and then set it back to comma separated values

These two points were actually caused by a memory management bug that I
had inadvertently introduced in the assign hook. They should be fixed now.

Attached is the fifth version of the patch.

Yours,
Laurenz Albe

On 11.03.25 10:46, Laurenz Albe wrote:

Thanks for the thorough test!

There are a few issues though ...

1) Invalid codes aren't rejected. Is there any way to validate them?

postgres=# SET log_suppress_errcodes TO '0foo1'; SHOW log_suppress_errcodes;
SET
 log_suppress_errcodes
-----------------------
 0foo1
(1 row)

That is intentional. I only test that the SQLSTATE is 5 characters long
and contains only ASCII letters and numbers. I looked at the SQL standard,
and while it defines the meaning of certain SQLSTATEs, it allows for
custom defined states.

Nothing bad can happen from setting an unused SQLSTATE; it just won't
suppress anything.

I suspected that. Just for the records, v5 now shows also "invalid"
SQLSTATEs in uppercase:

postgres=# SET log_suppress_errcodes TO 'x1y2z'; SHOW log_suppress_errcodes;
SET
 log_suppress_errcodes
-----------------------
 X1Y2Z
(1 row)

2) No duplication check (not critical IMO)

postgres=# SET log_suppress_errcodes TO '3F000,3F000'; SHOW
log_suppress_errcodes;
SET
 log_suppress_errcodes
-----------------------
 3F000,3F000
(1 row)

3) errcodes are not trimmed (also not critical..  just doesn't look nice)

postgres=# SET log_suppress_errcodes TO '               3F000, 42P01';
SHOW log_suppress_errcodes;
SET
    log_suppress_errcodes    
-----------------------------
                3F000, 42P01
(1 row)

These two are mostly cosmetic issues.

I originally thought it best to leave the parameter the way the user
entered it, but in the attached version I revised that by reassembling
the parameter string from the parsed SQLSTATEs, so that spaces and
duplicates will vanish and everything is converted to upper case.

So these complaints should be addressed.

Duplicated entries and whitespaces are now removed

postgres=# SET log_suppress_errcodes TO '   3F000,         3F000, 42P01';
SHOW log_suppress_errcodes;
SET
 log_suppress_errcodes
-----------------------
 3F000,42P01
(1 row)

4) SHOW log_suppress_errcodes displays an invalid value if we set it
twice to an empty string

$ /usr/local/postgres-dev/bin/psql postgres
psql (18devel)
Type "help" for help.

postgres=# SET log_suppress_errcodes TO ''; SHOW log_suppress_errcodes;
SET log_suppress_errcodes TO ''; SHOW log_suppress_errcodes;
SET
 log_suppress_errcodes
-----------------------
 
(1 row)

SET
 log_suppress_errcodes
-----------------------
 wV
(1 row)

5) The system crashes if we set log_suppress_errcodesto an empty string
and then set it back to comma separated values

These two points were actually caused by a memory management bug that I
had inadvertently introduced in the assign hook. They should be fixed now.

empty log_suppress_errcode now behaves as expected

$ /usr/local/postgres-dev/bin/psql postgres
psql (18devel)
Type "help" for help.

postgres=# SET log_suppress_errcodes TO ''; SHOW log_suppress_errcodes;
SET log_suppress_errcodes TO ''; SHOW log_suppress_errcodes;
SET
 log_suppress_errcodes
-----------------------
 
(1 row)

SET
 log_suppress_errcodes
-----------------------
 
(1 row)

The system no longer crashes when setting the parameter to an empty
string and set it back to comma separated values

$ /usr/local/postgres-dev/bin/psql postgres
psql (18devel)
Type "help" for help.

postgres=# SET log_suppress_errcodes TO '3F000,42883'; SHOW
log_suppress_errcodes;
SET log_suppress_errcodes TO ''; SHOW log_suppress_errcodes;
SET log_suppress_errcodes TO '42P01,23505'; SHOW log_suppress_errcodes;
SET log_suppress_errcodes TO '3D000,42704'; SHOW log_suppress_errcodes;
SET
 log_suppress_errcodes
-----------------------
 3F000,42883
(1 row)

SET
 log_suppress_errcodes
-----------------------
 
(1 row)

SET
 log_suppress_errcodes
-----------------------
 42P01,23505
(1 row)

SET
 log_suppress_errcodes
-----------------------
 3D000,42704
(1 row)

The previous tests work as expected and all issues were addressed.

If the other reviewers have no objections, I'll mark this patch as
"Ready for Committer".

Best regards, Jim

On Tue, 2025-03-11 at 10:46 +0100, Laurenz Albe wrote:

Attached is the fifth version of the patch.

... and here, for good measure, a pgindented version
Apart from that, no changes.

Yours,
Laurenz Albe

On Fri, 2025-03-14 at 06:58 +0100, Laurenz Albe wrote:

On Tue, 2025-03-11 at 10:46 +0100, Laurenz Albe wrote:

Attached is the fifth version of the patch.

... and here, for good measure, a pgindented version
Apart from that, no changes.

... and here is v7, improved in the spirit of
/messages/by-id/E132D362-A669-4606-AFE1-B45C9DFCC141@yesql.se

Yours,
Laurenz Albe

On 15.03.25 07:12, Laurenz Albe wrote:

... and here is v7, improved in the spirit of
/messages/by-id/E132D362-A669-4606-AFE1-B45C9DFCC141@yesql.se

I just revisited this patch and v7 passes all tests from [1,2].
LGTM.

Best regards, Jim

[1]: /messages/by-id/205505aa-4ba1-4d5b-b5f2-d006f14f4775@uni-muenster.de
/messages/by-id/205505aa-4ba1-4d5b-b5f2-d006f14f4775@uni-muenster.de
[2]: /messages/by-id/ec933afb-c8a3-4954-bb58-8f86b272a6f9@uni-muenster.de
/messages/by-id/ec933afb-c8a3-4954-bb58-8f86b272a6f9@uni-muenster.de

On 2025/03/17 17:12, Jim Jones wrote:

On 15.03.25 07:12, Laurenz Albe wrote:

... and here is v7, improved in the spirit of
/messages/by-id/E132D362-A669-4606-AFE1-B45C9DFCC141@yesql.se

I just revisited this patch and v7 passes all tests from [1,2].
LGTM.

Since this patch is marked as ready for committer, I've started looking at it.

Filtering log messages by SQLSTATE might be useful for some users,
but I'm unsure if it should belong in the core. There are also other
potential filtering needs, such as by application name, client host,
database, or roles. Adding only SQLSTATE filtering may not be good idea,
while supporting all possible cases in the core wouldn't be practical either.

Given that, I think implementing this as an extension using emit_log_hook
would be a better approach. Anyway, I'd like to hear more opinions from
other hackers on this.

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

Fujii Masao <masao.fujii@oss.nttdata.com> writes:

Filtering log messages by SQLSTATE might be useful for some users,
but I'm unsure if it should belong in the core. There are also other
potential filtering needs, such as by application name, client host,
database, or roles. Adding only SQLSTATE filtering may not be good idea,
while supporting all possible cases in the core wouldn't be practical either.

Given that, I think implementing this as an extension using emit_log_hook
would be a better approach. Anyway, I'd like to hear more opinions from
other hackers on this.

I took a brief look and I concur with Fujii-san's conclusion: this'd
be a fine extension a/k/a contrib module, but it seems a bit too
opinionated about what sort of filtering is needed to be appropriate
within elog.c itself.

Also, just as a minor coding thought, I'd suggest using -1 not 0
to terminate the array of encoded SQLSTATEs, rather than assuming
that nobody would write 00000. Compare commit 58fdca220.

regards, tom lane

On Wed, 2025-04-02 at 15:23 -0400, Tom Lane wrote:

Fujii Masao <masao.fujii@oss.nttdata.com> writes:

Filtering log messages by SQLSTATE might be useful for some users,
but I'm unsure if it should belong in the core. There are also other
potential filtering needs, such as by application name, client host,
database, or roles. Adding only SQLSTATE filtering may not be good idea,
while supporting all possible cases in the core wouldn't be practical either.

Given that, I think implementing this as an extension using emit_log_hook
would be a better approach. Anyway, I'd like to hear more opinions from
other hackers on this.

I took a brief look and I concur with Fujii-san's conclusion: this'd
be a fine extension a/k/a contrib module, but it seems a bit too
opinionated about what sort of filtering is needed to be appropriate
within elog.c itself.

Also, just as a minor coding thought, I'd suggest using -1 not 0
to terminate the array of encoded SQLSTATEs, rather than assuming
that nobody would write 00000.  Compare commit 58fdca220.

I agree with these assessments and will withdraw the patch.

Yours,
Laurenz Albe