Thread: Reducing the log spam

Inspired by feedback to [1], I thought about how to reduce log spam.

My experience from the field is that a lot of log spam looks like

  database/table/... "xy" does not exist
  duplicate key value violates unique constraint "xy"

So what about a parameter "log_suppress_sqlstates" that suppresses
logging ERROR and FATAL messages with the enumerated SQL states?

My idea for a default setting would be something like

  log_suppress_sqlstates = '23505,3D000,3F000,42601,42704,42883,42P01'

but that's of course bikeshedding territory.

Yours,
Laurenz Albe



 [1]: https://postgr.es/m/b8b8502915e50f44deb111bc0b43a99e2733e117.camel%40cybertec.at

Hi Laurenz

On 05.03.24 13:55, Laurenz Albe wrote:
> Inspired by feedback to [1], I thought about how to reduce log spam.
>
> My experience from the field is that a lot of log spam looks like
>
>    database/table/... "xy" does not exist
>    duplicate key value violates unique constraint "xy"
>
> So what about a parameter "log_suppress_sqlstates" that suppresses
> logging ERROR and FATAL messages with the enumerated SQL states?
>
> My idea for a default setting would be something like
>
>    log_suppress_sqlstates = '23505,3D000,3F000,42601,42704,42883,42P01'
>
> but that's of course bikeshedding territory.
>
> Yours,
> Laurenz Albe
>
>
>
>   [1]: https://postgr.es/m/b8b8502915e50f44deb111bc0b43a99e2733e117.camel%40cybertec.at

I like this idea, and I could see myself using it a lot in some projects.

Additionally, it would be nice to also have the possibility suppress a 
whole class instead of single SQL states, e.g.

log_suppress_sqlstates = 'class_08' to suppress these all at once:

08000     connection_exception
08003     connection_does_not_exist
08006     connection_failure
08001     sqlclient_unable_to_establish_sqlconnection
08004     sqlserver_rejected_establishment_of_sqlconnection
08007     transaction_resolution_unknown
08P01     protocol_violation

Best regards,
Jim

On Tue, 5 Mar 2024 at 14:55, Jim Jones <jim.jones@uni-muenster.de> wrote:
> > So what about a parameter "log_suppress_sqlstates" that suppresses
> > logging ERROR and FATAL messages with the enumerated SQL states?

Big +1 from me for this idea.

Hi,

> So what about a parameter "log_suppress_sqlstates" that suppresses
> logging ERROR and FATAL messages with the enumerated SQL states?
>
> My idea for a default setting would be something like
>
>   log_suppress_sqlstates = '23505,3D000,3F000,42601,42704,42883,42P01'
>
> but that's of course bikeshedding territory.

I like the idea of suppressing certain log messages in general, but
the particular user interface doesn't strike me as an especially
convenient one.

Firstly I don't think many people remember sqlstates and what 3F000
stands for. IMO most users don't know such a thing exists. Secondly,
whether we should list sqlstates to suppress or the opposite - list
the states that shouldn't be suppressed, is a debatable question. Last
but not least, it's not quite clear whether PostgreSQL core is the
right place for implementing this functionality. For instance, one
could argue that the log message should just contain sqlstate and be
directed to |grep instead.

I suspect this could be one of "there is no one size fits all"
situations. The typical solution in such cases is to form a structure
containing the log message and its attributes and submit this
structure to a registered hook of a pluggable logging subsystem. This
would be the most flexible approach. It will allow not only filtering
the messages but also using binary logging, JSON logging, logging to
external systems like Loki instead of a given text file, etc.

I don't think we currently have this in the core, but maybe I just missed it.

-- 
Best regards,
Aleksander Alekseev

On Wed, 2024-03-06 at 17:09 +0300, Aleksander Alekseev wrote:
> I like the idea of suppressing certain log messages in general, but
> the particular user interface doesn't strike me as an especially
> convenient one.
>
> Firstly I don't think many people remember sqlstates and what 3F000
> stands for. IMO most users don't know such a thing exists. Secondly,
> whether we should list sqlstates to suppress or the opposite - list
> the states that shouldn't be suppressed, is a debatable question. Last
> but not least, it's not quite clear whether PostgreSQL core is the
> right place for implementing this functionality. For instance, one
> could argue that the log message should just contain sqlstate and be
> directed to |grep instead.
>
> I suspect this could be one of "there is no one size fits all"
> situations. The typical solution in such cases is to form a structure
> containing the log message and its attributes and submit this
> structure to a registered hook of a pluggable logging subsystem. This
> would be the most flexible approach. It will allow not only filtering
> the messages but also using binary logging, JSON logging, logging to
> external systems like Loki instead of a given text file, etc.
>
> I don't think we currently have this in the core, but maybe I just missed it.

