Fix tracing of BackendKeyData and CancelRequest messages

On 03/07/2026 12:42, Anthonin Bonnefoy wrote:

BackendKeyData length was increased from 4 bytes to a variable sized
length (up to 256 bytes) in a460251f0a. However, PQtrace still traces
it as a 4 bytes key, leading to a "mismatched message length" warning
message. The same issue impacts the tracing of CancelRequest.

This shows the lack of coverage of tracing startup packets:
libpq_pipeline only starts traces once the connection is established.
There's also no way to test this with psql.

The attached patchset fixes the traces BackendKeyData and
CancelRequest, add the possibility of tracing any connection created
by libpq, and add test coverage for the startup packets. It contains
the following files:

0001: Fix tracing of BackendKeyData and CancelRequest messages

@@ -762,7 +762,7 @@ pqTraceOutputMessage(PGconn *conn, const char *message, bool toServer)
/* No message content */
break;
case PqMsg_BackendKeyData:
-                       pqTraceOutput_BackendKeyData(conn->Pfdebug, message, &logCursor, regress);
+                       pqTraceOutput_BackendKeyData(conn->Pfdebug, message, conn->be_cancel_key_len, &logCursor, regress);
break;
case PqMsg_NoData:
fprintf(conn->Pfdebug, "NoData");

This should use the 'length' parsed from the message, instead of relying
on conn->be_cancel_key_len. Same in pqTraceOutputNoTypeByteMessage(). I
changed that, and committed and backpatched. Thanks!

I did not look closely at the rest of the patches, but more test
coverage sounds like a good idea. Some quick comments just based on the
descriptions though:

0002: Add PGTRACE env var in libpq to enable protocol tracing to the
target file (or '-' for stdout). One limitation of this approach is
that you should only have one connection writing to a trace file. If
an application opens multiple connections to the same PGTRACE, each
connection will open its own fd and erase others traces. But given
this is to debug protocol messages, it sounds like an acceptable
limitation.

While testing just the first patch, I noticed that PQcancel() doesn't do
the tracing even if it was enabled in the main connection, which made it
a little hard to test. I didn't try this patch, but I hope it fixes that
problem too.

0003: Replace libpq_pipeline PQtrace calls by PGTRACE, adding tracing
of startup messages, with some additional regress masking. I've also
added a warning message to report mismatch length similar to what's
done in pqTraceOutputMessage.

Could you achieve the same by calling PQtrace() earlier? Perhaps switch
to PQconnectStart() interface, and call PQtrace() right after
PQconnectStart()?

0004: Add tracing of cancel requests in libpq_pipeline test. Calling
PQuntrace on the main and monitor connections was necessary to allow
the cancel connections to append the cancel messages without conflict.

Seems unrelated to pipelining, so perhaps this should go somewhere else.
Then again, we already crossed that bridge when we added the
"protocol_version" test there, which is also unrelated to pipelining.
Maybe we should rename the test module, or add some comments noting that
it's not just for pipelining anymore.

As a side note, I find the output from pqTraceOutputNchar() awkward for
things like the cancel key, which is raw binary bytes:

BackendKeyData 711421 'm[\x80\x95\xd6\x81{I\x8b\x04>\xab\x7fwMG\xda!\xc1\xb8\xa7\x8d\xb0.\xcd\xaa\x15\x9c\x0f\xd2\xe8\x1b'

We don't need to invest too much in making the trace output pretty, but
I think it would make sense to print that as a hex string.

- Heikki

Hi,

Thanks for the review!

On Fri, Jul 3, 2026 at 2:10 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:

While testing just the first patch, I noticed that PQcancel() doesn't do
the tracing even if it was enabled in the main connection, which made it
a little hard to test. I didn't try this patch, but I hope it fixes that
problem too.

Yeah, as PQcancel is signal-safe, it doesn't go through the normal
message construction, and thus is not traced. I've done an attempt to
fix that, but that requires a new flag that's enabled in the signal
handler, and then trying to generate the trace for the cancel request
after that, and it isn't great.
Given there's an active thread to get rid of PQcancel calls[0]/messages/by-id/DEY0N7FS8NCU.1F7QXGG37MQ09@jeltef.nl, maybe
it's not worth it to add more logic to the signal handler and PQcancel
to trace those cancel requests?

0003: Replace libpq_pipeline PQtrace calls by PGTRACE, adding tracing
of startup messages, with some additional regress masking. I've also
added a warning message to report mismatch length similar to what's
done in pqTraceOutputMessage.

Could you achieve the same by calling PQtrace() earlier? Perhaps switch
to PQconnectStart() interface, and call PQtrace() right after
PQconnectStart()?

That could be doable. However, another benefit of the PGTRACE approach
is to make tracing available in psql and make testing protocol changes
easier. With this, it should be possible to add a regression suite
using trace outputs that doesn't depend on the libpq_pipeline module.
I've also been trying to implement libpq compression, and my current
way to check the packet content is Wireshark which isn't very
practical. Which is why I've been looking into using PQtrace with psql
to make testing easier (and how I've stumbled on the BackendKeyData
issue).

0004: Add tracing of cancel requests in libpq_pipeline test. Calling
PQuntrace on the main and monitor connections was necessary to allow
the cancel connections to append the cancel messages without conflict.

Seems unrelated to pipelining, so perhaps this should go somewhere else.
Then again, we already crossed that bridge when we added the
"protocol_version" test there, which is also unrelated to pipelining.
Maybe we should rename the test module, or add some comments noting that
it's not just for pipelining anymore.

Given the module seems focused on testing the libpq API itself rather
than pipeline, would renaming it to test_libpq be good?

As a side note, I find the output from pqTraceOutputNchar() awkward for
things like the cancel key, which is raw binary bytes:

BackendKeyData 711421 'm[\x80\x95\xd6\x81{I\x8b\x04>\xab\x7fwMG\xda!\xc1\xb8\xa7\x8d\xb0.\xcd\xaa\x15\x9c\x0f\xd2\xe8\x1b'

We don't need to invest too much in making the trace output pretty, but
I think it would make sense to print that as a hex string.

Agreed. I've created a pqTraceOutputNbyte function to print a hex
string and use it for BackendKeyData and CancelRequest.

The new updated patchset has now:

0001: Create the pqTraceOutputNbyte and use it for BackendKeyData and
CancelRequest to print the backend key as hex string

0002: Additional regress masking for StartupMessage and ParameterValue

0003: Make pqtrace write line atomically. Instead of writing a line in
multiple fprintf, a line is now buffered in a PQExpBuffer and written
in a single fprintf. This is needed for 0004 and the tracing of cancel
requests.

0004: Add the PGTRACE var env to libpq. The previous version didn't
handle cancel requests correctly, as the cancel connection would open
a new fd to the trace file, truncating it while the source connection
was using it.
Now, PQcancelCreate copies the Pfdebug to the cancelConn to use it
when the cancel request is sent. As the lines are now written to
Pfdebug atomically, the source connection and cancel connection can
share the same Pfdebug.
This does make the assumption that the source connection outlives the
cancel connection to keep the Pfdebug fd opened.

0005: Switch libpq_pipeline to use PGTRACE and add the additional
startup messages to the traces

0006: Enable tracing of the cancel test in libpq_pipeline.

[0]: /messages/by-id/DEY0N7FS8NCU.1F7QXGG37MQ09@jeltef.nl

Regards,
Anthonin Bonnefoy