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