Re: Patch review for logging hooks (CF 2012-01)

Hi,

Here's my review for the "logging hooks" patch queued for the 2012-01
CommitFest by Martin Pihlak.

Submission review
----
The patch is in context diff format and applies fine. Tests are not
included and don't seem practical for this patch.

More documentation would always be nice, but as other hooks aren't
documented either, it seems that's acceptable. The function prototype
and ErrorData structure are largely self-documenting.

Usability review
----
> Do we want that?
> Do we already have it?

The patch aims to allow custom processing of log messages. There are
two slightly overlapping features already in Postgres: csvlog and
syslog. Both seem to have their drawbacks; csvlog is written to disk
first, and has to be processed in the background in batches. Syslog is
pretty universal, but the output format is more limited, and details
of a single report are split up into several lines. Also passing extra
data for parsing via log_line_prefix seems hacky and failure prone.

The proposal also allows more flexible filtering/instrumentation of
log messages, which is not available with current methods.

> Does the patch actually implement that?

The hooked EmitErrorReport function is responsible for calling other
log handlers, so all relevant logging and context information is
available.

> Does it follow SQL spec, or the community-agreed behavior?

So far, a few people have stated that this sort of a logging hook is
desirable. Nobody has opposed it so far.

Feature test
----
I tested the hook using Martin's own pg_logforward extension:
https://github.com/mpihlak/pg_logforward

I verified that the hook works for messages with DEBUG, LOG, NOTICE,
ERROR and FATAL levels, from the backend as well as postmaster.

> Are there corner cases the author has failed to consider?

Whether the hook is called depends on both the 'client_min_messages'
and 'log_min_messages' settings because of this optimization in
errstart:
/* Skip processing effort if non-error message will not be output */
if (elevel < ERROR && !output_to_server && !output_to_client)
return false;

This will certainly be surprising to users. I think making it depend
*only* on output_to_server (and thus log_min_messages) would be more
predictable.

Coding review
----
> Does it follow the project coding guidelines?

There's a minor whitespace problem. When declaring variables, and the
data type is longer than 12 characters, just use 1 single space
character to delimit the variable name, instead of tab:

extern emit_log_hook_type emit_log_hook;

> Will it work on Windows/BSD etc?

I see that other hooks are declared with PGDLLIMPORT. I presume that
this is necessary on Windows:
extern PGDLLIMPORT emit_log_hook_type emit_log_hook;

> Are the comments sufficient and accurate?

I think the hook warrants a comment that, whether the messages will be
seen, depends on the log_min_messages setting.

----

PS: This is my first patch review ever, any feedback would be welcome.

Regards,
Marti

On 01/17/2012 07:35 PM, Marti Raudsepp wrote:
> Here's my review for the "logging hooks" patch queued for the 2012-01
> CommitFest by Martin Pihlak.
>

Thanks for reviewing!

> There's a minor whitespace problem. When declaring variables, and the
> data type is longer than 12 characters, just use 1 single space
> character to delimit the variable name, instead of tab:
>

Fixed both in .h and .c

> I see that other hooks are declared with PGDLLIMPORT. I presume that
> this is necessary on Windows:
> extern PGDLLIMPORT emit_log_hook_type emit_log_hook;

Indeed, fixed now.

> I think the hook warrants a comment that, whether the messages will be
> seen, depends on the log_min_messages setting.
>

Comment added.

regards,
Martin

Hi!

On Tue, Jan 17, 2012 at 23:07, Martin Pihlak <martin(dot)pihlak(at)gmail(dot)com> wrote:
>> I think the hook warrants a comment that, whether the messages will be
>> seen, depends on the log_min_messages setting.
>
> Comment added.

Nice :)

It seems you missed a comment, that the current implementation is also
affected by client_min_messages. I think that being affected by
client-specific settings is surprising. I would put the
if(emit_log_hook) inside the existing if(edata->output_to_server)
condition. Unless you have some reason to do it this way?

Regards,
Marti

On Wed, Jan 18, 2012 at 2:35 AM, Marti Raudsepp <marti(at)juffo(dot)org> wrote:
>> Are there corner cases the author has failed to consider?

