pg.ddx.io  pgsql-hackers@postgresql.org mailing list archive  
help / color / mirror / Atom feed
libpq: Fix lots of discrepancies in PQtrace
14+ messages / 4 participants
[nested] [flat]

Commits from this thread:
  2024-08-16 b8b3f861fb  libpq: Trace all messages received from the server
  2024-08-14 a5c6b8f22c  libpq: Trace responses to SSLRequest and GSSENCRequest
  2024-08-12 ea92f3a0a5  libpq: Trace frontend authentication challenges
  2024-08-09 7adec2d5fc  libpq: Trace StartupMessage/SSLRequest/GSSENCRequest correctly
  2024-08-09 4eb179e5bf  libpq: Add suppress argument to pqTraceOutputNchar
* libpq: Fix lots of discrepancies in PQtrace
@ 2024-06-21 09:22  Jelte Fennema-Nio <postgres@jeltef.nl>
  0 siblings, 1 reply; 14+ messages in thread

From: Jelte Fennema-Nio @ 2024-06-21 09:22 UTC (permalink / raw)
  To: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>

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.gma...

Attachments: download all (8 files, .tar.gz)

v1-0001-libpq-Use-PqMsg-macros-in-fe-auth.c.patch (application/x-patch, 2.0K) download 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
v1-0002-libpq-Add-suppress-argument-to-pqTraceOutputNchar.patch (application/x-patch, 2.8K) download 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
v1-0003-libpq-Trace-StartupMessage-SSLRequest-GSSENCReque.patch (application/x-patch, 2.8K) download 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
v1-0004-libpq-Trace-frontend-authentication-challenges.patch (application/x-patch, 6.9K) download 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
v1-0005-libpq-Trace-responses-to-SSLRequest-and-GSSENCReq.patch (application/x-patch, 3.2K) download 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
v1-0006-libpq-Trace-all-messages-received-from-the-server.patch (application/x-patch, 8.2K) download 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
v1-0007-libpq-Trace-server-Authentication-messages-in-det.patch (application/x-patch, 3.0K) download 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
v1-0008-libpq-Trace-NegotiateProtocolVersion-correctly.patch (application/x-patch, 1.4K) download 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
^ permalink raw reply [nested|flat] 14+ messages in thread

* Re: libpq: Fix lots of discrepancies in PQtrace
@ 2024-06-21 21:01  Nathan Bossart <nathandbossart@gmail.com>
  parent: Jelte Fennema-Nio <postgres@jeltef.nl>
  0 siblings, 1 reply; 14+ messages in thread

From: Nathan Bossart @ 2024-06-21 21:01 UTC (permalink / raw)
  To: Jelte Fennema-Nio <postgres@jeltef.nl>; +Cc: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>

On Fri, Jun 21, 2024 at 11:22:05AM +0200, Jelte Fennema-Nio wrote:
> 0001 is some cleanup after f4b54e1ed9

Oops.  I'll plan on committing this after the 17beta2 release freeze is
lifted.

-- 
nathan





^ permalink  raw  reply  [nested|flat] 14+ messages in thread

* Re: libpq: Fix lots of discrepancies in PQtrace
@ 2024-06-26 16:28  Nathan Bossart <nathandbossart@gmail.com>
  parent: Nathan Bossart <nathandbossart@gmail.com>
  0 siblings, 1 reply; 14+ messages in thread

From: Nathan Bossart @ 2024-06-26 16:28 UTC (permalink / raw)
  To: Jelte Fennema-Nio <postgres@jeltef.nl>; +Cc: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>

On Fri, Jun 21, 2024 at 04:01:55PM -0500, Nathan Bossart wrote:
> On Fri, Jun 21, 2024 at 11:22:05AM +0200, Jelte Fennema-Nio wrote:
>> 0001 is some cleanup after f4b54e1ed9
> 
> Oops.  I'll plan on committing this after the 17beta2 release freeze is
> lifted.

Committed 0001.

-- 
nathan





^ permalink  raw  reply  [nested|flat] 14+ messages in thread

* Re: libpq: Fix lots of discrepancies in PQtrace
@ 2024-06-26 16:36  Alvaro Herrera <alvherre@alvh.no-ip.org>
  parent: Nathan Bossart <nathandbossart@gmail.com>
  0 siblings, 1 reply; 14+ messages in thread

From: Alvaro Herrera @ 2024-06-26 16:36 UTC (permalink / raw)
  To: Nathan Bossart <nathandbossart@gmail.com>; +Cc: Jelte Fennema-Nio <postgres@jeltef.nl>; PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>

On 2024-Jun-26, Nathan Bossart wrote:

> On Fri, Jun 21, 2024 at 04:01:55PM -0500, Nathan Bossart wrote:
> > On Fri, Jun 21, 2024 at 11:22:05AM +0200, Jelte Fennema-Nio wrote:
> >> 0001 is some cleanup after f4b54e1ed9
> > 
> > Oops.  I'll plan on committing this after the 17beta2 release freeze is
> > lifted.
> 
> Committed 0001.

