Обсуждение: log_min_messages = warning
We recently upgraded from postgres 12.8 to 14.3. We are running Aurora Postgres on AWS.
We have procedures that will make calls to RAISE NOTICE to write out messages if you interactively call the procedure through psql. These procedures are getting called by pg_cron.
Since upgrading these RAISE NOTICE messages are getting written to the postgres log file:
For example:
13:45:00.720882-05
CONTEXT: PL/pgSQL function perf.snap_stats() line 242 at RAISE
2022-09-06 18:45:01 UTC::@:[21535]:LOG: cron job 2: NOTICE: Snapping dba_hist_system_event at 2022-09-06 13:45:00.725818-05
Log_min_messages is set to warning so my understanding is that should only log messages at warning, error, log, fatal, or panic. Any idea how to troubleshoot why these are getting written to the log file?
Thanks
On 9/6/22 12:07, Dirschel, Steve wrote: > We recently upgraded from postgres 12.8 to 14.3. We are running Aurora > Postgres on AWS. > > We have procedures that will make calls to RAISE NOTICE to write out > messages if you interactively call the procedure through psql. These > procedures are getting called by pg_cron. > > Since upgrading these RAISE NOTICE messages are getting written to the > postgres log file: > > For example: > > 13:45:00.720882-05 > > CONTEXT: PL/pgSQL function perf.snap_stats() line 242 at RAISE > > 2022-09-06 18:45:01 UTC::@:[21535]:LOG: cron job 2: NOTICE: Snapping > dba_hist_system_event at 2022-09-06 13:45:00.725818-05 > > Log_min_messages is set to warning so my understanding is that should > only log messages at warning, error, log, fatal, or panic. Any idea how > to troubleshoot why these are getting written to the log file? 1) Has log_min_messages been commented out? 2) Was the setting changed from something else? 3) If 2) was the server reloaded/restarted to catch the change? 4) Are you sure you are looking at the correct setting? Try: select setting, source, sourcefile, pending_restart from pg_settings where name = 'log_min_messages'; to see if the value is coming from something like an include file. > > Thanks > > This e-mail is for the sole use of the intended recipient and contains > information that may be privileged and/or confidential. If you are not > an intended recipient, please notify the sender by return e-mail and > delete this e-mail and any attachments. Certain required legal entity > disclosures can be accessed on our website: > https://www.thomsonreuters.com/en/resources/disclosures.html -- Adrian Klaver adrian.klaver@aklaver.com
>On 9/6/22 12:07, Dirschel, Steve wrote: >> We recently upgraded from postgres 12.8 to 14.3. We are running >> Aurora Postgres on AWS. >> >> We have procedures that will make calls to RAISE NOTICE to write out >> messages if you interactively call the procedure through psql. These >> procedures are getting called by pg_cron. >> >> Since upgrading these RAISE NOTICE messages are getting written to the >> postgres log file: >> >> For example: >> >> 13:45:00.720882-05 >> >> CONTEXT: PL/pgSQL function perf.snap_stats() line 242 at RAISE >> >> 2022-09-06 18:45:01 UTC::@:[21535]:LOG: cron job 2: NOTICE: Snapping >> dba_hist_system_event at 2022-09-06 13:45:00.725818-05 >> >> Log_min_messages is set to warning so my understanding is that should >> only log messages at warning, error, log, fatal, or panic. Any idea >> how to troubleshoot why these are getting written to the log file? > > >1) Has log_min_messages been commented out? > >2) Was the setting changed from something else? > >3) If 2) was the server reloaded/restarted to catch the change? > >4) Are you sure you are looking at the correct setting? > >Try: > >select setting, source, sourcefile, pending_restart from pg_settings where name = 'log_min_messages'; > >to see if the value is coming from something like an include file. > >> >> Thanks >> >>This e-mail is for the sole use of the intended recipient and contains >> information that may be privileged and/or confidential. If you are not >> an intended recipient, please notify the sender by return e-mail and >> delete this e-mail and any attachments. Certain required legal entity >> disclosures can be accessed on our website: >> https://www.thomsonreuters.com/en/resources/disclosures.html >> > >-- >Adrian Klaver >adrian.klaver@aklaver.com shgroup02s=> select setting, source, sourcefile, pending_restart from pg_settings where name = 'log_min_messages'; setting | source | sourcefile | pending_restart ---------+---------+------------+----------------- warning | default | | f (1 row) Regards Steve
"Dirschel, Steve" <steve.dirschel@thomsonreuters.com> writes:
>>> We recently upgraded from postgres 12.8 to 14.3. We are running
>>> Aurora Postgres on AWS.
Aurora Postgres != Postgres. This doesn't seem like something they'd
change, but we can't rule that out entirely.
>> Try:
>> select setting, source, sourcefile, pending_restart from pg_settings where name = 'log_min_messages';
> shgroup02s=> select setting, source, sourcefile, pending_restart from pg_settings where name = 'log_min_messages';
> setting | source | sourcefile | pending_restart
> ---------+---------+------------+-----------------
> warning | default | | f
> (1 row)
OK, so log_min_messages has the expected value in your interactive
session, and yet evidently not in the sessions running these RAISE NOTICE
commands. Maybe you have done ALTER USER SET or ALTER DATABASE SET
commands that'd change it in those sessions? You could look in
the pg_db_role_setting catalog to answer that definitively.
regards, tom lane
>>>> We recently upgraded from postgres 12.8 to 14.3. We are running
>>>> Aurora Postgres on AWS.
>Aurora Postgres != Postgres. This doesn't seem like something they'd change, but we can't rule that out entirely.
>>> Try:
>>> select setting, source, sourcefile, pending_restart from pg_settings
>>> where name = 'log_min_messages';
>> shgroup02s=> select setting, source, sourcefile, pending_restart from
>> pg_settings where name = 'log_min_messages'; setting | source |
>> sourcefile | pending_restart
>> ---------+---------+------------+-----------------
>> warning | default | | f
>> (1 row)
>OK, so log_min_messages has the expected value in your interactive session, and yet evidently not in the sessions
runningthese RAISE NOTICE commands. Maybe you have done ALTER USER SET or ALTER DATABASE SET commands that'd change it
in>those sessions? You could look in the pg_db_role_setting catalog to answer that definitively.
> regards, tom lane
We have opened a case with AWS on this issue as well since it is Aurora but I decided to reach out to the community as
well.
We have pg_cron (which is kicking off the procedures that are executing the code that is causing these NOTICE messages
toget written to the log file) setup with cron.database_name = shgroup02s. That database is oid 16436.
shgroup02s=> select * from pg_db_role_setting ;
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
whichcauses 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. I see cron
hasa setting- cron.log_min_messages which is set to warning so it doesn't seem to come from that.
Regards
Steve
"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 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
> "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 userid
isunsurprising. 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,
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
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() line
6at 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
"Dirschel, Steve" <steve.dirschel@thomsonreuters.com> writes:
> I believe this clearly points to an issue with pg_cron. Would you agree?
Yeah, you certainly need to look into what sort of environment
that is setting up. I know zip about pg_cron, can't help you
there.
regards, tom lane
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