RE: libpq debug log

Tom-san, Alvaro-san,


From: Tom Lane <tgl@sss.pgh.pa.us>
> I took a quick look through the v22 patch, and TBH I don't like much of anything
> at all about the proposed architecture.  It's retained most of the flavor of the
> way it was done before, which was a hangover from the old process-on-the-fly
> scheme.

Yes, the patch just follows the current style of interspersing.  (But some places are removed so it's a bit cleaner.)

Anyway, I think your suggestion should be better, resulting in much cleaner separation of message handling and logging.


> I think the right way to do this, now that we've killed off v2 protocol support, is to
> rely on the fact that libpq fully buffers both incoming and outgoing messages.
> We should nuke every last bit of the existing code that intersperses tracing logic
> with normal message decoding and construction, and instead have two tracing
> entry points:

FWIW, I was surprised and glad when I saw the commit message to remove the v2 protocol.


> (1) Log a received message.  This is called as soon as we know (from the
> length word) that we have the whole message available, and it's just passed a
> pointer into the input buffer.  It should examine the input message for itself
> and print the details.
> 
> (2) Log a message-to-be-sent.  Again, call it as soon as we've constructed a
> complete message in the output buffer, and let it examine and print that
> message for itself.

I understood that the former is pqParseInput3() and the latter is pqPutMsgEnd().  They call the logging function wne conn->pfdebug is not NULL.  Its signature is like this (that will be defined in libpq-trace.c):

    void pqLogMessage(const char *message, bool toServer);

The message argument points to the message type byte.  toServer is true for messages sent to the server.  The signature could alternatively be one of the following, but this is a matter of taste:

    void pqLogMessage(char message_type, const char *message, bool toServer);
    void pqLogMessage(char message_type, int length, const char *message, bool toServer);

This function simply outputs the timestamp, message direction, message type, length, and message contents.  The output processing of message contents branches on a message type with a switch-case statement.  Perhaps the output processing of each message should be separated into its own function like pqLogMessageD() for 'D' message so that the indentation won't get deep in the main logging function.


> Both of these pieces of logic could be written directly from the protocol
> specification, without any interaction with the main libpq code paths, which
> would be a Good Thing IMO.  The current intertwined approach is somewhere
> between useless and counterproductive if you're in need of tracing down a
> libpq bug.  (In other words, I'm suggesting that the apparent need for
> duplicate logic would be good not bad, and indeed that it'd be best to write the
> tracing logic without consulting the existing libpq code at all.)

Yes, the only thing I'm concerned about is to have two places that have to be aware of the message format -- message encoding/decoding and logging.  But this cleaner separation would pay it.

Alvaro-san, what do you think?  Anyway, we'll soon post the updated patch that fixes the repeated ParseComplete issue based on the current patch.  After that, we'll send a patch based on Tom-san's idea.


Regards
Takayuki Tsunakawa