From 61e135006c3f48d6d5fb3e5a5400fca448e4cbc4 Mon Sep 17 00:00:00 2001
From: Alvaro Herrera <alvherre@alvh.no-ip.org>
Date: Wed, 16 Sep 2020 13:13:45 -0300
Subject: [PATCH v9] libpq trace

---
 doc/src/sgml/libpq.sgml             |   1 +
 src/interfaces/libpq/fe-connect.c   |  12 +-
 src/interfaces/libpq/fe-misc.c      | 576 ++++++++++++++++++++++++++--
 src/interfaces/libpq/fe-protocol3.c |   8 +
 src/interfaces/libpq/libpq-int.h    |  15 +
 src/tools/pgindent/typedefs.list    |   5 +
 6 files changed, 588 insertions(+), 29 deletions(-)

diff --git a/doc/src/sgml/libpq.sgml b/doc/src/sgml/libpq.sgml
index de60281fcb..bd6d89cf0f 100644
--- a/doc/src/sgml/libpq.sgml
+++ b/doc/src/sgml/libpq.sgml
@@ -5844,6 +5844,7 @@ PGContextVisibility PQsetErrorContextVisibility(PGconn *conn, PGContextVisibilit
     <listitem>
      <para>
       Enables  tracing of the client/server communication to a debugging file stream.
+      (Details of tracing contents appear in <xref linkend="protocol-message-formats"/>).
 <synopsis>
 void PQtrace(PGconn *conn, FILE *stream);
 </synopsis>
diff --git a/src/interfaces/libpq/fe-connect.c b/src/interfaces/libpq/fe-connect.c
index b0ca37c2ed..856e011d9a 100644
--- a/src/interfaces/libpq/fe-connect.c
+++ b/src/interfaces/libpq/fe-connect.c
@@ -6809,7 +6809,17 @@ PQtrace(PGconn *conn, FILE *debug_port)
 	if (conn == NULL)
 		return;
 	PQuntrace(conn);
-	conn->Pfdebug = debug_port;
+	if (pqTraceInit(conn))
+	{
+		conn->Pfdebug = debug_port;
+		setlinebuf(conn->Pfdebug);
+	}
+	else
+	{
+		/* XXX report ENOMEM? */
+		fprintf(conn->Pfdebug, "Failed to initialize trace support\n");
+		fflush(conn->Pfdebug);
+	}
 }
 
 void
diff --git a/src/interfaces/libpq/fe-misc.c b/src/interfaces/libpq/fe-misc.c
index 4ffc7f33fb..a6bb64dd5a 100644
--- a/src/interfaces/libpq/fe-misc.c
+++ b/src/interfaces/libpq/fe-misc.c
@@ -53,11 +53,154 @@
 #include "pg_config_paths.h"
 #include "port/pg_bswap.h"
 
