From 198b3716dba68544b55cb97bd120738a86d5df2d Mon Sep 17 00:00:00 2001 From: Alvaro Herrera Date: Tue, 30 Mar 2021 20:12:34 -0300 Subject: [PATCH] Improve PQtrace() output format MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Transform the PQtrace output format from its ancient (and mostly useless) byte-level output format to a logical-message-level output, making it much more usable. This implementation allows the printing code to be written (as it indeed was) by looking at the protocol documentation, which gives more confidence that the three (docs, trace code and actual code) actually match. Author: 岩田 彩 (Aya Iwata) Reviewed-by: 綱川 貴之 (Takayuki Tsunakawa) Reviewed-by: Kirk Jamison Reviewed-by: Kyotaro Horiguchi Reviewed-by: Tom Lane Reviewed-by: 黒田 隼人 (Hayato Kuroda) Reviewed-by: "Nagaura, Ryohei" Reviewed-by: Ryo Matsumura Reviewed-by: Greg Nancarrow Reviewed-by: Jim Doty Reviewed-by: Álvaro Herrera Discussion: https://postgr.es/m/71E660EB361DF14299875B198D4CE5423DE3FBA4@g01jpexmbkw25 --- doc/src/sgml/libpq.sgml | 42 +- src/interfaces/libpq/Makefile | 1 + src/interfaces/libpq/exports.txt | 1 + src/interfaces/libpq/fe-connect.c | 21 - src/interfaces/libpq/fe-exec.c | 4 - src/interfaces/libpq/fe-misc.c | 66 +-- src/interfaces/libpq/fe-protocol3.c | 13 + src/interfaces/libpq/fe-trace.c | 714 ++++++++++++++++++++++++++++ src/interfaces/libpq/libpq-fe.h | 17 +- src/interfaces/libpq/libpq-int.h | 7 + 10 files changed, 804 insertions(+), 82 deletions(-) create mode 100644 src/interfaces/libpq/fe-trace.c diff --git a/doc/src/sgml/libpq.sgml b/doc/src/sgml/libpq.sgml index be674fbaa9..3ec458ce09 100644 --- a/doc/src/sgml/libpq.sgml +++ b/doc/src/sgml/libpq.sgml @@ -6459,12 +6459,27 @@ PGContextVisibility PQsetErrorContextVisibility(PGconn *conn, PGContextVisibilit - Enables tracing of the client/server communication to a debugging file stream. + Enables tracing of the client/server communication to a debugging file + stream. void PQtrace(PGconn *conn, FILE *stream); + + Each line consists of: an optional timestamp, a direction indicator + (F for messages from client to server + or B for messages from server to client), + message length, message type, and message contents. + Non-message contents fields (timestamp, direction, length and message type) + are separated by a tab. Message contents are separated by a space. + Protocol strings are enclosed in double quotes, while strings used as data + values are enclosed in single quotes. Non-printable chars are printed as + hexadecimal escapes. + Further message-type-specific detail can be found in + . + + On Windows, if the libpq library and an application are @@ -6479,6 +6494,31 @@ void PQtrace(PGconn *conn, FILE *stream); + + PQtraceSetFlagsPQtraceSetFlags + + + + Controls the tracing behavior of client/server communication. + +void PQtraceSetFlags(PGconn *conn, int flags); + + + + + flags contains flag bits describing the operating mode + of tracing. + If flags contains PQTRACE_SUPPRESS_TIMESTAMPS, + then the timestamp is not included when printing each message. + If flags contains PQTRACE_REGRESS_MODE, + then some fields are redacted when printing each message, such as object + OIDs, to make the output more convenient to use in testing frameworks. + This function must be called after calling PQtrace. + + + + + PQuntracePQuntrace diff --git a/src/interfaces/libpq/Makefile b/src/interfaces/libpq/Makefile index 2aca882a2b..0c4e55b6ad 100644 --- a/src/interfaces/libpq/Makefile +++ b/src/interfaces/libpq/Makefile @@ -39,6 +39,7 @@ OBJS = \ fe-print.o \ fe-protocol3.o \ fe-secure.o \ + fe-trace.o \ legacy-pqsignal.o \ libpq-events.o \ pqexpbuffer.o \ diff --git a/src/interfaces/libpq/exports.txt b/src/interfaces/libpq/exports.txt index 5c48c14191..a00701f2c5 100644 --- a/src/interfaces/libpq/exports.txt +++ b/src/interfaces/libpq/exports.txt @@ -183,3 +183,4 @@ PQenterPipelineMode 180 PQexitPipelineMode 181 PQpipelineSync 182 PQpipelineStatus 183 +PQtraceSetFlags 184 diff --git a/src/interfaces/libpq/fe-connect.c b/src/interfaces/libpq/fe-connect.c index 53b354abb2..a90bdb8ab6 100644 --- a/src/interfaces/libpq/fe-connect.c +++ b/src/interfaces/libpq/fe-connect.c @@ -6859,27 +6859,6 @@ PQsetErrorContextVisibility(PGconn *conn, PGContextVisibility show_context) return old; } -void -PQtrace(PGconn *conn, FILE *debug_port) -{ - if (conn == NULL) - return; - PQuntrace(conn); - conn->Pfdebug = debug_port; -} - -void -PQuntrace(PGconn *conn) -{ - if (conn == NULL) - return; - if (conn->Pfdebug) - { - fflush(conn->Pfdebug); - conn->Pfdebug = NULL; - } -} - PQnoticeReceiver PQsetNoticeReceiver(PGconn *conn, PQnoticeReceiver proc, void *arg) { diff --git a/src/interfaces/libpq/fe-exec.c b/src/interfaces/libpq/fe-exec.c index f143b8b7fb..03592bdce9 100644 --- a/src/interfaces/libpq/fe-exec.c +++ b/src/interfaces/libpq/fe-exec.c @@ -970,10 +970,6 @@ pqSaveParameterStatus(PGconn *conn, const char *name, const char *value) pgParameterStatus *pstatus; pgParameterStatus *prev; - if (conn->Pfdebug) - fprintf(conn->Pfdebug, "pqSaveParameterStatus: '%s' = '%s'\n", - name, value); - /* * Forget any old information about the parameter */ diff --git a/src/interfaces/libpq/fe-misc.c b/src/interfaces/libpq/fe-misc.c index ce2d24b91f..082b583c15 100644 --- a/src/interfaces/libpq/fe-misc.c +++ b/src/interfaces/libpq/fe-misc.c @@ -84,9 +84,6 @@ pqGetc(char *result, PGconn *conn) *result = conn->inBuffer[conn->inCursor++]; - if (conn->Pfdebug) - fprintf(conn->Pfdebug, "From backend> %c\n", *result); - return 0; } @@ -100,9 +97,6 @@ pqPutc(char c, PGconn *conn) if (pqPutMsgBytes(&c, 1, conn)) return EOF; - if (conn->Pfdebug) - fprintf(conn->Pfdebug, "To backend> %c\n", c); - return 0; } @@ -138,10 +132,6 @@ pqGets_internal(PQExpBuffer buf, PGconn *conn, bool resetbuffer) conn->inCursor = ++inCursor; - if (conn->Pfdebug) - fprintf(conn->Pfdebug, "From backend> \"%s\"\n", - buf->data); - return 0; } @@ -167,9 +157,6 @@ pqPuts(const char *s, PGconn *conn) if (pqPutMsgBytes(s, strlen(s) + 1, conn)) return EOF; - if (conn->Pfdebug) - fprintf(conn->Pfdebug, "To backend> \"%s\"\n", s); - return 0; } @@ -188,13 +175,6 @@ pqGetnchar(char *s, size_t len, PGconn *conn) conn->inCursor += len; - if (conn->Pfdebug) - { - fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len); - fwrite(s, 1, len, conn->Pfdebug); - fprintf(conn->Pfdebug, "\n"); - } - return 0; } @@ -212,13 +192,6 @@ pqSkipnchar(size_t len, PGconn *conn) if (len > (size_t) (conn->inEnd - conn->inCursor)) return EOF; - if (conn->Pfdebug) - { - fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len); - fwrite(conn->inBuffer + conn->inCursor, 1, len, conn->Pfdebug); - fprintf(conn->Pfdebug, "\n"); - } - conn->inCursor += len; return 0; @@ -234,13 +207,6 @@ pqPutnchar(const char *s, size_t len, PGconn *conn) if (pqPutMsgBytes(s, len, conn)) return EOF; - if (conn->Pfdebug) - { - fprintf(conn->Pfdebug, "To backend> "); - fwrite(s, 1, len, conn->Pfdebug); - fprintf(conn->Pfdebug, "\n"); - } - return 0; } @@ -278,9 +244,6 @@ pqGetInt(int *result, size_t bytes, PGconn *conn) return EOF; } - if (conn->Pfdebug) - fprintf(conn->Pfdebug, "From backend (#%lu)> %d\n", (unsigned long) bytes, *result); - return 0; } @@ -314,9 +277,6 @@ pqPutInt(int value, size_t bytes, PGconn *conn) return EOF; } - if (conn->Pfdebug) - fprintf(conn->Pfdebug, "To backend (%lu#)> %d\n", (unsigned long) bytes, value); - return 0; } @@ -525,10 +485,6 @@ pqPutMsgStart(char msg_type, PGconn *conn) conn->outMsgEnd = endPos; /* length word, if needed, will be filled in by pqPutMsgEnd */ - if (conn->Pfdebug) - fprintf(conn->Pfdebug, "To backend> Msg %c\n", - msg_type ? msg_type : ' '); - return 0; } @@ -563,10 +519,6 @@ pqPutMsgBytes(const void *buf, size_t len, PGconn *conn) int pqPutMsgEnd(PGconn *conn) { - if (conn->Pfdebug) - fprintf(conn->Pfdebug, "To backend> Msg complete, length %u\n", - conn->outMsgEnd - conn->outCount); - /* Fill in length word if needed */ if (conn->outMsgStart >= 0) { @@ -576,6 +528,16 @@ pqPutMsgEnd(PGconn *conn) memcpy(conn->outBuffer + conn->outMsgStart, &msgLen, 4); } + /* trace client-to-server message */ + if (conn->Pfdebug) + { + if (conn->outCount < conn->outMsgStart) + pqTraceOutputMessage(conn, conn->outBuffer + conn->outCount, true); + else + pqTraceOutputNoTypeByteMessage(conn, + conn->outBuffer + conn->outMsgStart); + } + /* Make message eligible to send */ conn->outCount = conn->outMsgEnd; @@ -1002,11 +964,13 @@ pqSendSome(PGconn *conn, int len) int pqFlush(PGconn *conn) { - if (conn->Pfdebug) - fflush(conn->Pfdebug); - if (conn->outCount > 0) + { + if (conn->Pfdebug) + fflush(conn->Pfdebug); + return pqSendSome(conn, conn->outCount); + } return 0; } diff --git a/src/interfaces/libpq/fe-protocol3.c b/src/interfaces/libpq/fe-protocol3.c index 306e89acfd..b45fb7e705 100644 --- a/src/interfaces/libpq/fe-protocol3.c +++ b/src/interfaces/libpq/fe-protocol3.c @@ -457,6 +457,10 @@ 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; } @@ -1660,6 +1664,10 @@ 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; } @@ -2119,6 +2127,11 @@ pqFunctionCall3(PGconn *conn, Oid fnid, 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; diff --git a/src/interfaces/libpq/fe-trace.c b/src/interfaces/libpq/fe-trace.c new file mode 100644 index 0000000000..0bfae12a45 --- /dev/null +++ b/src/interfaces/libpq/fe-trace.c @@ -0,0 +1,714 @@ +/*------------------------------------------------------------------------- + * + * fe-trace.c + * functions for libpq protocol tracing + * + * Portions Copyright (c) 1996-2021, PostgreSQL Global Development Group + * Portions Copyright (c) 1994, Regents of the University of California + * + * IDENTIFICATION + * src/interfaces/libpq/fe-trace.c + * + *------------------------------------------------------------------------- + */ + +#include "postgres_fe.h" + +#include +#include + +#ifdef WIN32 +#include "win32.h" +#else +#include +#include +#endif + +#include "libpq-fe.h" +#include "libpq-int.h" +#include "pgtime.h" +#include "port/pg_bswap.h" + +/* Enable tracing */ +void +PQtrace(PGconn *conn, FILE *debug_port) +{ + if (conn == NULL) + return; + PQuntrace(conn); + if (debug_port == NULL) + return; + + /* Make the trace stream line-buffered */ + setvbuf(debug_port, NULL, _IOLBF, 0); + conn->Pfdebug = debug_port; + conn->traceFlags = 0; +} + +/* Disable tracing */ +void +PQuntrace(PGconn *conn) +{ + if (conn == NULL) + return; + if (conn->Pfdebug) + { + fflush(conn->Pfdebug); + conn->Pfdebug = NULL; + } + + conn->traceFlags = 0; +} + +/* Set flags for current tracing session */ +void +PQtraceSetFlags(PGconn *conn, int flags) +{ + if (conn == NULL) + return; + /* If PQtrace() failed, do nothing. */ + if (conn->Pfdebug == NULL) + return; + conn->traceFlags = flags; +} + +/* + * Print the current time, with microseconds, into a caller-supplied + * buffer. + * Cribbed from setup_formatted_log_time, but much simpler. + */ +static void +pqTraceFormatTimestamp(char *timestr, size_t ts_len) +{ + struct timeval tval; + pg_time_t stamp_time; + + gettimeofday(&tval, NULL); + stamp_time = (pg_time_t) tval.tv_sec; + + strftime(timestr, ts_len, + "%Y-%m-%d %H:%M:%S", + localtime(&stamp_time)); + /* append microseconds */ + sprintf(timestr + strlen(timestr), ".%06d", (int) (tval.tv_usec)); +} + +/* + * pqTraceOutputByte1: output a 1-char message to the log + */ +static void +pqTraceOutputByte1(FILE *pfdebug, const char *data, int *cursor) +{ + const char *v = data + *cursor; + + /* + * Show non-printable data in hex format, including the terminating \0 + * that completes ErrorResponse and NoticeResponse messages. + */ + if (!isprint(*v)) + fprintf(pfdebug, " \\x%02x", *v); + else + fprintf(pfdebug, " %c", *v); + *cursor += 1; +} + +/* + * pqTraceOutputInt16: output a 2-byte integer message to the log + */ +static int +pqTraceOutputInt16(FILE *pfdebug, const char *data, int *cursor) +{ + uint16 tmp; + int result; + + memcpy(&tmp, data + *cursor, 2); + *cursor += 2; + result = (int) pg_ntoh16(tmp); + fprintf(pfdebug, " %d", result); + + return result; +} + +/* + * pqTraceOutputInt32: output a 4-byte integer message to the log + * + * If 'suppress' is true, print a literal NNNN instead of the actual number. + */ +static int +pqTraceOutputInt32(FILE *pfdebug, const char *data, int *cursor, bool suppress) +{ + int result; + + memcpy(&result, data + *cursor, 4); + *cursor += 4; + result = (int) pg_ntoh32(result); + if (suppress) + fprintf(pfdebug, " NNNN"); + else + fprintf(pfdebug, " %d", result); + + return result; +} + +/* + * pqTraceOutputString: output a string message to the log + */ +static void +pqTraceOutputString(FILE *pfdebug, const char *data, int *cursor, bool suppress) +{ + int len; + + if (suppress) + { + fprintf(pfdebug, " \"SSSS\""); + *cursor += strlen(data + *cursor) + 1; + } + else + { + len = fprintf(pfdebug, " \"%s\"", data + *cursor); + + /* + * This is a null-terminated string. So add 1 after subtracting 3 + * which is the double quotes and space length from len. + */ + *cursor += (len - 3 + 1); + } +} + +/* + * pqTraceOutputNchar: output a string of exactly len bytes message to the log + */ +static void +pqTraceOutputNchar(FILE *pfdebug, int len, const char *data, int *cursor) +{ + int i, + next; /* first char not yet printed */ + const char *v = data + *cursor; + + fprintf(pfdebug, " \'"); + + for (next = i = 0; i < len; ++i) + { + if (isprint(v[i])) + continue; + else + { + fwrite(v + next, 1, i - next, pfdebug); + fprintf(pfdebug, "\\x%02x", v[i]); + next = i + 1; + } + } + if (next < len) + fwrite(v + next, 1, len - next, pfdebug); + + fprintf(pfdebug, "\'"); + *cursor += len; +} + +/* + * Output functions by protocol message type + */ + +/* NotificationResponse */ +static void +pqTraceOutputA(FILE *f, const char *message, int *cursor, bool regress) +{ + fprintf(f, "NotificationResponse\t"); + pqTraceOutputInt32(f, message, cursor, regress); + pqTraceOutputString(f, message, cursor, false); + pqTraceOutputString(f, message, cursor, false); +} + +/* Bind */ +static void +pqTraceOutputB(FILE *f, const char *message, int *cursor) +{ + int nparams; + + fprintf(f, "Bind\t"); + pqTraceOutputString(f, message, cursor, false); + pqTraceOutputString(f, message, cursor, false); + nparams = pqTraceOutputInt16(f, message, cursor); + + for (int i = 0; i < nparams; i++) + pqTraceOutputInt16(f, message, cursor); + + nparams = pqTraceOutputInt16(f, message, cursor); + + for (int i = 0; i < nparams; i++) + { + int nbytes; + + nbytes = pqTraceOutputInt32(f, message, cursor, false); + if (nbytes == -1) + continue; + pqTraceOutputNchar(f, nbytes, message, cursor); + } + + nparams = pqTraceOutputInt16(f, message, cursor); + for (int i = 0; i < nparams; i++) + pqTraceOutputInt16(f, message, cursor); +} + +/* Close(F) or CommandComplete(B) */ +static void +pqTraceOutputC(FILE *f, bool toServer, const char *message, int *cursor) +{ + if (toServer) + { + fprintf(f, "Close\t"); + pqTraceOutputByte1(f, message, cursor); + pqTraceOutputString(f, message, cursor, false); + } + else + { + fprintf(f, "CommandComplete\t"); + pqTraceOutputString(f, message, cursor, false); + } +} + +/* Describe(F) or DataRow(B) */ +static void +pqTraceOutputD(FILE *f, bool toServer, const char *message, int *cursor) +{ + if (toServer) + { + fprintf(f, "Describe\t"); + pqTraceOutputByte1(f, message, cursor); + pqTraceOutputString(f, message, cursor, false); + } + else + { + int nfields; + int len; + int i; + + fprintf(f, "DataRow\t"); + nfields = pqTraceOutputInt16(f, message, cursor); + for (i = 0; i < nfields; i++) + { + len = pqTraceOutputInt32(f, message, cursor, false); + if (len == -1) + continue; + pqTraceOutputNchar(f, len, message, cursor); + } + } +} + +/* NoticeResponse / ErrorResponse */ +static void +pqTraceOutputNR(FILE *f, const char *type, const char *message, int *cursor, + int length, bool regress) +{ + fprintf(f, "%s\t", type); + for (;;) + { + char field; + bool suppress; + + pqTraceOutputByte1(f, message, cursor); + field = message[*cursor - 1]; + if (field == '\0') + break; + + suppress = regress && (field == 'L' || field == 'F' || field == 'R'); + pqTraceOutputString(f, message, cursor, suppress); + } +} + +/* Execute(F) or ErrorResponse(B) */ +static void +pqTraceOutputE(FILE *f, bool toServer, const char *message, int *cursor, int length, bool regress) +{ + if (toServer) + { + fprintf(f, "Execute\t"); + pqTraceOutputString(f, message, cursor, false); + pqTraceOutputInt32(f, message, cursor, false); + } + else + pqTraceOutputNR(f, "ErrorResponse", message, cursor, length, regress); +} + +/* CopyFail */ +static void +pqTraceOutputf(FILE *f, const char *message, int *cursor) +{ + fprintf(f, "CopyFail\t"); + pqTraceOutputString(f, message, cursor, false); +} + +/* FunctionCall */ +static void +pqTraceOutputF(FILE *f, const char *message, int *cursor, bool regress) +{ + int nfields; + int nbytes; + + fprintf(f, "FunctionCall\t"); + pqTraceOutputInt32(f, message, cursor, regress); + nfields = pqTraceOutputInt16(f, message, cursor); + + for (int i = 0; i < nfields; i++) + pqTraceOutputInt16(f, message, cursor); + + nfields = pqTraceOutputInt16(f, message, cursor); + + for (int i = 0; i < nfields; i++) + { + nbytes = pqTraceOutputInt32(f, message, cursor, false); + if (nbytes == -1) + continue; + pqTraceOutputNchar(f, nbytes, message, cursor); + } + + pqTraceOutputInt16(f, message, cursor); +} + +/* CopyInResponse */ +static void +pqTraceOutputG(FILE *f, const char *message, int *cursor) +{ + int nfields; + + fprintf(f, "CopyInResponse\t"); + pqTraceOutputByte1(f, message, cursor); + nfields = pqTraceOutputInt16(f, message, cursor); + + for (int i = 0; i < nfields; i++) + pqTraceOutputInt16(f, message, cursor); +} + +/* CopyOutResponse */ +static void +pqTraceOutputH(FILE *f, const char *message, int *cursor) +{ + int nfields; + + fprintf(f, "CopyOutResponse\t"); + pqTraceOutputByte1(f, message, cursor); + nfields = pqTraceOutputInt16(f, message, cursor); + + for (int i = 0; i < nfields; i++) + pqTraceOutputInt16(f, message, cursor); +} + +/* BackendKeyData */ +static void +pqTraceOutputK(FILE *f, const char *message, int *cursor, bool regress) +{ + fprintf(f, "BackendKeyData\t"); + pqTraceOutputInt32(f, message, cursor, regress); + pqTraceOutputInt32(f, message, cursor, regress); +} + +/* Parse */ +static void +pqTraceOutputP(FILE *f, const char *message, int *cursor, bool regress) +{ + int nparams; + + fprintf(f, "Parse\t"); + pqTraceOutputString(f, message, cursor, false); + pqTraceOutputString(f, message, cursor, false); + nparams = pqTraceOutputInt16(f, message, cursor); + + for (int i = 0; i < nparams; i++) + pqTraceOutputInt32(f, message, cursor, regress); +} + +/* Query */ +static void +pqTraceOutputQ(FILE *f, const char *message, int *cursor) +{ + fprintf(f, "Query\t"); + pqTraceOutputString(f, message, cursor, false); +} + +/* Authentication */ +static void +pqTraceOutputR(FILE *f, const char *message, int *cursor) +{ + fprintf(f, "Authentication\t"); + pqTraceOutputInt32(f, message, cursor, false); +} + +/* ParameterStatus */ +static void +pqTraceOutputS(FILE *f, const char *message, int *cursor) +{ + fprintf(f, "ParameterStatus\t"); + pqTraceOutputString(f, message, cursor, false); + pqTraceOutputString(f, message, cursor, false); +} + +/* ParameterDescription */ +static void +pqTraceOutputt(FILE *f, const char *message, int *cursor, bool regress) +{ + int nfields; + + fprintf(f, "ParameterDescription\t"); + nfields = pqTraceOutputInt16(f, message, cursor); + + for (int i = 0; i < nfields; i++) + pqTraceOutputInt32(f, message, cursor, regress); +} + +/* RowDescription */ +static void +pqTraceOutputT(FILE *f, const char *message, int *cursor, bool regress) +{ + int nfields; + + fprintf(f, "RowDescription\t"); + nfields = pqTraceOutputInt16(f, message, cursor); + + for (int i = 0; i < nfields; i++) + { + pqTraceOutputString(f, message, cursor, false); + pqTraceOutputInt32(f, message, cursor, regress); + pqTraceOutputInt16(f, message, cursor); + pqTraceOutputInt32(f, message, cursor, regress); + pqTraceOutputInt16(f, message, cursor); + pqTraceOutputInt32(f, message, cursor, false); + pqTraceOutputInt16(f, message, cursor); + } +} + +/* NegotiateProtocolVersion */ +static void +pqTraceOutputv(FILE *f, const char *message, int *cursor) +{ + fprintf(f, "NegotiateProtocolVersion\t"); + pqTraceOutputInt32(f, message, cursor, false); + pqTraceOutputInt32(f, message, cursor, false); +} + +/* FunctionCallResponse */ +static void +pqTraceOutputV(FILE *f, const char *message, int *cursor) +{ + int len; + + fprintf(f, "FunctionCallResponse\t"); + len = pqTraceOutputInt32(f, message, cursor, false); + if (len != -1) + pqTraceOutputNchar(f, len, message, cursor); +} + +/* CopyBothResponse */ +static void +pqTraceOutputW(FILE *f, const char *message, int *cursor, int length) +{ + fprintf(f, "CopyBothResponse\t"); + pqTraceOutputByte1(f, message, cursor); + + while (length > *cursor) + pqTraceOutputInt16(f, message, cursor); +} + +/* ReadyForQuery */ +static void +pqTraceOutputZ(FILE *f, const char *message, int *cursor) +{ + fprintf(f, "ReadyForQuery\t"); + pqTraceOutputByte1(f, message, cursor); +} + +/* + * Print the given message to the trace output stream. + */ +void +pqTraceOutputMessage(PGconn *conn, const char *message, bool toServer) +{ + char id; + int length; + char *prefix = toServer ? "F" : "B"; + int logCursor = 0; + bool regress; + + if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0) + { + char timestr[128]; + + pqTraceFormatTimestamp(timestr, sizeof(timestr)); + fprintf(conn->Pfdebug, "%s\t", timestr); + } + regress = (conn->traceFlags & PQTRACE_REGRESS_MODE) != 0; + + id = message[logCursor++]; + + memcpy(&length, message + logCursor, 4); + length = (int) pg_ntoh32(length); + logCursor += 4; + + fprintf(conn->Pfdebug, "%s\t%d\t", prefix, length); + + switch (id) + { + case '1': + fprintf(conn->Pfdebug, "ParseComplete"); + /* No message content */ + break; + case '2': + fprintf(conn->Pfdebug, "BindComplete"); + /* No message content */ + break; + case '3': + fprintf(conn->Pfdebug, "CloseComplete"); + /* No message content */ + break; + case 'A': /* Notification Response */ + pqTraceOutputA(conn->Pfdebug, message, &logCursor, regress); + break; + case 'B': /* Bind */ + pqTraceOutputB(conn->Pfdebug, message, &logCursor); + break; + case 'c': + fprintf(conn->Pfdebug, "CopyDone"); + /* No message content */ + break; + case 'C': /* Close(F) or Command Complete(B) */ + pqTraceOutputC(conn->Pfdebug, toServer, message, &logCursor); + break; + case 'd': /* Copy Data */ + /* Drop COPY data to reduce the overhead of logging. */ + break; + case 'D': /* Describe(F) or Data Row(B) */ + pqTraceOutputD(conn->Pfdebug, toServer, message, &logCursor); + break; + case 'E': /* Execute(F) or Error Response(B) */ + pqTraceOutputE(conn->Pfdebug, toServer, message, &logCursor, + length, regress); + break; + case 'f': /* Copy Fail */ + pqTraceOutputf(conn->Pfdebug, message, &logCursor); + break; + case 'F': /* Function Call */ + pqTraceOutputF(conn->Pfdebug, message, &logCursor, regress); + break; + case 'G': /* Start Copy In */ + pqTraceOutputG(conn->Pfdebug, message, &logCursor); + break; + case 'H': /* Flush(F) or Start Copy Out(B) */ + if (!toServer) + pqTraceOutputH(conn->Pfdebug, message, &logCursor); + else + fprintf(conn->Pfdebug, "Flush"); /* no message content */ + break; + case 'I': + fprintf(conn->Pfdebug, "EmptyQueryResponse"); + /* No message content */ + break; + case 'K': /* secret key data from the backend */ + pqTraceOutputK(conn->Pfdebug, message, &logCursor, regress); + break; + case 'n': + fprintf(conn->Pfdebug, "NoData"); + /* No message content */ + break; + case 'N': + pqTraceOutputNR(conn->Pfdebug, "NoticeResponse", message, + &logCursor, length, regress); + break; + case 'P': /* Parse */ + pqTraceOutputP(conn->Pfdebug, message, &logCursor, regress); + break; + case 'Q': /* Query */ + pqTraceOutputQ(conn->Pfdebug, message, &logCursor); + break; + case 'R': /* Authentication */ + pqTraceOutputR(conn->Pfdebug, message, &logCursor); + break; + case 's': + fprintf(conn->Pfdebug, "PortalSuspended"); + /* No message content */ + break; + case 'S': /* Parameter Status(B) or Sync(F) */ + if (!toServer) + pqTraceOutputS(conn->Pfdebug, message, &logCursor); + else + fprintf(conn->Pfdebug, "Sync"); /* no message content */ + break; + case 't': /* Parameter Description */ + pqTraceOutputt(conn->Pfdebug, message, &logCursor, regress); + break; + case 'T': /* Row Description */ + pqTraceOutputT(conn->Pfdebug, message, &logCursor, regress); + break; + case 'v': /* Negotiate Protocol Version */ + pqTraceOutputv(conn->Pfdebug, message, &logCursor); + break; + case 'V': /* Function Call response */ + pqTraceOutputV(conn->Pfdebug, message, &logCursor); + break; + case 'W': /* Start Copy Both */ + pqTraceOutputW(conn->Pfdebug, message, &logCursor, length); + break; + case 'X': + fprintf(conn->Pfdebug, "Terminate"); + /* No message content */ + break; + case 'Z': /* Ready For Query */ + pqTraceOutputZ(conn->Pfdebug, message, &logCursor); + break; + default: + fprintf(conn->Pfdebug, "Unknown message: %02x", id); + break; + } + + fputc('\n', conn->Pfdebug); + + /* + * Verify the printing routine did it right. Note that the one-byte + * message identifier is not included in the length, but our cursor does + * include it. + */ + if (logCursor - 1 != length) + fprintf(conn->Pfdebug, + "mismatched message length: consumed %d, expected %d\n", + logCursor - 1, length); +} + +/* + * Print special messages (those containing no type byte) to the trace output + * stream. + */ +void +pqTraceOutputNoTypeByteMessage(PGconn *conn, const char *message) +{ + int length; + int logCursor = 0; + + if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0) + { + char timestr[128]; + + pqTraceFormatTimestamp(timestr, sizeof(timestr)); + fprintf(conn->Pfdebug, "%s\t", timestr); + } + + memcpy(&length, message + logCursor, 4); + length = (int) pg_ntoh32(length); + logCursor += 4; + + fprintf(conn->Pfdebug, "F\t%d\t", length); + + switch (length) + { + case 16: /* CancelRequest */ + fprintf(conn->Pfdebug, "CancelRequest\t"); + pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, false); + pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, false); + pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, false); + break; + case 8: /* GSSENCRequest or SSLRequest */ + /* These messages do not reach here. */ + default: + fprintf(conn->Pfdebug, "Unknown message: length is %d", length); + break; + } + + fputc('\n', conn->Pfdebug); +} diff --git a/src/interfaces/libpq/libpq-fe.h b/src/interfaces/libpq/libpq-fe.h index cee42d4843..227adde5a5 100644 --- a/src/interfaces/libpq/libpq-fe.h +++ b/src/interfaces/libpq/libpq-fe.h @@ -263,7 +263,7 @@ typedef struct pgresAttDesc * ---------------- */ -/* === in fe-connect.c === */ +/* === in fe-connect.c === */ /* make a new client connection to the backend */ /* Asynchronous (non-blocking) */ @@ -375,10 +375,6 @@ extern PGVerbosity PQsetErrorVerbosity(PGconn *conn, PGVerbosity verbosity); extern PGContextVisibility PQsetErrorContextVisibility(PGconn *conn, PGContextVisibility show_context); -/* Enable/disable tracing */ -extern void PQtrace(PGconn *conn, FILE *debug_port); -extern void PQuntrace(PGconn *conn); - /* Override default notice handling routines */ extern PQnoticeReceiver PQsetNoticeReceiver(PGconn *conn, PQnoticeReceiver proc, @@ -398,6 +394,17 @@ typedef void (*pgthreadlock_t) (int acquire); extern pgthreadlock_t PQregisterThreadLock(pgthreadlock_t newhandler); +/* === in fe-trace.c === */ +extern void PQtrace(PGconn *conn, FILE *debug_port); +extern void PQuntrace(PGconn *conn); + +/* flags controlling trace output */ +/* omit timestamps from each line */ +#define PQTRACE_SUPPRESS_TIMESTAMPS (1<<0) +/* redact portions of some messages, for testing frameworks */ +#define PQTRACE_REGRESS_MODE (1<<1) +extern void PQtraceSetFlags(PGconn *conn, int flags); + /* === in fe-exec.c === */ /* Simple synchronous query */ diff --git a/src/interfaces/libpq/libpq-int.h b/src/interfaces/libpq/libpq-int.h index 6374ec657a..3f7907127e 100644 --- a/src/interfaces/libpq/libpq-int.h +++ b/src/interfaces/libpq/libpq-int.h @@ -394,6 +394,7 @@ struct pg_conn /* Optional file to write trace info to */ FILE *Pfdebug; + int traceFlags; /* Callback procedures for notice message processing */ PGNoticeHooks noticeHooks; @@ -818,6 +819,12 @@ extern ssize_t pg_GSS_write(PGconn *conn, const void *ptr, size_t len); extern ssize_t pg_GSS_read(PGconn *conn, void *ptr, size_t len); #endif +/* === in libpq-trace.c === */ + +extern void pqTraceOutputMessage(PGconn *conn, const char *message, + bool toServer); +extern void pqTraceOutputNoTypeByteMessage(PGconn *conn, const char *message); + /* === miscellaneous macros === */ /*