Обсуждение: 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
út 5. 3. 2024 v 13:55 odesílatel Laurenz Albe <laurenz.albe@cybertec.at> napsal:
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'
+1 in this form
the overhead of this implementation should be small
Regards
Pavel
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
Hi
út 5. 3. 2024 v 14:55 odesílatel Jim Jones <jim.jones@uni-muenster.de> napsal:
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
It can take code from PLpgSQL.
Regards
Pavel
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 Tue, 5 Mar 2024 at 07:55, Laurenz Albe <laurenz.albe@cybertec.at> 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.
I like the basic idea and the way of specifying states seems likely to cover a lot of typical use cases. Of course in principle the application should be fixed, but in practice we can't always control that.
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.
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.
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