The hook can be executed by various processes since it's in
EmitErrorReport(). OTOH, log messages are written to the log
file by one process like syslogger (if you use csvlog or stderr)
or syslog process (if you use syslog). So ISTM that there is no
guarantee that the order of log messages processed by the
hook is same as that of messages written to the log file. For
example, imagine the case where two backends call EmitErrorReport()
at the same time. Is this OK? If not, the hook might need to be
in syslogger.

EmitErrorReport() can be called before shared library like Martin's
pg_logforward is preloaded. Which means that the hook may miss
some log messages. Is this OK?

Regards,

--
Fujii Masao
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

On 01/18/2012 03:56 AM, Fujii Masao wrote:
> or syslog process (if you use syslog). So ISTM that there is no
> guarantee that the order of log messages processed by the
> hook is same as that of messages written to the log file. For
> example, imagine the case where two backends call EmitErrorReport()
> at the same time. Is this OK? If not, the hook might need to be
> in syslogger.

For high volume logging I'd avoid going through the syslogger. One
big issue with syslogger is that it creates a choke point - everything
has to pass through it, and if it cannot keep up it starts stalling
the backends. Also, in EmitErrorReport the hook gets to have access
to the actual ErrorData structure -- that makes filtering and looking
at message content much simpler.

> EmitErrorReport() can be called before shared library like Martin's
> pg_logforward is preloaded. Which means that the hook may miss
> some log messages. Is this OK?
>

True, even though the shared or local preload libraries are loaded
quite early in PostmasterMain/PostgresMain there is a chance that
some messages (mostly initialization failures) are missed. I guess
there is no way to avoid this with module based approach. But IMHO
this is acceptable -- when the backend fails to initialise, it cannot
be assumed that the logging subsystem is set up properly. I guess it
deserves at least a comment though. Thanks for pointing this out.

regards,
Martin

On 01/18/2012 11:12 AM, Martin Pihlak wrote:
> On 01/18/2012 03:56 AM, Fujii Masao wrote:
>> or syslog process (if you use syslog). So ISTM that there is no
>> guarantee that the order of log messages processed by the
>> hook is same as that of messages written to the log file. For
>> example, imagine the case where two backends call EmitErrorReport()
>> at the same time. Is this OK? If not, the hook might need to be
>> in syslogger.
> For high volume logging I'd avoid going through the syslogger. One
> big issue with syslogger is that it creates a choke point - everything
> has to pass through it, and if it cannot keep up it starts stalling
> the backends. Also, in EmitErrorReport the hook gets to have access
> to the actual ErrorData structure -- that makes filtering and looking
> at message content much simpler.
>
>

Hmm, interesting. I don't think I've encountered a situation where
backends would actually stall. But in any case, I don't think we have to
be that deterministic. The only thing that needs to be absolutely
guaranteed is that the log messages from a given backend are in order.
Some slight fuzz between backends seems acceptable.

cheers

andrew

Excerpts from Andrew Dunstan's message of mié ene 18 13:27:40 -0300 2012:
>
> On 01/18/2012 11:12 AM, Martin Pihlak wrote:
> > On 01/18/2012 03:56 AM, Fujii Masao wrote:
> >> or syslog process (if you use syslog). So ISTM that there is no
> >> guarantee that the order of log messages processed by the
> >> hook is same as that of messages written to the log file. For
> >> example, imagine the case where two backends call EmitErrorReport()
> >> at the same time. Is this OK? If not, the hook might need to be
> >> in syslogger.
> > For high volume logging I'd avoid going through the syslogger. One
> > big issue with syslogger is that it creates a choke point - everything
> > has to pass through it, and if it cannot keep up it starts stalling
> > the backends. Also, in EmitErrorReport the hook gets to have access
> > to the actual ErrorData structure -- that makes filtering and looking
> > at message content much simpler.
>
> Hmm, interesting. I don't think I've encountered a situation where
> backends would actually stall.