Thanks, Nathan.  I'm holding myself responsible for the rest ... will
handle soon after the branch.

-- 
Álvaro Herrera        Breisgau, Deutschland  —  https://www.EnterpriseDB.com/
"The problem with the future is that it keeps turning into the present"
(Hobbes)





^ permalink  raw  reply  [nested|flat] 14+ messages in thread

* Re: libpq: Fix lots of discrepancies in PQtrace
@ 2024-06-26 20:02  Jelte Fennema-Nio <postgres@jeltef.nl>
  parent: Alvaro Herrera <alvherre@alvh.no-ip.org>
  0 siblings, 1 reply; 14+ messages in thread

From: Jelte Fennema-Nio @ 2024-06-26 20:02 UTC (permalink / raw)
  To: Alvaro Herrera <alvherre@alvh.no-ip.org>; +Cc: Nathan Bossart <nathandbossart@gmail.com>; PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>

On Wed, 26 Jun 2024 at 18:36, Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
> Thanks, Nathan.  I'm holding myself responsible for the rest ... will
> handle soon after the branch.

Sounds great. Out of curiosity, what is the backpatching policy for
something like this? Honestly most of these patches could be
considered bugfixes in PQtrace, so backpatching might make sense. OTOH
I don't think PQtrace is used very much in practice, so backpatching
might carry more risk than it's worth.





^ permalink  raw  reply  [nested|flat] 14+ messages in thread

* Re: libpq: Fix lots of discrepancies in PQtrace
@ 2024-06-27 05:39  Michael Paquier <michael@paquier.xyz>
  parent: Jelte Fennema-Nio <postgres@jeltef.nl>
  0 siblings, 1 reply; 14+ messages in thread

From: Michael Paquier @ 2024-06-27 05:39 UTC (permalink / raw)
  To: Jelte Fennema-Nio <postgres@jeltef.nl>; +Cc: Alvaro Herrera <alvherre@alvh.no-ip.org>; Nathan Bossart <nathandbossart@gmail.com>; PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>

On Wed, Jun 26, 2024 at 10:02:08PM +0200, Jelte Fennema-Nio wrote:
> On Wed, 26 Jun 2024 at 18:36, Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
> > Thanks, Nathan.  I'm holding myself responsible for the rest ... will
> > handle soon after the branch.
> 
> Sounds great. Out of curiosity, what is the backpatching policy for
> something like this? Honestly most of these patches could be
> considered bugfixes in PQtrace, so backpatching might make sense. OTOH
> I don't think PQtrace is used very much in practice, so backpatching
> might carry more risk than it's worth.

0001 getting on HEAD after the feature freeze as a cleanup piece
cleanup is no big deal.  That's cosmetic, still OK.

Looking at the whole, the rest of the patch set qualifies as a new
feature, even if they're aimed at closing existing gaps.
Particularly, you have bits of new infrastructure introduced in libpq
like the current_auth_response business in 0004, making it a new
feature by structure.

+	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;

It's a surprising approach.  Future callers of pqPacketSend() and
pqPutMsgEnd() would easily miss that this flag should be set, as much
as reset.  Isn't that something that should be added in input of these
functions?

+	AuthResponseType current_auth_response;
I'd recommend to document what this flag is here for, with a comment.
--
Michael

Attachments:

  signature.asc (application/pgp-signature, 832B) download

^ permalink  raw  reply  [nested|flat] 14+ messages in thread

* Re: libpq: Fix lots of discrepancies in PQtrace
@ 2024-06-27 08:03  Jelte Fennema-Nio <postgres@jeltef.nl>
  parent: Michael Paquier <michael@paquier.xyz>
  0 siblings, 2 replies; 14+ messages in thread

From: Jelte Fennema-Nio @ 2024-06-27 08:03 UTC (permalink / raw)
  To: Michael Paquier <michael@paquier.xyz>; +Cc: Alvaro Herrera <alvherre@alvh.no-ip.org>; Nathan Bossart <nathandbossart@gmail.com>; PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>

On Thu, 27 Jun 2024 at 07:39, Michael Paquier <michael@paquier.xyz> wrote:
> Looking at the whole, the rest of the patch set qualifies as a new
> feature, even if they're aimed at closing existing gaps.

Alright, seems reasonable. To be clear, I don't care at all about this
being backported personally.

> Particularly, you have bits of new infrastructure introduced in libpq
> like the current_auth_response business in 0004, making it a new
> feature by structure.
>
> +       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;
>
> It's a surprising approach.  Future callers of pqPacketSend() and
> pqPutMsgEnd() would easily miss that this flag should be set, as much
> as reset.  Isn't that something that should be added in input of these
> functions?

Yeah, I'm not entirely happy about it either. But adding an argument
to pqPutMsgEnd and pqPutPacketSend would mean all the existing call
sites would need to change, even though only 4 of them would care
about the new argument. You could argue that it's the better solution,
but it would at least greatly increase the size of the diff. Of course
to reduce the diff size you could make the old functions a wrapper
around a new one with the extra argument, but I couldn't think of a
good name for those functions. Overall I went for the chosen approach
here, because it only impacted code at the call sites for these auth
packets (which are the only v3 packets in the protocol that you cannot
interpret based on their contents alone).

