Re: libpq debug log

At Mon, 8 Feb 2021 14:57:47 +0000, "iwata(dot)aya(at)fujitsu(dot)com" <iwata(dot)aya(at)fujitsu(dot)com> wrote in
> I update the patch.
> I modified code according to review comments of Tsunakawa san and Horiguchi san.
>
> And I fixed some bugs.

Thanks for the new version.

+typedef enum
+{
+ MSGDIR_FROM_BACKEND,
+ MSGDIR_FROM_FRONTEND
+} PGCommSource;

This is halfly exposed to other part of libpq. Specifically only
MSGDIR_FROM_BACKEND is used in fe-misc.c and only for
pgLogMessageString and pqLogMessagenchar. I would suggest to hide this
enum from fe-misc.c.

Looking into pqLogMessageString,

+pqLogMessageString(PGconn *conn, const char *v, int length, PGCommSource source)
+{
+ if (source == MSGDIR_FROM_BACKEND && conn->be_msg->state != LOG_CONTENTS)
+ {
+ pqLogInvalidProtocol(conn, MSGDIR_FROM_BACKEND);
+ return; /* XXX ??? */
+ }
+
+ fprintf(conn->Pfdebug, "\"%s\"", v);
+ if (source == MSGDIR_FROM_BACKEND)
+ pqTraceMaybeBreakLine(length, conn);
+}

The only part that shared by both be and fe is the fprintf(). I think
it can be naturally split into separate functions for backend and
frontend messages.

Looking into pqLogMessagenchar,

+/*
+ * pqLogMessagenchar: output a string of exactly len bytes message to the log
+ */
+void
+pqLogMessagenchar(PGconn *conn, const char *v, int len, PGCommSource commsource)
+{
+ fprintf(conn->Pfdebug, "\'");
+ pqLogBinaryMsg(conn, v, len, commsource);
+ fprintf(conn->Pfdebug, "\'");
+ pqTraceMaybeBreakLine(len, conn);
+}

+static void
+pqLogBinaryMsg(PGconn *conn, const char *v, int length, PGCommSource source)
+{
+ int i,
+ pin;
+
+ if (source == MSGDIR_FROM_BACKEND && conn->be_msg->state != LOG_CONTENTS)
+ {
+ pqLogInvalidProtocol(conn, MSGDIR_FROM_BACKEND);
+ return; /* XXX ??? */

# What is this???

+ }
.. shared part
+}

pqLogMessagenchar is the sole caller of pqLogBinaryMsg. So we can
refactor the two functions and have pqLogMessagenchar_for_be and
_for_fe without a fear of the side effect to other callers. (The
names are discussed below.)

+typedef enum PGLogState
+{

This is libpq-logging.c internal type. It is not needed to be exposed.

+extern void pqTraceForcelyBreakLine(int size, PGconn *conn);
+extern void pqStoreFrontendMsg(PGconn *conn, PGLogMsgDataType type, int length)+extern void pqStoreFeMsgStart(PGconn *conn, char type);
+extern void pqLogFrontendMsg(PGconn *conn, int msgLen);
+extern void pqLogMessageByte1(PGconn *conn, char v);
+extern void pqLogMessageInt(PGconn *conn, int v, int length);
+extern void pqLogMessageString(PGconn *conn, const char *v, int length,
+ PGCommSource commsource);
+extern void pqLogMessagenchar(PGconn *conn, const char *v, int length,
+ PGCommSource commsource);

The API functions looks like randomly/inconsistently named and
designed. I think that API should be in more structurally designed.

The comments about individual function names follow.

+/*
+ * pqTraceForcelyBreakLine:
+ * If message is not completed, print a line break and reset.
+ */
+void
+pqTraceForcelyBreakLine(int size, PGconn *conn)
+{
+ fprintf(conn->Pfdebug, "\n");
+ pqTraceResetBeMsg(conn);
+}

Differently from the comment, this function doesn't work in a
conditional way nor in a forceful way. It is just putting a new line
and resetting the backend message variables. I would name this as
pqTrace(Finish|Close)BeMsgLog().

+/*
+ * pqStoreFrontendMsg
+ * Keep track of a from-frontend message that was just written to the
+ * output buffer.
+ *
+ * Frontend messages are constructed piece by piece, and the message length
+ * is determined at the end, but sent to the server first; so for tracing
+ * purposes we store everything in memory and print to the trace file when
+ * the message is complete.
+ */
+void
+pqStoreFrontendMsg(PGconn *conn, PGLogMsgDataType type, int length)
+{

I would name this as pqTrace(Store/Append)FeMsg().

+void
+pqStoreFeMsgStart(PGconn *conn, char type)
+{
+ conn->fe_msg->msg_type = type;
+}

The name says that "stores the message "start"". But it actually
stores the message type. I would name this as
pqTraceSetFeMsgType(). Or in contrast to pqTraceFinishBeMsgLog, this
can be named as pqTrace(Start|Begin|Init)BeMsgLog().

+ * pqLogFrontendMsg
+ * Print accumulated frontend message pieces to the trace file.
+ */
+void
+pqLogFrontendMsg(PGconn *conn, int msgLen)

I would name this as pqTraceEmitFeMsgLog().

+ * pqLogMessageByte1: output 1 char from-backend message to the log
+ * pqLogMessageInt: output a 2- or 4-byte integer from-backend msg to the log

I would name this as pqTraceEmitBeByteLog(), pqTraceEmitBeIntLog()
respectively.

+ * pqLogMessageString: output a null-terminated string to the log

This function is used for both directions. pqTraceEmitStringLog(). If it is split into fe and be parts, they would be pqTraceEmit(Be|Fe)StringLog().

+ * pqLogMessagenchar: output a string of exactly len bytes message to the log

This logs a byte sequence in hexadecimals. I would name that as
pqTraceEmitBytesLog(). Or pqTraceEmit(Be|Fe)BytesLog().

...I finish once here.

Is there any thoughts? Optinions on the namings?

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center