Improve PQtrace() output format

Transform the PQtrace output format from its ancient (and mostly
useless) byte-level output format to a logical-message-level output,
making it much more usable.  This implementation allows the printing
code to be written (as it indeed was) by looking at the protocol
documentation, which gives more confidence that the three (docs, trace
code and actual code) actually match.

Author: 岩田 彩 (Aya Iwata) <iwata.aya@fujitsu.com>
Reviewed-by: 綱川 貴之 (Takayuki Tsunakawa) <tsunakawa.takay@fujitsu.com>
Reviewed-by: Kirk Jamison <k.jamison@fujitsu.com>
Reviewed-by: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
Reviewed-by: Tom Lane <tgl@sss.pgh.pa.us>
Reviewed-by: 黒田 隼人 (Hayato Kuroda) <kuroda.hayato@fujitsu.com>
Reviewed-by: "Nagaura, Ryohei" <nagaura.ryohei@jp.fujitsu.com>
Reviewed-by: Ryo Matsumura <matsumura.ryo@fujitsu.com>
Reviewed-by: Greg Nancarrow <gregn4422@gmail.com>
Reviewed-by: Jim Doty <jdoty@pivotal.io>
Reviewed-by: Álvaro Herrera <alvherre@alvh.no-ip.org>
Discussion: https://postgr.es/m/71E660EB361DF14299875B198D4CE5423DE3FBA4@g01jpexmbkw25

doc/src/sgml/libpq.sgml

@@ -6459,12 +6459,27 @@ PGContextVisibility PQsetErrorContextVisibility(PGconn *conn, PGContextVisibilit
 
     <listitem>
      <para>
-      Enables  tracing of the client/server communication to a debugging file stream.
+      Enables tracing of the client/server communication to a debugging file
+      stream.
 <synopsis>
 void PQtrace(PGconn *conn, FILE *stream);
 </synopsis>
      </para>
 
+     <para>
+      Each line consists of: an optional timestamp, a direction indicator
+      (<literal>F</literal> for messages from client to server
+      or <literal>B</literal> for messages from server to client),
+      message length, message type, and message contents.
+      Non-message contents fields (timestamp, direction, length and message type)
+      are separated by a tab. Message contents are separated by a space.
+      Protocol strings are enclosed in double quotes, while strings used as data
+      values are enclosed in single quotes.  Non-printable chars are printed as
+      hexadecimal escapes.
+      Further message-type-specific detail can be found in
+      <xref linkend="protocol-message-formats"/>.
+     </para>
+
      <note>
       <para>
        On Windows, if the <application>libpq</application> library and an application are
@@ -6479,6 +6494,31 @@ void PQtrace(PGconn *conn, FILE *stream);
     </listitem>
    </varlistentry>
 
+   <varlistentry id="libpq-PQtraceSetFlags">
+    <term><function>PQtraceSetFlags</function><indexterm><primary>PQtraceSetFlags</primary></indexterm></term>
+
+    <listitem>
+     <para>
+      Controls the tracing behavior of client/server communication.
+<synopsis>
+void PQtraceSetFlags(PGconn *conn, int flags);
+</synopsis>
+     </para>
+
+     <para>
+      <literal>flags</literal> contains flag bits describing the operating mode
+      of tracing.
+      If <literal>flags</literal> contains <literal>PQTRACE_SUPPRESS_TIMESTAMPS</literal>,
+      then the timestamp is not included when printing each message.
+      If <literal>flags</literal> contains <literal>PQTRACE_REGRESS_MODE</literal>,
+      then some fields are redacted when printing each message, such as object
+      OIDs, to make the output more convenient to use in testing frameworks.
+      This function must be called after calling <function>PQtrace</function>.
+     </para>
+
+    </listitem>
+   </varlistentry>
+
    <varlistentry id="libpq-PQuntrace">
     <term><function>PQuntrace</function><indexterm><primary>PQuntrace</primary></indexterm></term>
 

src/interfaces/libpq/Makefile

@@ -39,6 +39,7 @@ OBJS = \
 	fe-print.o \
 	fe-protocol3.o \
 	fe-secure.o \
+	fe-trace.o \
 	legacy-pqsignal.o \
 	libpq-events.o \
 	pqexpbuffer.o \

src/interfaces/libpq/exports.txt

@@ -183,3 +183,4 @@ PQenterPipelineMode       180
 PQexitPipelineMode        181
 PQpipelineSync            182
 PQpipelineStatus          183
+PQtraceSetFlags           184

src/interfaces/libpq/fe-connect.c

@@ -6859,27 +6859,6 @@ PQsetErrorContextVisibility(PGconn *conn, PGContextVisibility show_context)
 	return old;
 }
 
