Re: [EXT] Re: log_min_messages = warning

Hi Steve,

I happened to see the pg_cron extensions these days, IMHO this is
not a bug, pg_cron has two kind of bg workers, one is the launcher
and the other is CronBackgroundWorker, the launcher is responsible
for scheduling the jobs, and CronBackgroundWorker is the real worker
doing the job.

See more comments inline.

On Wed, Sep 7, 2022 at 9:24 PM Dirschel, Steve
<steve.dirschel@thomsonreuters.com> wrote:
>
> > "Dirschel, Steve" <steve.dirschel@thomsonreuters.com> writes:
> >>  setdatabase | setrole |
                                              setconfig
 
>
> >> -------------+---------+----------------------------------------------
> >> -------------+---------+----------------------------------------------
> >> -------------+---------+----------------------------------------------
> >> -------------+---------+----------------------------------------------
> >> -------------+---------+--
> >> ----------------------------------------------------------------------------------------------------
> >>        16401 |       0 | {auto_explain.log_min_duration=-1}
> >>        16401 |      10 | {log_min_messages=panic}
> >>        16436 |       0 | {TimeZone=America/Chicago}
> >>            0 |      10 |
{TimeZone=utc,log_statement=all,log_min_error_statement=debug5,log_min_messages=panic,exit_on_error=0,statement_timeout=0,role=rdsadmin,auto_explain.log_min_duration=-1,temp_file_limit=
> >> -1,"search_path=pg_catalog,
> >> public",pg_hint_plan.enable_hint=off,default_transaction_read_only=off
> >> }
> >> (4 rows)
>
> >> If I login to the shgroup02s database as postgres user (using psql)
> >> and interactively call a procedure that cron calls which causes the
> >> RAISE NOTICE commands to be written to the log they do NOT get written
> >> to the log when I call the procedure.  The messages will be displayed
> >> on my screen but I don't see them getting written to the log.
>
> >You've evidently done "ALTER USER postgres SET log_min_messages=panic", so the lack of any messages under that
useridis unsurprising.  But we're not a lot closer to being sure why it's different for the procedures' normal
executionenvironment.
 
>
> >At this point it's hard to avoid the conclusion that those procedures'
> >session is changing the value itself.  (This is scary, because it implies that you're running those as superuser,
whichseems like a bad idea.) You might have to enable log_statement = all to verify that.
 
>
> >                       regards, tom lane
>
> I appreciate your feedback Tom.  To simplify this I created this procedure:
>
> create or replace procedure part.test1()
>  LANGUAGE plpgsql
>  AS $$
>  DECLARE
>
> BEGIN
>
> raise notice '***** raise notice test *****';
>
> END $$;
>
> If I call that through PSQL this is returned to my screen:
>
> shgroup02s=> call part.test1();
> NOTICE:  ***** raise notice test *****
> CALL
>
> And if I monitor the log file nothing is written to it.  But if I schedule that procedure through pg_cron:
>
> SELECT cron.schedule('Minute test', '* * * * *', 'call part.test1()');
>
> If I monitor the log file I see it writing this to the log-  it actually writes it out 2 times:
>
> 2022-09-07 12:54:33 UTC::@:[21535]:LOG: cron job 6: NOTICE: ***** raise notice test *****
> CONTEXT: PL/pgSQL function part.test1() line 6 at RAISE
> 2022-09-07 12:54:33 UTC::@:[21535]:LOG: cron job 6: NOTICE: ***** raise notice test *****
> CONTEXT: PL/pgSQL function part.test1() line 6 at RAISE
>
The above logs are printed by the launcher, it collects the result
from a finished job, and as we can
see, it's a *LOG* level log, the *NOTICE* here is just part of the message.

The bg worker doing the real job doesn't put any log into the logfile,
there is a
*cron.log_min_messages* which you can set to *NOTICE* in postgresql.conf,
and then you can see the *NOTICE* log in the logfile.

Another thing that should be make clear is, the *LOG* level seems always
get printed into the log file due to the logic of `is_log_level_output`:

```
static inline bool
is_log_level_output(int elevel, int log_min_level)
{
    if (elevel == LOG || elevel == LOG_SERVER_ONLY)
    {
        if (log_min_level == LOG || log_min_level <= ERROR)
        return true;
    }
```

You can also set *cron.log_min_messages* to *fatal* or *panic* to get rid of
the launcher's *LOG* level log.

> If I create another test procedure:
>
> create or replace procedure part.test2()
>  LANGUAGE plpgsql
>  AS $$
>  DECLARE
>
> BEGIN
>
> raise exception '***** raise ERROR test *****';
>
> END $$;
>
> When I execute that through PSQL this is returned:
>
> shgroup02s=> call part.test2();
> ERROR:  ***** raise ERROR test *****
>
> And in the log file I see this written:
>
> 2022-09-07 12:58:00 UTC:10.210.119.217(42434):postgres@shgroup02s:[15409]:ERROR: ***** raise ERROR test *****
> 2022-09-07 12:58:00 UTC:10.210.119.217(42434):postgres@shgroup02s:[15409]:CONTEXT: PL/pgSQL function part.test2()
line6 at RAISE
 
> 2022-09-07 12:58:00 UTC:10.210.119.217(42434):postgres@shgroup02s:[15409]:STATEMENT: call part.test2();
>
> So the raise exception gets written to the log file when I execute it through PSQL which I believe is expected.
>
> I believe this clearly points to an issue with pg_cron.  Would you agree?
>
> Regards
> Steve
>
>


-- 
Regards
Junwang Zhao