I think your worry about easily missing to set/clear the flag is not a
huge problem in practice. We almost never add new authentication
messages and it's only needed there. Also the clearing is not even
strictly necessary for the tracing to behave correctly, but it seemed
like the right thing to do.

> +       AuthResponseType current_auth_response;
> I'd recommend to document what this flag is here for, with a comment.

Oops, yeah I forgot about that. Done now.

Attachments: download all (7 files, .tar.gz)

v2-0002-libpq-Add-suppress-argument-to-pqTraceOutputNchar.patch (application/octet-stream, 2.9K) download From 5655f0912765a646cf84ca9026b4cd23d9fde3c4 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 v2 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 base-commit: 3e53492aa7084bceaa92757c90e067d79768797e -- 2.34.1
v2-0003-libpq-Trace-StartupMessage-SSLRequest-GSSENCReque.patch (application/octet-stream, 2.8K) download From 04e788a9dc4ef85621f1ee97c3d5a8b4e22b423f 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 v2 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
v2-0004-libpq-Trace-frontend-authentication-challenges.patch (application/octet-stream, 7.1K) download From 1872f76bc014a853603c208da7632e7eff7787a3 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 v2 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 | 12 +++++++ src/tools/pgindent/typedefs.list | 1 + 4 files changed, 89 insertions(+) diff --git a/src/interfaces/libpq/fe-auth.c b/src/interfaces/libpq/fe-auth.c index 3b25d8afda4..f6bb58fd902 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,8 +766,10 @@ 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..3a00ee2903f 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,9 @@ struct pg_conn * codes */ bool client_finished_auth; /* have we finished our half of the * authentication exchange? */ + AuthResponseType current_auth_response; /* used by pqTraceOutputMessage to + * know which auth response we're + * sending */ /* 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
v2-0005-libpq-Trace-responses-to-SSLRequest-and-GSSENCReq.patch (application/octet-stream, 3.2K) download From 550a4104394e1567984b2bd69d5db97ccb706ac7 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 v2 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 3a00ee2903f..82a568f8040 100644 --- a/src/interfaces/libpq/libpq-int.h +++ b/src/interfaces/libpq/libpq-int.h @@ -887,6 +887,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
v2-0006-libpq-Trace-all-messages-received-from-the-server.patch (application/octet-stream, 8.2K) download From 795e21456af5a3ce758bec41b4f0eac825a66fd3 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 v2 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 f6bb58fd902..6d37f07b691 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 82a568f8040..74af7d36676 100644 --- a/src/interfaces/libpq/libpq-int.h +++ b/src/interfaces/libpq/libpq-int.h @@ -726,6 +726,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
v2-0007-libpq-Trace-server-Authentication-messages-in-det.patch (application/octet-stream, 3.0K) download From 0cac5b1e14a1395fbf91d9fecceff03d53f32af6 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 v2 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
v2-0008-libpq-Trace-NegotiateProtocolVersion-correctly.patch (application/octet-stream, 1.4K) download From 7f76a23ef6fca9d7aeb5763631fe6a9cecc7c7bc 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 v2 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
^ permalink raw reply [nested|flat] 14+ messages in thread

* Re: libpq: Fix lots of discrepancies in PQtrace
@ 2024-08-09 22:08  Alvaro Herrera <alvherre@alvh.no-ip.org>
  parent: Jelte Fennema-Nio <postgres@jeltef.nl>
  1 sibling, 1 reply; 14+ messages in thread

From: Alvaro Herrera @ 2024-08-09 22:08 UTC (permalink / raw)
  To: Jelte Fennema-Nio <postgres@jeltef.nl>; +Cc: Michael Paquier <michael@paquier.xyz>; Nathan Bossart <nathandbossart@gmail.com>; PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>

Pushed 0002 and 0003.  On the latter: I decided against using int32 to
print the request identifiers; by splitting into two int16's, we see
that the numbers match the values in the PG_PROTOCOL() declarations:

2024-08-09 17:37:38.364622	F	8	SSLRequest	 1234 5679
and
2024-08-09 17:37:38.422109	F	16	CancelRequest	 1234 5678 NNNN NNNN

(I didn't verify GSSEncRequest directly.)

I also verified that in non-regress mode, the values printed by
CancelRequest match those in the BackendKeyData message,
2024-08-09 17:34:27.544686	B	12	BackendKeyData	 NNNN NNNN

I also added suppression in regress mode for the backend key in the
CancelRequest message, since they would be different each time.

There are no tests for this code.  We could add a trace file for the
connection packet in libpq_pipeline by changing PQconnectdb() to
PQconnectStart() and then do PQtrace before polling until the connection
is ready; we would have to have it match for the TAP test.  Not sure
this is worth the effort.  But doing this in a very crude way allowed me
to verify that, at least on my machine, this code is doing what's
expected.

Thank you,

-- 
Álvaro Herrera         PostgreSQL Developer  —  https://www.EnterpriseDB.com/





^ permalink  raw  reply  [nested|flat] 14+ messages in thread

* Re: libpq: Fix lots of discrepancies in PQtrace
@ 2024-08-09 23:08  Alvaro Herrera <alvherre@alvh.no-ip.org>
  parent: Alvaro Herrera <alvherre@alvh.no-ip.org>
  0 siblings, 1 reply; 14+ messages in thread

From: Alvaro Herrera @ 2024-08-09 23:08 UTC (permalink / raw)
  To: Jelte Fennema-Nio <postgres@jeltef.nl>; +Cc: Michael Paquier <michael@paquier.xyz>; Nathan Bossart <nathandbossart@gmail.com>; PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>

Regarding 0004:

I don't want to add 4 bytes to struct pg_conn for tracing support.  I'm
tempted to make the new struct member a plain 'char' to reduce overhead
for a feature that almost nobody is going to use.  According to pahole
we have a 3 bytes hole in that position of the struct, so if we make it
a 1- or 2-byte member, there's no storage overhead whatsoever.

Also, why not have pqTraceOutputMessage() responsible for resetting the
byte after printing the message?  It seems to cause less undesirable
detritus.

I propose something like the attached, but it's as yet untested.  What
do you think?

-- 
Álvaro Herrera               48°01'N 7°57'E  —  https://www.EnterpriseDB.com/
"El sentido de las cosas no viene de las cosas, sino de
las inteligencias que las aplican a sus problemas diarios
en busca del progreso." (Ernesto Hernández-Novich)

Attachments:

0001-libpq-Trace-frontend-authentication-challenges.patch (text/x-diff, 6.5K) download From 4a26851519266d31624ad9e332bd89483d7280a2 Mon Sep 17 00:00:00 2001 From: Alvaro Herrera <alvherre@alvh.no-ip.org> Date: Fri, 9 Aug 2024 19:05:08 -0400 Subject: [PATCH] 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. Author: Jelte Fennema-Nio <postgres@jeltef.nl> Reviewed-by: Michael Paquier <michael@paquier.xyz> Discussion: https://postgr.es/m/CAGECzQSoPHtZ4xe0raJ6FYSEiPPS+YWXBhOGo+Y1YecLgknF3g@mail.gmail.com --- src/interfaces/libpq/fe-auth.c | 6 +++ src/interfaces/libpq/fe-trace.c | 69 ++++++++++++++++++++++++++++++++ src/interfaces/libpq/libpq-int.h | 16 +++++++- 3 files changed, 90 insertions(+), 1 deletion(-) diff --git a/src/interfaces/libpq/fe-auth.c b/src/interfaces/libpq/fe-auth.c index 3b25d8afda..4da07c1f98 100644 --- a/src/interfaces/libpq/fe-auth.c +++ b/src/interfaces/libpq/fe-auth.c @@ -124,6 +124,7 @@ pg_GSS_continue(PGconn *conn, int payloadlen) * first or subsequent packet, just send the same kind of password * packet. */ + conn->current_auth_response = AUTH_RESPONSE_GSS; if (pqPacketSend(conn, PqMsg_GSSResponse, goutbuf.value, goutbuf.length) != STATUS_OK) { @@ -324,6 +325,7 @@ pg_SSPI_continue(PGconn *conn, int payloadlen) */ if (outbuf.pBuffers[0].cbBuffer > 0) { + conn->current_auth_response = AUTH_RESPONSE_GSS; if (pqPacketSend(conn, PqMsg_GSSResponse, outbuf.pBuffers[0].pvBuffer, outbuf.pBuffers[0].cbBuffer)) { @@ -597,8 +599,10 @@ pg_SASL_init(PGconn *conn, int payloadlen) if (pqPutnchar(initialresponse, initialresponselen, conn)) goto error; } + conn->current_auth_response = AUTH_RESPONSE_SASL_INITIAL; if (pqPutMsgEnd(conn)) goto error; + if (pqFlush(conn)) goto error; @@ -683,6 +687,7 @@ pg_SASL_continue(PGconn *conn, int payloadlen, bool final) /* * Send the SASL response to the server. */ + conn->current_auth_response = AUTH_RESPONSE_SASL; res = pqPacketSend(conn, PqMsg_SASLResponse, output, outputlen); free(output); @@ -754,6 +759,7 @@ pg_password_sendauth(PGconn *conn, const char *password, AuthRequest areq) default: return STATUS_ERROR; } + conn->current_auth_response = AUTH_RESPONSE_PASSWORD; ret = pqPacketSend(conn, PqMsg_PasswordMessage, pwd_to_send, strlen(pwd_to_send) + 1); free(crypt_pwd); diff --git a/src/interfaces/libpq/fe-trace.c b/src/interfaces/libpq/fe-trace.c index c34047a6e4..367b322b99 100644 --- a/src/interfaces/libpq/fe-trace.c +++ b/src/interfaces/libpq/fe-trace.c @@ -354,6 +354,42 @@ 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) { @@ -610,6 +646,39 @@ 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); + + /* + * These messages share a common type byte, so we discriminate by + * having the code store the auth type separately. + */ + switch (conn->current_auth_response) + { + case AUTH_RESPONSE_GSS: + pqTraceOutput_GSSResponse(conn->Pfdebug, message, + &logCursor, length, regress); + break; + case AUTH_RESPONSE_PASSWORD: + pqTraceOutput_PasswordMessage(conn->Pfdebug, message, + &logCursor); + break; + case AUTH_RESPONSE_SASL_INITIAL: + pqTraceOutput_SASLInitialResponse(conn->Pfdebug, message, + &logCursor, regress); + break; + case AUTH_RESPONSE_SASL: + pqTraceOutput_SASLResponse(conn->Pfdebug, message, + &logCursor, length, regress); + break; + default: + fprintf(conn->Pfdebug, "UnknownAuthenticationResponse"); + break; + } + conn->current_auth_response = '\0'; + 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 f36d76bf3f..03e4da40ba 100644 --- a/src/interfaces/libpq/libpq-int.h +++ b/src/interfaces/libpq/libpq-int.h @@ -331,6 +331,18 @@ typedef enum PGQUERY_CLOSE /* Close Statement or Portal */ } PGQueryClass; + +/* + * valid values for pg_conn->current_auth_response. These are just for + * libpq internal use: since authentication response types all use the + * protocol byte 'p', fe-trace.c needs a way to distinguish them in order + * to print them correctly. + */ +#define AUTH_RESPONSE_GSS 'G' +#define AUTH_RESPONSE_PASSWORD 'P' +#define AUTH_RESPONSE_SASL_INITIAL 'I' +#define AUTH_RESPONSE_SASL 'S' + /* * An entry in the pending command queue. */ @@ -490,7 +502,9 @@ struct pg_conn * codes */ bool client_finished_auth; /* have we finished our half of the * authentication exchange? */ - + char current_auth_response; /* used by pqTraceOutputMessage to + * know which auth response we're + * sending */ /* Transient state needed while establishing connection */ PGTargetServerType target_server_type; /* desired session properties */ -- 2.39.2
^ permalink raw reply [nested|flat] 14+ messages in thread

