libpq: Trace all messages received from the server

Not all messages that libpq received from the server would be sent
through our message tracing logic.  This commit tries to fix that by
introducing a new function pqParseDone which make it harder to forget
about doing so.

The messages that we now newly send through our tracing logic are:

- CopyData (received by COPY TO STDOUT)
- Authentication requests
- NegotiateProtocolVersion
- Some ErrorResponse messages during connection startup
- ReadyForQuery when received after a FunctionCall message

Author: Jelte Fennema-Nio <[email protected]>
Discussion: https://postgr.es/m/CAGECzQSoPHtZ4xe0raJ6FYSEiPPS+YWXBhOGo+Y1YecLgknF3g@mail.gmail.com

diff --git a/src/interfaces/libpq/fe-auth.c b/src/interfaces/libpq/fe-auth.c
index 4da07c1f9864831ab0be375bb4cbabe1a99a56c4..5c8f404463f15cbadee8009cf6a5427691a13e00 100644 (file)
--- a/src/interfaces/libpq/fe-auth.c
+++ b/src/interfaces/libpq/fe-auth.c
@@ -94,6 +94,10 @@ pg_GSS_continue(PGconn *conn, int payloadlen)
        ginbuf.value = NULL;
    }
 
+   /* finished parsing, trace server-to-client message */
+   if (conn->Pfdebug)
+       pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
+
    /* Only try to acquire credentials if GSS delegation isn't disabled. */
    if (!pg_GSS_have_cred_cache(&conn->gcred))
        conn->gcred = GSS_C_NO_CREDENTIAL;
@@ -258,6 +262,10 @@ pg_SSPI_continue(PGconn *conn, int payloadlen)
        InBuffers[0].BufferType = SECBUFFER_TOKEN;
    }
 
+   /* finished parsing, trace server-to-client message */
+   if (conn->Pfdebug)
+       pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
+
    OutBuffers[0].pvBuffer = NULL;
    OutBuffers[0].BufferType = SECBUFFER_TOKEN;
    OutBuffers[0].cbBuffer = 0;
@@ -563,6 +571,10 @@ pg_SASL_init(PGconn *conn, int payloadlen)
        }
    }
 
+   /* finished parsing, trace server-to-client message */
+   if (conn->Pfdebug)
+       pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
+
    Assert(conn->sasl);
 
    /*
@@ -651,6 +663,11 @@ pg_SASL_continue(PGconn *conn, int payloadlen, bool final)
        free(challenge);
        return STATUS_ERROR;
    }
+
+   /* finished parsing, trace server-to-client message */
+   if (conn->Pfdebug)
+       pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
+
    /* For safety and convenience, ensure the buffer is NULL-terminated. */
    challenge[payloadlen] = '\0';
 
@@ -716,6 +733,10 @@ pg_password_sendauth(PGconn *conn, const char *password, AuthRequest areq)
            return STATUS_ERROR;    /* shouldn't happen */
    }
 
+   /* finished parsing, trace server-to-client message */
+   if (conn->Pfdebug)
+       pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
+
    /* Encrypt the password if needed. */
 
    switch (areq)

diff --git a/src/interfaces/libpq/fe-connect.c b/src/interfaces/libpq/fe-connect.c
index 246055df960ae525a1fd3a9f0ab9a2d674c69155..ab308a0580fe916aefd2106ff4e07ab4b926b011 100644 (file)
--- a/src/interfaces/libpq/fe-connect.c
+++ b/src/interfaces/libpq/fe-connect.c
@@ -3797,7 +3797,7 @@ keep_going:                       /* We will come back to here until there is
                        return PGRES_POLLING_READING;
                    }
                    /* OK, we read the message; mark data consumed */
-                   conn->inStart = conn->inCursor;
+                   pqParseDone(conn, conn->inCursor);
 
                    /*
                     * Before 7.2, the postmaster didn't always end its
@@ -3847,7 +3847,7 @@ keep_going:                       /* We will come back to here until there is
                        goto error_return;
                    }
                    /* OK, we read the message; mark data consumed */
-                   conn->inStart = conn->inCursor;
+                   pqParseDone(conn, conn->inCursor);
 
                    /*
                     * If error is "cannot connect now", try the next host if
@@ -3876,7 +3876,7 @@ keep_going:                       /* We will come back to here until there is
                        goto error_return;
                    }
                    /* OK, we read the message; mark data consumed */
-                   conn->inStart = conn->inCursor;
+                   pqParseDone(conn, conn->inCursor);
                    goto error_return;
                }
 
@@ -3901,7 +3901,11 @@ keep_going:                      /* We will come back to here until there is
                 */
                res = pg_fe_sendauth(areq, msgLength, conn);
 
-               /* OK, we have processed the message; mark data consumed */
+               /*
+                * OK, we have processed the message; mark data consumed.  We
+                * don't call pqParseDone here because we already traced this
+                * message inside pg_fe_sendauth.
+                */
                conn->inStart = conn->inCursor;
 
                if (res != STATUS_OK)