The target would not primarily be installations where people configure
nifty logging software to filter logs (those people know how to deal
with log spam), but installations where people don't even know enough
to configure "shared_buffers".  So I'd like something that is part of
core and reduces spam without the user needing to configure anything.

I am somewhat worried that people will come up with all kinds of
justified but complicated wishes for such a feature:

- an option to choose whether to include or to exclude certain errors
- be able to configure that certain errors be logged on FATAL, but
  not on ERROR
- allow exception names in addition to SQL states
- have wildcards for exception names
- ...

I would like to write a simple patch that covers the basic functionality
I described, provided enough people find it useful.  That does not
exclude the option for future extensions for this feature.

Yours,
Laurenz Albe

On Wed, 2024-03-06 at 10:50 -0500, Greg Sabino Mullane wrote:
> On Tue, Mar 5, 2024 at 7:55 AM Laurenz Albe <laurenz.albe@cybertec.at> wrote:
> > My experience from the field is that a lot of log spam looks like
> >
> >   database/table/... "xy" does not exist
> >   duplicate key value violates unique constraint "xy"
>
> Forcibly hiding those at the Postgres level seems a heavy hammer for what is ultimately an application problem.

Yes... or no.  Lots of applications violate constraints routinely.
As long as the error is caught and handled, that's not a problem.

Whoever cares about the log messages can enable them.  My impression
is that most people don't care about them.

But thanks for your opinion.

Yours,
Laurenz Albe

On Wed, 2024-03-06 at 17:33 -0500, Isaac Morland wrote:
> I have two questions about this:
>
> First, can it be done per role? If I have a particular application which is
> constantly throwing some particular error, I might want to suppress it, but
> not suppress the same error occasionally coming from another application.
> I see ALTER DATABASE name SET configuration_parameter … as being useful here,
> but often multiple applications share a database.
>
> Second, where can this setting be adjusted? Can any session turn off logging
> of arbitrary sets of sqlstates resulting from its queries? It feels to me
> like that might allow security problems to be hidden. Specifically, the first
> thing an SQL injection might do would be to turn off logging of important
> error states, then proceed to try various nefarious things.

I was envisioning the parameter to be like other logging parameters, for
example "log_statement":  only superusers can set the parameter or GRANT
that privilege to others.  Also, a superuser could use ALTER ROLE to set
the parameter for all sessions by that role.

> It seems to me the above questions interact; an answer to the first might be
> "ALTER ROLE role_specification SET configuration_parameter", but I think that
> would allow roles to change their own settings, contrary to the concern
> raised by the second question.

If a superuser sets "log_statement" on a role, that role cannot undo or change
the setting.  That's just how I plan to implement the new parameter.

Yours,
Laurenz Albe

On Thu, 2024-03-07 at 08:30 +0100, Laurenz Albe wrote:
> On Wed, 2024-03-06 at 17:33 -0500, Isaac Morland wrote:
> > I have two questions about this:
> >
> > First, can it be done per role? If I have a particular application which is
> > constantly throwing some particular error, I might want to suppress it, but
> > not suppress the same error occasionally coming from another application.
> > I see ALTER DATABASE name SET configuration_parameter … as being useful here,
> > but often multiple applications share a database.
> >
> > Second, where can this setting be adjusted? Can any session turn off logging
> > of arbitrary sets of sqlstates resulting from its queries? It feels to me
> > like that might allow security problems to be hidden. Specifically, the first
> > thing an SQL injection might do would be to turn off logging of important
> > error states, then proceed to try various nefarious things.
>
> I was envisioning the parameter to be like other logging parameters, for
> example "log_statement":  only superusers can set the parameter or GRANT
> that privilege to others.  Also, a superuser could use ALTER ROLE to set
> the parameter for all sessions by that role.
>
> > It seems to me the above questions interact; an answer to the first might be
> > "ALTER ROLE role_specification SET configuration_parameter", but I think that
> > would allow roles to change their own settings, contrary to the concern
> > raised by the second question.
>
> If a superuser sets "log_statement" on a role, that role cannot undo or change
> the setting.  That's just how I plan to implement the new parameter.