* Re: libpq: Fix lots of discrepancies in PQtrace
@ 2024-08-10 14:27  Jelte Fennema-Nio <postgres@jeltef.nl>
  parent: Alvaro Herrera <alvherre@alvh.no-ip.org>
  0 siblings, 1 reply; 14+ messages in thread

From: Jelte Fennema-Nio @ 2024-08-10 14:27 UTC (permalink / raw)
  To: Alvaro Herrera <alvherre@alvh.no-ip.org>; +Cc: Michael Paquier <michael@paquier.xyz>; Nathan Bossart <nathandbossart@gmail.com>; PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>

On Sat, 10 Aug 2024 at 01:08, Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
> I don't want to add 4 bytes to struct pg_conn for tracing support.  I'm
> tempted to make the new struct member a plain 'char' to reduce overhead
> for a feature that almost nobody is going to use.  According to pahole
> we have a 3 bytes hole in that position of the struct, so if we make it
> a 1- or 2-byte member, there's no storage overhead whatsoever.

Sounds fine to me.

> Also, why not have pqTraceOutputMessage() responsible for resetting the
> byte after printing the message?  It seems to cause less undesirable
> detritus.

Yeah, that's indeed much nicer.

> I propose something like the attached, but it's as yet untested.  What
> do you think?

Looks good, but I haven't tested it yet either.