diff --git a/src/interfaces/libpq/fe-misc.c b/src/interfaces/libpq/fe-misc.c
index f235bfbb41fb558b19bd2f32ecca96b88a7d75a8..928a47162d1a3bd5ca8aec42262877187b3781b8 100644 (file)
--- a/src/interfaces/libpq/fe-misc.c
+++ b/src/interfaces/libpq/fe-misc.c
@@ -435,6 +435,21 @@ pqCheckInBufferSpace(size_t bytes_needed, PGconn *conn)
    return EOF;
 }
 
+/*
+ * pqParseDone: after a server-to-client message has successfully
+ * been parsed, advance conn->inStart to account for it.
+ */
+void
+pqParseDone(PGconn *conn, int newInStart)
+{
+   /* trace server-to-client message */
+   if (conn->Pfdebug)
+       pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
+
+   /* Mark message as done */
+   conn->inStart = newInStart;
+}
+
 /*
  * pqPutMsgStart: begin construction of a message to the server
  *

diff --git a/src/interfaces/libpq/fe-protocol3.c b/src/interfaces/libpq/fe-protocol3.c
index 3170d484f026ac67dd6104580dad176373c5785c..8c5ac1729f0e69f91388bf72d62fc41f08054554 100644 (file)
--- a/src/interfaces/libpq/fe-protocol3.c
+++ b/src/interfaces/libpq/fe-protocol3.c
@@ -454,12 +454,8 @@ pqParseInput3(PGconn *conn)
        /* Successfully consumed this message */
        if (conn->inCursor == conn->inStart + 5 + msgLength)
        {
-           /* trace server-to-client message */
-           if (conn->Pfdebug)
-               pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
-
            /* Normal case: parsing agrees with specified length */
-           conn->inStart = conn->inCursor;
+           pqParseDone(conn, conn->inCursor);
        }
        else
        {
@@ -1728,12 +1724,8 @@ getCopyDataMessage(PGconn *conn)
                return -1;
        }
 
-       /* trace server-to-client message */
-       if (conn->Pfdebug)
-           pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
-
        /* Drop the processed message and loop around for another */
-       conn->inStart = conn->inCursor;
+       pqParseDone(conn, conn->inCursor);
    }
 }
 
@@ -1791,13 +1783,13 @@ pqGetCopyData3(PGconn *conn, char **buffer, int async)
            (*buffer)[msgLength] = '\0';    /* Add terminating null */
 
            /* Mark message consumed */
-           conn->inStart = conn->inCursor + msgLength;
+           pqParseDone(conn, conn->inCursor + msgLength);
 
            return msgLength;
        }
 
        /* Empty, so drop it and loop around for another */
-       conn->inStart = conn->inCursor;
+       pqParseDone(conn, conn->inCursor);
    }
 }
 
@@ -2168,8 +2160,9 @@ pqFunctionCall3(PGconn *conn, Oid fnid,
            case 'Z':           /* backend is ready for new query */
                if (getReadyForQuery(conn))
                    continue;
-               /* consume the message and exit */
-               conn->inStart += 5 + msgLength;
+
+               /* consume the message */
+               pqParseDone(conn, conn->inStart + 5 + msgLength);
 
                /*
                 * If we already have a result object (probably an error), use
@@ -2194,6 +2187,7 @@ pqFunctionCall3(PGconn *conn, Oid fnid,
                        pqSaveErrorResult(conn);
                    }
                }
+               /* and we're out */
                return pqPrepareAsyncResult(conn);
            case 'S':           /* parameter status */
                if (getParameterStatus(conn))
@@ -2203,18 +2197,18 @@ pqFunctionCall3(PGconn *conn, Oid fnid,
                /* The backend violates the protocol. */
                libpq_append_conn_error(conn, "protocol error: id=0x%x", id);
                pqSaveErrorResult(conn);
-               /* trust the specified message length as what to skip */
+
+               /*
+                * We can't call parsing done due to the protocol violation
+                * (so message tracing wouldn't work), but trust the specified
+                * message length as what to skip.
+                */
                conn->inStart += 5 + msgLength;
                return pqPrepareAsyncResult(conn);
        }
 
-       /* trace server-to-client message */
-       if (conn->Pfdebug)
-           pqTraceOutputMessage(conn, conn->inBuffer + conn->inStart, false);
-
-       /* Completed this message, keep going */
-       /* trust the specified message length as what to skip */
-       conn->inStart += 5 + msgLength;
+       /* Completed parsing this message, keep going */
+       pqParseDone(conn, conn->inStart + 5 + msgLength);
        needInput = false;
    }
 

diff --git a/src/interfaces/libpq/fe-trace.c b/src/interfaces/libpq/fe-trace.c
index 3527b9f0f5dff6f8587791cb15c34c2c9ccffb8c..bff7d919d570774af16e3f001acb6043391adf3b 100644 (file)
--- a/src/interfaces/libpq/fe-trace.c
+++ b/src/interfaces/libpq/fe-trace.c
@@ -280,6 +280,14 @@ pqTraceOutput_CommandComplete(FILE *f, const char *message, int *cursor)
    pqTraceOutputString(f, message, cursor, false);
 }
 
