/*------------------------------------------------------------------------- * * fe-trace.c * functions for libpq protocol tracing * * Portions Copyright (c) 1996-2024, 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 get_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 */ static void pqTraceOutput_NotificationResponse(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); } static void pqTraceOutput_Bind(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); } static void pqTraceOutput_Close(FILE *f, const char *message, int *cursor) { fprintf(f, "Close\t"); pqTraceOutputByte1(f, message, cursor); pqTraceOutputString(f, message, cursor, false); } static void pqTraceOutput_CommandComplete(FILE *f, const char *message, int *cursor) { fprintf(f, "CommandComplete\t"); pqTraceOutputString(f, message, cursor, false); } static void pqTraceOutput_DataRow(FILE *f, const char *message, int *cursor) { 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); } } static void pqTraceOutput_Describe(FILE *f, const char *message, int *cursor) { fprintf(f, "Describe\t"); pqTraceOutputByte1(f, message, cursor); pqTraceOutputString(f, message, cursor, false); } /* shared code 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); } } static void pqTraceOutput_ErrorResponse(FILE *f, const char *message, int *cursor, bool regress) { pqTraceOutputNR(f, "ErrorResponse", message, cursor, regress); } static void pqTraceOutput_NoticeResponse(FILE *f, const char *message, int *cursor, bool regress) { pqTraceOutputNR(f, "NoticeResponse", message, cursor, regress); } static void pqTraceOutput_Execute(FILE *f, const char *message, int *cursor, bool regress) { fprintf(f, "Execute\t"); pqTraceOutputString(f, message, cursor, false); pqTraceOutputInt32(f, message, cursor, false); } static void pqTraceOutput_CopyFail(FILE *f, const char *message, int *cursor) { fprintf(f, "CopyFail\t"); pqTraceOutputString(f, message, cursor, false); } static void pqTraceOutput_FunctionCall(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); } static void pqTraceOutput_CopyInResponse(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); } static void pqTraceOutput_CopyOutResponse(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); } static void pqTraceOutput_BackendKeyData(FILE *f, const char *message, int *cursor, bool regress) { fprintf(f, "BackendKeyData\t"); pqTraceOutputInt32(f, message, cursor, regress); pqTraceOutputInt32(f, message, cursor, regress); } static void pqTraceOutput_Parse(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); } static void pqTraceOutput_Query(FILE *f, const char *message, int *cursor) { fprintf(f, "Query\t"); pqTraceOutputString(f, message, cursor, false); } static void pqTraceOutput_Authentication(FILE *f, const char *message, int *cursor) { fprintf(f, "Authentication\t"); pqTraceOutputInt32(f, message, cursor, false); } static void pqTraceOutput_ParameterStatus(FILE *f, const char *message, int *cursor) { fprintf(f, "ParameterStatus\t"); pqTraceOutputString(f, message, cursor, false); pqTraceOutputString(f, message, cursor, false); } static void pqTraceOutput_ParameterDescription(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); } static void pqTraceOutput_RowDescription(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); } } static void pqTraceOutput_NegotiateProtocolVersion(FILE *f, const char *message, int *cursor) { fprintf(f, "NegotiateProtocolVersion\t"); pqTraceOutputInt32(f, message, cursor, false); pqTraceOutputInt32(f, message, cursor, false); } static void pqTraceOutput_FunctionCallResponse(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); } static void pqTraceOutput_CopyBothResponse(FILE *f, const char *message, int *cursor, int length) { fprintf(f, "CopyBothResponse\t"); pqTraceOutputByte1(f, message, cursor); while (length > *cursor) pqTraceOutputInt16(f, message, cursor); } static void pqTraceOutput_ReadyForQuery(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 == PqMsg_ErrorResponse || id == PqMsg_NoticeResponse)) fprintf(conn->Pfdebug, "%s\tNN\t", prefix); else fprintf(conn->Pfdebug, "%s\t%d\t", prefix, length); switch (id) { case PqMsg_ParseComplete: fprintf(conn->Pfdebug, "ParseComplete"); /* No message content */ break; case PqMsg_BindComplete: fprintf(conn->Pfdebug, "BindComplete"); /* No message content */ break; case PqMsg_CloseComplete: fprintf(conn->Pfdebug, "CloseComplete"); /* No message content */ break; case PqMsg_NotificationResponse: pqTraceOutput_NotificationResponse(conn->Pfdebug, message, &logCursor, regress); break; case PqMsg_Bind: pqTraceOutput_Bind(conn->Pfdebug, message, &logCursor); break; case PqMsg_CopyDone: fprintf(conn->Pfdebug, "CopyDone"); /* No message content */ break; case PqMsg_CommandComplete: /* Close(F) and CommandComplete(B) use the same identifier. */ Assert(PqMsg_Close == PqMsg_CommandComplete); if (toServer) pqTraceOutput_Close(conn->Pfdebug, message, &logCursor); else pqTraceOutput_CommandComplete(conn->Pfdebug, message, &logCursor); break; case PqMsg_CopyData: /* Drop COPY data to reduce the overhead of logging. */ break; case PqMsg_Describe: /* Describe(F) and DataRow(B) use the same identifier. */ Assert(PqMsg_Describe == PqMsg_DataRow); if (toServer) pqTraceOutput_Describe(conn->Pfdebug, message, &logCursor); else pqTraceOutput_DataRow(conn->Pfdebug, message, &logCursor); break; case PqMsg_Execute: /* Execute(F) and ErrorResponse(B) use the same identifier. */ Assert(PqMsg_Execute == PqMsg_ErrorResponse); if (toServer) pqTraceOutput_Execute(conn->Pfdebug, message, &logCursor, regress); else pqTraceOutput_ErrorResponse(conn->Pfdebug, message, &logCursor, regress); break; case PqMsg_CopyFail: pqTraceOutput_CopyFail(conn->Pfdebug, message, &logCursor); break; case PqMsg_FunctionCall: pqTraceOutput_FunctionCall(conn->Pfdebug, message, &logCursor, regress); break; case PqMsg_CopyInResponse: pqTraceOutput_CopyInResponse(conn->Pfdebug, message, &logCursor); break; case PqMsg_Flush: /* Flush(F) and CopyOutResponse(B) use the same identifier */ Assert(PqMsg_CopyOutResponse == PqMsg_Flush); if (toServer) fprintf(conn->Pfdebug, "Flush"); /* no message content */ else pqTraceOutput_CopyOutResponse(conn->Pfdebug, message, &logCursor); break; case PqMsg_EmptyQueryResponse: fprintf(conn->Pfdebug, "EmptyQueryResponse"); /* No message content */ break; case PqMsg_BackendKeyData: pqTraceOutput_BackendKeyData(conn->Pfdebug, message, &logCursor, regress); break; case PqMsg_NoData: fprintf(conn->Pfdebug, "NoData"); /* No message content */ break; case PqMsg_NoticeResponse: pqTraceOutput_NoticeResponse(conn->Pfdebug, message, &logCursor, regress); break; case PqMsg_Parse: pqTraceOutput_Parse(conn->Pfdebug, message, &logCursor, regress); break; case PqMsg_Query: pqTraceOutput_Query(conn->Pfdebug, message, &logCursor); break; case PqMsg_AuthenticationRequest: pqTraceOutput_Authentication(conn->Pfdebug, message, &logCursor); break; case PqMsg_PortalSuspended: fprintf(conn->Pfdebug, "PortalSuspended"); /* No message content */ break; case PqMsg_Sync: /* ParameterStatus(B) and Sync(F) use the same identifier */ Assert(PqMsg_ParameterStatus == PqMsg_Sync); if (toServer) fprintf(conn->Pfdebug, "Sync"); /* no message content */ else pqTraceOutput_ParameterStatus(conn->Pfdebug, message, &logCursor); break; case PqMsg_ParameterDescription: pqTraceOutput_ParameterDescription(conn->Pfdebug, message, &logCursor, regress); break; case PqMsg_RowDescription: pqTraceOutput_RowDescription(conn->Pfdebug, message, &logCursor, regress); break; case PqMsg_NegotiateProtocolVersion: pqTraceOutput_NegotiateProtocolVersion(conn->Pfdebug, message, &logCursor); break; case PqMsg_FunctionCallResponse: pqTraceOutput_FunctionCallResponse(conn->Pfdebug, message, &logCursor); break; case PqMsg_CopyBothResponse: pqTraceOutput_CopyBothResponse(conn->Pfdebug, message, &logCursor, length); break; case PqMsg_Terminate: fprintf(conn->Pfdebug, "Terminate"); /* No message content */ break; case PqMsg_ReadyForQuery: pqTraceOutput_ReadyForQuery(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); }