^ permalink  raw  reply  [nested|flat] 14+ messages in thread

* Re: libpq: Fix lots of discrepancies in PQtrace
@ 2024-08-12 23:15  Alvaro Herrera <alvherre@alvh.no-ip.org>
  parent: Jelte Fennema-Nio <postgres@jeltef.nl>
  0 siblings, 0 replies; 14+ messages in thread

From: Alvaro Herrera @ 2024-08-12 23:15 UTC (permalink / raw)
  To: Jelte Fennema-Nio <postgres@jeltef.nl>; +Cc: Michael Paquier <michael@paquier.xyz>; Nathan Bossart <nathandbossart@gmail.com>; PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>

On 2024-Aug-10, Jelte Fennema-Nio wrote:

> On Sat, 10 Aug 2024 at 01:08, Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:

> > I propose something like the attached, but it's as yet untested.  What
> > do you think?
> 
> Looks good, but I haven't tested it yet either.

I tested the SASL exchange and it looks OK.  Didn't test the other ones.

Thanks!

-- 
Álvaro Herrera        Breisgau, Deutschland  —  https://www.EnterpriseDB.com/





^ permalink  raw  reply  [nested|flat] 14+ messages in thread

* Re: libpq: Fix lots of discrepancies in PQtrace
@ 2024-08-14 17:37  Alvaro Herrera <alvherre@alvh.no-ip.org>
  parent: Jelte Fennema-Nio <postgres@jeltef.nl>
  1 sibling, 1 reply; 14+ messages in thread

