From 311bcfc6b3acdd6fd152798c7f287ddf74fa2a98 Mon Sep 17 00:00:00 2001 From: Daniel Baumann Date: Tue, 16 Apr 2024 21:46:48 +0200 Subject: Adding upstream version 15.4. Signed-off-by: Daniel Baumann --- src/interfaces/libpq/fe-trace.c | 729 ++++++++++++++++++++++++++++++++++++++++ 1 file changed, 729 insertions(+) create mode 100644 src/interfaces/libpq/fe-trace.c (limited to 'src/interfaces/libpq/fe-trace.c') diff --git a/src/interfaces/libpq/fe-trace.c b/src/interfaces/libpq/fe-trace.c new file mode 100644 index 0000000..5d68cf2 --- /dev/null +++ b/src/interfaces/libpq/fe-trace.c @@ -0,0 +1,729 @@ +/*------------------------------------------------------------------------- + * + * fe-trace.c + * functions for libpq protocol tracing + * + * Portions Copyright (c) 1996-2022, 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 +#include +#include + +#ifdef WIN32 +#include "win32.h" +#else +#include +#endif + +#include "libpq-fe.h" +#include "libpq-int.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; + + 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 +PQsetTraceFlags(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; + time_t now; + + gettimeofday(&tval, NULL); + + /* + * MSVC's implementation of timeval uses a long for tv_sec, however, + * localtime() expects a time_t pointer. Here we'll assign tv_sec to a + * local time_t variable so that we pass localtime() the correct pointer + * type. + */ + now = tval.tv_sec; + strftime(timestr, ts_len, + "%Y-%m-%d %H:%M:%S", + localtime(&now)); + /* append microseconds */ + snprintf(timestr + strlen(timestr), ts_len - strlen(timestr), + ".%06u", (unsigned 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((unsigned char) *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((unsigned char) 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, + 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, bool regress) +{ + if (toServer) + { + fprintf(f, "Execute\t"); + pqTraceOutputString(f, message, cursor, false); + pqTraceOutputInt32(f, message, cursor, false); + } + else + pqTraceOutputNR(f, "ErrorResponse", message, cursor, 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; + + /* + * In regress mode, suppress the length of ErrorResponse and + * NoticeResponse. The F (file name), L (line number) and R (routine + * name) fields can change as server code is modified, and if their + * lengths differ from the originals, that would break tests. + */ + if (regress && !toServer && (id == 'E' || id == 'N')) + fprintf(conn->Pfdebug, "%s\tNN\t", prefix); + else + 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, + 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, 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); +} -- cgit v1.2.3