From ae0e3853a805d186abdd9e06acceca7ada48107a 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 v8 1/2] libpq trace v8

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

diff --git a/doc/src/sgml/libpq.sgml b/doc/src/sgml/libpq.sgml
index a397073526..0d365f3bb3 100644
--- a/doc/src/sgml/libpq.sgml
+++ b/doc/src/sgml/libpq.sgml
@@ -5854,6 +5854,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 724076a310..0795861c92 100644
--- a/src/interfaces/libpq/fe-connect.c
+++ b/src/interfaces/libpq/fe-connect.c
@@ -6813,6 +6813,7 @@ PQtrace(PGconn *conn, FILE *debug_port)
 		return;
 	PQuntrace(conn);
 	conn->Pfdebug = debug_port;
+	setlinebuf(conn->Pfdebug);
 }
 
 void
diff --git a/src/interfaces/libpq/fe-misc.c b/src/interfaces/libpq/fe-misc.c
index ff840b7730..de84da6e83 100644
--- a/src/interfaces/libpq/fe-misc.c
+++ b/src/interfaces/libpq/fe-misc.c
@@ -35,6 +35,7 @@
 
 #ifdef WIN32
 #include "win32.h"
+#include <windows.h>
 #else
 #include <unistd.h>
 #include <sys/time.h>
@@ -45,6 +46,7 @@
 #endif
 #ifdef HAVE_SYS_SELECT_H
 #include <sys/select.h>
+#include <sys/timeb.h>
 #endif
 
 #include "libpq-fe.h"
@@ -53,11 +55,304 @@
 #include "pg_config_paths.h"
 #include "port/pg_bswap.h"
 
+/*
+ * 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 pqLogMsgByte1(PGconn *conn, char v, 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);
+static void pqLogMsgInt(PGconn *conn, int v, int length, PGCommSource commsource);
+static void pqGetCurrentTime(char *currenttime);
+#define	TRACELOG_TIME_SIZE	33
+
+/*
+ * pqGetProtocolMsgType:
+ * 	Get a protocol type from first byte identifier
+ */
+static const char *
+pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
+{
+	const char *message_type;
+
+	if (commsource == FROM_BACKEND && c < lengthof(protocol_message_type_b))
+		message_type = protocol_message_type_b[c];
+	else if (commsource == FROM_FRONTEND && c < lengthof(protocol_message_type_f))
+		message_type = protocol_message_type_f[c];
+	else
+		return "UnknownCommand";
+}
+
+/* pqInitMsgLog: Initializing logging message */
+static void
+pqInitMsgLog(PGconn *conn)
+{
+	conn->logging_message.state = LOG_FIRST_BYTE;
+	conn->logging_message.length = 0;
+}
+
+/* pqLogInvalidProtocol: Output a message the protocol is invalid */
+static void
+pqLogInvalidProtocol(PGconn *conn)
+{
+	fprintf(conn->Pfdebug, ":::Invalid Protocol\n");
+	conn->logging_message.state = LOG_FIRST_BYTE;
+}
+
+/*
+ * pqLogLineBreak:
+ * 	Check whether message formats is complete. If so,
+ * 	break the line.
+ */
+void
+pqLogLineBreak(int size, PGconn *conn)
+{
+	conn->logging_message.length -= size;
+	if (conn->logging_message.length <= 0)
+	{
+		fprintf(conn->Pfdebug, "\n");
+		pqInitMsgLog(conn);
+	}
+}
+
+/*
+ * pqStoreFrontendMsg: Store message addresses that frontend sends.
+ *
+ * 	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->frontend_entry[conn->nMsgEntries].type = type;
+		conn->frontend_entry[conn->nMsgEntries].message_addr = conn->outMsgEnd - length;
+		conn->frontend_entry[conn->nMsgEntries].message_length = length;
+		conn->nMsgEntries++;
+	}
+	else
+	{
+		/* Output one content per one 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:
+ * 	Output frontend message contents after the message length.
+ */
+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->nMsgEntries; i++)
+	{
+		message_addr = conn->frontend_entry[i].message_addr;
+		length = conn->frontend_entry[i].message_length;
+
+		switch (conn->frontend_entry[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;
+		}
+	}
+	pqInitMsgLog(conn);
+}
+
+/*
+ * pqGetCurrentTime: get current time for trace log output
+ */
+static void
+pqGetCurrentTime(char *currenttime)
+{
+#ifdef WIN32
+	SYSTEMTIME	localTime;
+	TIME_ZONE_INFORMATION TimezoneInfo;
+
+	GetLocalTime(&localTime);
+
+	GetTimeZoneInformation(&TimezoneInfo);
+	snprintf(currenttime, TRACELOG_TIME_SIZE, "%4d-%02d-%02d %02d:%02d:%02d.%03d %s ",
+			 localTime.wYear, localTime.wMonth, localTime.wDay,
+			 localTime.wHour, localTime.wMinute, localTime.wSecond,
+			 localTime.wMilliseconds, TimezoneInfo.Bias);
+#else
+	struct timeb localTime;
+	struct tm  *tm;
+	char		timezone[100];
+
+	ftime(&localTime);
+	tm = localtime(&localTime.time);
+
+	strftime(timezone, sizeof(timezone), "%Z", tm);
+	snprintf(currenttime, TRACELOG_TIME_SIZE, "%4d-%02d-%02d %02d:%02d:%02d.%03d %s ",
+			 1900 + tm->tm_year, 1 + tm->tm_mon, tm->tm_mday,
+			 tm->tm_hour, tm->tm_min, tm->tm_sec, localTime.millitm, timezone);
+#endif
+}
 
 /*
  * PQlibVersion: return the libpq version number
@@ -85,12 +380,11 @@ 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;
 }
 
-
 /*
  * pqPutc: write 1 char to the current message
  */
