RE: libpq debug log

Hi Iwata-san

I reviewed v10-0001-libpq-trace.patch. (But I don't check recent discussion...)
I found some bugs.
I'm suggesting some refactoring.

****
@@ -6809,7 +6809,17 @@ PQtrace(PGconn *conn, FILE *debug_port)
+ if (pqTraceInit(conn))
+ {
+ conn->Pfdebug = debug_port;
+ setlinebuf(conn->Pfdebug);

If debug_port is NULL, setlinebuf() causes segmentation fault.
We should have policy that libpq-trace framework works only when
Pfdebug is not NULL.

For example, we should also think that PQtrace(conn, NULL) has same
effect as PQuntrace(conn).

****
+ 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x65 ... \0x6d */

There should be 9 zero, but 15 zero.

****
@@ -85,7 +228,7 @@ pqGetc(char *result, PGconn *conn)
if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend> %c\n", *result);
+ pqLogMsgByte1(conn, *result, FROM_BACKEND);

I suggest to move confirming Pfdebug to pqLogMsgByte1() and
other logging functions. If you want to avoid overhead of calling
function, use macro function like the following:

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

****
@@ -168,7 +310,7 @@ 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);
+ pqStoreFrontendMsg(conn, LOG_STRING, strlen(s) + 1);

It's better that you store strlen(s) to local variable and use it.
strlen(s) is not cost-free.

****
@@ -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

It's better to make the style same as pqGetInt().
(It is not important.)

switch(bytes) {
case 2:
type = LOG_INT16;
break;
case 4:
type = LOG_INT32;
break;
}
pqStoreFrontendMsg(conn, type, bytes);

****
+pqTraceInit(PGconn *conn)
+{
+ conn->fe_msg = malloc(MAX_FRONTEND_MSGS * sizeof(pqFrontendMessage));
+ if (conn->fe_msg == NULL)
+ {
+ free(conn->be_msg);
+ return false;

Maybe, we need to clear conn->be_msg by NULL for next calling pqTraceInit().

****
+pqTraceInit(PGconn *conn)
+{
+ conn->fe_msg = malloc(MAX_FRONTEND_MSGS * sizeof(pqFrontendMessage));
+ conn->n_fe_msgs = 0;

Data structure design is odd.
Frontend message is basically constructed as the following:
- message type
- message length
- field
- field
- field

So the deisign may be as the follwong and remove n_fe_msg from pg_conn.

typedef struct pqFrontendMessageField
{
int offset_in_buffer; message_addr is not real address.
int length; message_length is wrong name. it is length of FIELD.
} pqFrontendMessageField;

typedef struct pqFrontendMessage
{
PGLogMsgDataType type;
int field_num;
pqFrontendMessageField fields[FLEXIBLE_ARRAY_MEMBER];
} pqFrontendMessage;

And then pqTraceInit() is as the following.
conn->fe_msg = malloc(sizeof(pqFrontendMessage) +
MAX_FRONTEND_MSG_FIELDS * sizeof(pqFrontendMessage));
conn->fe_msg->field_num = 0;

****
+pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
+ return "UnknownCommand";

It is "UnknownMessageType", isn't it?

****
+ * 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.

I understand as the following:
* The message length is fixed after putting the last field,
* but message length should be print before printing any field.
* So we must store the field data in memory.

****
+pqStoreFrontendMsg(PGconn *conn, PGLogMsgDataType type, int length)
+ case LOG_STRING:
+ memcpy(&message, conn->outBuffer + conn->outMsgEnd - length, length);
+ fprintf(conn->Pfdebug, "To backend> \"%c\"\n", message);

%s is correct.
At least, %c is not correct.

****
+pqStoreFrontendMsg(PGconn *conn, PGLogMsgDataType type, int length)
+ case LOG_BYTE1:
+ memcpy(&message, conn->outBuffer + conn->outMsgEnd - length, length);

It is unnecessary to call memcpy().
LOG_BYTE1, LOG_STRING, and LOG_NCHAR can be passed its pointer directly to fprintf().
You can also pass LOG_INT* data with casting to fprintf() without memcpy(), but I think either is fine.

****
+ case LOG_INT16:
+ fprintf(conn->Pfdebug, "To backend (#%d)> %c\n", length, result);
+ case LOG_INT32:
+ fprintf(conn->Pfdebug, "To backend (#%d)> %c\n", length, result);

%d is correct.
At least, %c is not correct.

****
+pqStoreFrontendMsg(PGconn *conn, PGLogMsgDataType type, int length)
+ char message;
+ uint16 result16 = 0;
+ uint32 result32 = 0;
+ int result = 0;

It's better that these variables declared in each block.
Initializing result* is unnecessary.

case LOG_INT16:
{
uint16 wk;
memcpy(&wk, conn->outBuffer + conn->outMsgEnd - 2, 2);
wk = pg_ntoh16(wk);
fprintf(conn->Pfdebug, "To backend (#%d)> %h\n", 2, wk);
break;
}

****
+pqLogFrontendMsg(PGconn *conn)
+ int message_addr;
+ int length;
+ char message;
+ uint16 result16 = 0;
+ uint32 result32 = 0;
+ int result = 0;

Same as pqStoreFrontendMsg().

+ memcpy(&message, conn->outBuffer + message_addr, length);

Same as pqStoreFrontendMsg().

****
+pqLogMsgByte1(PGconn *conn, char v, PGCommSource commsource)
+ char *message_source = commsource == FROM_BACKEND ? "<" : ">";

I understand that 'commsource' means source, but message_source means direction of sending.
It is better that the variable is named message_direction.

****
+pqLogMsgByte1(PGconn *conn, char v, PGCommSource commsource)
+ case LOG_FIRST_BYTE:
+ if (v == '\0')
+ return;

Maybe is it needed for packets whose msg_type is '\0'?

I get the following output because pqLogMsgnchar() is called
at conn->be_msg->state == LENGTH. I attach a program for reproduction.

2020-12-25 00:58:48 UTC > StartupMessage :::Invalid Protocol

I think confusing transition of state causes it.
I suggest refactoring instead of fixing the above bug.

msg_type of Startup packet, SSLRequest packet, and GSSNegotiate packet
is '\0'. (I guess GSSNegotiate packet may be forgotten).
At these packet, Byte1 is not sent actually, but if libpq-trace framework consider
that it is sent, the transition may become more clear like the following:

pqLogMsgByte1(PGconn *conn, char v, PGCommSource commsource)
:
fprintf(conn->Pfdebug, "%s %s ", timestr, message_source);
/*
* 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));

conn->be_msg->state = LOG_LENGTH;
conn->be_msg->command = v;

pqLogMsgInt(PGconn *conn, int v, int length, PGCommSource commsource)
:

/* remove case LOG_FIRST_BYTE and... */

case LOG_LENGTH:
if (conn->be_msg->command == '\0')
{
/* We delayed to print message type for special message. */
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 if (result == NEGOTIATE_GSS_CODE)
message_type = "GSSRequest";
else
message_type = "StartupMessage";
fprintf(conn->Pfdebug, "%s ", message_type);
}

fprintf(conn->Pfdebug, "%d", v);
conn->be_msg->length = v - length;
conn->be_msg->state = LOG_CONTENTS;
pqTraceMaybeBreakLine(0, conn);
break;

****
+pqLogMsgByte1(PGconn *conn, char v, PGCommSource commsource)
+ case LOG_CONTENTS:
+ /* Suppresses printing terminating zero byte */
+ if (v == '\0')
+ fprintf(conn->Pfdebug, "0");

Is the above code for end of 'E' or 'N' message?
We should comment because it is special case.
Additionally, we may confuse whether 0 is numerical character or '\0'.

/*
* 'E' or 'N' message format is as the following:
* 'E' len [byte1-tag string(null-terminated)]* \0(eof-tag)
*
* So we detect eof-tag at pqLogMsgByte1() with LOG_CONTENTS state.
* The eof-tag is data so we should print it.
* On the way, we care other non-ascii character.
*/
if (!isascii(v))
fprintf(conn->Pfdebug, "\\x%02x", v);

****
+pqLogMsgByte1(PGconn *conn, char v, PGCommSource commsource)
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ else
+ fprintf(conn->Pfdebug, "FROM backend> %c\n", v);

Umm. Also see the following.

+pqLogMsgInt(PGconn *conn, int v, int length, PGCommSource commsource)
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ else
+ fprintf(conn->Pfdebug, "To backend (#%d)> %d\n", length, v);

In the later case, "FROM backend" is correct.

The bug is caused by confusing design.
I suggest to refactor that:
- Move callings fprintf() in pqStoreFrontendMsg() to each pqLogMsgXXX()
- pqStoreFrontendMsg() calls each pqLogMsgXXX().

****
+pqLogMsgString(PGconn *conn, const char *v, int length, PGCommSource commsource)
+{
+ if (length < 0)
+ length = strlen(v) + 1;

I cannot find length==-1 route.

****
+pqLogMsgnchar(PGconn *conn, const char *v, int length, PGCommSource commsource)
+ fprintf(conn->Pfdebug, "\'");
+ fwrite(v, 1, length, conn->Pfdebug);
+ fprintf(conn->Pfdebug, "\'");

We should consider that 'v' is binary data.
So it is better to convert non-ascii character to ascii (e.g. x%02x format).

e.g. case of StartupPacket
2020-12-25 08:07:42 UTC > StartupMessage 40 'userk5userdatabasetemplate1'

The length of StartupPacket includes length itselft.
The length of 'user...tepmlate1' is only 27.
We could not find 8 bytes(40 - 4 - 27 = 8).

If non-ascii character is printed, we can find them.
2020-12-25 08:29:19 UTC > StartupMessage 40 '\x00\x03\x00\x00user\x00k5user\x00database\x00template1\x00\x00'

static void
pqLogMsgBinary(PGconn *conn, const char *v, int length, PGCommSource commsource)
{
int i, pin;
for (pin = i = 0; i < length; ++i)
{
if (isprint(v[i]))
continue;
else
{
fwrite(v + pin, 1, i - pin, conn->Pfdebug);
fprintf(conn->Pfdebug, "\\x%02x", v[i]);
pin = i + 1;
}
}
if (pin < length)
fwrite(v + pin, 1, length - pin, conn->Pfdebug);
}

****
@@ -123,6 +123,9 @@ pqParseInput3(PGconn *conn)
+ /* Terminate a half-finished logging message */
+ if (conn->Pfdebug)
+ pqTraceMaybeBreakLine(msgLength, conn);
return;

I understand that the above code only want to do [conn->be_msg->length = 0].
If it is true, you should create new wrapper function like pqTraceForcelyTerminateMessage()
and handleSyncLoss() itself should call pqTraceForcelyTerminateMessage().

pqTraceForcelyTerminateMessage()
{
if (conn->be_msg->length > 0)
fprintf(conn->Pfdebug, "\n");

pqTraceResetBeMsg(conn);
}

****
pqSaveParameterStatus(PGconn *conn, const char *name, const char *value)
if (conn->Pfdebug)
fprintf(conn->Pfdebug, "pqSaveParameterStatus: '%s' = '%s'\n",
name, value);

I think the above code has become to be unnecessary because new pqTrace framework
become to print it.

Regards
Ryo Matsumura