+static void
+pqTraceOutput_CopyData(FILE *f, const char *message, int *cursor, int length,
+                      bool suppress)
+{
+   fprintf(f, "CopyData\t");
+   pqTraceOutputNchar(f, length - *cursor + 1, message, cursor, suppress);
+}
+
 static void
 pqTraceOutput_DataRow(FILE *f, const char *message, int *cursor)
 {
@@ -472,10 +480,58 @@ pqTraceOutput_Query(FILE *f, const char *message, int *cursor)
 }
 
 static void
-pqTraceOutput_Authentication(FILE *f, const char *message, int *cursor)
+pqTraceOutput_Authentication(FILE *f, const char *message, int *cursor,
+                            int length, bool suppress)
 {
-   fprintf(f, "Authentication\t");
-   pqTraceOutputInt32(f, message, cursor, false);
+   int         authType = 0;
+
+   memcpy(&authType, message + *cursor, 4);
+   authType = (int) pg_ntoh32(authType);
+   *cursor += 4;
+   switch (authType)
+   {
+       case AUTH_REQ_OK:
+           fprintf(f, "AuthenticationOk");
+           break;
+           /* AUTH_REQ_KRB4 not supported */
+           /* AUTH_REQ_KRB5 not supported */
+       case AUTH_REQ_PASSWORD:
+           fprintf(f, "AuthenticationCleartextPassword");
+           break;
+           /* AUTH_REQ_CRYPT not supported */
+       case AUTH_REQ_MD5:
+           fprintf(f, "AuthenticationMD5Password");
+           break;
+       case AUTH_REQ_GSS:
+           fprintf(f, "AuthenticationGSS");
+           break;
+       case AUTH_REQ_GSS_CONT:
+           fprintf(f, "AuthenticationGSSContinue\t");
+           pqTraceOutputNchar(f, length - *cursor + 1, message, cursor,
+                              suppress);
+           break;
+       case AUTH_REQ_SSPI:
+           fprintf(f, "AuthenticationSSPI");
+           break;
+       case AUTH_REQ_SASL:
+           fprintf(f, "AuthenticationSASL\t");
+           while (message[*cursor] != '\0')
+               pqTraceOutputString(f, message, cursor, false);
+           pqTraceOutputString(f, message, cursor, false);
+           break;
+       case AUTH_REQ_SASL_CONT:
+           fprintf(f, "AuthenticationSASLContinue\t");
+           pqTraceOutputNchar(f, length - *cursor + 1, message, cursor,
+                              suppress);
+           break;
+       case AUTH_REQ_SASL_FIN:
+           fprintf(f, "AuthenticationSASLFinal\t");
+           pqTraceOutputNchar(f, length - *cursor + 1, message, cursor,
+                              suppress);
+           break;
+       default:
+           fprintf(f, "Unknown authentication message %d", authType);
+   }
 }
 
 static void
@@ -625,7 +681,8 @@ pqTraceOutputMessage(PGconn *conn, const char *message, bool toServer)
                pqTraceOutput_CommandComplete(conn->Pfdebug, message, &logCursor);
            break;
        case PqMsg_CopyData:
-           /* Drop COPY data to reduce the overhead of logging. */
+           pqTraceOutput_CopyData(conn->Pfdebug, message, &logCursor,
+                                  length, regress);
            break;
        case PqMsg_Describe:
            /* Describe(F) and DataRow(B) use the same identifier. */
@@ -714,7 +771,8 @@ pqTraceOutputMessage(PGconn *conn, const char *message, bool toServer)
            pqTraceOutput_Query(conn->Pfdebug, message, &logCursor);
            break;
        case PqMsg_AuthenticationRequest:
-           pqTraceOutput_Authentication(conn->Pfdebug, message, &logCursor);
+           pqTraceOutput_Authentication(conn->Pfdebug, message, &logCursor,
+                                        length, regress);
            break;
        case PqMsg_PortalSuspended:
            fprintf(conn->Pfdebug, "PortalSuspended");

diff --git a/src/interfaces/libpq/libpq-int.h b/src/interfaces/libpq/libpq-int.h
index d97b595c97f3f41a62fce9a01fe8796fc1a6a35e..8ed1b28fcc0252f0d40d441b18febb7c97bd1553 100644 (file)
--- a/src/interfaces/libpq/libpq-int.h
+++ b/src/interfaces/libpq/libpq-int.h
@@ -753,6 +753,7 @@ extern PGresult *pqFunctionCall3(PGconn *conn, Oid fnid,
   */
 extern int pqCheckOutBufferSpace(size_t bytes_needed, PGconn *conn);
 extern int pqCheckInBufferSpace(size_t bytes_needed, PGconn *conn);
+extern void pqParseDone(PGconn *conn, int newInStart);
 extern int pqGetc(char *result, PGconn *conn);
 extern int pqPutc(char c, PGconn *conn);
 extern int pqGets(PQExpBuffer buf, PGconn *conn);