Обсуждение: print in plpython not appearing in logs

I'm having problems wherein my print() statements inside my plpython stored proc are not appearing in postgresql log. I
triedsetting the file=sys.stderr 

To reproduce:

CREATE OR REPLACE PROCEDURE p_ludwig_test()
AS
$$
       import sys
       try:
              x = 1 / 0
       except:
              plpy.log("hello")
              print("oink oink", file=sys.stderr)
              print("oink oink - v2")
              plpy.log("haha")
$$
LANGUAGE plpython3u;

call p_ludwig_test()



Output:
---------------------
2022-12-02 11:46:11.324 UTC [19390] LOG:  hello
2022-12-02 11:46:11.324 UTC [19390] CONTEXT:  PL/Python procedure "p_ludwig_test"
2022-12-02 11:46:11.324 UTC [19390] STATEMENT:  call p_ludwig_test();
2022-12-02 11:46:11.324 UTC [19390] LOG:  haha
2022-12-02 11:46:11.324 UTC [19390] CONTEXT:  PL/Python procedure "p_ludwig_test"
2022-12-02 11:46:11.324 UTC [19390] STATEMENT:  call p_ludwig_test();


Notice that the "oink oink"  is  not there.


Relevant logging configuration:
logging_collector = on    
log_directory = 'logs'  
log_min_messages = info 
log_min_error_statement = error 

PG version
-------------------
 PostgreSQL 14.6 on aarch64-unknown-linux-gnu, compiled by gcc (GCC) 7.3.1 20180712 (Red Hat 7.3.1-15), 64-bit



The reason why I'm trying to use print() is because plpy logger is quite verbose. Each logging will output 3 line

for example:
   plpy.log("hello")

Will generate the following 3 lines in the log:
2022-12-02 11:46:11.324 UTC [19390] LOG:  hello
2022-12-02 11:46:11.324 UTC [19390] CONTEXT:  PL/Python procedure "p_ludwig_test"
2022-12-02 11:46:11.324 UTC [19390] STATEMENT:  call p_ludwig_test();

Another thing is there is another stored procedure that I have wherein the print() to stderr actually works, so I'm not
surewhat I'm doing wrong. 


Thank you in advance,
Ludwig

Ludwig Isaac Lim <ludz_lim@yahoo.com> writes:
> I'm having problems wherein my print() statements inside my plpython stored proc are not appearing in postgresql log.
Itried setting the file=sys.stderr 

Hmm.  I can tell you that with "logging_collector = on", I would only
expect the logs to capture stderr output, not stdout.  So it makes
sense to me that plain "print" would disappear into the bit bucket.
But if you specify stderr output, it ought to work.  I don't know
enough Python to know why it's not working, but it seems to me this is
primarily a Python question not a Postgres question.  Maybe you need
an explicit fflush-equivalent step?  Dunno.

            regards, tom lane

Hi Tom:


>> I'm having problems wherein my print() statements inside my plpython stored proc are not appearing in postgresql
log.I tried setting the file=sys.stderr 


> Hmm.  I can tell you that with "logging_collector = on", I would only expect the logs to capture stderr output, not
stdout. So it makes 
> sense to me that plain "print" would disappear into the bit bucket. But if you specify stderr output, it ought to
work. I don't know 
> enough Python to know why it's not working, but it seems to me this is primarily a Python question not a Postgres
question. Maybe you need 
> an explicit fflush-equivalent step?  Dunno.

>            regards, tom lane

As usual, thank you for pointing out where problem lies.

I made it work by adding flush=True flag to the print() statement.

print("oink oink", file=sys.stderr, flush=True)

I was under the wrong impression that output to stderr are automatically flushed.

Thank you once again.

Regards,
Ludwig

I'm having problems wherein my print() statements inside my plpython stored proc are not appearing in postgresql log. I tried setting the file=sys.stderr

To reproduce:

CREATE OR REPLACE PROCEDURE p_ludwig_test()
AS
$$
       import sys
       try:
              x = 1 / 0
       except:
              plpy.log("hello")
              print("oink oink", file=sys.stderr)
              print("oink oink - v2")
              plpy.log("haha")
$$
LANGUAGE plpython3u;

call p_ludwig_test()



Output:
---------------------
2022-12-02 11:46:11.324 UTC [19390] LOG:  hello
2022-12-02 11:46:11.324 UTC [19390] CONTEXT:  PL/Python procedure "p_ludwig_test"
2022-12-02 11:46:11.324 UTC [19390] STATEMENT:  call p_ludwig_test();
2022-12-02 11:46:11.324 UTC [19390] LOG:  haha
2022-12-02 11:46:11.324 UTC [19390] CONTEXT:  PL/Python procedure "p_ludwig_test"
2022-12-02 11:46:11.324 UTC [19390] STATEMENT:  call p_ludwig_test();


Notice that the "oink oink"  is  not there.


Relevant logging configuration:
logging_collector = on    
log_directory = 'logs'  
log_min_messages = info 
log_min_error_statement = error 

PG version
-------------------
 PostgreSQL 14.6 on aarch64-unknown-linux-gnu, compiled by gcc (GCC) 7.3.1 20180712 (Red Hat 7.3.1-15), 64-bit



The reason why I'm trying to use print() is because plpy logger is quite verbose. Each logging will output 3 line

for example:
   plpy.log("hello")

Will generate the following 3 lines in the log:
2022-12-02 11:46:11.324 UTC [19390] LOG:  hello
2022-12-02 11:46:11.324 UTC [19390] CONTEXT:  PL/Python procedure "p_ludwig_test"
2022-12-02 11:46:11.324 UTC [19390] STATEMENT:  call p_ludwig_test();

Another thing is there is another stored procedure that I have wherein the print() to stderr actually works, so I'm not sure what I'm doing wrong.


Thank you in advance,
Ludwig

On 12/13/22 13:20, Shaozhong SHI wrote:
> What is brilliant about plpython?  Any brilliant examples to look at?
> 

1) It is actually plython(3)u where the u means untrusted. This means 
you can reach outside the database and do things. That can seen as 
brilliant or dangerous.

2) You have no end of Python libraries you can work with. Again combined 
  with 1) up you whether that is brilliant or dangerous.

3) Python is more dynamic then plpgsql so you can get more adventurous 
with doing dynamic SQL.

Downside is that plpython(3)u is not tied as closely to SQL as plpgsql 
so it very often takes you many more lines of code to get something done.

-- 
Adrian Klaver
adrian.klaver@aklaver.com