RE: libpq debug log

From: iwata.aya@fujitsu.com <iwata.aya@fujitsu.com>
> This patch includes these items:

Is there anything else in this revision that is not handled?

Below are my comments.

Also, why don't you try running the regression tests with a temporary modification to PQtrace() to output the trace to a file?  The sole purpose is to confirm that this patch makes the test crash (core dump).


(1)
-	conn->Pfdebug = debug_port;
+	if (pqTraceInit(conn))
+	{
+		conn->Pfdebug = debug_port;
+		if (conn->Pfdebug != NULL)
+			setlinebuf(conn->Pfdebug);
+	}
+	else
+	{
+		/* XXX report ENOMEM? */
+		fprintf(conn->Pfdebug, "Failed to initialize trace support\n");
+		fflush(conn->Pfdebug);
+	}
 }

* When the passed debug_port is NULL, the function should return after calling PQuntrace().

* Is setlinebuf() available on Windows?  Maybe you should use setvbuf() instead.

* I don't see the need for separate pqTraceInit() function, because it is only called here.


(2)
+bool
+pqTraceInit(PGconn *conn)
+{
+	/* already done? */
+	if (conn->be_msg != NULL)
+	{

What's this code for?  I think it's sufficient that PQuntrace() frees b_msg and PQtrace() always allocates b_msg.


(3)
+	conn->fe_msg = malloc(sizeof(pqFrontendMessage) +
+							MAX_FRONTEND_MSGS * sizeof(pqFrontendMessageField));
+	conn->fe_msg->field_num = 0;
+	if (conn->fe_msg == NULL)
+	{
+		free(conn->be_msg);
+		/* NULL out for the case that fe_msg malloc fails */
+		conn->be_msg = NULL;
+		return false;
+	}
+	conn->fe_msg->field_num = 0;

The memory for the fields array is one entry larger than necessary.  The allocation code would be:

+	conn->fe_msg = malloc(offsetof(pqFrontendMessage, fields) +
+							MAX_FRONTEND_MSGS * sizeof(pqFrontendMessageField));

Also, the line with "field_num = 0" appears twice.  The first one should be removed.


(4)
+static void
+pqLogMessageByte1(PGconn *conn, char v, PGCommSource commsource)
+{
...
+	if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+	{

I think you can remove the protocol version check in various logging functions, because PQtrace() disables logging when the protocol version is 2.


(5)
@@ -966,10 +966,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);
-

Where is this information output instead?


(6)
+ * Set up state so that we can trace. NB -- this might be called mutiple

mutiple -> multiple


(7)
+	LOG_FIRST_BYTE,				/* logging the first byte identifing the
+								   protocol message type */

identifing -> identifying


(8)
+#define pqLogMsgByte1(CONN, CH, SOURCE) \
+((CONN)->Pfdebug ? pqLogMessageByte1(CONN, CH, SOURCE) : 0)

For functions that return void, follow the style of CHECK_FOR_INTERRUPTS() defined in miscadmin.h.


(9)
+				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_direction);

It's better to have microsecond accuracy, because knowing the accumulation of such fine-grained timings may help to troubleshoot heavily-loaded client cases.  You can mimic setup_formatted_log_time() in src/backend/utils/error/elog.c.  This is used for the %m marker in log_line_prefix.


(10)
I think it's better to use tabs (or any other character that is less likely to appear in the log field) as a field separator, because it makes it easier to process the log with a spreadsheet or some other tools.


(11)
+				/*
+				 * True type of message tagged '\0' is known when next 4 bytes is
+				 * checked. So we delay printing message type to pqLogMsgInt()
+				 */
+				if (v != '\0')
+					fprintf(conn->Pfdebug, "%s ",
+							pqGetProtocolMsgType((unsigned char) v, commsource));

In what cases does '\0' appear as a message type?


(12)
+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 "UnknownMessage";
+}

This function returns NULL (=0) when protocol_message_type_b/f[c] is 0.  That crashes the caller:

+					fprintf(conn->Pfdebug, "%s ",
+							pqGetProtocolMsgType((unsigned char) v, commsource));

Plus, you may as well print the invalid message type.  Why don't you do something like this:

+static const char *
+pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
+{
+	static char unknown_message[64];
+	char *msg = NULL;

+	if (commsource == FROM_BACKEND && c < lengthof(protocol_message_type_b))
+		msg = protocol_message_type_b[c];
+	else if (commsource == FROM_FRONTEND && c < lengthof(protocol_message_type_f))
+		msg = protocol_message_type_f[c];
+
+	if (msg == NULL)
+	{
+		sprintf(unknown_message, "Unknown message %02x", c);
+		msg = unknown_message;
+	}
+
+	return msg;
+}


(13)
@@ -156,7 +156,12 @@ pqParseInput3(PGconn *conn)
 		{
 			/* If not IDLE state, just wait ... */
 			if (conn->asyncStatus != PGASYNC_IDLE)
+			{
+				/* Terminate a half-finished logging message */
+				if (conn->Pfdebug)
+					pqTraceForcelyBreakLine(msgLength, conn);
 				return;
+			}
 
 			/*
 			 * Unexpected message in IDLE state; need to recover somehow.

What's this situation like?  Why output a new line and reset the trace status?


(14)
+/* 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;
+}

Is it sufficient to just reset the state field?  Isn't it necessary to call pqTraceResetBeMsg() instead?


(15)
@@ -212,15 +368,8 @@ pqSkipnchar(size_t len, PGconn *conn)
...
 	conn->inCursor += len;
-
 	return 0;
 }

This is an unnecessary removal of an empty line.


(16)
+static void
+pqLogMessageByte1(PGconn *conn, char v, PGCommSource commsource)
+{
+	char	   *message_direction = commsource == FROM_BACKEND ? "<" : ">";
...
+		switch (conn->be_msg->state)

This function handles messages in both directions.  But the switch condition is based on the backend message state (b_msg).  How is this correct?


(17)
What's the difference between pqLogMsgString() and pqLogMsgnchar()?  They both take a length argument.  Do they have to be separate functions?


(18)
 	if (conn->Pfdebug)
-		fprintf(conn->Pfdebug, "To backend> %c\n", c);
+		pqStoreFrontendMsg(conn, LOG_BYTE1, 1);

To match the style for backend messages with pqLogMsgByte1 etc., why don't you wrap the conn->Pfdebug check in the macro?


(19)
@@ -520,8 +667,6 @@ pqPutMsgStart(char msg_type, bool force_len, PGconn *conn)
 		/* allow room for message length */
 		endPos += 4;
 	}
-	else
-		lenPos = -1;
 
Why is this change necessary?


(20)
+static void
+pqLogFrontendMsg(PGconn *conn)
...
+	for (i = 0; i < conn->fe_msg->field_num; i++)
+	{
+		message_addr = conn->fe_msg->fields[i].offset_in_buffer;
+		length = conn->fe_msg->fields[i].length;
+
+		switch (conn->fe_msg[i].type)
+		{
+			case LOG_BYTE1:

When I saw this switch condition, the confusion exploded.  Shouldn't the type should be the attribute of each field as follows?

+		switch (conn->fe_msg->fields[i].type)

I also found the function names for frontend -> backend messages hard to grasp.  Could you show the flow of function calls when sending messages to the backend?


(21)
+				uint16		result16;
+				memcpy(&result16, conn->outBuffer + message_addr, length);

You should have an empty line between the declaration part and execution part.


(22)
I couldn't understand pqLogBinaryMsg() at all.  Could you explain what it does?  Particularly, if all bytes in the string is printable, the function seems to do nothing:

+		if (isprint(v[i]))
+			continue;

Should the following part be placed outside the for loop?  What does 'pin' mean? (I want the variable name to be more intuitive.)

+		if (pin < length)
+			fwrite(v + pin, 1, length - pin, conn->Pfdebug);


Regards
Takayuki Tsunakawa