Bug #958: plperl notice server log

pgsql-bugs@postgresql.org writes:

The notice message raised by a plperl function is flushed into the server log file only when that client is disconnected and the client does not receive the message. On the other hand, the notice raised by a plpgsql function are flushed into the server log immediately.

Difficult to believe, since they both call elog() which does a write(2,...)
--- I see no way that perl could screw that up ...

regards, tom lane

The notice message raised by a plperl function is flushed into the
server log file only when that client is disconnected and the client
does not receive the message. On the other hand, the notice raised by
a plpgsql function are flushed into the server log immediately.

Difficult to believe, since they both call elog() which does a write(2,...)
--- I see no way that perl could screw that up ...

FYI, i have attached the repeatable sequence of commands, sample perl
code and the server log. I have also attached the sequence of commands,
sample plpgsql code and the server log.

regards,
bhuvaneswaran

<perl_code>
create or replace function perl_test (text, text)
returns int as '

my ($A1, $A2) = @_;
print "Argument 1 :$A1:\n";
print "Argument 2 :$A2:\n";
return 1;
'
language 'plperl';

</perl_code>

<perl_seq>
Welcome to psql 7.3.1, the PostgreSQL interactive terminal.

Type: \copyright for distribution terms
\h for help with SQL commands
\? for help on internal slash commands
\g or terminate with semicolon to execute query
\q to quit

bhuvan=> SELECT perl_test('bhuvan', 'eswar');
perl_test
-----------
1
(1 row)

bhuvan=> SELECT perl_test('bhuvan', 'eswar');
perl_test
-----------
1
(1 row)

bhuvan=> \q
</perl_seq>

<perl_log>
2003-04-29 10:22:06 [4151] LOG: connection received: host=[local]
2003-04-29 10:22:06 [4151] LOG: connection authorized: user=bhuvan
database=bhuvan
2003-04-29 10:22:06 [4151] LOG: query: begin; select
getdatabaseencoding(); commit
2003-04-29 10:22:06 [4151] LOG: duration: 0.002896 sec
2003-04-29 10:22:06 [4151] LOG: query: BEGIN; SELECT usesuper FROM
pg_catalog.pg_user WHERE usename = 'bhuvan'; COMMIT
2003-04-29 10:22:06 [4151] LOG: duration: 0.011538 sec
2003-04-29 10:22:20 [4151] LOG: query: SELECT perl_test('bhuvan',
'eswar');
2003-04-29 10:22:20 [4151] LOG: duration: 0.109914 sec
2003-04-29 10:22:21 [4151] LOG: query: SELECT perl_test('bhuvan',
'eswar');
2003-04-29 10:22:21 [4151] LOG: duration: 0.001063 sec
Argument 1 :bhuvan:
Argument 2 :eswar:
Argument 1 :bhuvan:
Argument 2 :eswar:
</perl_log>

<plpgsql_code>
create or replace function plpgsql_test (text, text)
returns int as '

begin

raise notice ''plpgsql: Argument 1 :%:'', $1;
raise notice ''plpgsql: Argument 2 :%:'', $2;
return 1;
end;'
language 'plpgsql';
</plpgsql_code>

<plpgsql_seq>
Welcome to psql 7.3.1, the PostgreSQL interactive terminal.

Type: \copyright for distribution terms
\h for help with SQL commands
\? for help on internal slash commands
\g or terminate with semicolon to execute query
\q to quit

bhuvan=> SELECT plpgsql_test('bhuvan', 'eswar');
NOTICE: plpgsql: Argument 1 :bhuvan:
NOTICE: plpgsql: Argument 2 :eswar:
plpgsql_test
--------------
1
(1 row)

bhuvan=> SELECT plpgsql_test('bhuvan', 'eswar');
NOTICE: plpgsql: Argument 1 :bhuvan:
NOTICE: plpgsql: Argument 2 :eswar:
plpgsql_test
--------------
1
(1 row)

bhuvan=> \q
</plpgsql_seq>

<plpgsql_log>
2003-04-29 10:29:13 [9479] LOG: connection received: host=[local]
2003-04-29 10:29:13 [9479] LOG: connection authorized: user=bhuvan
database=bhuvan
2003-04-29 10:29:13 [9479] LOG: query: begin; select
getdatabaseencoding(); commit
2003-04-29 10:29:13 [9479] LOG: duration: 0.003444 sec
2003-04-29 10:29:13 [9479] LOG: query: BEGIN; SELECT usesuper FROM
pg_catalog.pg_user WHERE usename = 'bhuvan'; COMMIT
2003-04-29 10:29:13 [9479] LOG: duration: 0.045066 sec
2003-04-29 10:29:14 [9479] LOG: query: SELECT plpgsql_test('bhuvan',
'eswar');
2003-04-29 10:29:14 [9479] NOTICE: plpgsql: Argument 1 :bhuvan:
2003-04-29 10:29:14 [9479] NOTICE: plpgsql: Argument 2 :eswar:
2003-04-29 10:29:14 [9479] LOG: query: SELECT 1
2003-04-29 10:29:14 [9479] LOG: duration: 0.005317 sec
2003-04-29 10:29:16 [9479] LOG: query: SELECT plpgsql_test('bhuvan',
'eswar');
2003-04-29 10:29:16 [9479] NOTICE: plpgsql: Argument 1 :bhuvan:
2003-04-29 10:29:16 [9479] NOTICE: plpgsql: Argument 2 :eswar:
2003-04-29 10:29:16 [9479] LOG: duration: 0.001173 sec
</plpgsql_log>

"A.Bhuvaneswaran" <bhuvansql@myrealbox.com> writes:

create or replace function perl_test (text, text)
returns int as '

my ($A1, $A2) = @_;
print "Argument 1 :$A1:\n";
print "Argument 2 :$A2:\n";
return 1;
'
language 'plperl';

Printing to stdout is not the defined way to send a notice to a Postgres
client. Use elog:
http://www.ca.postgresql.org/users-lounge/docs/7.3/postgres/plperl-database.html

regards, tom lane

Printing to stdout is not the defined way to send a notice to a Postgres
client. Use elog:
http://www.ca.postgresql.org/users-lounge/docs/7.3/postgres/plperl-database.html

Fine and thank you very much. As you said, elog is sending the notice to
client and server log immediately. But what stops print from flushing the
output to server log file immediately?

regards,
bhuvaneswaran

"A.Bhuvaneswaran" <bhuvansql@myrealbox.com> writes:

Fine and thank you very much. As you said, elog is sending the notice to
client and server log immediately. But what stops print from flushing the
output to server log file immediately?

stdout is fully buffered by default, on most platforms anyway ... if you
printed to stderr it'd act different ...

regards, tom lane