+/* Log message source */
+typedef enum
+{
+	FROM_BACKEND,
+	FROM_FRONTEND
+} PGCommSource;
+
+/* Messages from backend */
+typedef enum PGLogState
+{
+	LOG_FIRST_BYTE,				/* logging the first byte identifing the
+								 * protocol message type */
+	LOG_LENGTH,					/* logging protocol message length */
+	LOG_CONTENTS				/* logging protocol message contents */
+} PGLogState;
+
+typedef struct pqBackendMessage
+{
+	PGLogState	state;			/* state of logging message state machine */
+	int			length;			/* protocol message length */
+	char		command;		/* first one byte of protocol message */
+} pqBackendMessage;
+
+/* Messages from frontend */
+#define MAX_FRONTEND_MSGS 1024
+typedef enum
+{
+	LOG_BYTE1,
+	LOG_STRING,
+	LOG_NCHAR,
+	LOG_INT16,
+	LOG_INT32
+} PGLogMsgDataType;
+
+typedef struct pqFrontendMessage
+{
+	PGLogMsgDataType type;
+	int			message_addr;
+	int			message_length;
+} pqFrontendMessage;
+
+/*
+ * protocol message types:
+ *
+ * protocol_message_type_b[]: message types sent by a backend
+ * protocol_message_type_f[]: message types sent by a frontend
+ */
+static const char *const protocol_message_type_b[] = {
+	0,							/* 0 */
+	"ParseComplete",			/* 1 */
+	"BindComplete",				/* 2 */
+	"CloseComplete",			/* 3 */
+	0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x04 ... \x0f */
+	0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x10 ... \x1f */
+	0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x20 ... \x2f */
+	0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x30 ... \x3f */
+	0,							/* @ */
+	"NotificationResponse",		/* A */
+	0,							/* B */
+	"CommandComplete",			/* C */
+	"DataRow",					/* D */
+	"ErrorResponse",			/* E */
+	0,							/* F */
+	"CopyInResponse",			/* G */
+	"CopyOutResponse",			/* H */
+	"EmptyQueryResponse",		/* I */
+	0,							/* J */
+	"BackendKeyData",			/* K */
+	0,							/* L */
+	0,							/* M */
+	"NoticeResponse",			/* N */
+	0,							/* O */
+	0,							/* P */
+	0,							/* Q */
+	"Authentication",			/* R */
+	"ParameterStatus",			/* S */
+	"RowDescription",			/* T */
+	0,							/* U */
+	"FunctionCallResponse",		/* V */
+	"CopyBothResponse",			/* W */
+	0,							/* X */
+	0,							/* Y */
+	"ReadyForQuery",			/* Z */
+	0, 0, 0, 0, 0,				/* \x5b ... \x5f */
+	0,							/* ` */
+	0,							/* a */
+	0,							/* b */
+	"CopyDone",					/* c */
+	"CopyData",					/* d */
+	0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,	/* \x65 ... \0x6d */
+	"NoData",					/* n */
+	0,							/* o */
+	0,							/* p */
+	0,							/* q */
+	0,							/* r */
+	"PortalSuspended",			/* s */
+	"ParameterDescription",		/* t */
+	0,							/* u */
+	"NegotiateProtocolVersion", /* v */
+};
+
+static const char *const protocol_message_type_f[] = {
+	0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x00 ... \x0f */
+	0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x10 ... \x1f */
+	0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x20 ... \x2f */
+	0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x30 ... \x3f */
+	0,							/* @ */
+	0,							/* A */
+	"Bind",						/* B */
+	"Close",					/* C */
+	"Describe",					/* D */
+	"Execute",					/* E */
+	"FunctionCall",				/* F */
+	0,							/* G */
+	"Flush",					/* H */
+	0, 0, 0, 0, 0, 0, 0,		/* I ... O */
+	"Parse",					/* P */
+	"Query",					/* Q */
+	0,							/* R */
+	"Sync",						/* S */
+	0, 0, 0, 0,					/* T ... W */
+	"Terminate",				/* X */
+	0, 0, 0, 0, 0, 0, 0,		/* \x59 ... \x5f */
+	0,							/* ` */
+	0,							/* a */
+	0,							/* b */
+	"CopyDone",					/* c */
+	"CopyData",					/* d */
+	0,							/* e */
+	"CopyFail",					/* f */
+	0, 0, 0, 0, 0, 0, 0, 0, 0,	/* g ... o */
+	"AuthenticationResponse",	/* p */
+};
+
 static int	pqPutMsgBytes(const void *buf, size_t len, PGconn *conn);
 static int	pqSendSome(PGconn *conn, int len);
 static int	pqSocketCheck(PGconn *conn, int forRead, int forWrite,
 						  time_t end_time);
 static int	pqSocketPoll(int sock, int forRead, int forWrite, time_t end_time);
