Thread: [PATCH] Filter error log statements by sqlstate

Allow the default log_min_error_statement to be overridden per sqlstate
to make it possible to filter out some error types while maintaining a
low log_min_error_statement or enable logging for some error types when
the default is to not log anything.

I've tried to do something like this using rsyslog filters, but that's
pretty awkward and doesn't work at all when the statement is split to
multiple syslog messages.

https://github.com/saaros/postgres/compare/log-by-sqlstate

  src/backend/utils/error/elog.c | 183
++++++++++++++++++++++++++++++++++++++++-
  src/backend/utils/misc/guc.c   |  14 +++-
  src/include/utils/guc.h        |   4 +
  src/include/utils/guc_tables.h |   1 +
  4 files changed, 199 insertions(+), 3 deletions(-)

/ Oskari

Hi,

On 13/01/14 10:26, Jeevan Chalke wrote:
> 1. Documentation is missing and thus becomes difficult to understand what
> exactly you are trying to do. Or in other words, user will be uncertain
> about using it more efficiently.

I figured I'd write documentation for this if it looks like a useful 
feature which would be accepted for 9.4, but I guess it would've helped 
to have a bit better description of this for the initial submission as well.

> 2. Some more comments required. At each new function and specifically at
> get_sqlstate_error_level().

Just after I submitted the patch I noticed that I had a placeholder for 
comment about that function but never wrote the actual comment, sorry 
about that.

> 3. Please add test-case if possible.

Sure.

> 4. Some code part does not comply with PostgreSQL indentation style. (Can be
> ignored as it will pass through pg_indent, but better fix it).

I'll try to fix this for v2.

> 5. You have used ""XX000:warning," string to get maximum possible length of
> the valid sqlstate:level identifier. It's perfect, but small explanation
> about that will be good there. Also in future if we have any other error level
> which exceeds this, we need changes here too. Right ?

Good point, I'll address this in v2.

> I will look into this further. But please have your attention on above
> points.

Thanks for the review!

/ Oskari

> On Fri, Jan 10, 2014 at 12:56 AM, Oskari Saarenmaa <os@ohmu.fi>
> wrote:
> > Allow the default log_min_error_statement to be overridden per
> > sqlstate to make it possible to filter out some error types while
> > maintaining a low log_min_error_statement or enable logging for some
> > error types when the default is to not log anything.
> >
> > I've tried to do something like this using rsyslog filters, but
> > that's pretty awkward and doesn't work at all when the statement is
> > split to multiple syslog messages.
> >
> > https://github.com/saaros/postgres/compare/log-by-sqlstate

On Tue, Jan 14, 2014 at 12:22:30PM +0530, Jeevan Chalke wrote:
> On Mon, Jan 13, 2014 at 4:30 PM, Oskari Saarenmaa <os@ohmu.fi> wrote:
> > On 13/01/14 10:26, Jeevan Chalke wrote:
> >
> > > 1. Documentation is missing and thus becomes difficult to understand
> > > what exactly you are trying to do.  Or in other words, user will be
> > > uncertain about using it more efficiently.
> >
> > I figured I'd write documentation for this if it looks like a useful
> > feature which would be accepted for 9.4, but I guess it would've
> > helped to have a bit better description of this for the initial
> > submission as well.
> >
> >
> > > 2. Some more comments required. At each new function and
> > > specifically at get_sqlstate_error_level().
> >
> > Just after I submitted the patch I noticed that I had a placeholder
> > for comment about that function but never wrote the actual comment,
> > sorry about that.
> >
> > > 3. Please add test-case if possible.
> >
> > Sure.
> >
> > > 4. Some code part does not comply with PostgreSQL indentation style.
> > > (Can be ignored as it will pass through pg_indent, but better fix
> > > it).
> > >
> >
> > I'll try to fix this for v2.
> >
> > > 5. You have used ""XX000:warning," string to get maximum possible
> > > length of the valid sqlstate:level identifier.  It's perfect, but
> > > small explanation about that will be good there.  Also in future if
> > > we have any other error level which exceeds this, we need changes
> > > here too.  Right ?
> >
> > Good point, I'll address this in v2.
> >
> > > I will look into this further. But please have your attention on above
> > > points.
> >
> > Thanks for the review!
>
> Since you are taking care of most of the points above. I will wait for v2
> patch. Till then marking "Waiting on Author".