-void
-PQtrace(PGconn *conn, FILE *debug_port)
-{
-	if (conn == NULL)
-		return;
-	PQuntrace(conn);
-	conn->Pfdebug = debug_port;
-}
-
-void
-PQuntrace(PGconn *conn)
-{
-	if (conn == NULL)
-		return;
-	if (conn->Pfdebug)
-	{
-		fflush(conn->Pfdebug);
-		conn->Pfdebug = NULL;
-	}
-}
-
 PQnoticeReceiver
 PQsetNoticeReceiver(PGconn *conn, PQnoticeReceiver proc, void *arg)
 {

src/interfaces/libpq/fe-exec.c

@@ -970,10 +970,6 @@ pqSaveParameterStatus(PGconn *conn, const char *name, const char *value)
 	pgParameterStatus *pstatus;
 	pgParameterStatus *prev;
 
-	if (conn->Pfdebug)
-		fprintf(conn->Pfdebug, "pqSaveParameterStatus: '%s' = '%s'\n",
-				name, value);
-
 	/*
 	 * Forget any old information about the parameter
 	 */

src/interfaces/libpq/fe-misc.c

@@ -84,9 +84,6 @@ pqGetc(char *result, PGconn *conn)
 
 	*result = conn->inBuffer[conn->inCursor++];
 
-	if (conn->Pfdebug)
-		fprintf(conn->Pfdebug, "From backend> %c\n", *result);
-
 	return 0;
 }
 
@@ -100,9 +97,6 @@ pqPutc(char c, PGconn *conn)
 	if (pqPutMsgBytes(&c, 1, conn))
 		return EOF;
 
-	if (conn->Pfdebug)
-		fprintf(conn->Pfdebug, "To backend> %c\n", c);
-
 	return 0;
 }
 
@@ -138,10 +132,6 @@ pqGets_internal(PQExpBuffer buf, PGconn *conn, bool resetbuffer)
 
 	conn->inCursor = ++inCursor;
 
-	if (conn->Pfdebug)
-		fprintf(conn->Pfdebug, "From backend> \"%s\"\n",
-				buf->data);
-
 	return 0;
 }
 
@@ -167,9 +157,6 @@ pqPuts(const char *s, PGconn *conn)
 	if (pqPutMsgBytes(s, strlen(s) + 1, conn))
 		return EOF;
 
-	if (conn->Pfdebug)
-		fprintf(conn->Pfdebug, "To backend> \"%s\"\n", s);
-
 	return 0;
 }
 
@@ -188,13 +175,6 @@ pqGetnchar(char *s, size_t len, PGconn *conn)
 
 	conn->inCursor += len;
 
-	if (conn->Pfdebug)
-	{
-		fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len);
-		fwrite(s, 1, len, conn->Pfdebug);
-		fprintf(conn->Pfdebug, "\n");
-	}
-
 	return 0;
 }
 
@@ -212,13 +192,6 @@ pqSkipnchar(size_t len, PGconn *conn)
 	if (len > (size_t) (conn->inEnd - conn->inCursor))
 		return EOF;
 
-	if (conn->Pfdebug)
-	{
-		fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len);
-		fwrite(conn->inBuffer + conn->inCursor, 1, len, conn->Pfdebug);
-		fprintf(conn->Pfdebug, "\n");
-	}
-
 	conn->inCursor += len;
 
 	return 0;
@@ -234,13 +207,6 @@ pqPutnchar(const char *s, size_t len, PGconn *conn)
 	if (pqPutMsgBytes(s, len, conn))
 		return EOF;
 
-	if (conn->Pfdebug)
-	{
-		fprintf(conn->Pfdebug, "To backend> ");
-		fwrite(s, 1, len, conn->Pfdebug);
-		fprintf(conn->Pfdebug, "\n");
-	}
-
 	return 0;
 }
 
@@ -278,9 +244,6 @@ pqGetInt(int *result, size_t bytes, PGconn *conn)
 			return EOF;
 	}
 
-	if (conn->Pfdebug)
-		fprintf(conn->Pfdebug, "From backend (#%lu)> %d\n", (unsigned long) bytes, *result);
-
 	return 0;
 }
 
@@ -314,9 +277,6 @@ pqPutInt(int value, size_t bytes, PGconn *conn)
 			return EOF;
 	}
 
-	if (conn->Pfdebug)
-		fprintf(conn->Pfdebug, "To backend (%lu#)> %d\n", (unsigned long) bytes, value);
-
 	return 0;
 }
 
@@ -525,10 +485,6 @@ pqPutMsgStart(char msg_type, PGconn *conn)
 	conn->outMsgEnd = endPos;
 	/* length word, if needed, will be filled in by pqPutMsgEnd */
 
