v7-libpq-PQtrace-output-one-line.patch

application/octet-stream

Filename: v7-libpq-PQtrace-output-one-line.patch
Type: application/octet-stream
Part: 0
Message: RE: libpq debug log
diff --git a/doc/src/sgml/libpq.sgml b/doc/src/sgml/libpq.sgml
index 258b09c..f62b014 100644
--- a/doc/src/sgml/libpq.sgml
+++ b/doc/src/sgml/libpq.sgml
@@ -5714,6 +5714,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-misc.c b/src/interfaces/libpq/fe-misc.c
index a7c08c5..5747ffa 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,351 @@
 #include "pg_config_paths.h"
 #include "port/pg_bswap.h"
 
+/*
+ * protocol types:
+ *
+ * protocol_message_type_b[]: message types sent by a backend
+ * protocol_message_type_f[]: message types sent by a frontend
+ * protocol_message_type_bf[]: messages types sent by both backend and frontend
+ *
+ */
+static char *protocol_message_type_b[] = {
+	 /* 1 */ "ParseComplete",
+	 /* 2 */ "BindComplete",
+	 /* 3 */ "CloseComplete",
+	 /* \x04 - \x0f */ 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, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
+	 /* @ */ 0,
+	 /* A */ "NotificationResponse",
+	 /* B */ 0,
+	 /* C */ "CommandComplete",
+	 /* D */ "DataRow",
+	 /* E */ "ErrorResponse",
+	 /* F */ 0,
+	 /* G */ "CopyInResponse",
+	 /* H */ "CopyOutResponse",
+	 /* I */ "EmptyQueryResponse",
+	 /* J */ 0,
+	 /* K */ "BackendKeyData",
+	 /* L */ 0,
+	 /* M */ 0,
+	 /* N */ "NoticeResponse",
+	 /* O */ 0,
+	 /* P */ 0,
+	 /* Q */ 0,
+	 /* R */ "Authentication",
+	 /* S */ "ParameterStatus",
+	 /* T */ "RowDescription",
+	 /* U */ 0,
+	 /* V */ "FunctionCallResponse",
+	 /* W */ "CopyBothResponse",
+	 /* X */ 0,
+	 /* Y */ 0,
+	 /* Z */ "ReadyForQuery",
+	 /* \x5b - \x5f */ 0, 0, 0, 0, 0,
+	 /* \x60 - \x6d */ 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
+	 /* n */ "NoData",
+	 /* o */ 0,
+	 /* p */ 0,
+	 /* q */ 0,
+	 /* r */ 0,
+	 /* s */ "PortalSuspended",
+	 /* t */ "ParameterDescription",
+	 /* u */ 0,
+	 /* v */ "NegotiateProtocolVersion",
+};
+#define COMMAND_B_MIN ((unsigned char)1)
+#define COMMAND_B_MAX (sizeof(protocol_message_type_b) / sizeof(*protocol_message_type_b))
+
+static char *protocol_message_type_f[] = {
+	 /* B */ "Bind",
+	 /* C */ "Close",
+	 /* D */ "Describe",
+	 /* E */ "Execute",
+	 /* F */ "FunctionCall",
+	 /* G */ 0,
+	 /* H */ "Flush",
+	 /* I - O       */ 0, 0, 0, 0, 0, 0, 0,
+	 /* P */ "Parse",
+	 /* Q */ "Query",
+	 /* R */ 0,
+	 /* S */ "Sync",
+	 /* T - W       */ 0, 0, 0, 0,
+	 /* X */ "Terminate",
+	 /* Y */ 0,
+	 /* Z */ 0,
+	 /* \x5b - \x65 */ 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
+	 /* f */ "CopyFail",
+	 /* g - o       */ 0, 0, 0, 0, 0, 0, 0, 0, 0,
+	 /* p */ "AuthnenticationResponse",
+};
+#define COMMAND_F_MIN ((unsigned char)'B')
+#define COMMAND_F_MAX (sizeof(protocol_message_type_f) / sizeof(*protocol_message_type_f)) + COMMAND_F_MIN
+
+static char *protocol_message_type_bf[] = {
+	 /* c */ "CopyDone",
+	 /* d */ "CopyData",
+};
+#define COMMAND_BF_MIN ((unsigned char)'c')
+#define COMMAND_BF_MAX (sizeof(protocol_message_type_bf) / sizeof(*protocol_message_type_bf)) + COMMAND_BF_MIN
+
+
 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 fputnbytes(FILE *f, const char *str, size_t n);