From: Alvaro Herrera @ 2024-08-14 17:37 UTC (permalink / raw)
  To: Jelte Fennema-Nio <postgres@jeltef.nl>; +Cc: Michael Paquier <michael@paquier.xyz>; Nathan Bossart <nathandbossart@gmail.com>; PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>

I gave another look to the remaining patches; here they are again.  I
propose some changes:

- to 0005 I change your pqTraceOutputEncryptionRequestResponse()
  function name to pqTraceOutputCharResponse and instead of attaching
  the "Response" literal in the outpuer to the name given in the
  function call, just pass the whole string as argument to the function.

- to 0006 I change function name pqFinishParsingMessage() to
  pqParseDone() and reworded the commentary; also moved it to fe-misc.c.
  Looks good otherwise.

- 0008 to fix NegotiateProtocolVersion looks correct per [1], but I
  don't know how to test it.  Suggestions?

I didn't look at 0007.

[1] https://www.postgresql.org/docs/16/protocol-message-formats.html#PROTOCOL-MESSAGE-FORMATS-NEGOTIATEP...

-- 
Álvaro Herrera         PostgreSQL Developer  —  https://www.EnterpriseDB.com/
"No hay hombre que no aspire a la plenitud, es decir,
la suma de experiencias de que un hombre es capaz"

Attachments: download all (4 files, .tar.gz)