Here is a patch that implements this.

I went with "log_suppress_errcodes", since the term "error code" is used
throughout our documentation.

The initial value is 23505,3D000,3F000,42601,42704,42883,42P01,57P03

Yours,
Laurenz Albe

On Sat, 2024-03-09 at 14:03 +0100, Laurenz Albe wrote:
> Here is a patch that implements this.

And here is patch v2 that fixes a bug and passes the regression tests.

Yours,
Laurenz Albe

-   the subscriber's server log.
+   the subscriber's server log if you remove <literal>23505</literal> from
+   <xref linkend="guc-log-suppress-errcodes"/>.

This seems like a pretty big regression. Being able to know why your
replication got closed seems pretty critical.

On Mon, 11 Mar 2024 at 03:44, Laurenz Albe <laurenz.albe@cybertec.at> wrote:
>
> On Sat, 2024-03-09 at 14:03 +0100, Laurenz Albe wrote:
> > Here is a patch that implements this.
>
> And here is patch v2 that fixes a bug and passes the regression tests.
>
> Yours,
> Laurenz Albe

On Mon, 2024-03-11 at 09:33 +0100, Jelte Fennema-Nio wrote:
> -   the subscriber's server log.
> +   the subscriber's server log if you remove <literal>23505</literal> from
> +   <xref linkend="guc-log-suppress-errcodes"/>.
>
> This seems like a pretty big regression. Being able to know why your
> replication got closed seems pretty critical.

The actual SQLSTATEs that get suppressed are subject to discussion
(an I have a gut feeling that some people will want the list empty).

As far as this specific functionality is concerned, I think that the
actual problem is a deficiency in PostgreSQL.  The problem is that
the log is the *only* place where you can get this information.  That
will be a problem for many people, even without "log_suppress_errcodes".

I think that this isformation should be available in some statistics
view.

Yours,
Laurenz Albe

On Mon, 2024-03-11 at 09:33 +0100, Jelte Fennema-Nio wrote:
> -   the subscriber's server log.
> +   the subscriber's server log if you remove <literal>23505</literal> from
> +   <xref linkend="guc-log-suppress-errcodes"/>.
>
> This seems like a pretty big regression. Being able to know why your
> replication got closed seems pretty critical.

Yes.  But I'd argue that that is a shortcoming of logical replication:
there should be a ways to get this information via SQL.  Having to look into
the log file is not a very useful option.

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

Yours,
Laurenz Albe

On Thu, 2 May 2024 at 12:47, Laurenz Albe <laurenz.albe@cybertec.at> wrote:
> Yes.  But I'd argue that that is a shortcoming of logical replication:
> there should be a ways to get this information via SQL.  Having to look into
> the log file is not a very useful option.

Definitely agreed that accessing the error details using SQL would be
much better. But having no way at all (by default) to find the cause
of the failure is clearly much worse.

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

Agreed. How about changing the patch so that the GUC is not applied to
logical replication apply workers (and document that accordingly). I
can think of two ways of achieving that (but there might be
other/better ones):
1. Set the GUC to empty string when an apply worker is started.
2. Change the newly added check in errcode() to only set
output_to_server to false when IsLogicalWorker() returns false.

On Thu, 2 May 2024 at 13:08, Jelte Fennema-Nio <postgres@jeltef.nl> wrote:
> 2. Change the newly added check in errcode() to only set
> output_to_server to false when IsLogicalWorker() returns false.

Actually a third, and probably even better solution would be to only
apply this new GUC to non-backgroundworker processes. That seems quite
reasonable, since often the only way to access background worker
errors is often through the logs.

On Thu, 2024-05-02 at 13:11 +0200, Jelte Fennema-Nio wrote:
> On Thu, 2 May 2024 at 13:08, Jelte Fennema-Nio <postgres@jeltef.nl> wrote:
> > 2. Change the newly added check in errcode() to only set
> > output_to_server to false when IsLogicalWorker() returns false.
>
> Actually a third, and probably even better solution would be to only
> apply this new GUC to non-backgroundworker processes. That seems quite
> reasonable, since often the only way to access background worker
> errors is often through the logs.

That is a good idea.  This version only suppresses error messages
in ordinary backend processes.