+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);
+
+/*
+ * pqGetProtocolMsgType:
+ * 	Get a protocol type from first byte identifier
+ */
+static char *
+pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
+{
+	char	   *message_type = 0;
+
+	if (c >= COMMAND_BF_MIN && c < COMMAND_BF_MAX)
+	{
+		message_type = protocol_message_type_bf[c - COMMAND_BF_MIN];
+		if (message_type)
+			return message_type;
+	}
+
+	if (commsource == FROM_BACKEND && c >= COMMAND_B_MIN && c < COMMAND_B_MAX)
+	{
+		message_type = protocol_message_type_b[c - COMMAND_B_MIN];
+		if (message_type)
+			return message_type;
+	}
+
+	if (commsource == FROM_FRONTEND && c >= COMMAND_F_MIN && c < COMMAND_F_MAX)
+	{
+		message_type = protocol_message_type_f[c - COMMAND_F_MIN];
+		if (message_type)
+			return message_type;
+	}
+
+	return "UnknownCommand";
+}
+
+/* pqInitMsgLog: Initializing logging message */
+static void
+pqInitMsgLog(PGconn *conn)
+{
+	conn->logging_message.state = LOG_FIRST_BYTE;
+	conn->logging_message.length = 0;
+}
+
+/* pqFreeFrontendEntry: forget stored protocol messages from frontend */
+static void
+pqFreeFrontendEntry(PGconn *conn)
+{
+	PGFrontendLogMsgEntry *entry;
+
+	entry = conn->frontend_entry_head;
+	while (entry != NULL)
+	{
+		PGFrontendLogMsgEntry *prev = entry;
+
+		entry = entry->next;
+		free(prev);
+	}
+	conn->frontend_entry_head = conn->frontend_entry_tail = NULL;
+}
+
+/* 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;
+	PGFrontendLogMsgEntry *newFrontendEntry;
+
+	if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+	{
+		newFrontendEntry = (PGFrontendLogMsgEntry *) malloc(sizeof(PGFrontendLogMsgEntry));
+		if (newFrontendEntry)
+		{
+			newFrontendEntry->type = type;
+			newFrontendEntry->message_addr = conn->outMsgEnd - length;
+			newFrontendEntry->message_length = length;
+			newFrontendEntry->next = NULL;
+			if (conn->frontend_entry_tail)
+				conn->frontend_entry_tail->next = newFrontendEntry;
+			else
+				conn->frontend_entry_head = newFrontendEntry;
+			conn->frontend_entry_tail = newFrontendEntry;
+		}
+	}
+	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);
+				fputnbytes(conn->Pfdebug, conn->outBuffer + conn->outMsgEnd - length, length);
+				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			message_addr;
+	int			length;
+	PGFrontendLogMsgEntry *entry;
+
+	char		message;
+	uint16		result16 = 0;
+	uint32		result32 = 0;
+	int			result = 0;
+
+	entry = conn->frontend_entry_head;
+
+	for (entry = conn->frontend_entry_head;
+		 entry != NULL;
+		 entry = entry->next)
+	{
+		message_addr = entry->message_addr;
+		length = entry->message_length;
+
+		switch (entry->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;
+		}
+	}
+	pqFreeFrontendEntry(conn);
+	pqInitMsgLog(conn);
+}
+
+#define	TRACELOG_TIME_SIZE	33
+/*
+ * 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
@@ -98,12 +440,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
  */
