RE: libpq debug log - Mailing list pgsql-hackers

Hi all,

Thank you for your review. I update patch to v17.

> From: Tsunakawa, Takayuki/綱川 貴之 <tsunakawa.takay@fujitsu.com>
> Sent: Tuesday, February 9, 2021 11:26 AM
> (45)
...
> The description of PQtrace() should be written independent of PQtraceEx().
> It is an unnecessary implementation detail to the user that PQtrace() calls
> PQtraceEx() internally.  Plus, a separate entry for PQtraceEx() needs to be
> added.

I add PQtraceSetFlags() description instead of PQtraceEx() in response to Horiguchi san's suggestion.

> (46)
>
> If skipLogging is intended for use with backend -> frontend messages only,
> shouldn't it be placed in conn->b_msg?

I moved skip flag to be_msg.

> (47)
...
> I'm not completely sure if other places interpose a block comment like this
> between if/for/while conditions, but I think it's better to put the comment
> before if.

I moved this comment to before if.

> From: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
> Sent: Tuesday, February 9, 2021 5:26 PM

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

Thank you for your advice on refactoring.
Separating pqLogMessagenchar() into pqLogMessagenchar_for_be and pqLogMessagenchar_for_fe
seemed like adding more similar code. So I didn't work on it.

> +typedef enum PGLogState
> +{
>
> This is libpq-logging.c internal type. It is not needed to be exposed.

I fixed it.

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

Thank you for your advice. I changed these functions name.
>
> +/*
> + * 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().

This function can be used when a connection is lost or when the copyData result is ignored according to the original
code.
It is called to reset halfway logging. So I want to know that it will be forced to quit.
Therefore, I changed the name as pqTraceForcelyFinishBeMsgLog().

>
> +/*
> + * 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().

I renamed it to pqTraceStoreFeMsg(). Because people who do not know this feature is confused due to the name.
It is difficult to understand why store message during the logging.
>
>
> +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().

I think pqTraceSetFeMsgType() is better because this function's behavior is just set first byte1 message from Frontend.
>
>
> + * pqLogFrontendMsg
> + *        Print accumulated frontend message pieces to the trace file.
> + */
> +void
> +pqLogFrontendMsg(PGconn *conn, int msgLen)
>
> I would name this as pqTraceEmitFeMsgLog().

I would name this as pqTraceLogFeMsg().
It is shorter and we can easy to understand what this function do.

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

I think log and emit would mean the same thing in this case. And log is more easy to understand in this case.
So I changed name to pqTraceLogBeMsgByte1() and pqTraceLogBeMsgInt().

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

I changed name to pqTraceLogMsgString().


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

It is named to refer to pqGetnchar/pqPutnchar. So I changed this name to pqTraceLogMsgnchar().

> ...I finish once here.

Thank you for your review.

> From: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
> Sent: Tuesday, February 9, 2021 5:30 PM

> > > PQtrace(conn, of);
> > > PQtraceSetFlags(conn, PQTRACE_SUPPRESS_TIMESTAMPS); <logging
> without
> > > timestamps> PQtraceSetFlags(conn, 0); <logging with timestamps>
> >
> > I find this better because the application does not have to call
> > PQuntrace() and PQtrace() again to enable/disable timestamp output,
> > which requires passing the FILE pointer again.  (I don't imagine
> > applications would repeatedly turn logging on and off in practice,
> > though.)
>
> Thanks and Yes, I also don't imagine that users change the timestmp state
> repeatedly:p It's just a example.

I implemented PQtraceSetFlags() function. And add documentation of PQtraceSetFlags().

> > > The name skipLogging is somewhat obscure. The flag doesn't inhibit
> > > all logs from being emitted.  It seems like it represents how far
> > > bytes the logging mechanism consumed for the limited cases. Thus, I
> > > think it can be a cursor variable like inCursor.
...
> > > I'm not sure this is easier to read than the skipLogging.
> >
> > I'd like Iwata-san to evaluate this and decide whether to take this approach
> or the current one.
>
> +1

I thought this idea was very good and tried it easily. But this didn't work...
So I didn't work on this implementation because the code can be more complex.

Regards
Aya Iwata
Fujits