+static void pqStoreFrontendMsg(PGconn *conn, PGLogMsgDataType type, int length);
+static void pqLogFrontendMsg(PGconn *conn);
+static void pqLogMsgByte1(PGconn *conn, char v, PGCommSource commsource);
+static void pqLogMsgInt(PGconn *conn, int v, int length, PGCommSource commsource);
+static void pqLogMsgString(PGconn *conn, const char *v, int length,
+						   PGCommSource commsource);
+static void pqLogMsgnchar(PGconn *conn, const char *v, int length,
+						  PGCommSource commsource);
+
 
 /*
  * PQlibVersion: return the libpq version number
@@ -85,7 +228,7 @@ pqGetc(char *result, PGconn *conn)
 	*result = conn->inBuffer[conn->inCursor++];
 
 	if (conn->Pfdebug)
-		fprintf(conn->Pfdebug, "From backend> %c\n", *result);
+		pqLogMsgByte1(conn, *result, FROM_BACKEND);
 
 	return 0;
 }
@@ -101,7 +244,7 @@ pqPutc(char c, PGconn *conn)
 		return EOF;
 
 	if (conn->Pfdebug)
-		fprintf(conn->Pfdebug, "To backend> %c\n", c);
+		pqStoreFrontendMsg(conn, LOG_BYTE1, 1);
 
 	return 0;
 }
@@ -139,8 +282,7 @@ pqGets_internal(PQExpBuffer buf, PGconn *conn, bool resetbuffer)
 	conn->inCursor = ++inCursor;
 
 	if (conn->Pfdebug)
-		fprintf(conn->Pfdebug, "From backend> \"%s\"\n",
-				buf->data);
+		pqLogMsgString(conn, buf->data, buf->len + 1, FROM_BACKEND);
 
 	return 0;
 }
@@ -168,7 +310,7 @@ pqPuts(const char *s, PGconn *conn)
 		return EOF;
 
 	if (conn->Pfdebug)
-		fprintf(conn->Pfdebug, "To backend> \"%s\"\n", s);
+		pqStoreFrontendMsg(conn, LOG_STRING, strlen(s) + 1);
 
 	return 0;
 }
@@ -189,11 +331,7 @@ 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");
-	}
+		pqLogMsgnchar(conn, s, len, FROM_BACKEND);
 
 	return 0;
 }
@@ -213,11 +351,7 @@ pqSkipnchar(size_t len, PGconn *conn)
 		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");
-	}
+		pqLogMsgnchar(conn, conn->inBuffer + conn->inCursor, len, FROM_BACKEND);
 
 	conn->inCursor += len;
 
@@ -235,11 +369,7 @@ pqPutnchar(const char *s, size_t len, PGconn *conn)
 		return EOF;
 
 	if (conn->Pfdebug)
-	{
-		fprintf(conn->Pfdebug, "To backend> ");
-		fwrite(s, 1, len, conn->Pfdebug);
-		fprintf(conn->Pfdebug, "\n");
-	}
+		pqStoreFrontendMsg(conn, LOG_NCHAR, len);
 
 	return 0;
 }
@@ -279,7 +409,7 @@ pqGetInt(int *result, size_t bytes, PGconn *conn)
 	}
 
 	if (conn->Pfdebug)
-		fprintf(conn->Pfdebug, "From backend (#%lu)> %d\n", (unsigned long) bytes, *result);
+		pqLogMsgInt(conn, *result, (unsigned int) bytes, FROM_BACKEND);
 
 	return 0;
 }
@@ -301,11 +431,15 @@ pqPutInt(int value, size_t bytes, PGconn *conn)
 			tmp2 = pg_hton16((uint16) value);
 			if (pqPutMsgBytes((const char *) &tmp2, 2, conn))
 				return EOF;
+			if (conn->Pfdebug)
+				pqStoreFrontendMsg(conn, LOG_INT16, 2);
 			break;
 		case 4:
 			tmp4 = pg_hton32((uint32) value);
 			if (pqPutMsgBytes((const char *) &tmp4, 4, conn))
 				return EOF;
+			if (conn->Pfdebug)
+				pqStoreFrontendMsg(conn, LOG_INT32, 4);
 			break;
 		default:
 			pqInternalNotice(&conn->noticeHooks,
@@ -313,10 +447,6 @@ pqPutInt(int value, size_t bytes, PGconn *conn)
 							 (unsigned long) bytes);
 			return EOF;
 	}
-
-	if (conn->Pfdebug)
-		fprintf(conn->Pfdebug, "To backend (%lu#)> %d\n", (unsigned long) bytes, value);
-
 	return 0;
 }
 
@@ -535,8 +665,7 @@ pqPutMsgStart(char msg_type, bool force_len, PGconn *conn)
 	/* 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 : ' ');
+		pqLogMsgByte1(conn, msg_type, FROM_FRONTEND);
 
 	return 0;
 }
@@ -572,15 +701,23 @@ pqPutMsgBytes(const void *buf, size_t len, PGconn *conn)
 int
 pqPutMsgEnd(PGconn *conn)
 {
-	if (conn->Pfdebug)
+	if (conn->Pfdebug && PG_PROTOCOL_MAJOR(conn->pversion) < 3)
+	{
 		fprintf(conn->Pfdebug, "To backend> Msg complete, length %u\n",
 				conn->outMsgEnd - conn->outCount);
+	}
 
 	/* Fill in length word if needed */
 	if (conn->outMsgStart >= 0)
 	{
 		uint32		msgLen = conn->outMsgEnd - conn->outMsgStart;
 
+		if (conn->Pfdebug)
+		{
+			pqLogMsgInt(conn, (int) msgLen, 4, FROM_FRONTEND);
+			pqLogFrontendMsg(conn);
+		}
+
 		msgLen = pg_hton32(msgLen);
 		memcpy(conn->outBuffer + conn->outMsgStart, &msgLen, 4);
 	}