Yours,
Laurenz Albe

On Thu, May 02, 2024 at 12:47:45PM +0200, Laurenz Albe wrote:
> On Mon, 2024-03-11 at 09:33 +0100, Jelte Fennema-Nio wrote:
> > -   the subscriber's server log.
> > +   the subscriber's server log if you remove <literal>23505</literal> from
> > +   <xref linkend="guc-log-suppress-errcodes"/>.
> > 
> > This seems like a pretty big regression. Being able to know why your
> > replication got closed seems pretty critical.
> 
> Yes.  But I'd argue that that is a shortcoming of logical replication:
> there should be a ways to get this information via SQL.  Having to look into
> the log file is not a very useful option.
> 
> 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.

> @@ -6892,6 +6892,41 @@ local0.*    /var/log/postgresql
>        </listitem>
>       </varlistentry>
>  
> +     <varlistentry id="guc-log-suppress-errcodes" xreflabel="log_suppress_errcodes">
> +      <term><varname>log_suppress_errcodes</varname> (<type>string</type>)
> +      <indexterm>
> +       <primary><varname>log_suppress_errcodes</varname> configuration parameter</primary>
> +      </indexterm>
> +      </term>
> +      <listitem>
> +       <para>
> +        Causes <literal>ERROR</literal> and <literal>FATAL</literal> messages
> +        from client backend processes with certain error codes to be excluded
> +        from the log.
> +        The value is a comma-separated list of five-character error codes as
> +        listed in <xref linkend="errcodes-appendix"/>.  An error code that
> +        represents a class of errors (ends with three zeros) suppresses logging
> +        of all error codes within that class.  For example, the entry
> +        <literal>08000</literal> (<literal>connection_exception</literal>)
> +        would suppress an error with code <literal>08P01</literal>
> +        (<literal>protocol_violation</literal>).  The default setting is
> +        <literal>23505,3D000,3F000,42601,42704,42883,42P01,57P03</literal>.
> +        Only superusers and users with the appropriate <literal>SET</literal>
> +        privilege can change this setting.
> +       </para>

> +
> +       <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 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.

> +        {"log_suppress_errcodes", PGC_SUSET, LOGGING_WHEN,
> +            gettext_noop("ERROR and FATAL messages with these error codes don't get logged."),
> +            NULL,
> +            GUC_LIST_INPUT
> +        },
> +        &log_suppress_errcodes,
> +        DEFAULT_LOG_SUPPRESS_ERRCODES,
> +        check_log_suppress_errcodes, assign_log_suppress_errcodes, NULL

> +/*
> + * Default value for log_suppress_errcodes.  ERROR or FATAL messages with
> + * these error codes are never logged.  Error classes (error codes ending with
> + * three zeros) match all error codes in the class.   The idea is to suppress
> + * messages that usually don't indicate a serious problem but tend to pollute
> + * the log file.
> + */
> +
> +#define DEFAULT_LOG_SUPPRESS_ERRCODES "23505,3D000,3F000,42601,42704,42883,42P01,57P03"
> +

../src/backend/utils/errcodes.txt:23505    E    ERRCODE_UNIQUE_VIOLATION
unique_violation
../src/backend/utils/errcodes.txt:3D000    E    ERRCODE_INVALID_CATALOG_NAME
invalid_catalog_name
../src/backend/utils/errcodes.txt:3F000    E    ERRCODE_INVALID_SCHEMA_NAME
invalid_schema_name
../src/backend/utils/errcodes.txt:42601    E    ERRCODE_SYNTAX_ERROR
syntax_error
../src/backend/utils/errcodes.txt:3D000    E    ERRCODE_UNDEFINED_DATABASE
../src/backend/utils/errcodes.txt:42883    E    ERRCODE_UNDEFINED_FUNCTION
undefined_function
../src/backend/utils/errcodes.txt:3F000    E    ERRCODE_UNDEFINED_SCHEMA
../src/backend/utils/errcodes.txt:42P01    E    ERRCODE_UNDEFINED_TABLE
undefined_table
../src/backend/utils/errcodes.txt:42704    E    ERRCODE_UNDEFINED_OBJECT
undefined_object
../src/backend/utils/errcodes.txt:57P03    E    ERRCODE_CANNOT_CONNECT_NOW
cannot_connect_now

-- 
Justin

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