After initially trying to add trace support for
StartupMessage/SSLRequest/GSSENCRequest[1] I realized there were many
more cases where PQtrace was not correctly tracing messages, or not
even tracing them at all. These patches fix all of the issues that I
was able to find.
0001 is some cleanup after f4b54e1ed9
0002 does some preparatory changes for 0004 & 0007
All the others improve the tracing, and apart from 0004 and 0007
depending on 0002, none of these patches depend on each other.
Although you could argue that 0007 and 0008 depend on 0006, because
without 0006 the code added by 0007 and 0008 won't ever really be
executed.
To test you can add a PQreset(conn) call to the start of the
test_cancel function in:
src/test/modules/libpq_pipeline/libpq_pipeline.c.
And then run:
ninja -C build all install-quiet &&
build/src/test/modules/libpq_pipeline/libpq_pipeline cancel
'port=5432' -t test.trace
And then look at the top of test.trace
[1]:
https://www.postgresql.org/message-id/CAGECzQTTN5aGqtDaRifJXPyd_O5qHWQcOxsHJsDSVNqMugGNEA%40mail.gmail.com
From 8567a09b4e1816ccdd58786f912ee055accfbc93 Mon Sep 17 00:00:00 2001
From: Jelte Fennema-Nio <jelte.fennema@microsoft.com>
Date: Fri, 21 Jun 2024 01:05:24 +0200
Subject: [PATCH v1 1/8] libpq: Use PqMsg macros in fe-auth.c
In f4b54e1ed9 macros were introduced for protocol characters to improve
readability of code. But these new macros were not used everywhere in
fe-auth.c by accident. This fixes the final three places.
---
src/interfaces/libpq/fe-auth.c | 8 ++++----
1 file changed, 4 insertions(+), 4 deletions(-)
diff --git a/src/interfaces/libpq/fe-auth.c b/src/interfaces/libpq/fe-auth.c
index 256f596e6bb..b5b367f24d0 100644
--- a/src/interfaces/libpq/fe-auth.c
+++ b/src/interfaces/libpq/fe-auth.c
@@ -124,7 +124,7 @@ pg_GSS_continue(PGconn *conn, int payloadlen)
* first or subsequent packet, just send the same kind of password
* packet.
*/
- if (pqPacketSend(conn, 'p',
+ if (pqPacketSend(conn, PqMsg_GSSResponse,
goutbuf.value, goutbuf.length) != STATUS_OK)
{
gss_release_buffer(&lmin_s, &goutbuf);
@@ -324,7 +324,7 @@ pg_SSPI_continue(PGconn *conn, int payloadlen)
*/
if (outbuf.pBuffers[0].cbBuffer > 0)
{
- if (pqPacketSend(conn, 'p',
+ if (pqPacketSend(conn, PqMsg_GSSResponse,
outbuf.pBuffers[0].pvBuffer, outbuf.pBuffers[0].cbBuffer))
{
FreeContextBuffer(outbuf.pBuffers[0].pvBuffer);
@@ -683,7 +683,7 @@ pg_SASL_continue(PGconn *conn, int payloadlen, bool final)
/*
* Send the SASL response to the server.
*/
- res = pqPacketSend(conn, 'p', output, outputlen);
+ res = pqPacketSend(conn, PqMsg_SASLResponse, output, outputlen);
free(output);
if (res != STATUS_OK)
@@ -754,7 +754,7 @@ pg_password_sendauth(PGconn *conn, const char *password, AuthRequest areq)
default:
return STATUS_ERROR;
}
- ret = pqPacketSend(conn, 'p', pwd_to_send, strlen(pwd_to_send) + 1);
+ ret = pqPacketSend(conn, PqMsg_PasswordMessage, pwd_to_send, strlen(pwd_to_send) + 1);
free(crypt_pwd);
return ret;
}
base-commit: c5c82123d3050c3a5eef0f51e9783f1cc5004ba0
--
2.34.1
From 1187d694bbff1e1c13041bb361db906a0cb329f1 Mon Sep 17 00:00:00 2001
From: Jelte Fennema-Nio <jelte.fennema@microsoft.com>
Date: Fri, 21 Jun 2024 10:45:38 +0200
Subject: [PATCH v1 2/8] libpq: Add suppress argument to pqTraceOutputNchar
In future commits we're going to trace authentication related messages.
Some of these messages contain challenge bytes as part of a
challenge-responese flow. Since these bytes are different for every
connection we want normalized them when the PQTRACE_REGRESS_MODE trace
flag is set. This commit modifies pqTraceOutputNchar to take a suppress
argument, which makes it possible to do so.
---
src/interfaces/libpq/fe-trace.c | 17 ++++++++++++-----
1 file changed, 12 insertions(+), 5 deletions(-)
diff --git a/src/interfaces/libpq/fe-trace.c b/src/interfaces/libpq/fe-trace.c
index d7a61ec9cc1..6ea7bb821a1 100644
--- a/src/interfaces/libpq/fe-trace.c
+++ b/src/interfaces/libpq/fe-trace.c
@@ -185,12 +185,19 @@ pqTraceOutputString(FILE *pfdebug, const char *data, int *cursor, bool suppress)
* pqTraceOutputNchar: output a string of exactly len bytes message to the log
*/
static void
-pqTraceOutputNchar(FILE *pfdebug, int len, const char *data, int *cursor)
+pqTraceOutputNchar(FILE *pfdebug, int len, const char *data, int *cursor, bool suppress)
{
int i,
next; /* first char not yet printed */
const char *v = data + *cursor;
+ if (suppress)
+ {
+ fprintf(pfdebug, " 'BBBB'");
+ *cursor += len;
+ return;
+ }
+
fprintf(pfdebug, " \'");
for (next = i = 0; i < len; ++i)
@@ -246,7 +253,7 @@ pqTraceOutput_Bind(FILE *f, const char *message, int *cursor)
nbytes = pqTraceOutputInt32(f, message, cursor, false);
if (nbytes == -1)
continue;
- pqTraceOutputNchar(f, nbytes, message, cursor);
+ pqTraceOutputNchar(f, nbytes, message, cursor, false);
}
nparams = pqTraceOutputInt16(f, message, cursor);
@@ -283,7 +290,7 @@ pqTraceOutput_DataRow(FILE *f, const char *message, int *cursor)
len = pqTraceOutputInt32(f, message, cursor, false);
if (len == -1)
continue;
- pqTraceOutputNchar(f, len, message, cursor);
+ pqTraceOutputNchar(f, len, message, cursor, false);
}
}
@@ -363,7 +370,7 @@ pqTraceOutput_FunctionCall(FILE *f, const char *message, int *cursor, bool regre
nbytes = pqTraceOutputInt32(f, message, cursor, false);
if (nbytes == -1)
continue;
- pqTraceOutputNchar(f, nbytes, message, cursor);
+ pqTraceOutputNchar(f, nbytes, message, cursor, false);
}
pqTraceOutputInt16(f, message, cursor);
@@ -487,7 +494,7 @@ pqTraceOutput_FunctionCallResponse(FILE *f, const char *message, int *cursor)
fprintf(f, "FunctionCallResponse\t");
len = pqTraceOutputInt32(f, message, cursor, false);
if (len != -1)
- pqTraceOutputNchar(f, len, message, cursor);
+ pqTraceOutputNchar(f, len, message, cursor, false);
}
static void
--
2.34.1
From 265ad6f3965206a058114d825f1d13a9d54b4660 Mon Sep 17 00:00:00 2001
From: Jelte Fennema-Nio <jelte.fennema@microsoft.com>
Date: Wed, 5 Jun 2024 12:07:09 +0200
Subject: [PATCH v1 3/8] libpq: Trace StartupMessage/SSLRequest/GSSENCRequest
correctly
If tracing was enabled during connection startup, these messages would
previously be listed in the trace output as something like this:
F 8 Unknown message: length is 8
F 38 Unknown message: length is 38
With this commit their type and contents are now correctly listed.
---
src/interfaces/libpq/fe-trace.c | 47 ++++++++++++++++++++++++---------
1 file changed, 35 insertions(+), 12 deletions(-)
diff --git a/src/interfaces/libpq/fe-trace.c b/src/interfaces/libpq/fe-trace.c
index 6ea7bb821a1..f1e4c07cc25 100644
--- a/src/interfaces/libpq/fe-trace.c
+++ b/src/interfaces/libpq/fe-trace.c
@@ -704,6 +704,7 @@ pqTraceOutputNoTypeByteMessage(PGconn *conn, const char *message)
{
int length;
int logCursor = 0;
+ int version = 0;
if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
{
@@ -719,19 +720,41 @@ pqTraceOutputNoTypeByteMessage(PGconn *conn, const char *message)
fprintf(conn->Pfdebug, "F\t%d\t", length);
- switch (length)
+ if (length < 8)
{
- case 16: /* CancelRequest */
- fprintf(conn->Pfdebug, "CancelRequest\t");
- pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, false);
- pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, false);
- pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, false);
- break;
- case 8: /* GSSENCRequest or SSLRequest */
- /* These messages do not reach here. */
- default:
- fprintf(conn->Pfdebug, "Unknown message: length is %d", length);
- break;
+ fprintf(conn->Pfdebug, "Unknown message: length is %d\n", length);
+ return;
+ }
+
+ memcpy(&version, message + logCursor, 4);
+ version = (int) pg_ntoh32(version);
+
+ if (version == CANCEL_REQUEST_CODE)
+ {
+ fprintf(conn->Pfdebug, "CancelRequest\t");
+ pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, false);
+ pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, false);
+ pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, false);
+ }
+ else if (version == NEGOTIATE_SSL_CODE)
+ {
+ fprintf(conn->Pfdebug, "SSLRequest\t");
+ pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, false);
+ }
+ else if (version == NEGOTIATE_GSS_CODE)
+ {
+ fprintf(conn->Pfdebug, "GSSENCRequest\t");
+ pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, false);
+ }
+ else
+ {
+ fprintf(conn->Pfdebug, "StartupMessage\t");
+ pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, false);
+ while (message[logCursor] != '\0')
+ {
+ pqTraceOutputString(conn->Pfdebug, message, &logCursor, false);
+ pqTraceOutputString(conn->Pfdebug, message, &logCursor, false);
+ }
}
fputc('\n', conn->Pfdebug);
--
2.34.1
From 8cbba167f99b2ce3f5ca3010645aaebf38920429 Mon Sep 17 00:00:00 2001
From: Jelte Fennema-Nio <jelte.fennema@microsoft.com>
Date: Fri, 21 Jun 2024 00:13:05 +0200
Subject: [PATCH v1 4/8] libpq: Trace frontend authentication challenges
If tracing was enabled during connection startup, these messages would
previously be listed in the trace output as something like this:
F 54 Unknown message: 70
mismatched message length: consumed 4, expected 54
With this commit their type and contents are now correctly listed.
---
src/interfaces/libpq/fe-auth.c | 14 ++++++++
src/interfaces/libpq/fe-trace.c | 62 ++++++++++++++++++++++++++++++++
src/interfaces/libpq/libpq-int.h | 10 ++++++
src/tools/pgindent/typedefs.list | 1 +
4 files changed, 87 insertions(+)
diff --git a/src/interfaces/libpq/fe-auth.c b/src/interfaces/libpq/fe-auth.c
index b5b367f24d0..cb3919e0492 100644
--- a/src/interfaces/libpq/fe-auth.c
+++ b/src/interfaces/libpq/fe-auth.c
@@ -124,12 +124,15 @@ pg_GSS_continue(PGconn *conn, int payloadlen)
* first or subsequent packet, just send the same kind of password
* packet.
*/
+ conn->current_auth_response = AUTH_RESP_GSS;
if (pqPacketSend(conn, PqMsg_GSSResponse,
goutbuf.value, goutbuf.length) != STATUS_OK)
{
+ conn->current_auth_response = AUTH_RESP_NONE;
gss_release_buffer(&lmin_s, &goutbuf);
return STATUS_ERROR;
}
+ conn->current_auth_response = AUTH_RESP_NONE;
}
gss_release_buffer(&lmin_s, &goutbuf);
@@ -324,12 +327,15 @@ pg_SSPI_continue(PGconn *conn, int payloadlen)
*/
if (outbuf.pBuffers[0].cbBuffer > 0)
{
+ conn->current_auth_response = AUTH_RESP_GSS;
if (pqPacketSend(conn, PqMsg_GSSResponse,
outbuf.pBuffers[0].pvBuffer, outbuf.pBuffers[0].cbBuffer))
{
+ conn->current_auth_response = AUTH_RESP_NONE;
FreeContextBuffer(outbuf.pBuffers[0].pvBuffer);
return STATUS_ERROR;
}
+ conn->current_auth_response = AUTH_RESP_NONE;
}
FreeContextBuffer(outbuf.pBuffers[0].pvBuffer);
}
@@ -597,8 +603,11 @@ pg_SASL_init(PGconn *conn, int payloadlen)
if (pqPutnchar(initialresponse, initialresponselen, conn))
goto error;
}
+ conn->current_auth_response = AUTH_RESP_SASL_INITIAL;
if (pqPutMsgEnd(conn))
goto error;
+ conn->current_auth_response = AUTH_RESP_NONE;
+
if (pqFlush(conn))
goto error;
@@ -608,6 +617,7 @@ pg_SASL_init(PGconn *conn, int payloadlen)
return STATUS_OK;
error:
+ conn->current_auth_response = AUTH_RESP_NONE;
termPQExpBuffer(&mechanism_buf);
free(initialresponse);
return STATUS_ERROR;
@@ -683,7 +693,9 @@ pg_SASL_continue(PGconn *conn, int payloadlen, bool final)
/*
* Send the SASL response to the server.
*/
+ conn->current_auth_response = AUTH_RESP_SASL;
res = pqPacketSend(conn, PqMsg_SASLResponse, output, outputlen);
+ conn->current_auth_response = AUTH_RESP_NONE;
free(output);
if (res != STATUS_OK)
@@ -754,7 +766,9 @@ pg_password_sendauth(PGconn *conn, const char *password, AuthRequest areq)
default:
return STATUS_ERROR;
}
+ conn->current_auth_response = AUTH_RESP_PASSWORD;
ret = pqPacketSend(conn, PqMsg_PasswordMessage, pwd_to_send, strlen(pwd_to_send) + 1);
+ conn->current_auth_response = AUTH_RESP_NONE;
free(crypt_pwd);
return ret;
}
diff --git a/src/interfaces/libpq/fe-trace.c b/src/interfaces/libpq/fe-trace.c
index f1e4c07cc25..23df8d0e10e 100644
--- a/src/interfaces/libpq/fe-trace.c
+++ b/src/interfaces/libpq/fe-trace.c
@@ -350,6 +350,40 @@ pqTraceOutput_CopyFail(FILE *f, const char *message, int *cursor)
pqTraceOutputString(f, message, cursor, false);
}
+static void
+pqTraceOutput_GSSResponse(FILE *f, const char *message, int *cursor, int length, bool regress)
+{
+ fprintf(f, "GSSResponse\t");
+ pqTraceOutputNchar(f, length - *cursor + 1, message, cursor, regress);
+}
+
+static void
+pqTraceOutput_PasswordMessage(FILE *f, const char *message, int *cursor)
+{
+ fprintf(f, "PasswordMessage\t");
+ pqTraceOutputString(f, message, cursor, false);
+}
+
+static void
+pqTraceOutput_SASLInitialResponse(FILE *f, const char *message, int *cursor, bool regress)
+{
+ int initialResponse;
+
+ fprintf(f, "SASLInitialResponse\t");
+ pqTraceOutputString(f, message, cursor, false);
+ initialResponse = pqTraceOutputInt32(f, message, cursor, false);
+ if (initialResponse != -1)
+ pqTraceOutputNchar(f, initialResponse, message, cursor, regress);
+}
+
+static void
+pqTraceOutput_SASLResponse(FILE *f, const char *message, int *cursor, int length, bool regress)
+{
+ fprintf(f, "SASLResponse\t");
+ pqTraceOutputNchar(f, length - *cursor + 1, message, cursor, regress);
+}
+
+
static void
pqTraceOutput_FunctionCall(FILE *f, const char *message, int *cursor, bool regress)
{
@@ -606,6 +640,34 @@ pqTraceOutputMessage(PGconn *conn, const char *message, bool toServer)
case PqMsg_CopyFail:
pqTraceOutput_CopyFail(conn->Pfdebug, message, &logCursor);
break;
+ case PqMsg_GSSResponse:
+ Assert(PqMsg_GSSResponse == PqMsg_PasswordMessage);
+ Assert(PqMsg_GSSResponse == PqMsg_SASLInitialResponse);
+ Assert(PqMsg_GSSResponse == PqMsg_SASLResponse);
+
+ /*
+ * pqTraceOutput_PasswordMessage(conn->Pfdebug, message,
+ * &logCursor);
+ */
+ switch (conn->current_auth_response)
+ {
+ case AUTH_RESP_GSS:
+ pqTraceOutput_GSSResponse(conn->Pfdebug, message, &logCursor, length, regress);
+ break;
+ case AUTH_RESP_PASSWORD:
+ pqTraceOutput_PasswordMessage(conn->Pfdebug, message, &logCursor);
+ break;
+ case AUTH_RESP_SASL_INITIAL:
+ pqTraceOutput_SASLInitialResponse(conn->Pfdebug, message, &logCursor, regress);
+ break;
+ case AUTH_RESP_SASL:
+ pqTraceOutput_SASLResponse(conn->Pfdebug, message, &logCursor, length, regress);
+ break;
+ default:
+ fprintf(conn->Pfdebug, "UnknownAuthenticationResponse");
+ break;
+ }
+ break;
case PqMsg_FunctionCall:
pqTraceOutput_FunctionCall(conn->Pfdebug, message, &logCursor, regress);
break;
diff --git a/src/interfaces/libpq/libpq-int.h b/src/interfaces/libpq/libpq-int.h
index f36d76bf3fe..f9b21c86ae4 100644
--- a/src/interfaces/libpq/libpq-int.h
+++ b/src/interfaces/libpq/libpq-int.h
@@ -331,6 +331,15 @@ typedef enum
PGQUERY_CLOSE /* Close Statement or Portal */
} PGQueryClass;
+typedef enum
+{
+ AUTH_RESP_NONE = 0,
+ AUTH_RESP_GSS,
+ AUTH_RESP_PASSWORD,
+ AUTH_RESP_SASL_INITIAL,
+ AUTH_RESP_SASL,
+} AuthResponseType;
+
/*
* An entry in the pending command queue.
*/
@@ -490,6 +499,7 @@ struct pg_conn
* codes */
bool client_finished_auth; /* have we finished our half of the
* authentication exchange? */
+ AuthResponseType current_auth_response;
/* Transient state needed while establishing connection */
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index 61ad417cde6..06ac0574bfd 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -167,6 +167,7 @@ AttrMissing
AttrNumber
AttributeOpts
AuthRequest
+AuthResponseType
AuthToken
AutoPrewarmSharedState
AutoVacOpts
--
2.34.1
From 0c02582e87cee908c6ccaa0dc4ba6c57aa33188e Mon Sep 17 00:00:00 2001
From: Jelte Fennema-Nio <jelte.fennema@microsoft.com>
Date: Thu, 20 Jun 2024 17:40:08 +0200
Subject: [PATCH v1 5/8] libpq: Trace responses to SSLRequest and GSSENCRequest
Since these are single bytes instead of v2 or v3 messages they need
custom tracing logic. These "messages" don't even have official names in
the protocol specification, so I called them SSLResponse and
GSSENCResponse here.
---
src/interfaces/libpq/fe-connect.c | 10 ++++++++++
src/interfaces/libpq/fe-trace.c | 14 ++++++++++++++
src/interfaces/libpq/libpq-int.h | 1 +
3 files changed, 25 insertions(+)
diff --git a/src/interfaces/libpq/fe-connect.c b/src/interfaces/libpq/fe-connect.c
index 071b1b34aa1..0772455c7d1 100644
--- a/src/interfaces/libpq/fe-connect.c
+++ b/src/interfaces/libpq/fe-connect.c
@@ -3493,11 +3493,15 @@ keep_going: /* We will come back to here until there is
}
if (SSLok == 'S')
{
+ if (conn->Pfdebug)
+ pqTraceOutputEncryptionRequestResponse(conn, "SSL", SSLok);
/* mark byte consumed */
conn->inStart = conn->inCursor;
}
else if (SSLok == 'N')
{
+ if (conn->Pfdebug)
+ pqTraceOutputEncryptionRequestResponse(conn, "SSL", SSLok);
/* mark byte consumed */
conn->inStart = conn->inCursor;
@@ -3622,6 +3626,9 @@ keep_going: /* We will come back to here until there is
if (gss_ok == 'N')
{
+ if (conn->Pfdebug)
+ pqTraceOutputEncryptionRequestResponse(conn, "GSSENC", gss_ok);
+
/*
* The connection is still valid, so if it's OK to
* continue without GSS, we can proceed using this
@@ -3635,6 +3642,9 @@ keep_going: /* We will come back to here until there is
gss_ok);
goto error_return;
}
+
+ if (conn->Pfdebug)
+ pqTraceOutputEncryptionRequestResponse(conn, "GSSENC", gss_ok);
}
/* Begin or continue GSSAPI negotiation */
diff --git a/src/interfaces/libpq/fe-trace.c b/src/interfaces/libpq/fe-trace.c
index 23df8d0e10e..4978a92ea5e 100644
--- a/src/interfaces/libpq/fe-trace.c
+++ b/src/interfaces/libpq/fe-trace.c
@@ -821,3 +821,17 @@ pqTraceOutputNoTypeByteMessage(PGconn *conn, const char *message)
fputc('\n', conn->Pfdebug);
}
+
+void
+pqTraceOutputEncryptionRequestResponse(PGconn *conn, const char *requestType, char response)
+{
+ if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
+ {
+ char timestr[128];
+
+ pqTraceFormatTimestamp(timestr, sizeof(timestr));
+ fprintf(conn->Pfdebug, "%s\t", timestr);
+ }
+
+ fprintf(conn->Pfdebug, "B\t1\t%sResponse\t %c\n", requestType, response);
+}
diff --git a/src/interfaces/libpq/libpq-int.h b/src/interfaces/libpq/libpq-int.h
index f9b21c86ae4..575f9dbc7f0 100644
--- a/src/interfaces/libpq/libpq-int.h
+++ b/src/interfaces/libpq/libpq-int.h
@@ -885,6 +885,7 @@ extern ssize_t pg_GSS_read(PGconn *conn, void *ptr, size_t len);
extern void pqTraceOutputMessage(PGconn *conn, const char *message,
bool toServer);
extern void pqTraceOutputNoTypeByteMessage(PGconn *conn, const char *message);
+extern void pqTraceOutputEncryptionRequestResponse(PGconn *conn, const char *requestType, char response);
/* === miscellaneous macros === */
--
2.34.1
From 0a5b8257d4d7902ee964f6c938a13e033eb20f62 Mon Sep 17 00:00:00 2001
From: Jelte Fennema-Nio <jelte.fennema@microsoft.com>
Date: Thu, 13 Jun 2024 19:35:43 +0200
Subject: [PATCH v1 6/8] libpq: Trace all messages received from the server
Not all messages that libpq received from the server would be sent
through our message tracing logic. This fixes that by introducing
pqFinishParsingMessage which makes it a lot harder to forget about doing
so.
The messages that we now newly send through our tracing logic are:
- CopyData (received by COPY TO STDOUT)
- Authentication requests
- NegotiateProtocolVersion
- Some ErrorResponse messages during connection startup
- ReadyForQuery when received after a FunctionCall message
---
src/interfaces/libpq/fe-auth.c | 21 ++++++++++++++
src/interfaces/libpq/fe-connect.c | 13 ++++++---
src/interfaces/libpq/fe-protocol3.c | 45 +++++++++++++++--------------
src/interfaces/libpq/libpq-int.h | 1 +
4 files changed, 54 insertions(+), 26 deletions(-)
diff --git a/src/interfaces/libpq/fe-auth.c b/src/interfaces/libpq/fe-auth.c
index cb3919e0492..b5704656193 100644
--- a/src/interfaces/libpq/fe-auth.c
+++ b/src/interfaces/libpq/fe-auth.c
@@ -94,6 +94,10 @@ pg_GSS_continue(PGconn *conn, int payloadlen)
ginbuf.value = NULL;
}
+ /* finished parsing, trace server-to-client message */
+ if (conn->Pfdebug)
+ pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
+
/* Only try to acquire credentials if GSS delegation isn't disabled. */
if (!pg_GSS_have_cred_cache(&conn->gcred))
conn->gcred = GSS_C_NO_CREDENTIAL;
@@ -260,6 +264,10 @@ pg_SSPI_continue(PGconn *conn, int payloadlen)
InBuffers[0].BufferType = SECBUFFER_TOKEN;
}
+ /* finished parsing, trace server-to-client message */
+ if (conn->Pfdebug)
+ pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
+
OutBuffers[0].pvBuffer = NULL;
OutBuffers[0].BufferType = SECBUFFER_TOKEN;
OutBuffers[0].cbBuffer = 0;
@@ -567,6 +575,10 @@ pg_SASL_init(PGconn *conn, int payloadlen)
}
}
+ /* finished parsing, trace server-to-client message */
+ if (conn->Pfdebug)
+ pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
+
Assert(conn->sasl);
/*
@@ -657,6 +669,11 @@ pg_SASL_continue(PGconn *conn, int payloadlen, bool final)
free(challenge);
return STATUS_ERROR;
}
+
+ /* finished parsing, trace server-to-client message */
+ if (conn->Pfdebug)
+ pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
+
/* For safety and convenience, ensure the buffer is NULL-terminated. */
challenge[payloadlen] = '\0';
@@ -723,6 +740,10 @@ pg_password_sendauth(PGconn *conn, const char *password, AuthRequest areq)
return STATUS_ERROR; /* shouldn't happen */
}
+ /* finished parsing, trace server-to-client message */
+ if (conn->Pfdebug)
+ pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
+
/* Encrypt the password if needed. */
switch (areq)
diff --git a/src/interfaces/libpq/fe-connect.c b/src/interfaces/libpq/fe-connect.c
index 0772455c7d1..babb22c69f0 100644
--- a/src/interfaces/libpq/fe-connect.c
+++ b/src/interfaces/libpq/fe-connect.c
@@ -3776,7 +3776,7 @@ keep_going: /* We will come back to here until there is
return PGRES_POLLING_READING;
}
/* OK, we read the message; mark data consumed */
- conn->inStart = conn->inCursor;
+ pqFinishParsingMessage(conn, conn->inCursor);
/*
* Before 7.2, the postmaster didn't always end its
@@ -3826,7 +3826,7 @@ keep_going: /* We will come back to here until there is
goto error_return;
}
/* OK, we read the message; mark data consumed */
- conn->inStart = conn->inCursor;
+ pqFinishParsingMessage(conn, conn->inCursor);
/*
* If error is "cannot connect now", try the next host if
@@ -3855,7 +3855,7 @@ keep_going: /* We will come back to here until there is
goto error_return;
}
/* OK, we read the message; mark data consumed */
- conn->inStart = conn->inCursor;
+ pqFinishParsingMessage(conn, conn->inCursor);
goto error_return;
}
@@ -3880,7 +3880,12 @@ keep_going: /* We will come back to here until there is
*/
res = pg_fe_sendauth(areq, msgLength, conn);
- /* OK, we have processed the message; mark data consumed */
+ /*
+ * OK, we have processed the message; mark data consumed We
+ * don't call pqFinishParsingMessage here because we already
+ * trace this message inside pg_fe_sendauth (since we need to
+ * trace it before sending the response.
+ */
conn->inStart = conn->inCursor;
if (res != STATUS_OK)
diff --git a/src/interfaces/libpq/fe-protocol3.c b/src/interfaces/libpq/fe-protocol3.c
index 3170d484f02..f165009d3bb 100644
--- a/src/interfaces/libpq/fe-protocol3.c
+++ b/src/interfaces/libpq/fe-protocol3.c
@@ -57,6 +57,22 @@ static int build_startup_packet(const PGconn *conn, char *packet,
const PQEnvironmentOption *options);
+/*
+ * pqFinishParsingMessage is a simple helper function to advance inStart after
+ * a server-to-client message has successfully been parsed. It's main purpose
+ * is making it hard forget to call pqTraceOutputMessage when doing so.
+ */
+void
+pqFinishParsingMessage(PGconn *conn, int newInStart)
+{
+ /* trace server-to-client message */
+ if (conn->Pfdebug)
+ pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
+
+ /* Mark message as done */
+ conn->inStart = newInStart;
+}
+
/*
* parseInput: if appropriate, parse input data from backend
* until input is exhausted or a stopping state is reached.
@@ -454,12 +470,8 @@ pqParseInput3(PGconn *conn)
/* Successfully consumed this message */
if (conn->inCursor == conn->inStart + 5 + msgLength)
{
- /* trace server-to-client message */
- if (conn->Pfdebug)
- pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
-
/* Normal case: parsing agrees with specified length */
- conn->inStart = conn->inCursor;
+ pqFinishParsingMessage(conn, conn->inCursor);
}
else
{
@@ -1728,12 +1740,7 @@ getCopyDataMessage(PGconn *conn)
return -1;
}
- /* trace server-to-client message */
- if (conn->Pfdebug)
- pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
-
- /* Drop the processed message and loop around for another */
- conn->inStart = conn->inCursor;
+ pqFinishParsingMessage(conn, conn->inCursor);
}
}
@@ -1791,13 +1798,13 @@ pqGetCopyData3(PGconn *conn, char **buffer, int async)
(*buffer)[msgLength] = '\0'; /* Add terminating null */
/* Mark message consumed */
- conn->inStart = conn->inCursor + msgLength;
+ pqFinishParsingMessage(conn, conn->inCursor + msgLength);
return msgLength;
}
/* Empty, so drop it and loop around for another */
- conn->inStart = conn->inCursor;
+ pqFinishParsingMessage(conn, conn->inCursor);
}
}
@@ -2168,8 +2175,8 @@ pqFunctionCall3(PGconn *conn, Oid fnid,
case 'Z': /* backend is ready for new query */
if (getReadyForQuery(conn))
continue;
- /* consume the message and exit */
- conn->inStart += 5 + msgLength;
+
+ pqFinishParsingMessage(conn, conn->inStart + 5 + msgLength);
/*
* If we already have a result object (probably an error), use
@@ -2208,13 +2215,7 @@ pqFunctionCall3(PGconn *conn, Oid fnid,
return pqPrepareAsyncResult(conn);
}
- /* trace server-to-client message */
- if (conn->Pfdebug)
- pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
-
- /* Completed this message, keep going */
- /* trust the specified message length as what to skip */
- conn->inStart += 5 + msgLength;
+ pqFinishParsingMessage(conn, conn->inStart + 5 + msgLength);
needInput = false;
}
diff --git a/src/interfaces/libpq/libpq-int.h b/src/interfaces/libpq/libpq-int.h
index 575f9dbc7f0..6a54ee4a6e0 100644
--- a/src/interfaces/libpq/libpq-int.h
+++ b/src/interfaces/libpq/libpq-int.h
@@ -724,6 +724,7 @@ extern int PQsendQueryContinue(PGconn *conn, const char *query);
/* === in fe-protocol3.c === */
+extern void pqFinishParsingMessage(PGconn *conn, int newInStart);
extern char *pqBuildStartupPacket3(PGconn *conn, int *packetlen,
const PQEnvironmentOption *options);
extern void pqParseInput3(PGconn *conn);
--
2.34.1
From b1be382002fc4b94b3a5d1d7e1c9b39041e4af67 Mon Sep 17 00:00:00 2001
From: Jelte Fennema-Nio <jelte.fennema@microsoft.com>
Date: Thu, 13 Jun 2024 21:53:03 +0200
Subject: [PATCH v1 7/8] libpq: Trace server Authentication messages in detail
The tracing logic for Authentication messages comming from the server
was incomplete. It previously only listed the number in the
authentication type field of the message. This now starts to correctly
list the name of the message and its contents based on that type field.
---
src/interfaces/libpq/fe-trace.c | 55 ++++++++++++++++++++++++++++++---
1 file changed, 51 insertions(+), 4 deletions(-)
diff --git a/src/interfaces/libpq/fe-trace.c b/src/interfaces/libpq/fe-trace.c
index 4978a92ea5e..f130a1765bd 100644
--- a/src/interfaces/libpq/fe-trace.c
+++ b/src/interfaces/libpq/fe-trace.c
@@ -466,10 +466,57 @@ pqTraceOutput_Query(FILE *f, const char *message, int *cursor)
}
static void
-pqTraceOutput_Authentication(FILE *f, const char *message, int *cursor)
+pqTraceOutput_Authentication(FILE *f, const char *message, int *cursor, int length, bool regress)
{
- fprintf(f, "Authentication\t");
- pqTraceOutputInt32(f, message, cursor, false);
+ int authType = 0;
+
+ memcpy(&authType, message + *cursor, 4);
+ authType = (int) pg_ntoh32(authType);
+ *cursor += 4;
+ switch (authType)
+ {
+ case AUTH_REQ_OK:
+ fprintf(f, "AuthenticationOk");
+ break;
+ case AUTH_REQ_KRB5:
+ fprintf(f, "AuthenticationKerberosV5");
+ break;
+ case AUTH_REQ_PASSWORD:
+ fprintf(f, "AuthenticationCleartextPassword");
+ break;
+ case AUTH_REQ_MD5:
+ fprintf(f, "AuthenticationMD5Password");
+ break;
+ case AUTH_REQ_GSS:
+ fprintf(f, "AuthenticationGSS");
+ break;
+ case AUTH_REQ_GSS_CONT:
+ fprintf(f, "AuthenticationGSSContinue");
+ pqTraceOutputNchar(f, length - *cursor + 1, message, cursor, regress);
+ break;
+ case AUTH_REQ_SSPI:
+ fprintf(f, "AuthenticationSSPI");
+ break;
+ case AUTH_REQ_SASL:
+ fprintf(f, "AuthenticationSASL");
+ while (message[*cursor] != '\0')
+ {
+ pqTraceOutputString(f, message, cursor, false);
+ }
+ pqTraceOutputString(f, message, cursor, false);
+
+ break;
+ case AUTH_REQ_SASL_CONT:
+ fprintf(f, "AuthenticationSASLContinue");
+ pqTraceOutputNchar(f, length - *cursor + 1, message, cursor, regress);
+ break;
+ case AUTH_REQ_SASL_FIN:
+ fprintf(f, "AuthenticationSASLFinal");
+ pqTraceOutputNchar(f, length - *cursor + 1, message, cursor, regress);
+ break;
+ default:
+ fprintf(f, "Unknown authentication message %d", authType);
+ }
}
static void
@@ -703,7 +750,7 @@ pqTraceOutputMessage(PGconn *conn, const char *message, bool toServer)
pqTraceOutput_Query(conn->Pfdebug, message, &logCursor);
break;
case PqMsg_AuthenticationRequest:
- pqTraceOutput_Authentication(conn->Pfdebug, message, &logCursor);
+ pqTraceOutput_Authentication(conn->Pfdebug, message, &logCursor, length, regress);
break;
case PqMsg_PortalSuspended:
fprintf(conn->Pfdebug, "PortalSuspended");
--
2.34.1
From 1c3c61fffebb53a8d41e1c1bb49a4b58645377eb Mon Sep 17 00:00:00 2001
From: Jelte Fennema-Nio <jelte.fennema@microsoft.com>
Date: Wed, 5 Jun 2024 11:40:04 +0200
Subject: [PATCH v1 8/8] libpq: Trace NegotiateProtocolVersion correctly
This changes the libpq tracing code to correctly trace the
NegotiateProtocolVersion message. Previously it wasn't important that
tracing of the NegotiateProtocolVersion message worked correctly,
because in practice libpq never received it. Now that we are planning to
introduce protocol changes in future commits it starts to become more
useful for testing/debugging.
---
src/interfaces/libpq/fe-trace.c | 8 +++++++-
1 file changed, 7 insertions(+), 1 deletion(-)
diff --git a/src/interfaces/libpq/fe-trace.c b/src/interfaces/libpq/fe-trace.c
index f130a1765bd..03a3e35898d 100644
--- a/src/interfaces/libpq/fe-trace.c
+++ b/src/interfaces/libpq/fe-trace.c
@@ -562,9 +562,15 @@ pqTraceOutput_RowDescription(FILE *f, const char *message, int *cursor, bool reg
static void
pqTraceOutput_NegotiateProtocolVersion(FILE *f, const char *message, int *cursor)
{
+ int nparams;
+
fprintf(f, "NegotiateProtocolVersion\t");
pqTraceOutputInt32(f, message, cursor, false);
- pqTraceOutputInt32(f, message, cursor, false);
+ nparams = pqTraceOutputInt32(f, message, cursor, false);
+ for (int i = 0; i < nparams; i++)
+ {
+ pqTraceOutputString(f, message, cursor, false);
+ }
}
static void
--
2.34.1
