[pgpool-hackers: 4538] 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?

After thinking more, maybe this is not a practical issue because
DataRow messages are always followed by CommandComplete or
ErrorResponse. Same thing can be said to ParameterStatus
messages. They are follwed by BackendKeyData or ErrorResponse. Also
this is applied to CopyData. The only case these are broken is, the
child process is killed while counting the number of messages.  Maybe
we could make log_backend_messages to take not only just on or off,
but something like:

off: the default
terse: current patch behavior (e.g. "last DataRow message from backend 0 repeated 7 times")
verbose: log each message as soon as it is detected. This never miss
	 log messages even when the child process is killed, but could produce lots of log lines.


> =========================== 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