RE: [EXT] Re: log_min_messages = warning

> "Dirschel, Steve" <steve(dot)dirschel(at)thomsonreuters(dot)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 userid is unsurprising. But we're not a lot closer to being sure why it's different for the procedures' normal execution environment.

>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, which seems 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

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(at)shgroup02s:[15409]:ERROR: ***** raise ERROR test *****
2022-09-07 12:58:00 UTC:10.210.119.217(42434):postgres(at)shgroup02s:[15409]:CONTEXT: PL/pgSQL function part.test2() line 6 at RAISE
2022-09-07 12:58:00 UTC:10.210.119.217(42434):postgres(at)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