@@ -600,6 +737,383 @@ pqPutMsgEnd(PGconn *conn)
 	return 0;
 }
 
+/* -------------------------
+ * FE/BE trace support
+ *
+ * We accumulate frontend message pieces in an array as the libpq code writes
+ * them, and log the complete message when pqLogFrontendMsg is called.
+ * For backend, we print the pieces as soon as we receive them from the server.
+ * -------------------------
+ */
+
+/*
+ * Set up state so that we can trace. NB -- this might be called mutiple
+ * times in a process; make sure it's idempotent.  We don't release memory
+ * on PQuntrace(), as that would be useless.
+ */
+bool
+pqTraceInit(PGconn *conn)
+{
+	/* already done? */
+	if (conn->be_msg != NULL)
+	{
+		conn->n_fe_msgs = 0;
+		conn->be_msg->state = LOG_FIRST_BYTE;
+		conn->be_msg->length = 0;
+		return true;
+	}
+
+	conn->be_msg = malloc(sizeof(pqBackendMessage));
+	if (conn->be_msg == NULL)
+		return false;
+	conn->be_msg->state = LOG_FIRST_BYTE;
+	conn->be_msg->length = 0;
+
+	conn->fe_msg = malloc(MAX_FRONTEND_MSGS * sizeof(pqFrontendMessage));
+	if (conn->fe_msg == NULL)
+	{
+		free(conn->be_msg);
+		return false;
+	}
+	conn->n_fe_msgs = 0;
+
+	return true;
+}
+
+/*
+ * pqGetProtocolMsgType:
+ *		Get a protocol type from first byte identifier
+ */
+static const char *
+pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
+{
+	if (commsource == FROM_BACKEND && c < lengthof(protocol_message_type_b))
+		return protocol_message_type_b[c];
+	else if (commsource == FROM_FRONTEND && c < lengthof(protocol_message_type_f))
+		return protocol_message_type_f[c];
+	else
+		return "UnknownCommand";
+}
+
+/* pqTraceResetBeMsg: Initialize backend message */
+static void
+pqTraceResetBeMsg(PGconn *conn)
+{
+	conn->be_msg->state = LOG_FIRST_BYTE;
+	conn->be_msg->length = 0;
+}
+
+/* pqLogInvalidProtocol: Print that the protocol message is invalid */
+static void
+pqLogInvalidProtocol(PGconn *conn)
+{
+	fprintf(conn->Pfdebug, ":::Invalid Protocol\n");
+	conn->be_msg->state = LOG_FIRST_BYTE;
+}
+
+/*
+ * pqTraceMaybeBreakLine:
+ *		Check whether the backend message is complete. If so, print a line
+ *		break and reset the buffer.
+ */
+void
+pqTraceMaybeBreakLine(int size, PGconn *conn)
+{
+	conn->be_msg->length -= size;
+	if (conn->be_msg->length <= 0)
+	{
+		fprintf(conn->Pfdebug, "\n");
+		pqTraceResetBeMsg(conn);
+	}
+}
+
+/*
+ * pqStoreFrontendMsg
+ *		Store message sent by frontend for later display.
+ *
+ *		In protocol v2, we immediately print each message as we receive it.
+ *		(XXX why?)
+ *		In protocol v3, we store the messages and print them all as a single
+ *		line when we get the message-end.
+ *
+ * XXX -- ??
+ * 	Message length is added at the last if message is sent by the frontend.
+ * 	To arrange the log output format, frontend message contents are stored in the list.
+ */
+static void
+pqStoreFrontendMsg(PGconn *conn, PGLogMsgDataType type, int length)
+{
+	char		message;
+	uint16		result16 = 0;
+	uint32		result32 = 0;
+	int			result = 0;
+
+	if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+	{
+		conn->fe_msg[conn->n_fe_msgs].type = type;
+		conn->fe_msg[conn->n_fe_msgs].message_addr = conn->outMsgEnd - length;
+		conn->fe_msg[conn->n_fe_msgs].message_length = length;
+		conn->n_fe_msgs++;
+		/* make sure not to overrun the buffer when a message is too large */
+		if (conn->n_fe_msgs >= MAX_FRONTEND_MSGS)
+			pqLogFrontendMsg(conn);
+	}
+	else
+	{
+		/* Output one content per line in older protocol version */
+		switch (type)
+		{
+			case LOG_BYTE1:
+				memcpy(&message, conn->outBuffer + conn->outMsgEnd - length, length);
+				fprintf(conn->Pfdebug, "To backend> %c\n", message);
+				break;
+
+			case LOG_STRING:
+				memcpy(&message, conn->outBuffer + conn->outMsgEnd - length, length);
+				fprintf(conn->Pfdebug, "To backend> \"%c\"\n", message);
+				break;
+
+			case LOG_NCHAR:
+				fprintf(conn->Pfdebug, "To backend (%d)> ", length);
+				fwrite(conn->outBuffer + conn->outMsgEnd - length, 1, length, conn->Pfdebug);
+				fprintf(conn->Pfdebug, "\n");
+				break;
+
+			case LOG_INT16:
+				memcpy(&result16, conn->outBuffer + conn->outMsgEnd - length, length);
+				result = (int) pg_ntoh16(result16);
+				fprintf(conn->Pfdebug, "To backend (#%d)> %c\n", length, result);
+				break;
+
+			case LOG_INT32:
+				memcpy(&result32, conn->outBuffer + conn->outMsgEnd - length, length);
+				result = (int) pg_ntoh32(result32);
+				fprintf(conn->Pfdebug, "To backend (#%d)> %c\n", length, result);
+				break;
+		}
+	}
+}
+
+/*
+ * pqLogFrontendMsg
+ *		Print accumulated frontend message pieces to the trace file.
+ */
+static void
+pqLogFrontendMsg(PGconn *conn)
+{
+	int			i;
+	int			message_addr;
+	int			length;
+	char		message;
+	uint16		result16 = 0;
+	uint32		result32 = 0;
+	int			result = 0;
+
+	for (i = 0; i < conn->n_fe_msgs; i++)
+	{
+		message_addr = conn->fe_msg[i].message_addr;
+		length = conn->fe_msg[i].message_length;
+
+		switch (conn->fe_msg[i].type)
+		{
+			case LOG_BYTE1:
+				memcpy(&message, conn->outBuffer + message_addr, length);
+				pqLogMsgByte1(conn, message, FROM_FRONTEND);
+				break;
+
+			case LOG_STRING:
+				pqLogMsgString(conn, conn->outBuffer + message_addr,
+							   length, FROM_FRONTEND);
+				break;
+
+			case LOG_NCHAR:
+				pqLogMsgnchar(conn, conn->outBuffer + message_addr,
+							  length, FROM_FRONTEND);
+				break;
+
+			case LOG_INT16:
+				memcpy(&result16, conn->outBuffer + message_addr, length);
+				result = (int) pg_ntoh16(result16);
+				pqLogMsgInt(conn, result, length, FROM_FRONTEND);
+				break;
+
+			case LOG_INT32:
+				memcpy(&result32, conn->outBuffer + message_addr, length);
+				result = (int) pg_ntoh32(result32);
+				pqLogMsgInt(conn, result, length, FROM_FRONTEND);
+				break;
+		}
+	}
+	conn->n_fe_msgs = 0;
+}
+
+/*
+ * pqLogMsgByte1: output 1 char message to the log
+ */
+static void
+pqLogMsgByte1(PGconn *conn, char v, PGCommSource commsource)
+{
+	char	   *message_source = commsource == FROM_BACKEND ? "<" : ">";
+	time_t		currtime;
+	struct tm  *tmp;
+	char		timestr[128];
+
+	if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+	{
+		switch (conn->be_msg->state)
+		{
+			case LOG_FIRST_BYTE:
+				currtime = time(NULL);
+				tmp = localtime(&currtime);
+				strftime(timestr, sizeof(timestr), "%Y-%m-%d %H:%M:%S %Z", tmp);
+
+				fprintf(conn->Pfdebug, "%s %s ", timestr, message_source);
+				/* If there is no first 1 byte protocol message, */
+				if (v == '\0')
+					return;
+
+				fprintf(conn->Pfdebug, "%s ",
+						pqGetProtocolMsgType((unsigned char) v, commsource));
+				/* Next, log the message length */
+				conn->be_msg->state = LOG_LENGTH;
+				conn->be_msg->command = v;
+				break;
+
+			case LOG_CONTENTS:
+				fprintf(conn->Pfdebug, "%c ", v);
+				pqTraceMaybeBreakLine(sizeof(v), conn);
+				break;
+
+			default:
+				pqLogInvalidProtocol(conn);
+				break;
+		}
+	}
+	else
+		fprintf(conn->Pfdebug, "FROM backend> %c\n", v);
+
+	return;
+}
+
+/*
+ * pqLogMsgInt: output a 2 or 4 bytes integer message to the log
+ */
+static void
+pqLogMsgInt(PGconn *conn, int v, int length, PGCommSource commsource)
+{
+	char	   *prefix = length == 4 ? "" : "#";
+	char	   *message_type = 0;
+	uint32		result32 = 0;
+	int			result = 0;
+	int			message_addr;
+
+	if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+	{
+		switch (conn->be_msg->state)
+		{
+			case LOG_FIRST_BYTE:
+
+				/*
+				 * Output message type here for protocol messages that do not
+				 * have the first byte.
+				 */
+				if (conn->n_fe_msgs > 0)
+				{
+					message_addr = conn->fe_msg[0].message_addr;
+					memcpy(&result32, conn->outBuffer + message_addr, 4);
+					result = (int) pg_ntoh32(result32);
+
+					if (result == NEGOTIATE_SSL_CODE)
+						message_type = "SSLRequest";
+					else
+						message_type = "StartupMessage";
+				}
+				else
+					message_type = "UnknownCommand";
+				fprintf(conn->Pfdebug, "%s ", message_type);
+				conn->be_msg->state = LOG_LENGTH;
+				break;
+
+			case LOG_LENGTH:
+				fprintf(conn->Pfdebug, "%d ", v);
+				conn->be_msg->length = v - length;
+				/* Next, log the message contents */
+				conn->be_msg->state = LOG_CONTENTS;
+				pqTraceMaybeBreakLine(0, conn);
+				break;
+
+			case LOG_CONTENTS:
+				fprintf(conn->Pfdebug, "%s%d ", prefix, v);
+				pqTraceMaybeBreakLine(length, conn);
+				break;
+
+			default:
+				pqLogInvalidProtocol(conn);
+				break;
+		}
+	}
+	else
+		fprintf(conn->Pfdebug, "To backend (#%d)> %d\n", length, v);
+}
+
+
+/*
+ * pqLogMsgString: output a null-terminated string to the log
+ */
+static void
+pqLogMsgString(PGconn *conn, const char *v, int length, PGCommSource commsource)
+{
+	if (length < 0)
+		length = strlen(v) + 1;
+
+	if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+	{
+		switch (conn->be_msg->state)
+		{
+			case LOG_CONTENTS:
+				fprintf(conn->Pfdebug, "\"%s\" ", v);
+				pqTraceMaybeBreakLine(length, conn);
+				break;
+
+			default:
+				pqLogInvalidProtocol(conn);
+				break;
+		}
+	}
+	else
+		fprintf(conn->Pfdebug, "To backend> \"%s\"\n", v);
+}
+
+/*
+ * pqLogMsgnchar: output a string of exactly len bytes message to the log
+ */
+static void
+pqLogMsgnchar(PGconn *conn, const char *v, int length, PGCommSource commsource)
+{
+	if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+	{
+		switch (conn->be_msg->state)
+		{
+			case LOG_CONTENTS:
+				fprintf(conn->Pfdebug, "\'");
+				fwrite(v, 1, length, conn->Pfdebug);
+				fprintf(conn->Pfdebug, "\' ");
+				pqTraceMaybeBreakLine(length, conn);
+				break;
+
+			default:
+				pqLogInvalidProtocol(conn);
+				break;
+		}
+	}
+	else
+	{
+		fprintf(conn->Pfdebug, "From backend (%d)> ", length);
+		fwrite(v, 1, length, conn->Pfdebug);
+		fprintf(conn->Pfdebug, "\n");
+	}
+}
+
 /* ----------
  * pqReadData: read more data, if any is available
  * Possible return values:
@@ -1011,6 +1525,12 @@ pqSendSome(PGconn *conn, int len)
 int
 pqFlush(PGconn *conn)
 {
+	/*
+	 * XXX I don't think fflush here is sufficient: there could be unsent
+	 * trace messages pointing to the output area; may be overwritten after
+	 * this.  So we need to send stuff to the trace file before flushing the
+	 * libpq buffer.
+	 */
 	if (conn->Pfdebug)
 		fflush(conn->Pfdebug);
 