-	if (conn->Pfdebug)
-		fprintf(conn->Pfdebug, "To backend> Msg %c\n",
-				msg_type ? msg_type : ' ');
-
 	return 0;
 }
 
@@ -563,10 +519,6 @@ pqPutMsgBytes(const void *buf, size_t len, PGconn *conn)
 int
 pqPutMsgEnd(PGconn *conn)
 {
-	if (conn->Pfdebug)
-		fprintf(conn->Pfdebug, "To backend> Msg complete, length %u\n",
-				conn->outMsgEnd - conn->outCount);
-
 	/* Fill in length word if needed */
 	if (conn->outMsgStart >= 0)
 	{
@@ -576,6 +528,16 @@ pqPutMsgEnd(PGconn *conn)
 		memcpy(conn->outBuffer + conn->outMsgStart, &msgLen, 4);
 	}
 
+	/* trace client-to-server message */
+	if (conn->Pfdebug)
+	{
+		if (conn->outCount < conn->outMsgStart)
+			pqTraceOutputMessage(conn, conn->outBuffer + conn->outCount, true);
+		else
+			pqTraceOutputNoTypeByteMessage(conn,
+										   conn->outBuffer + conn->outMsgStart);
+	}
+
 	/* Make message eligible to send */
 	conn->outCount = conn->outMsgEnd;
 
@@ -1002,11 +964,13 @@ pqSendSome(PGconn *conn, int len)
 int
 pqFlush(PGconn *conn)
 {
-	if (conn->Pfdebug)
-		fflush(conn->Pfdebug);
-
 	if (conn->outCount > 0)
+	{
+		if (conn->Pfdebug)
+			fflush(conn->Pfdebug);
+
 		return pqSendSome(conn, conn->outCount);
+	}
 
 	return 0;
 }

src/interfaces/libpq/fe-protocol3.c

@@ -457,6 +457,10 @@ 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;
 		}
@@ -1660,6 +1664,10 @@ 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;
 	}
@@ -2119,6 +2127,11 @@ pqFunctionCall3(PGconn *conn, Oid fnid,
 				conn->inStart += 5 + msgLength;
 				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;

src/interfaces/libpq/libpq-fe.h

@@ -263,7 +263,7 @@ typedef struct pgresAttDesc
  * ----------------
  */
 
-/* ===	in fe-connect.c === */
+/* === in fe-connect.c === */
 
 /* make a new client connection to the backend */
 /* Asynchronous (non-blocking) */
@@ -375,10 +375,6 @@ extern PGVerbosity PQsetErrorVerbosity(PGconn *conn, PGVerbosity verbosity);
 extern PGContextVisibility PQsetErrorContextVisibility(PGconn *conn,
 													   PGContextVisibility show_context);
 
-/* Enable/disable tracing */
-extern void PQtrace(PGconn *conn, FILE *debug_port);
-extern void PQuntrace(PGconn *conn);
-
 /* Override default notice handling routines */
 extern PQnoticeReceiver PQsetNoticeReceiver(PGconn *conn,
 											PQnoticeReceiver proc,
@@ -398,6 +394,17 @@ typedef void (*pgthreadlock_t) (int acquire);
 
 extern pgthreadlock_t PQregisterThreadLock(pgthreadlock_t newhandler);
 
+/* === in fe-trace.c === */
+extern void PQtrace(PGconn *conn, FILE *debug_port);
+extern void PQuntrace(PGconn *conn);
+
+/* flags controlling trace output */
+/* omit timestamps from each line */
+#define PQTRACE_SUPPRESS_TIMESTAMPS		(1<<0)
+/* redact portions of some messages, for testing frameworks */
+#define PQTRACE_REGRESS_MODE			(1<<1)
+extern void PQtraceSetFlags(PGconn *conn, int flags);
+
 /* === in fe-exec.c === */
 
 /* Simple synchronous query */

src/interfaces/libpq/libpq-int.h

@@ -394,6 +394,7 @@ struct pg_conn
 
 	/* Optional file to write trace info to */
 	FILE	   *Pfdebug;
+	int			traceFlags;
 
 	/* Callback procedures for notice message processing */
 	PGNoticeHooks noticeHooks;
@@ -818,6 +819,12 @@ extern ssize_t pg_GSS_write(PGconn *conn, const void *ptr, size_t len);
 extern ssize_t pg_GSS_read(PGconn *conn, void *ptr, size_t len);
 #endif
 
+/* === in libpq-trace.c === */
+
+extern void pqTraceOutputMessage(PGconn *conn, const char *message,
+								 bool toServer);
+extern void pqTraceOutputNoTypeByteMessage(PGconn *conn, const char *message);
+
 /* === miscellaneous macros === */
 
 /*