@@ -114,11 +455,55 @@ 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)
+{
+	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;
+				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]:
@@ -152,8 +537,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;
 }
@@ -181,12 +565,39 @@ 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 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
  */
@@ -202,11 +613,7 @@ pqGetnchar(char *s, size_t len, PGconn *conn)
 	conn->inCursor += len;
 
 	if (conn->Pfdebug)
-	{
-		fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len);
-		fputnbytes(conn->Pfdebug, s, len);
-		fprintf(conn->Pfdebug, "\n");
-	}
+		pqLogMsgnchar(conn, s, len, FROM_BACKEND);
 
 	return 0;
 }
@@ -226,11 +633,7 @@ pqSkipnchar(size_t len, PGconn *conn)
 		return EOF;
 
 	if (conn->Pfdebug)
-	{
-		fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len);
-		fputnbytes(conn->Pfdebug, conn->inBuffer + conn->inCursor, len);
-		fprintf(conn->Pfdebug, "\n");
-	}
+		pqLogMsgnchar(conn, conn->inBuffer + conn->inCursor, len, FROM_BACKEND);
 
 	conn->inCursor += len;
 
@@ -248,13 +651,39 @@ pqPutnchar(const char *s, size_t len, PGconn *conn)
 		return EOF;
 
 	if (conn->Pfdebug)
+		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, "\'");
+				fputnbytes(conn->Pfdebug, v, length);
+				fprintf(conn->Pfdebug, "\' ");
+				pqLogLineBreak(length, conn);
+				break;
+
+			default:
+				pqLogInvalidProtocol(conn);
+				break;
+		}
+	}
+	else
 	{
-		fprintf(conn->Pfdebug, "To backend> ");
-		fputnbytes(conn->Pfdebug, s, len);
+		fprintf(conn->Pfdebug, "From backend (%d)> ", length);
+		fputnbytes(conn->Pfdebug, v, length);
 		fprintf(conn->Pfdebug, "\n");
 	}
-
-	return 0;
 }
 
 /*
@@ -292,7 +721,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;
 }
@@ -314,11 +743,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,
@@ -326,11 +759,66 @@ pqPutInt(int value, size_t bytes, PGconn *conn)
 							 (unsigned long) bytes);
 			return EOF;
 	}
+	return 0;
+}
 
-	if (conn->Pfdebug)
-		fprintf(conn->Pfdebug, "To backend (%lu#)> %d\n", (unsigned long) bytes, value);
+/*
+ * 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;
 
-	return 0;
+	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->frontend_entry_head)
+				{
+					message_addr = conn->frontend_entry_head->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;
+
+			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);
 }
 
 /*
@@ -548,8 +1036,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;
 }
@@ -585,7 +1072,7 @@ 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);
 
@@ -594,6 +1081,12 @@ pqPutMsgEnd(PGconn *conn)
 	{
 		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 c97841e..611d70a 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 harf-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 harf-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 64468ab..8a0ce35 100644
--- a/src/interfaces/libpq/libpq-int.h
+++ b/src/interfaces/libpq/libpq-int.h
@@ -155,6 +155,53 @@ 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;
+	struct PGFrontendLogMsgEntry *next; /* list link */
+}			PGFrontendLogMsgEntry;
+
 typedef struct PGEvent
 {
 	PGEventProc proc;			/* the function to call on events */
@@ -373,6 +420,13 @@ struct pg_conn
 	/* Optional file to write trace info to */
 	FILE	   *Pfdebug;
 
+	/* Trace log info to output one line */
+	PGLogMsg	logging_message;
+
+	/* Trace log entrys needed when sending a message from frontend */
+	PGFrontendLogMsgEntry *frontend_entry_head; /* oldest stored frontend msg */
+	PGFrontendLogMsgEntry *frontend_entry_tail; /* newest stored frontend msg */
+
 	/* Callback procedures for notice message processing */
 	PGNoticeHooks noticeHooks;
 
@@ -659,6 +713,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 === */