v3-0005-libpq-Trace-responses-to-SSLRequest-and-GSSENCReq.patch (text/x-diff, 3.6K) download From f34fb8a816a74301c402da32897deab98d1ac069 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 v3 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 (Jelte) called them SSLResponse and GSSENCResponse here. Author: Jelte Fennema-Nio <postgres@jeltef.nl> Discussion: https://postgr.es/m/CAGECzQSoPHtZ4xe0raJ6FYSEiPPS+YWXBhOGo+Y1YecLgknF3g@mail.gmail.com --- src/interfaces/libpq/fe-connect.c | 16 ++++++++++++++++ src/interfaces/libpq/fe-trace.c | 20 ++++++++++++++++++++ src/interfaces/libpq/libpq-int.h | 2 ++ 3 files changed, 38 insertions(+) diff --git a/src/interfaces/libpq/fe-connect.c b/src/interfaces/libpq/fe-connect.c index 360d9a4547..f7ece66b69 100644 --- a/src/interfaces/libpq/fe-connect.c +++ b/src/interfaces/libpq/fe-connect.c @@ -3493,11 +3493,17 @@ keep_going: /* We will come back to here until there is } if (SSLok == 'S') { + if (conn->Pfdebug) + pqTraceOutputCharResponse(conn, "SSLResponse", + SSLok); /* mark byte consumed */ conn->inStart = conn->inCursor; } else if (SSLok == 'N') { + if (conn->Pfdebug) + pqTraceOutputCharResponse(conn, "SSLResponse", + SSLok); /* mark byte consumed */ conn->inStart = conn->inCursor; @@ -3635,6 +3641,11 @@ keep_going: /* We will come back to here until there is if (gss_ok == 'N') { + if (conn->Pfdebug) + pqTraceOutputCharResponse(conn, + "GSSENCResponse", + gss_ok); + /* * The connection is still valid, so if it's OK to * continue without GSS, we can proceed using this @@ -3648,6 +3659,11 @@ keep_going: /* We will come back to here until there is gss_ok); goto error_return; } + + if (conn->Pfdebug) + pqTraceOutputCharResponse(conn, + "GSSENCResponse", + gss_ok); } /* Begin or continue GSSAPI negotiation */ diff --git a/src/interfaces/libpq/fe-trace.c b/src/interfaces/libpq/fe-trace.c index 367b322b99..3bb62397ec 100644 --- a/src/interfaces/libpq/fe-trace.c +++ b/src/interfaces/libpq/fe-trace.c @@ -840,3 +840,23 @@ pqTraceOutputNoTypeByteMessage(PGconn *conn, const char *message) fputc('\n', conn->Pfdebug); } + +/* + * Trace a single-byte backend response received for a specific request + * type the frontend previously sent. Only useful for the simplest of + * FE/BE interaction workflows such as authentication. + */ +void +pqTraceOutputCharResponse(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%s\t %c\n", requestType, response); +} diff --git a/src/interfaces/libpq/libpq-int.h b/src/interfaces/libpq/libpq-int.h index 03e4da40ba..bca3284041 100644 --- a/src/interfaces/libpq/libpq-int.h +++ b/src/interfaces/libpq/libpq-int.h @@ -889,6 +889,8 @@ 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 pqTraceOutputCharResponse(PGconn *conn, const char *requestType, + char response); /* === miscellaneous macros === */ -- 2.39.2
v3-0006-libpq-Trace-all-messages-received-from-the-server.patch (text/x-diff, 8.3K) download From a874cf35382c5c40db914e4500f3755f61fa29d1 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 v3 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 pqParseDone 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 Author: Jelte Fennema-Nio <postgres@jeltef.nl> Discussion: https://postgr.es/m/CAGECzQSoPHtZ4xe0raJ6FYSEiPPS+YWXBhOGo+Y1YecLgknF3g@mail.gmail.com --- src/interfaces/libpq/fe-auth.c | 21 +++++++++++++++++++++ src/interfaces/libpq/fe-connect.c | 13 +++++++++---- src/interfaces/libpq/fe-misc.c | 15 +++++++++++++++ src/interfaces/libpq/fe-protocol3.c | 29 +++++++---------------------- src/interfaces/libpq/libpq-int.h | 1 + 5 files changed, 53 insertions(+), 26 deletions(-) diff --git a/src/interfaces/libpq/fe-auth.c b/src/interfaces/libpq/fe-auth.c index 4da07c1f98..5c8f404463 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; @@ -258,6 +262,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; @@ -563,6 +571,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); /* @@ -651,6 +663,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'; @@ -716,6 +733,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 f7ece66b69..6d110a605c 100644 --- a/src/interfaces/libpq/fe-connect.c +++ b/src/interfaces/libpq/fe-connect.c @@ -3799,7 +3799,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; + pqParseDone(conn, conn->inCursor); /* * Before 7.2, the postmaster didn't always end its @@ -3849,7 +3849,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; + pqParseDone(conn, conn->inCursor); /* * If error is "cannot connect now", try the next host if @@ -3878,7 +3878,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; + pqParseDone(conn, conn->inCursor); goto error_return; } @@ -3903,7 +3903,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 pqParseDone here because we already traced 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-misc.c b/src/interfaces/libpq/fe-misc.c index f235bfbb41..928a47162d 100644 --- a/src/interfaces/libpq/fe-misc.c +++ b/src/interfaces/libpq/fe-misc.c @@ -435,6 +435,21 @@ pqCheckInBufferSpace(size_t bytes_needed, PGconn *conn) return EOF; } +/* + * pqParseDone: after a server-to-client message has successfully + * been parsed, advance conn->inStart to account for it. + */ +void +pqParseDone(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; +} + /* * pqPutMsgStart: begin construction of a message to the server * diff --git a/src/interfaces/libpq/fe-protocol3.c b/src/interfaces/libpq/fe-protocol3.c index 3170d484f0..5d88777e9d 100644 --- a/src/interfaces/libpq/fe-protocol3.c +++ b/src/interfaces/libpq/fe-protocol3.c @@ -454,12 +454,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; + pqParseDone(conn, conn->inCursor); } else { @@ -1728,12 +1724,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; + pqParseDone(conn, conn->inCursor); } } @@ -1791,13 +1782,13 @@ pqGetCopyData3(PGconn *conn, char **buffer, int async) (*buffer)[msgLength] = '\0'; /* Add terminating null */ /* Mark message consumed */ - conn->inStart = conn->inCursor + msgLength; + pqParseDone(conn, conn->inCursor + msgLength); return msgLength; } /* Empty, so drop it and loop around for another */ - conn->inStart = conn->inCursor; + pqParseDone(conn, conn->inCursor); } } @@ -2168,8 +2159,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; + + pqParseDone(conn, conn->inStart + 5 + msgLength); /* * If we already have a result object (probably an error), use @@ -2208,13 +2199,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; + pqParseDone(conn, conn->inStart + 5 + msgLength); needInput = false; } diff --git a/src/interfaces/libpq/libpq-int.h b/src/interfaces/libpq/libpq-int.h index bca3284041..bd3088c91d 100644 --- a/src/interfaces/libpq/libpq-int.h +++ b/src/interfaces/libpq/libpq-int.h @@ -753,6 +753,7 @@ extern PGresult *pqFunctionCall3(PGconn *conn, Oid fnid, */ extern int pqCheckOutBufferSpace(size_t bytes_needed, PGconn *conn); extern int pqCheckInBufferSpace(size_t bytes_needed, PGconn *conn); +extern void pqParseDone(PGconn *conn, int newInStart); extern int pqGetc(char *result, PGconn *conn); extern int pqPutc(char c, PGconn *conn); extern int pqGets(PQExpBuffer buf, PGconn *conn); -- 2.39.2
v3-0007-libpq-Trace-server-Authentication-messages-in-det.patch (text/x-diff, 3.0K) download From 6328de8d46088d90c18e5892e2e5554edc02d831 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 v3 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 3bb62397ec..5fee6580ed 100644 --- a/src/interfaces/libpq/fe-trace.c +++ b/src/interfaces/libpq/fe-trace.c @@ -472,10 +472,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 @@ -714,7 +761,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.39.2
v3-0008-libpq-Trace-NegotiateProtocolVersion-correctly.patch (text/x-diff, 1.4K) download From e68beae1c1b80326f3526631ed160acd2562cf01 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 v3 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 5fee6580ed..47cc1f42dc 100644 --- a/src/interfaces/libpq/fe-trace.c +++ b/src/interfaces/libpq/fe-trace.c @@ -568,9 +568,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.39.2
^ permalink raw reply [nested|flat] 14+ messages in thread