Attached v2 of the patch which addresses the above points.  I couldn't
figure out how to test log output, but at least the patch now tests that
it can set and show the log level.

Thanks,
Oskari

Oskari Saarenmaa <os@ohmu.fi> writes:
> [ 0001-Filter-error-log-statements-by-sqlstate.patch ]

I looked at this patch.  It took me some time to understand that what
it actually does has got approximately nothing to do with what one might
first expect: rather than suppressing the entire log message about some
error, it only suppresses printing of the triggering SQL statement
(if that's available to begin with).  The proposed documentation is
certainly not clear enough on that point, and the API which appears to
allow changing the error severity level associated with a SQLSTATE isn't
exactly helping to clarify things either.

Also, the patch claims it allows logging of statements that otherwise
wouldn't get logged, but AFAICS that's wrong, because we'll never get to
this code at all if errstart decides we're not going to log the message.

I find it hard to follow exactly what the use-case for this is; could
you make a defense of why we should carry a feature like this?

In any case, I'm finding it hard to believe that filtering by individual
SQLSTATEs is a practical API.  When we've discussed providing better log
filtering in the past, that approach was invariably dismissed on the
grounds that it would be far too unwieldy to use --- any DBA attempting to
use it in anger would end up with a huge and ever-incomplete list of
SQLSTATEs he'd need to filter.  A long time ago I suggested that filtering
by SQLSTATE class (the first two characters of SQLSTATE) might be useful,
but I'm not sure I still believe that, and anyway it's not what's
implemented here.

I'm concerned also about the potential performance impact of this patch,
if used with a SQLSTATE list as long as I think they're likely to get in
practice.  Have you done any performance testing?

As far as the code goes, bit manipulations on uint64s are a pretty crummy
substitute for defining a struct with a couple of fields; and the way
you're choosing to sort the array seems mighty inefficient, as well as
probably wrong in detail (why is the loop ignoring the first array
element?); and rather than make fragile assumptions about the maximum
length of an elevel name, why not just leave the user's string as-is?
But I wouldn't advise worrying about code style issues until we decide if
we're accepting the feature.  Right now my inclination is to reject it.
        regards, tom lane

Please fix the compiler warning:

elog.c: In function ‘check_log_sqlstate_error’:
elog.c:3789:41: warning: ‘new_newval_end’ may be used uninitialized in
this function [-Wuninitialized]

17.01.2014 00:13, Tom Lane kirjoitti:
> Oskari Saarenmaa <os@ohmu.fi> writes:
>> [ 0001-Filter-error-log-statements-by-sqlstate.patch ]
>
> I looked at this patch.  It took me some time to understand that what
> it actually does has got approximately nothing to do with what one might
> first expect: rather than suppressing the entire log message about some
> error, it only suppresses printing of the triggering SQL statement
> (if that's available to begin with).  The proposed documentation is
> certainly not clear enough on that point, and the API which appears to
> allow changing the error severity level associated with a SQLSTATE isn't
> exactly helping to clarify things either.
>
> Also, the patch claims it allows logging of statements that otherwise
> wouldn't get logged, but AFAICS that's wrong, because we'll never get to
> this code at all if errstart decides we're not going to log the message.

I agree the documentation (and perhaps the feature itself) are a bit 
confusing, but the idea is to control SQL statement logging when errors 
occur.  This patch doesn't do anything about normal error logging, it 
only controls when the statements are printed.

Running:
  set log_min_messages = 'warning';
  set log_min_error_statement = 'panic';  set log_sqlstate_error_statement = '';  do 'begin raise exception ''foobar
1'';end';
 
  set log_sqlstate_error_statement = 'P0001:error';  do 'begin raise exception ''foobar 2''; end';
  set log_min_error_statement = 'error';  set log_sqlstate_error_statement = 'P0001:panic';  do 'begin raise exception
''foobar3''; end';
 

logs
  2014-01-17 00:37:12 EET ERROR:  foobar 1  2014-01-17 00:37:20 EET ERROR:  foobar 2  2014-01-17 00:37:20 EET
STATEMENT: do 'begin raise exception 
 
''foobar 2''; end';  2014-01-17 00:38:34 EET ERROR:  foobar 3

> I find it hard to follow exactly what the use-case for this is; could
> you make a defense of why we should carry a feature like this?

I usually run PG with log_min_messages = warning and 
log_min_error_statement = error to log any unexpected errors.  But as I 
have a lot of check constraints in my database as well as a lot of 
plpgsql and plpython code which raises exceptions on invalid user input 
I also get tons of logs for statements causing "expected" errors which I 
have to try to filter out with other tools.

> In any case, I'm finding it hard to believe that filtering by individual
> SQLSTATEs is a practical API.  When we've discussed providing better log
> filtering in the past, that approach was invariably dismissed on the
> grounds that it would be far too unwieldy to use --- any DBA attempting to
> use it in anger would end up with a huge and ever-incomplete list of
> SQLSTATEs he'd need to filter.  A long time ago I suggested that filtering
> by SQLSTATE class (the first two characters of SQLSTATE) might be useful,
> but I'm not sure I still believe that, and anyway it's not what's
> implemented here.

I don't know about others, but filtering by individual SQLSTATE is 
exactly what I need - I don't want to suppress all plpgsql errors or 
constraint violations, but I may want to suppress plpgsql RAISE 
EXCEPTION and CHECK violations.

> I'm concerned also about the potential performance impact of this patch,
> if used with a SQLSTATE list as long as I think they're likely to get in
> practice.  Have you done any performance testing?

Not yet.  As this only applies to statement logging (for now at least) I 
doubt it's a big deal, formatting and writing the statement somewhere is 
probably at least as expensive as looking up the configuration.

> As far as the code goes, bit manipulations on uint64s are a pretty crummy
> substitute for defining a struct with a couple of fields; and the way
> you're choosing to sort the array seems mighty inefficient, as well as
> probably wrong in detail (why is the loop ignoring the first array
> element?); and rather than make fragile assumptions about the maximum
> length of an elevel name, why not just leave the user's string as-is?
> But I wouldn't advise worrying about code style issues until we decide if
> we're accepting the feature.  Right now my inclination is to reject it.

I agree, I should've just defined a struct and used the original string 
length when rewriting user string (it's rewritten to drop any 
duplicates.)  I don't think the sort is a big deal, it's only done when 
the value is defined; the first array element is the length of the 
array.  I can address these points in a new version of this patch if the 
feature looks useful.

Thanks for the review! Oskari

Oskari Saarenmaa <os@ohmu.fi> writes:
> 17.01.2014 00:13, Tom Lane kirjoitti:
>> I find it hard to follow exactly what the use-case for this is; could
>> you make a defense of why we should carry a feature like this?

> I usually run PG with log_min_messages = warning and 
> log_min_error_statement = error to log any unexpected errors.  But as I 
> have a lot of check constraints in my database as well as a lot of 
> plpgsql and plpython code which raises exceptions on invalid user input 
> I also get tons of logs for statements causing "expected" errors which I 
> have to try to filter out with other tools.

But if the goal is to reduce clutter in your log, wouldn't you wish
to suppress the *entire* log entry for "expected" errors, not just the
SQL-statement field?  Certainly all the previous discussion about this
type of feature (and there has been plenty) has presumed that you'd want
to suppress whole entries.

>> In any case, I'm finding it hard to believe that filtering by individual
>> SQLSTATEs is a practical API.

> I don't know about others, but filtering by individual SQLSTATE is 
> exactly what I need - I don't want to suppress all plpgsql errors or 
> constraint violations, but I may want to suppress plpgsql RAISE 
> EXCEPTION and CHECK violations.

Meh.  Again, there's been lots of prior discussion, and I think there's
consensus that a filtering API based solely on a list of SQLSTATEs
wouldn't be widely adequate.  The most recent discussion I can find
about this is in this thread:


http://www.postgresql.org/message-id/flat/20131205204512.GD6777@eldon.alvh.no-ip.org#20131205204512.GD6777@eldon.alvh.no-ip.org

That thread references an older one

http://www.postgresql.org/message-id/flat/19791.1335902957@sss.pgh.pa.us#19791.1335902957@sss.pgh.pa.us

and I'm pretty sure that there are several others you could find with
a bit of digging.  The more ambitious proposals required decorating
ereport calls with a new kind of severity labeling, reflecting how
likely it'd be that DBAs would want to read about the particular
error in their logs.  That's be a lot of work though, and would require
us to make a lot of value judgements that might be wrong.  The main
alternative that was discussed was to filter on the basis of SQLSTATE
classes, and maybe relocate a few specific ERRCODEs to different classes
if it seemed that they were a lot unlike other things in their class.

It hasn't really been proven that SQLSTATE-class filtering would work
conveniently, but AFAICS the only way to prove or disprove that is for
somebody to code it up and use it in production.

What I'd suggest is that you revise this patch so that it can handle
filtering on the basis of either individual SQLSTATEs or whole classes,
the former being able to override the latter.  With a bit of wholesale
notation invention, an example could be

log_sqlstates = 'P0,!P0001,!42,42P05'

which would mean "log all messages in class P0, except don't log P0001;
don't log anything in class 42, except always log 42P05; for everything
else, log according to log_min_messages".

If you don't like that notation, feel free to propose another.  I did
not like the one you had to start with, though, because it looked like
it was actually changing the error severity level, not just the log or
don't log decision.

BTW, I'd suggest that this filtering only happen for messages < PANIC
level; it's pretty hard to believe that anybody would ever want to
suppress a PANIC report.

Another thought here is that if you're willing to have the filter
only able to *prevent* logging, and not to let it *cause* logging
of messages that would otherwise be suppressed by log_min_messages,
it could be implemented as a loadable module using the emit_log_hook.
An experimental feature, which is what this really is, is always a lot
easier sell in that format since anybody who finds it useless needn't
pay the overhead (which I'm still concerned about ...).  But I'm not
sure how important it might be to be able to upgrade a message's log
priority, so maybe that approach would be significantly less usable.
        regards, tom lane

30.01.2014 11:37, Jeevan Chalke kirjoitti:
> Hi Oskari,
>
> Are you planning to work on what Tom has suggested ? It make sense to me
> as well.
>
> What are your views on that ?

Tom's suggestions make sense to me, but unfortunately I haven't had time 
to work on this feature recently so I don't think it'll make it to 9.4 
unless I can complete it during FOSDEM.

I updated https://github.com/saaros/postgres/tree/log-by-sqlstate some 
time ago based on Tom's first set of comments but the tree is still 
missing changes suggested in the last email.

/ Oskari

17.01.2014 19:07, Tom Lane kirjoitti:
> Oskari Saarenmaa <os@ohmu.fi> writes:
>> I don't know about others, but filtering by individual SQLSTATE is
>> exactly what I need - I don't want to suppress all plpgsql errors or
>> constraint violations, but I may want to suppress plpgsql RAISE
>> EXCEPTION and CHECK violations.

[...]

> It hasn't really been proven that SQLSTATE-class filtering would work
> conveniently, but AFAICS the only way to prove or disprove that is for
> somebody to code it up and use it in production.

[...]

> Another thought here is that if you're willing to have the filter
> only able to *prevent* logging, and not to let it *cause* logging
> of messages that would otherwise be suppressed by log_min_messages,
> it could be implemented as a loadable module using the emit_log_hook.

So this is what we ended up doing: a module with emit_log_hook to allow 
upgrading "log_min_messages" and "log_min_error_statement" values per 
sqlstate.  I'm now using this in production and it has had a positive 
impact in reducing the volume of (unwanted) logs being collected and 
allowing a kludgy rsyslog.conf filter to be removed (which didn't really 
work that well - it only dropped the first part of a multipart log 
entry, writing partial pg log entries in syslog).

https://github.com/ohmu/pgloggingfilter

I'm not super happy about the syntax it uses, but at least it should be 
obvious that it works just like the core GUCs but is settable per 
sqlstate.  I've been planning to sketch a proposal for a better way to 
configure log verbosity and details based on sqlstate, statement 
duration or other variables, but unfortunately haven't had time to do it 
yet.

/ Oskari