Re: BUG #6168: db_link may generate additional unformatted log entries in stderr

The following bug has been logged online:

Bug reference: 6168
Logged by: Marc Mamin
Email address: marc(at)intershop(dot)de
PostgreSQL version: 9.1 Beta 3
Operating system: Linux
Description: db_link may generate additional unformatted log entries
in stderr
Details:

Hello,

The problem occures with 9.1 Beta 3 on Linux, but I suspect this to be an
older issue in db_link

here my logging configuration:
log_destination = 'stderr,csvlog'
logging_collector = on
log_line_prefix = '%t|%c|%p|%u|'
log_min_messages = warning

I've stumbled on a few entries in my stderr log where the line prefix where
missing. e.g.:

2011-08-08 13:12:16 CEST|4e3fc490.17bc|6076|foo|DETAIL: Returned type
character ...
2011-08-08 13:12:16 CEST|4e3fc490.17bc|6076|foo|CONTEXT: PL/pgSQL
function "bm_ ...
2011-08-08 13:12:16 CEST|4e3fc490.17bc|6076|foo|STATEMENT: Select
coalesce(colu ...
=> NOTICE: table "sessions_summary_raw_20110815" does not exist, skipping
=> NOTICE: ALTER TABLE / ADD PRIMARY KEY will create implicit index
"pk_sessions_s ...
=> NOTICE: table "sessions_site_summary_raw_20110815" does not exist,
skipping

NOTICE entries should moreover not be logged !

Those entries are coming from db_link.

Here is a small test case to repeat:

CREATE FUNCTION my_warn (msg varchar) returns int AS
$$
BEGIN
raise WARNING '%', msg;
return 0;
END;
$$
language 'PLPGSQL';

cic_db=# SELECT dblink_connect_u('1', 'hostaddr=127.0.0.1 port=5432
dbname=cic_db user=isdb1 password=foo');
dblink_connect_u
------------------
OK
(1 row)

cic_db=# SELECT dblink_send_query ('1', $$select my_warn ('my_warn
test')$$);
dblink_send_query
-------------------
1
(1 row)

cic_db=# SELECT * FROM dblink_get_result('1') AS t1(f1 int);
f1
----
0
(1 row)

cic_db=# SELECT dblink_disconnect('1');
dblink_disconnect
-------------------
OK
(1 row)

DROP FUNCTION my_warn(msg varchar);

stderr log: the correct warning entry is followed by a repetiton of the
message:
(In my real case I only see the unformated NOTICE, probably because of the
log_min_messages set to warning)
;

2011-08-19 12:44:11 CEST|4e4e3e7b.529d|21149|isdb1|WARNING: my_warn
test
=> WARNING: my_warn test

the csvlog is clean. It does not contains these extra entries:

2011-08-19 12:44:11.799
CEST,"isdb1","cic_db",21149,"127.0.0.1:42769",4e4e3e7b.529d,1,"SELECT",2011-
08-19 12:44:11 CEST,4/116414,0,WARNING,01000,"my_warn test",,,,,,,,,""

As far as I see, this is just a cosmetic issue, but might be problmatic for
third party applications that parse the stderr log.

HTH,

Marc Mamin

"Marc Mamin" <marc(at)intershop(dot)de> writes:
> I've stumbled on a few entries in my stderr log where the line prefix where
> missing. e.g.:

> 2011-08-08 13:12:16 CEST|4e3fc490.17bc|6076|foo|DETAIL: Returned type
> character ...
> 2011-08-08 13:12:16 CEST|4e3fc490.17bc|6076|foo|CONTEXT: PL/pgSQL
> function "bm_ ...
> 2011-08-08 13:12:16 CEST|4e3fc490.17bc|6076|foo|STATEMENT: Select
> coalesce(colu ...
> => NOTICE: table "sessions_summary_raw_20110815" does not exist, skipping
> => NOTICE: ALTER TABLE / ADD PRIMARY KEY will create implicit index
> "pk_sessions_s ...
> => NOTICE: table "sessions_site_summary_raw_20110815" does not exist,
> skipping

> NOTICE entries should moreover not be logged !

> Those entries are coming from db_link.

I guess your test case is looping back to the same Postgres instance?

What I see here is that the target backend (the one connected to by
dblink) logs the warning as expected, and then the dblink one also
prints the warning to stderr. This is because dblink does not override
either PQsetNoticeReceiver or PQsetNoticeProcessor, so libpq provides
its default behavior of printing warnings/notices on stderr.

It'd probably make sense for dblink to supply a notice receiver that
converts the result into an ereport() call, much as it does for actual
error results (in fact it could likely use dblink_res_error for that).
But frankly this is an enhancement request, not a bug. The entire point
of the stderr logging mechanism is to capture random printouts to stderr
that might happen in code called by the backend, and it's doing exactly
what it's supposed to.

regards, tom lane

>> I've stumbled on a few entries in my stderr log where the line prefix where
>> missing. e.g.:
>>
>> 2011-08-08 13:12:16 CEST|4e3fc490.17bc|6076|foo|DETAIL: Returned type
>> character ...
>> 2011-08-08 13:12:16 CEST|4e3fc490.17bc|6076|foo|CONTEXT: PL/pgSQL
>> function "bm_ ...
>> 2011-08-08 13:12:16 CEST|4e3fc490.17bc|6076|foo|STATEMENT: Select
>> coalesce(colu ...
>> => NOTICE: table "sessions_summary_raw_20110815" does not exist, skipping
>> => NOTICE: ALTER TABLE / ADD PRIMARY KEY will create implicit index
>> "pk_sessions_s ...
>> => NOTICE: table "sessions_site_summary_raw_20110815" does not exist,
>> skipping
>>
>> NOTICE entries should moreover not be logged !
>>
>> Those entries are coming from db_link.
>>

>I guess your test case is looping back to the same Postgres instance?

Yes, I use db_link to trigger multithreading :)

>But frankly this is an enhancement request, not a bug. The entire point
>of the stderr logging mechanism is to capture random printouts to stderr
>that might happen in code called by the backend, and it's doing exactly
>what it's supposed to.

Thanks for the explanation, this issue has no impact on our application.

best regards,

Marc Mamin