* Re: libpq: Fix lots of discrepancies in PQtrace
@ 2024-08-14 18:18  Jelte Fennema-Nio <postgres@jeltef.nl>
  parent: Alvaro Herrera <alvherre@alvh.no-ip.org>
  0 siblings, 1 reply; 14+ messages in thread

From: Jelte Fennema-Nio @ 2024-08-14 18:18 UTC (permalink / raw)
  To: Alvaro Herrera <alvherre@alvh.no-ip.org>; +Cc: Michael Paquier <michael@paquier.xyz>; Nathan Bossart <nathandbossart@gmail.com>; PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>

On Wed, 14 Aug 2024 at 19:37, Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
> - to 0005 I change your pqTraceOutputEncryptionRequestResponse()
>   function name to pqTraceOutputCharResponse and instead of attaching
>   the "Response" literal in the outpuer to the name given in the
>   function call, just pass the whole string as argument to the function.

Fine by me

> - to 0006 I change function name pqFinishParsingMessage() to
>   pqParseDone() and reworded the commentary; also moved it to fe-misc.c.
>   Looks good otherwise.

The following removed comments seems useful to keep (I realize I
already removed them in a previous version of the patch, but I don't
think I did that on purpose)

-       /* Drop the processed message and loop around for another */

-               /* consume the message and exit */


-       /* Completed this message, keep going */
-       /* trust the specified message length as what to skip */


> - 0008 to fix NegotiateProtocolVersion looks correct per [1], but I
>   don't know how to test it.  Suggestions?

Two options:
1. Manually change code to make sure SendNegotiateProtocolVersion is
called in src/backend/tcop/backend_startup.c
2. Apply my patches from this thread[2] and use
max_protocol_version=latest in the connection string while connecting
to an older postgres server.

[2]: https://www.postgresql.org/message-id/flat/CAGECzQTyXDNtMXdq2L-Wp%3DOvOCPa07r6%2BU_MGb%3D%3Dh90MrfT%...





^ permalink  raw  reply  [nested|flat] 14+ messages in thread

* Re: libpq: Fix lots of discrepancies in PQtrace
@ 2024-08-16 00:05  Alvaro Herrera <alvherre@alvh.no-ip.org>
  parent: Jelte Fennema-Nio <postgres@jeltef.nl>
  0 siblings, 0 replies; 14+ messages in thread

From: Alvaro Herrera @ 2024-08-16 00:05 UTC (permalink / raw)
  To: Jelte Fennema-Nio <postgres@jeltef.nl>; +Cc: Michael Paquier <michael@paquier.xyz>; Nathan Bossart <nathandbossart@gmail.com>; PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>

Hello,

On 2024-Aug-14, Jelte Fennema-Nio wrote:

> The following removed comments seems useful to keep (I realize I
> already removed them in a previous version of the patch, but I don't
> think I did that on purpose)
> [...]

Ah, yeah, I agree.  I put them back, and pushed 0005, 6 and 7 as a
single commit.  It didn't seem worth pushing each separately, really.  I
added two lines for the CopyData message as well, since otherwise the
output shows the "mismatched length" error when getting COPY data.

I'm leaving 0008 to whoever is doing the NegotiateProtocolVersion stuff;
maybe post that one in that thread you mentioned.  I'll mark this CF
entry committed.

Many thanks!

-- 
Álvaro Herrera        Breisgau, Deutschland  —  https://www.EnterpriseDB.com/





^ permalink  raw  reply  [nested|flat] 14+ messages in thread


end of thread, other threads:[~2024-08-16 00:05 UTC | newest]

Thread overview: 14+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2024-06-21 09:22 libpq: Fix lots of discrepancies in PQtrace Jelte Fennema-Nio <postgres@jeltef.nl>
2024-06-21 21:01 ` Nathan Bossart <nathandbossart@gmail.com>
2024-06-26 16:28   ` Nathan Bossart <nathandbossart@gmail.com>
2024-06-26 16:36     ` Alvaro Herrera <alvherre@alvh.no-ip.org>
2024-06-26 20:02       ` Jelte Fennema-Nio <postgres@jeltef.nl>
2024-06-27 05:39         ` Michael Paquier <michael@paquier.xyz>
2024-06-27 08:03           ` Jelte Fennema-Nio <postgres@jeltef.nl>
2024-08-09 22:08             ` Alvaro Herrera <alvherre@alvh.no-ip.org>
2024-08-09 23:08               ` Alvaro Herrera <alvherre@alvh.no-ip.org>
2024-08-10 14:27                 ` Jelte Fennema-Nio <postgres@jeltef.nl>
2024-08-12 23:15                   ` Alvaro Herrera <alvherre@alvh.no-ip.org>
2024-08-14 17:37             ` Alvaro Herrera <alvherre@alvh.no-ip.org>
2024-08-14 18:18               ` Jelte Fennema-Nio <postgres@jeltef.nl>
2024-08-16 00:05                 ` Alvaro Herrera <alvherre@alvh.no-ip.org>

This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox