Thread: Unfiltered server logs routing via a new elog hook or existing emit_log_hook bypassing log_min_message check

Hi,

Currently the emit_log_hook gets called only for the log messages of
type <= log_min_message i.e when edata->output_to_server is true [1],
which means that I can't use an implementation of emit_log_hook to
just intercept, say, all DEBUGX messages without interrupting the
actual server logs flow and changing the log_min_message. The use case
is this, in production environments, say an issue is occuring every
time or sporadically, to figure out what the issue is or do root cause
analysis, I might need some of the DEBUGX messages (not all of course)
and I may not want to set log_min_message to DEBUGX as it might
overload the server logs (can lead to server out of disk crashes) or
writing to the postgres container console at a higher pace. If I had
postgres elog hook, say emit_unfiltered_log_hook [2], I can basically
write an external module (with a bunch of GUCs say log_level to route,
place to store the logs, even an option to filter logs based on text
say logs containing word 'replication', max disk space that these
routed logs would occupy etc.) implementing emit_unfiltered_log_hook
to just route the interested logs to a cheaper storage (for debugging
purposes), after analysis I can disable the external module and blow
away the routed logs.

In the production environments such a hook and extension will be super
useful IMO. Many times, we would have better debugged issues had there
been certain logs without disturbing the main flow of server logs. We
could've used the existing hook emit_log_hook but that breaks the
existing external modules implementing emit_log_hook, that's why a new
hook emit_unfiltered_log_hook.

Thoughts?

[1]
    if (edata->output_to_server && emit_log_hook)
        (*emit_log_hook) (edata);
[2]
   if (emit_unfiltered_log_hook)
      (*emit_unfiltered_log_hook) (edata);

Regards,
Bharath Rupireddy.

Hi,

On Mon, May 02, 2022 at 05:11:34PM +0530, Bharath Rupireddy wrote:
>
> Currently the emit_log_hook gets called only for the log messages of
> type <= log_min_message i.e when edata->output_to_server is true [1],
> which means that I can't use an implementation of emit_log_hook to
> just intercept, say, all DEBUGX messages without interrupting the
> actual server logs flow and changing the log_min_message.
> [...]
> If I had
> postgres elog hook, say emit_unfiltered_log_hook [2], I can basically
> write an external module (with a bunch of GUCs say log_level to route,
> place to store the logs, even an option to filter logs based on text
> say logs containing word 'replication', max disk space that these
> routed logs would occupy etc.) implementing emit_unfiltered_log_hook
> to just route the interested logs to a cheaper storage (for debugging
> purposes), after analysis I can disable the external module and blow
> away the routed logs.

Unless I'm missing something you can already do all of that with the current
hook, since as mentioned in the comment above the hook can disable the server's
logging:

     * Call hook before sending message to log.  The hook function is allowed
     * to turn off edata->output_to_server, so we must recheck that afterward.

So you can configure your server with a very verbose log_min_message, and have
the same setting in your own extension to disable output_to_server after its
own processing is done.

On Mon, May 2, 2022 at 6:32 PM Julien Rouhaud <rjuju123@gmail.com> wrote:
>
> Hi,
>
> On Mon, May 02, 2022 at 05:11:34PM +0530, Bharath Rupireddy wrote:
> >
> > Currently the emit_log_hook gets called only for the log messages of
> > type <= log_min_message i.e when edata->output_to_server is true [1],
> > which means that I can't use an implementation of emit_log_hook to
> > just intercept, say, all DEBUGX messages without interrupting the
> > actual server logs flow and changing the log_min_message.
> > [...]
> > If I had
> > postgres elog hook, say emit_unfiltered_log_hook [2], I can basically
> > write an external module (with a bunch of GUCs say log_level to route,
> > place to store the logs, even an option to filter logs based on text
> > say logs containing word 'replication', max disk space that these
> > routed logs would occupy etc.) implementing emit_unfiltered_log_hook
> > to just route the interested logs to a cheaper storage (for debugging
> > purposes), after analysis I can disable the external module and blow
> > away the routed logs.
>
> Unless I'm missing something you can already do all of that with the current
> hook, since as mentioned in the comment above the hook can disable the server's
> logging:
>
>          * Call hook before sending message to log.  The hook function is allowed
>          * to turn off edata->output_to_server, so we must recheck that afterward.
>
> So you can configure your server with a very verbose log_min_message, and have
> the same setting in your own extension to disable output_to_server after its
> own processing is done.

No. The emit_log_hook isn't called for all the log messages, but only
when output_to_server = true which means, say my log_min_messages is
'WARNING', the hook isn't called for the messages say elevel above it
(NOTICE, INFO, DEBUGX).

Regards,
Bharath Rupireddy.

