Feedback-ID: ia2694551:Fastmail
Date: Wed, 14 Aug 2024 13:37:30 -0400
From: Alvaro Herrera <alvherre@alvh.no-ip.org>
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>
Subject: Re: libpq: Fix lots of discrepancies in PQtrace
Message-ID: <202408141737.cneamqvnv4l4@alvherre.pgsql>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="hqh5ifezvx5otzff"
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: 
 <CAGECzQQwXdvy2gMNChJcq4nT3HU1KzMfnS3PD_Erk3viFUpoQQ@mail.gmail.com>
Archived-At: 
 <https://www.postgresql.org/message-id/202408141737.cneamqvnv4l4%40alvherre.pgsql>
Precedence: bulk


--hqh5ifezvx5otzff
Content-Type: text/plain; charset=utf-8
Content-Disposition: inline
Content-Transfer-Encoding: 8bit

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

-- 
Á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"

--hqh5ifezvx5otzff
Content-Type: text/x-diff; charset=utf-8
Content-Disposition: attachment;
	filename="v3-0005-libpq-Trace-responses-to-SSLRequest-and-GSSENCReq.patch"

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


--hqh5ifezvx5otzff
Content-Type: text/x-diff; charset=utf-8
Content-Disposition: attachment;
	filename="v3-0006-libpq-Trace-all-messages-received-from-the-server.patch"

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


--hqh5ifezvx5otzff
Content-Type: text/x-diff; charset=utf-8
Content-Disposition: attachment;
	filename="v3-0007-libpq-Trace-server-Authentication-messages-in-det.patch"

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


--hqh5ifezvx5otzff
Content-Type: text/x-diff; charset=utf-8
Content-Disposition: attachment;
	filename="v3-0008-libpq-Trace-NegotiateProtocolVersion-correctly.patch"

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


--hqh5ifezvx5otzff--