Re: libpq debug log

At Wed, 16 Sep 2020 17:41:55 -0300, Alvaro Herrera <alvherre@2ndquadrant.com> wrote in
> Hello Aya Iwata,
>
> I like this patch, and I think we should have it.  I have updated it, as
> it had conflicts.
>
> In 0002, I remove use of ftime(), because that function is obsolete.
> However, with that change we lose printing of milliseconds in the trace
> lines.  I think that's not great, but I also think we can live without
> them until somebody gets motivated to write the code for that.  It seems
> a little messy so I'd prefer to leave that for a subsequent commit.
> (Maybe we can just use pg_strftime.)
>
> Looking at the message type tables, I decided to get rid of the "bf"
> table, which had only two bytes, and instead put CopyData and CopyDone
> in the other two tables.  That seems simpler.  Also, the COMMAND_x_MAX
> macros were a bit pointless; I just expanded at the only caller of each,
> using lengthof().  And since the message type is unsigned, there's no
> need to do "c >= 0" since it must always be true.
>
> I added setlinebuf() to the debug file.  Works better than without,
> because "tail -f /tmp/libpqtrace.log" works as you'd expect.
>
> One thing that it might be good to do is to avoid creating the message
> type tables as const but instead initialize them if and only if tracing
> is enabled, on the first call.  I think that would not only save space
> in the constant area of the library for the 99.99% of the cases where
> tracing isn't used, but also make the initialization code be more
> sensible (since presumably you wouldn't have to initialize all the
> zeroes.)
>
> Opinions?  I experimented by patching psql as below (not intended for
> commit) and it looks good.  Only ErrorResponse prints the terminator as
> a control character, or something:
>
> 2020-09-16 13:27:29.072 -03  < ErrorResponse 117 S "ERROR" V "ERROR" C "42704" M "no existe el slot de replicación
«foobar»"F "slot.c" L "408" R "ReplicationSlotAcquireInternal" ^@  
>
>
> diff --git a/src/bin/psql/startup.c b/src/bin/psql/startup.c
> index 8232a0143b..01728ba8e8 100644
> --- a/src/bin/psql/startup.c
> +++ b/src/bin/psql/startup.c
> @@ -301,6 +301,11 @@ main(int argc, char *argv[])
>
>      psql_setup_cancel_handler();
>
> +    {
> +        FILE *trace = fopen("/tmp/libpqtrace.log", "a+");
> +        PQtrace(pset.db, trace);
> +    }
> +
>      PQsetNoticeProcessor(pset.db, NoticeProcessor, NULL);
>
>      SyncVariables();

I saw that version and have some comments.

+pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
+{
+    const char *message_type;

Compiler complains that this is unused.

+static const char *
+pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
+{
...
+    else
+        return "UnknownCommand";
+}

Compiler complains as "control reached end of non-void function"


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

pqLogMsgString(conn, str, -1, FROM_*) means actual length may be
different from the caller thinks, but the pqLogLineBreak() subtracts
that value from the message length rememberd in in logging_message.
Anyway AFAICS the patch doesn't use the code path so we should remove
the first two lines.

+            case LOG_CONTENTS:
+                fprintf(conn->Pfdebug, "%s%d ", prefix, v);

That prints #65535 for v = -1 and length = 2. I think it should be
properly expanded as a signed integer.


@@ -139,8 +447,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);

By the way, appendBinaryPQExpBuffer() enlarges its buffer by the size
of the exact length of the given data, but appends '\0' at the end of
the copied data. Couldn't that leads to an memory overrun?


regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center