@@ -101,11 +395,56 @@ 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;
 }
 
+/*
+ * pqLogMsgByte1: output 1 char message to the log
+ */
+static void
+pqLogMsgByte1(PGconn *conn, char v, PGCommSource commsource)
+{
+	const char *protocol_message_type;
+	char	   *message_source = commsource == FROM_BACKEND ? "<" : ">";
+	char		current_time[TRACELOG_TIME_SIZE];
+
+	if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+	{
+		switch (conn->logging_message.state)
+		{
+			case LOG_FIRST_BYTE:
+				pqGetCurrentTime(current_time);
+				fprintf(conn->Pfdebug, "%s %s ", current_time, message_source);
+				/* If there is no first 1 byte protocol message, */
+				if (v == ' ')
+					return;
+
+				protocol_message_type = pqGetProtocolMsgType((unsigned char) v, commsource);
+				fprintf(conn->Pfdebug, "%s ", protocol_message_type);
+				/* Change the state to get protocol message length */
+				conn->logging_message.state = LOG_LENGTH;
+				conn->logging_message.command = v;
+				conn->nMsgEntries = 0;
+				break;
+
+			case LOG_CONTENTS:
+				fprintf(conn->Pfdebug, "%c ", v);
+				pqLogLineBreak(sizeof(v), conn);
+				break;
+
+			default:
+				pqLogInvalidProtocol(conn);
+				break;
+		}
+	}
+	else
+		fprintf(conn->Pfdebug, "FROM backend> %c\n", v);
+
+	return;
+}
+
 
 /*
  * pqGets[_append]:
@@ -139,8 +478,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,11 +506,38 @@ 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;
 }
 
+/*
+ * pqLogMsgString: output a 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->logging_message.state)
+		{
+			case LOG_CONTENTS:
+				fprintf(conn->Pfdebug, "\"%s\" ", v);
+				pqLogLineBreak(length, conn);
+				break;
+
+			default:
+				pqLogInvalidProtocol(conn);
+				break;
+		}
+	}
+	else
+		fprintf(conn->Pfdebug, "To backend> \"%s\"\n", v);
+}
+
 /*
  * pqGetnchar:
  *	get a string of exactly len bytes in buffer s, no null termination
@@ -189,11 +554,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 +574,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,15 +592,42 @@ 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;
 }
 
+/*
+ * 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->logging_message.state)
+		{
+			case LOG_CONTENTS:
+				fprintf(conn->Pfdebug, "\'");
+				fwrite(v, 1, length, conn->Pfdebug);
+				fprintf(conn->Pfdebug, "\' ");
+				pqLogLineBreak(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");
+	}
+}
+
+
 /*
  * pqGetInt
  *	read a 2 or 4 byte integer and convert from network byte order
@@ -279,7 +663,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 +685,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,13 +701,69 @@ 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;
 }
 
+/*
+ * 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->logging_message.state)
+		{
+				/*
+				 * Output message type here for protocol messages that do not
+				 * have the first byte.
+				 */
+			case LOG_FIRST_BYTE:
+				if (conn->nMsgEntries > 0)
+				{
+					message_addr = conn->frontend_entry[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->logging_message.state = LOG_LENGTH;
+				/* fall-through */
+
+			case LOG_LENGTH:
+				fprintf(conn->Pfdebug, "%d ", v);
+				conn->logging_message.length = v - length;
+				/* Change the state to log protocol message contents */
+				conn->logging_message.state = LOG_CONTENTS;
+				pqLogLineBreak(0, conn);
+				break;
+
+			case LOG_CONTENTS:
+				fprintf(conn->Pfdebug, "%s%d ", prefix, v);
+				pqLogLineBreak(length, conn);
+				break;
+
+			default:
+				pqLogInvalidProtocol(conn);
+				break;
+		}
+	}
+	else
+		fprintf(conn->Pfdebug, "To backend (#%d)> %d\n", length, v);
+}
+
 /*
  * Make sure conn's output buffer can hold bytes_needed bytes (caller must
  * include already-stored data into the value!)
@@ -535,8 +979,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 ? msg_type : ' ', FROM_FRONTEND);
 
 	return 0;
 }
@@ -572,15 +1015,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);
 	}
diff --git a/src/interfaces/libpq/fe-protocol3.c b/src/interfaces/libpq/fe-protocol3.c
index 1696525475..2b8b9921ee 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)
+				pqLogLineBreak(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)
+					pqLogLineBreak(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..8af4163aa1 100644
--- a/src/interfaces/libpq/libpq-int.h
+++ b/src/interfaces/libpq/libpq-int.h
@@ -155,6 +155,52 @@ typedef struct
 	void	   *noticeProcArg;
 } PGNoticeHooks;
 
+/*
+ * Logging
+ */
+
+/* Log message source */
+typedef enum
+{
+	FROM_BACKEND,
+	FROM_FRONTEND
+} PGCommSource;
+
+/* PGLogState defines the state of the Logging message state machine */
+typedef enum
+{
+	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;
+
+/* Protocol message */
+typedef struct PGLogMsg
+{
+	PGLogState	state;			/* state of logging message state machine */
+	int			length;			/* protocol message length */
+	char		command;		/* first one byte of protocol message */
+} PGLogMsg;
+
+/* Frontend message data type */
+typedef enum
+{
+	LOG_BYTE1,
+	LOG_STRING,
+	LOG_NCHAR,
+	LOG_INT16,
+	LOG_INT32
+} PGLogMsgDataType;
+
+/* Store frontend message address */
+typedef struct PGFrontendLogMsgEntry
+{
+	PGLogMsgDataType type;
+	int			message_addr;
+	int			message_length;
+} PGFrontendLogMsgEntry;
+
 typedef struct PGEvent
 {
 	PGEventProc proc;			/* the function to call on events */
@@ -376,6 +422,11 @@ struct pg_conn
 	/* Optional file to write trace info to */
 	FILE	   *Pfdebug;
 
+	/* pending log message */
+	PGLogMsg	logging_message;
+	PGFrontendLogMsgEntry frontend_entry[MAXPGPATH];
+	int			nMsgEntries;
+
 	/* Callback procedures for notice message processing */
 	PGNoticeHooks noticeHooks;
 
@@ -674,6 +725,7 @@ extern int	pqWaitTimed(int forRead, int forWrite, PGconn *conn,
 						time_t finish_time);
 extern int	pqReadReady(PGconn *conn);
 extern int	pqWriteReady(PGconn *conn);
+extern void pqLogLineBreak(int size, PGconn *conn);
 
 /* === in fe-secure.c === */
 
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index b1afb345c3..61f22404e8 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -1504,6 +1504,7 @@ PGAlignedXLogBlock
 PGAsyncStatusType
 PGCALL2
 PGChecksummablePage
+PGCommSource
 PGContextVisibility
 PGEvent
 PGEventConnDestroy
@@ -1516,9 +1517,13 @@ PGEventResultCreate
 PGEventResultDestroy
 PGFInfoFunction
 PGFileType
+PGFrontendLogMsgEntry
 PGFunction
 PGLZ_HistEntry
 PGLZ_Strategy
+PGLogMsg
+PGLogMsgDataType
+PGLogState
 PGMessageField
 PGModuleMagicFunction
 PGNoticeHooks
-- 
2.20.1