You have to have really high velocity for this to happen. At least one
customer of ours has suffered this problem (I vaguely recall a second
case but I'm not really sure), having had to switch to syslog (which
uses lossy sockets, with the advantage that it doesn't cause stalls).

> But in any case, I don't think we have to
> be that deterministic. The only thing that needs to be absolutely
> guaranteed is that the log messages from a given backend are in order.
> Some slight fuzz between backends seems acceptable.

Agreed.

--
Álvaro Herrera <alvherre(at)commandprompt(dot)com>
The PostgreSQL Company - Command Prompt, Inc.
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

On 01/17/2012 11:40 PM, Marti Raudsepp wrote:
> It seems you missed a comment, that the current implementation is also
> affected by client_min_messages. I think that being affected by
> client-specific settings is surprising. I would put the
> if(emit_log_hook) inside the existing if(edata->output_to_server)
> condition. Unless you have some reason to do it this way?
>

I have no strong feelings about this -- if the behaviour seems
surprising, lets remove it. We need to keep the "if" separate
though -- the hook might want to omit the message from server
log so the "output_to_server" needs to be rechecked.

Updated patch attached.

regards,
Martin

On Wed, Jan 18, 2012 at 22:56, Martin Pihlak <martin(dot)pihlak(at)gmail(dot)com> wrote:
> We need to keep the "if" separate
> though -- the hook might want to omit the message from server
> log so the "output_to_server" needs to be rechecked.

Oh, yes makes sense.

The updated patch looks good, marking as 'Ready for Committer'

Regards,
Marti

On 01/18/2012 04:23 PM, Marti Raudsepp wrote:
> The updated patch looks good, marking as 'Ready for Committer'

Patches without documentation are never ready for commit. For this one,
I'm not sure if that should be in the form of a reference example in
contrib, or just something that documents that the hook exists and what
the ground rules are for grabbing it.

--
Greg Smith 2ndQuadrant US greg(at)2ndQuadrant(dot)com Baltimore, MD
PostgreSQL Training, Services, and 24x7 Support www.2ndQuadrant.com

On Fri, Jan 20, 2012 at 2:47 AM, Greg Smith <greg(at)2ndquadrant(dot)com> wrote:
>> The updated patch looks good, marking as 'Ready for Committer'
>
> Patches without documentation are never ready for commit.  For this one, I'm
> not sure if that should be in the form of a reference example in contrib, or
> just something that documents that the hook exists and what the ground rules
> are for grabbing it.

Hooks are frequently not documented, and we only sometimes even bother
to include an example in contrib. We should probably at least have a
working example for testing purposes, though, whether or not we end up
committing it.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On Fri, Jan 20, 2012 at 17:01, Robert Haas <robertmhaas(at)gmail(dot)com> wrote:
> We should probably at least have a
> working example for testing purposes, though, whether or not we end up
> committing it.

Martin Pihlak sent a short description of how to test the patch with
his pg_logforward module:
http://archives.postgresql.org/pgsql-hackers/2012-01/msg00790.php

That's what I used when reviewing, too.

Regards,
Marti

On 01/20/2012 10:01 AM, Robert Haas wrote:
> On Fri, Jan 20, 2012 at 2:47 AM, Greg Smith<greg(at)2ndquadrant(dot)com> wrote:
>>> The updated patch looks good, marking as 'Ready for Committer'
>> Patches without documentation are never ready for commit. For this one, I'm
>> not sure if that should be in the form of a reference example in contrib, or
>> just something that documents that the hook exists and what the ground rules
>> are for grabbing it.
> Hooks are frequently not documented, and we only sometimes even bother
> to include an example in contrib. We should probably at least have a
> working example for testing purposes, though, whether or not we end up
> committing it.
>

I'm just looking at this patch, and I agree, it should be testable. I'm
wondering if it wouldn't be a good idea to have a module or set of
modules for demonstrating and testing bits of the API that we expose.
src/test/api or something similar? I'm not sure how we'd automate a test
for this case, though. I guess we could use something like pg_logforward
and have a UDP receiver catch the messages and write them to a file.
Something like that should be possible to rig up in Perl. But all that
seems a lot of work at this stage of the game. So the question is do we
want to commit this patch without it?

cheers

andrew

On Sun, Mar 4, 2012 at 10:45 AM, Andrew Dunstan <andrew(at)dunslane(dot)net> wrote:
> I'm just looking at this patch, and I agree, it should be testable. I'm
> wondering if it wouldn't be a good idea to have a module or set of modules
> for demonstrating and testing bits of the API that we expose. src/test/api
> or something similar? I'm not sure how we'd automate a test for this case,
> though. I guess we could use something like pg_logforward and have a UDP
> receiver catch the messages and write them to a file. Something like that
> should be possible to rig up in Perl. But all that seems a lot of work at
> this stage of the game. So the question is do we want to commit this patch
> without it?

The latest version of this patch looks sound to me. We haven't
insisted on having even a sample application for every hook before,
let alone a regression test, so I don't think this patch needs one
either. Now, it might be fairly said that we ought to have regression
tests for a lot more things than we do right now, but that's basically
a limitation of our regression-testing environment which the author of
this patch shouldn't be obliged to fix.

So my vote is to go ahead and commit it.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> On Sun, Mar 4, 2012 at 10:45 AM, Andrew Dunstan <andrew(at)dunslane(dot)net> wrote:
>> I'm just looking at this patch, and I agree, it should be testable. I'm
>> wondering if it wouldn't be a good idea to have a module or set of modules
>> for demonstrating and testing bits of the API that we expose. src/test/api
>> or something similar? I'm not sure how we'd automate a test for this case,
>> though. I guess we could use something like pg_logforward and have a UDP
>> receiver catch the messages and write them to a file. Something like that
>> should be possible to rig up in Perl. But all that seems a lot of work at
>> this stage of the game. So the question is do we want to commit this patch
>> without it?

> The latest version of this patch looks sound to me. We haven't
> insisted on having even a sample application for every hook before,
> let alone a regression test, so I don't think this patch needs one
> either.

What we've generally asked for with hooks is a working sample usage of
the hook, just as a cross-check that something useful can be done with
it and you didn't overlook any obvious usability problems. I agree that
a regression test is often not practical, especially not if you're not
prepared to create a whole contrib module to provide a sample usage.

In the case at hand, ISTM there are some usability questions around
where/when the hook is called: in particular, if I'm reading it right,
the hook could not override a log_min_messages-based decision that a
given message is not to be emitted. Do we care? Also, if the hook
is meant to be able to change the data that gets logged, as seems to be
the case, do we care that it would also affect what gets sent to the
client?

I'd like to see a spec for exactly which fields of ErrorData the hook is
allowed to change, and some rationale.

regards, tom lane

On 03/05/2012 12:08 PM, Tom Lane wrote:
> Robert Haas<robertmhaas(at)gmail(dot)com> writes:
>> On Sun, Mar 4, 2012 at 10:45 AM, Andrew Dunstan<andrew(at)dunslane(dot)net> wrote:
>>> I'm just looking at this patch, and I agree, it should be testable. I'm
>>> wondering if it wouldn't be a good idea to have a module or set of modules
>>> for demonstrating and testing bits of the API that we expose. src/test/api
>>> or something similar? I'm not sure how we'd automate a test for this case,
>>> though. I guess we could use something like pg_logforward and have a UDP
>>> receiver catch the messages and write them to a file. Something like that
>>> should be possible to rig up in Perl. But all that seems a lot of work at
>>> this stage of the game. So the question is do we want to commit this patch
>>> without it?
>> The latest version of this patch looks sound to me. We haven't
>> insisted on having even a sample application for every hook before,
>> let alone a regression test, so I don't think this patch needs one
>> either.
> What we've generally asked for with hooks is a working sample usage of
> the hook, just as a cross-check that something useful can be done with
> it and you didn't overlook any obvious usability problems. I agree that
> a regression test is often not practical, especially not if you're not
> prepared to create a whole contrib module to provide a sample usage.
>
> In the case at hand, ISTM there are some usability questions around
> where/when the hook is called: in particular, if I'm reading it right,
> the hook could not override a log_min_messages-based decision that a
> given message is not to be emitted. Do we care?

That's what I understand too. We could relax that at some stage in the
future if we had a requirement, I guess.

> Also, if the hook
> is meant to be able to change the data that gets logged, as seems to be
> the case, do we care that it would also affect what gets sent to the
> client?
>
> I'd like to see a spec for exactly which fields of ErrorData the hook is
> allowed to change, and some rationale.
>
>

Good question. I'd somewhat be inclined to say that it should only be
able to change output_to_server and output_to_client, and possibly only
to change them from true to false (i.e. I'm not sure the hook should be
able to induce more verbose logging.) But maybe that's too restrictive.
I doubt we can enforce good behaviour, though, only state that if you
break things you get to keep all the pieces.

cheers

andrew

On Mon, Mar 5, 2012 at 12:50 PM, Andrew Dunstan <andrew(at)dunslane(dot)net> wrote:
>>> The latest version of this patch looks sound to me.  We haven't
>>> insisted on having even a sample application for every hook before,
>>> let alone a regression test, so I don't think this patch needs one
>>> either.
>>
>> What we've generally asked for with hooks is a working sample usage of
>> the hook, just as a cross-check that something useful can be done with
>> it and you didn't overlook any obvious usability problems.  I agree that
>> a regression test is often not practical, especially not if you're not
>> prepared to create a whole contrib module to provide a sample usage.
>>
>> In the case at hand, ISTM there are some usability questions around
>> where/when the hook is called: in particular, if I'm reading it right,
>> the hook could not override a log_min_messages-based decision that a
>> given message is not to be emitted.  Do we care?
>
> That's what I understand too. We could relax that at some stage in the
> future if we had a requirement, I guess.
>
>>   Also, if the hook
>> is meant to be able to change the data that gets logged, as seems to be
>> the case, do we care that it would also affect what gets sent to the
>> client?
>>
>> I'd like to see a spec for exactly which fields of ErrorData the hook is
>> allowed to change, and some rationale.
>
>
> Good question. I'd somewhat be inclined to say that it should only be able
> to change output_to_server and output_to_client, and possibly only to change
> them from true to false (i.e. I'm not sure the hook should be able to induce
> more verbose logging.) But maybe that's too restrictive. I doubt we can
> enforce good behaviour, though, only state that if you break things you get
> to keep all the pieces.

It sort of looks like it's intended to apply only to server output, so
I'd find it odd to say that it should be able to mess with
output_to_client.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> On Mon, Mar 5, 2012 at 12:50 PM, Andrew Dunstan <andrew(at)dunslane(dot)net> wrote:
>>> I'd like to see a spec for exactly which fields of ErrorData the hook is
>>> allowed to change, and some rationale.

>> Good question. I'd somewhat be inclined to say that it should only be able
>> to change output_to_server and output_to_client, and possibly only to change
>> them from true to false (i.e. I'm not sure the hook should be able to induce
>> more verbose logging.) But maybe that's too restrictive. I doubt we can
>> enforce good behaviour, though, only state that if you break things you get
>> to keep all the pieces.

The reason it can't sensibly expect to change them from off to on is
that control will never get here in the first place if they're both off.
That is a feature not a bug: the ereport mechanisms are designed to skip
most of the message-construction work for messages that are so low
priority that they're not going to get printed anywhere. If we wanted
the hook to be able to override that, it would have to be called from
errstart and it would then have much less information to work with.

> It sort of looks like it's intended to apply only to server output, so
> I'd find it odd to say that it should be able to mess with
> output_to_client.

OK, so let's document that the only supported change in ErrorData is to
turn output_to_server from on to off. I can see how that constitutes
a potential feature: the hook might be intended as a filter that allows
logging or not logging according to some rule not supported by the core
system. You'd have to ensure that log_min_messages is set low enough
for all desired messages to get generated in the first place, but then
the hook could control things beyond that. I can also imagine a hook
that's meant as some sort of aggregator, so that it would accumulate a
summary form of messages that it then told the core not to print.

regards, tom lane

Martin Pihlak <martin(dot)pihlak(at)gmail(dot)com> writes:
> Updated patch attached.

Applied with minor editorialization (mainly just improving the
comments).

regards, tom lane

On Tue, Mar 6, 2012 at 10:37 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Applied with minor editorialization (mainly just improving the
> comments).

Thanks and kudos to all the reviewers!

regards,
Martin