[pgpool-hackers: 4537] Re: New feature: log_backend_messages

[Tatsuo Ishii]

Hi Peng,

Thank you for the feedback.

> Hi Ishii-san,
> 
> Thank you for your proposal.
> I think it is a useful feature for debugging.
> 
>> One thing maybe better to think about the feature is, whether we want to show the log line:
>> 2024-11-25 13:50:43.735: pgproto pid 325721: LOG:  DataRow message from backend 0
> 
> Yes, I agree with you to log messages using the message instead of the message kind.

Ok, attached is the patch to implement it.  The log messages look like
below.

One thing I am wondering is, when a particular message is repeating,
pgpool will not print the log immediately, just keep the number of
messages while the same message type keeps on arriving. Once a
different message type arrives, pgpool prints like:

2024-11-27 17:08:35.245: pgproto pid 487733: LOG: last ParameterStatus message from backend 0 repeated 13 times

But what if the pgpool session terminates before the next different
message arrives? pgpool print nothing. Thought?

=========================== Log messages with log_backend_messages =========================

2024-11-27 17:08:35.244: child pid 487733: LOG:  AuthenticationRequest message from backend 0
2024-11-27 17:08:35.244: child pid 487733: LOG:  AuthenticationRequest message from backend 1
2024-11-27 17:08:35.244: child pid 487733: LOG:  AuthenticationRequest message from backend 2
2024-11-27 17:08:35.244: child pid 487733: LOG:  ParameterStatus message from backend 0
2024-11-27 17:08:35.244: child pid 487733: LOG:  ParameterStatus message from backend 1
2024-11-27 17:08:35.244: child pid 487733: LOG:  ParameterStatus message from backend 2
2024-11-27 17:08:35.244: child pid 487733: LOG:  ParameterStatus "TimeZone": node 1 message length 17 is different from main node message length 24
2024-11-27 17:08:35.244: child pid 487733: LOG:  ParameterStatus "TimeZone": node 1 message length 17 is different from main node message length 24
2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  last ParameterStatus message from backend 0 repeated 13 times
2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  BackendKeyData message from backend 0
2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  last ParameterStatus message from backend 1 repeated 13 times
2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  BackendKeyData message from backend 1
2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  last ParameterStatus message from backend 2 repeated 13 times
2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  BackendKeyData message from backend 2
2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  ReadyForQuery message from backend 0
2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  ReadyForQuery message from backend 1
2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  ReadyForQuery message from backend 2
2024-11-27 17:08:35.246: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: SELECT pg_catalog.version()
2024-11-27 17:08:35.247: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: BEGIN
2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  CommandComplete message from backend 0
2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  ReadyForQuery message from backend 0
2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: Parse: INSERT INTO t1 VALUES(1)
2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: Bind: INSERT INTO t1 VALUES(1)
2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: Execute: INSERT INTO t1 VALUES(1)
2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: Parse: SELECT * FROM t1
2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: Bind: SELECT * FROM t1
2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: Execute: SELECT * FROM t1
2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  ParseComplete message from backend 0
2024-11-27 17:08:35.249: pgproto pid 487733: LOG:  BindComplete message from backend 0
2024-11-27 17:08:35.249: pgproto pid 487733: LOG:  CommandComplete message from backend 0
2024-11-27 17:08:35.249: pgproto pid 487733: LOG:  ParseComplete message from backend 0
2024-11-27 17:08:35.249: pgproto pid 487733: LOG:  BindComplete message from backend 0
2024-11-27 17:08:35.249: pgproto pid 487733: LOG:  DataRow message from backend 0
2024-11-27 17:08:35.249: pgproto pid 487733: LOG:  last DataRow message from backend 0 repeated 7 times
2024-11-27 17:08:35.249: pgproto pid 487733: LOG:  CommandComplete message from backend 0
2024-11-27 17:08:35.249: pgproto pid 487733: LOG:  ReadyForQuery message from backend 0
2024-11-27 17:08:35.250: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: END
2024-11-27 17:08:35.251: pgproto pid 487733: LOG:  CommandComplete message from backend 0
2024-11-27 17:08:35.251: pgproto pid 487733: LOG:  ReadyForQuery message from backend 0
2024-11-27 17:08:35.251: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: DISCARD ALL
2024-11-27 17:08:35.251: pgproto pid 487733: LOG:  CommandComplete message from backend 0
2024-11-27 17:08:35.251: pgproto pid 487733: LOG:  ReadyForQuery message from backend 0
-------------- next part --------------
A non-text attachment was scrubbed...
Name: v1-0001-Feature-add-log_backend_messages.patch
Type: text/x-patch
Size: 5397 bytes
Desc: not available
URL: <http://www.pgpool.net/pipermail/pgpool-hackers/attachments/20241127/2e37ef3f/attachment.bin>