postgresql/src/interfaces/libpq/fe-trace.c

/*-------------------------------------------------------------------------
 *
 *	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 <ctype.h>
#include <limits.h>
#include <sys/time.h>
#include <time.h>

#ifdef WIN32
#include "win32.h"
#else
#include <unistd.h>
#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);
}