diff --git a/src/interfaces/libpq/fe-protocol3.c b/src/interfaces/libpq/fe-protocol3.c
index 1696525475..1d4fa7840c 100644
--- a/src/interfaces/libpq/fe-protocol3.c
+++ b/src/interfaces/libpq/fe-protocol3.c
@@ -123,6 +123,9 @@ pqParseInput3(PGconn *conn)
 				 */
 				handleSyncLoss(conn, id, msgLength);
 			}
+			/* Terminate a half-finished logging message */
+			if (conn->Pfdebug)
+				pqTraceMaybeBreakLine(msgLength, conn);
 			return;
 		}
 
@@ -156,7 +159,12 @@ pqParseInput3(PGconn *conn)
 		{
 			/* If not IDLE state, just wait ... */
 			if (conn->asyncStatus != PGASYNC_IDLE)
+			{
+				/* Terminate a half-finished logging message */
+				if (conn->Pfdebug)
+					pqTraceMaybeBreakLine(msgLength, conn);
 				return;
+			}
 
 			/*
 			 * Unexpected message in IDLE state; need to recover somehow.
diff --git a/src/interfaces/libpq/libpq-int.h b/src/interfaces/libpq/libpq-int.h
index 1de91ae295..bc38fcfce8 100644
--- a/src/interfaces/libpq/libpq-int.h
+++ b/src/interfaces/libpq/libpq-int.h
@@ -155,6 +155,14 @@ typedef struct
 	void	   *noticeProcArg;
 } PGNoticeHooks;
 
+/*
+ * Logging
+ */
+
+/* Forward declarations */
+struct pqBackendMessage;
+struct pqFrontendMessage;
+
 typedef struct PGEvent
 {
 	PGEventProc proc;			/* the function to call on events */
@@ -376,6 +384,11 @@ struct pg_conn
 	/* Optional file to write trace info to */
 	FILE	   *Pfdebug;
 
+	/* unwritten protocol traces */
+	struct pqBackendMessage *be_msg;
+	struct pqFrontendMessage *fe_msg;
+	int			n_fe_msgs;
+
 	/* Callback procedures for notice message processing */
 	PGNoticeHooks noticeHooks;
 
@@ -668,6 +681,8 @@ extern int	pqPutInt(int value, size_t bytes, PGconn *conn);
 extern int	pqPutMsgStart(char msg_type, bool force_len, PGconn *conn);
 extern int	pqPutMsgEnd(PGconn *conn);
 extern int	pqReadData(PGconn *conn);
+extern bool pqTraceInit(PGconn *conn);
+extern void pqTraceMaybeBreakLine(int size, PGconn *conn);	/* XXX dubious */
 extern int	pqFlush(PGconn *conn);
 extern int	pqWait(int forRead, int forWrite, PGconn *conn);
 extern int	pqWaitTimed(int forRead, int forWrite, PGconn *conn,
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index ff853634bc..7d39acb770 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -1505,6 +1505,7 @@ PGAlignedXLogBlock
 PGAsyncStatusType
 PGCALL2
 PGChecksummablePage
+PGCommSource
 PGContextVisibility
 PGEvent
 PGEventConnDestroy
@@ -1520,6 +1521,8 @@ PGFileType
 PGFunction
 PGLZ_HistEntry
 PGLZ_Strategy
+PGLogMsgDataType
+PGLogState
 PGMessageField
 PGModuleMagicFunction
 PGNoticeHooks
@@ -3240,6 +3243,8 @@ pointer
 polymorphic_actuals
 pos_trgm
 post_parse_analyze_hook_type
+pqBackendMessage
+pqFrontendMessage
 pqbool
 pqsigfunc
 printQueryOpt
-- 
2.20.1