On Mon, May 02, 2022 at 06:40:05PM +0530, Bharath Rupireddy wrote:
> On Mon, May 2, 2022 at 6:32 PM Julien Rouhaud <rjuju123@gmail.com> wrote:
> >
> > Unless I'm missing something you can already do all of that with the current
> > hook, since as mentioned in the comment above the hook can disable the server's
> > logging:
> >
> >          * Call hook before sending message to log.  The hook function is allowed
> >          * to turn off edata->output_to_server, so we must recheck that afterward.
> >
> > So you can configure your server with a very verbose log_min_message, and have
> > the same setting in your own extension to disable output_to_server after its
> > own processing is done.
> 
> No. The emit_log_hook isn't called for all the log messages, but only
> when output_to_server = true which means, say my log_min_messages is
> 'WARNING', the hook isn't called for the messages say elevel above it
> (NOTICE, INFO, DEBUGX).

I know.  What I said you could do is configure log_min_message to DEBUGX, so
your extension sees everything you want it to see.  And *in your extension* set
output_to_server to false if the level is not the *real level* you want to log.

On Mon, May 2, 2022 at 6:44 PM Julien Rouhaud <rjuju123@gmail.com> wrote:
>
> On Mon, May 02, 2022 at 06:40:05PM +0530, Bharath Rupireddy wrote:
> > On Mon, May 2, 2022 at 6:32 PM Julien Rouhaud <rjuju123@gmail.com> wrote:
> > >
> > > Unless I'm missing something you can already do all of that with the current
> > > hook, since as mentioned in the comment above the hook can disable the server's
> > > logging:
> > >
> > >          * Call hook before sending message to log.  The hook function is allowed
> > >          * to turn off edata->output_to_server, so we must recheck that afterward.
> > >
> > > So you can configure your server with a very verbose log_min_message, and have
> > > the same setting in your own extension to disable output_to_server after its
> > > own processing is done.
> >
> > No. The emit_log_hook isn't called for all the log messages, but only
> > when output_to_server = true which means, say my log_min_messages is
> > 'WARNING', the hook isn't called for the messages say elevel above it
> > (NOTICE, INFO, DEBUGX).
>
> I know.  What I said you could do is configure log_min_message to DEBUGX, so
> your extension sees everything you want it to see.  And *in your extension* set
> output_to_server to false if the level is not the *real level* you want to log.

I basically want to avoid normal users/developers setting any
parameter (especially the superuser-only log_min_message GUC, all
users might not have superuser access in production environments) or
making any changes to the running server except just LOADing the
server log routing/intercepting extension.

Regards,
Bharath Rupireddy.

On Mon, May 02, 2022 at 07:24:04PM +0530, Bharath Rupireddy wrote:
> On Mon, May 2, 2022 at 6:44 PM Julien Rouhaud <rjuju123@gmail.com> wrote:
> >
> > I know.  What I said you could do is configure log_min_message to DEBUGX, so
> > your extension sees everything you want it to see.  And *in your extension* set
> > output_to_server to false if the level is not the *real level* you want to log.
>
> I basically want to avoid normal users/developers setting any
> parameter (especially the superuser-only log_min_message GUC, all
> users might not have superuser access in production environments) or
> making any changes to the running server except just LOADing the
> server log routing/intercepting extension.

The kind of scenario you mentioned didn't seem "normal users" oriented.  Note
that LOAD is restricted to superuser anyway.

Julien Rouhaud <rjuju123@gmail.com> writes:
> On Mon, May 02, 2022 at 07:24:04PM +0530, Bharath Rupireddy wrote:
>> I basically want to avoid normal users/developers setting any
>> parameter (especially the superuser-only log_min_message GUC, all
>> users might not have superuser access in production environments) or
>> making any changes to the running server except just LOADing the
>> server log routing/intercepting extension.

> The kind of scenario you mentioned didn't seem "normal users" oriented.  Note
> that LOAD is restricted to superuser anyway.

It seems completely silly to be worrying that setting a GUC in a
particular way is too hard for somebody who's going to be installing
a loadable extension.  In any case, if you wanted to force the issue
you could set log_min_messages in the extension's _PG_init function.

            regards, tom lane

On Mon, May 2, 2022 at 7:37 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
>
> Julien Rouhaud <rjuju123@gmail.com> writes:
> > On Mon, May 02, 2022 at 07:24:04PM +0530, Bharath Rupireddy wrote:
> >> I basically want to avoid normal users/developers setting any
> >> parameter (especially the superuser-only log_min_message GUC, all
> >> users might not have superuser access in production environments) or
> >> making any changes to the running server except just LOADing the
> >> server log routing/intercepting extension.
>
> > The kind of scenario you mentioned didn't seem "normal users" oriented.  Note
> > that LOAD is restricted to superuser anyway.
>
> It seems completely silly to be worrying that setting a GUC in a
> particular way is too hard for somebody who's going to be installing
> a loadable extension.  In any case, if you wanted to force the issue
> you could set log_min_messages in the extension's _PG_init function.

Thanks Tom and Julien. I developed a simple external module called
pg_intercept_logs [1].

[1] https://github.com/BRupireddy/pg_intercept_server_logs

Regards,
Bharath Rupireddy.