Обсуждение: 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@intershop.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@intershop.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
Re: BUG #6168: db_link may generate additional unformatted log entries in stderr
От
"Marc Mamin"
Дата:
>> I've stumbled on a few entries in my stderr log where the line prefix wh= ere >> 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 ... >> =3D> NOTICE: table "sessions_summary_raw_20110815" does not exist, skip= ping >> =3D> NOTICE: ALTER TABLE / ADD PRIMARY KEY will create implicit index >> "pk_sessions_s ... >> =3D> 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