v11-0001-libpq-trace.patch
application/octet-stream
Filename: v11-0001-libpq-trace.patch
Type: application/octet-stream
Part: 0
Message:
RE: libpq debug log
diff --git a/doc/src/sgml/libpq.sgml b/doc/src/sgml/libpq.sgml
index 2bb3bf7..4b2bd31 100644
--- a/doc/src/sgml/libpq.sgml
+++ b/doc/src/sgml/libpq.sgml
@@ -5882,6 +5882,7 @@ PGContextVisibility PQsetErrorContextVisibility(PGconn *conn, PGContextVisibilit
<listitem>
<para>
Enables tracing of the client/server communication to a debugging file stream.
+ (Details of tracing contents appear in <xref linkend="protocol-message-formats"/>).
<synopsis>
void PQtrace(PGconn *conn, FILE *stream);
</synopsis>
diff --git a/src/interfaces/libpq/fe-connect.c b/src/interfaces/libpq/fe-connect.c
index 2b78ed8..025be0e 100644
--- a/src/interfaces/libpq/fe-connect.c
+++ b/src/interfaces/libpq/fe-connect.c
@@ -6764,8 +6764,23 @@ PQtrace(PGconn *conn, FILE *debug_port)
{
if (conn == NULL)
return;
+ /* Protocol 2.0 is not supported. */
+ if (PG_PROTOCOL_MAJOR(conn->pversion) < 3)
+ return;
+
PQuntrace(conn);
- conn->Pfdebug = debug_port;
+ if (pqTraceInit(conn))
+ {
+ conn->Pfdebug = debug_port;
+ if (conn->Pfdebug != NULL)
+ setlinebuf(conn->Pfdebug);
+ }
+ else
+ {
+ /* XXX report ENOMEM? */
+ fprintf(conn->Pfdebug, "Failed to initialize trace support\n");
+ fflush(conn->Pfdebug);
+ }
}
void
diff --git a/src/interfaces/libpq/fe-exec.c b/src/interfaces/libpq/fe-exec.c
index e730753..e8503aa 100644
--- a/src/interfaces/libpq/fe-exec.c
+++ b/src/interfaces/libpq/fe-exec.c
@@ -966,10 +966,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 2bfb6ac..8bc9966 100644
--- a/src/interfaces/libpq/fe-misc.c
+++ b/src/interfaces/libpq/fe-misc.c
@@ -53,11 +53,174 @@
#include "pg_config_paths.h"
#include "port/pg_bswap.h"
+/* Log message source */
+typedef enum
+{
+ FROM_BACKEND,
+ FROM_FRONTEND
+} PGCommSource;
+
+/* Messages from backend */
+typedef enum PGLogState
+{
+ LOG_FIRST_BYTE, /* logging the first byte identifing the
+ protocol message type */
+ LOG_LENGTH, /* logging protocol message length */
+ LOG_CONTENTS /* logging protocol message contents */
+} PGLogState;
+
+typedef struct pqBackendMessage
+{
+ PGLogState state; /* state of logging message state machine */
+ int length; /* protocol message length */
+ char command; /* first one byte of protocol message */
+} pqBackendMessage;
+
+/* Messages from frontend */
+#define MAX_FRONTEND_MSGS 1024
+typedef enum
+{
+ LOG_BYTE1,
+ LOG_STRING,
+ LOG_NCHAR,
+ LOG_INT16,
+ LOG_INT32
+} PGLogMsgDataType;
+
+typedef struct pqFrontendMessageField
+{
+ int offset_in_buffer;
+ int length;
+} pqFrontendMessageField;
+
+typedef struct pqFrontendMessage
+{
+ PGLogMsgDataType type;
+ int field_num;
+ pqFrontendMessageField fields[FLEXIBLE_ARRAY_MEMBER];
+} pqFrontendMessage;
+
+/*
+ * protocol message types:
+ *
+ * protocol_message_type_b[]: message types sent by a backend
+ * protocol_message_type_f[]: message types sent by a frontend
+ */
+static const char *const protocol_message_type_b[] = {
+ 0, /* 0 */
+ "ParseComplete", /* 1 */
+ "BindComplete", /* 2 */
+ "CloseComplete", /* 3 */
+ 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x04 ... \x0f */
+ 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x10 ... \x1f */
+ 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x20 ... \x2f */
+ 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x30 ... \x3f */
+ 0, /* @ */
+ "NotificationResponse", /* A */
+ 0, /* B */
+ "CommandComplete", /* C */
+ "DataRow", /* D */
+ "ErrorResponse", /* E */
+ 0, /* F */
+ "CopyInResponse", /* G */
+ "CopyOutResponse", /* H */
+ "EmptyQueryResponse", /* I */
+ 0, /* J */
+ "BackendKeyData", /* K */
+ 0, /* L */
+ 0, /* M */
+ "NoticeResponse", /* N */
+ 0, /* O */
+ 0, /* P */
+ 0, /* Q */
+ "Authentication", /* R */
+ "ParameterStatus", /* S */
+ "RowDescription", /* T */
+ 0, /* U */
+ "FunctionCallResponse", /* V */
+ "CopyBothResponse", /* W */
+ 0, /* X */
+ 0, /* Y */
+ "ReadyForQuery", /* Z */
+ 0, 0, 0, 0, 0, /* \x5b ... \x5f */
+ 0, /* ` */
+ 0, /* a */
+ 0, /* b */
+ "CopyDone", /* c */
+ "CopyData", /* d */
+ 0, 0, 0, 0, 0, 0, 0, 0, /* \x65 ... \0x6d */
+ "NoData", /* n */
+ 0, /* o */
+ 0, /* p */
+ 0, /* q */
+ 0, /* r */
+ "PortalSuspended", /* s */
+ "ParameterDescription", /* t */
+ 0, /* u */
+ "NegotiateProtocolVersion", /* v */
+};
+
+static const char *const protocol_message_type_f[] = {
+ 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x00 ... \x0f */
+ 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x10 ... \x1f */
+ 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x20 ... \x2f */
+ 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x30 ... \x3f */
+ 0, /* @ */
+ 0, /* A */
+ "Bind", /* B */
+ "Close", /* C */
+ "Describe", /* D */
+ "Execute", /* E */
+ "FunctionCall", /* F */
+ 0, /* G */
+ "Flush", /* H */
+ 0, 0, 0, 0, 0, 0, 0, /* I ... O */
+ "Parse", /* P */
+ "Query", /* Q */
+ 0, /* R */
+ "Sync", /* S */
+ 0, 0, 0, 0, /* T ... W */
+ "Terminate", /* X */
+ 0, 0, 0, 0, 0, 0, 0, /* \x59 ... \x5f */
+ 0, /* ` */
+ 0, /* a */
+ 0, /* b */
+ "CopyDone", /* c */
+ "CopyData", /* d */
+ 0, /* e */
+ "CopyFail", /* f */
+ 0, 0, 0, 0, 0, 0, 0, 0, 0, /* g ... o */
+ "AuthenticationResponse", /* p */
+};
+
static int pqPutMsgBytes(const void *buf, size_t len, PGconn *conn);
static int pqSendSome(PGconn *conn, int len);
static int pqSocketCheck(PGconn *conn, int forRead, int forWrite,
time_t end_time);
static int pqSocketPoll(int sock, int forRead, int forWrite, time_t end_time);
+static void pqStoreFrontendMsg(PGconn *conn, PGLogMsgDataType type, int length);
+static void pqLogFrontendMsg(PGconn *conn);
+static void pqTraceMaybeBreakLine(int size, PGconn *conn);
+static void pqLogMessageByte1(PGconn *conn, char v, PGCommSource commsource);
+static void pqLogMessageInt(PGconn *conn, int v, int length, PGCommSource commsource);
+static void pqLogMessageString(PGconn *conn, const char *v, int length,
+ PGCommSource commsource);
+static void pqLogBinaryMsg(PGconn *conn, const char *v, int length,
+ PGCommSource commsource);
+static void pqLogMessagenchar(PGconn *conn, const char *v, int length,
+ PGCommSource commsource);
+
+#define pqLogMsgByte1(CONN, CH, SOURCE) \
+((CONN)->Pfdebug ? pqLogMessageByte1(CONN, CH, SOURCE) : 0)
+
+#define pqLogMsgInt(CONN, INT, LENGTH, SOURCE) \
+((CONN)->Pfdebug ? pqLogMessageInt(CONN, INT, LENGTH, SOURCE) : 0)
+
+#define pqLogMsgString(CONN, CH, LENGTH, SOURCE) \
+((CONN)->Pfdebug ? pqLogMessageString(CONN, CH, LENGTH, SOURCE) : 0)
+
+#define pqLogMsgnchar(CONN, CH, LENGTH, SOURCE) \
+((CONN)->Pfdebug ? pqLogMessagenchar(CONN, CH, LENGTH, SOURCE) : 0)
/*
* PQlibVersion: return the libpq version number
@@ -84,8 +247,7 @@ pqGetc(char *result, PGconn *conn)
*result = conn->inBuffer[conn->inCursor++];
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend> %c\n", *result);
+ pqLogMsgByte1(conn, *result, FROM_BACKEND);
return 0;
}
@@ -101,7 +263,7 @@ pqPutc(char c, PGconn *conn)
return EOF;
if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> %c\n", c);
+ pqStoreFrontendMsg(conn, LOG_BYTE1, 1);
return 0;
}
@@ -138,9 +300,7 @@ pqGets_internal(PQExpBuffer buf, PGconn *conn, bool resetbuffer)
conn->inCursor = ++inCursor;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend> \"%s\"\n",
- buf->data);
+ pqLogMsgString(conn, buf->data, buf->len + 1, FROM_BACKEND);
return 0;
}
@@ -164,11 +324,12 @@ pqGets_append(PQExpBuffer buf, PGconn *conn)
int
pqPuts(const char *s, PGconn *conn)
{
- if (pqPutMsgBytes(s, strlen(s) + 1, conn))
+ int length = strlen(s) + 1;
+ if (pqPutMsgBytes(s, length, conn))
return EOF;
if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> \"%s\"\n", s);
+ pqStoreFrontendMsg(conn, LOG_STRING, length);
return 0;
}
@@ -188,12 +349,7 @@ 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");
- }
+ pqLogMsgnchar(conn, s, len, FROM_BACKEND);
return 0;
}
@@ -212,15 +368,8 @@ 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");
- }
-
+ pqLogMsgnchar(conn, conn->inBuffer + conn->inCursor, len, FROM_BACKEND);
conn->inCursor += len;
-
return 0;
}
@@ -235,11 +384,7 @@ pqPutnchar(const char *s, size_t len, PGconn *conn)
return EOF;
if (conn->Pfdebug)
- {
- fprintf(conn->Pfdebug, "To backend> ");
- fwrite(s, 1, len, conn->Pfdebug);
- fprintf(conn->Pfdebug, "\n");
- }
+ pqStoreFrontendMsg(conn, LOG_NCHAR, len);
return 0;
}
@@ -278,8 +423,7 @@ 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);
+ pqLogMsgInt(conn, *result, (unsigned int) bytes, FROM_BACKEND);
return 0;
}
@@ -294,15 +438,18 @@ pqPutInt(int value, size_t bytes, PGconn *conn)
{
uint16 tmp2;
uint32 tmp4;
+ PGLogMsgDataType type;
switch (bytes)
{
case 2:
+ type = LOG_INT16;
tmp2 = pg_hton16((uint16) value);
if (pqPutMsgBytes((const char *) &tmp2, 2, conn))
return EOF;
break;
case 4:
+ type = LOG_INT32;
tmp4 = pg_hton32((uint32) value);
if (pqPutMsgBytes((const char *) &tmp4, 4, conn))
return EOF;
@@ -315,7 +462,7 @@ pqPutInt(int value, size_t bytes, PGconn *conn)
}
if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend (%lu#)> %d\n", (unsigned long) bytes, value);
+ pqStoreFrontendMsg(conn, type, (unsigned int) bytes);
return 0;
}
@@ -520,8 +667,6 @@ pqPutMsgStart(char msg_type, bool force_len, PGconn *conn)
/* allow room for message length */
endPos += 4;
}
- else
- lenPos = -1;
/* make sure there is room for message header */
if (pqCheckOutBufferSpace(endPos, conn))
@@ -534,9 +679,7 @@ pqPutMsgStart(char msg_type, bool force_len, 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 : ' ');
+ pqLogMsgByte1(conn, msg_type, FROM_FRONTEND);
return 0;
}
@@ -572,15 +715,15 @@ 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)
{
uint32 msgLen = conn->outMsgEnd - conn->outMsgStart;
+ pqLogMsgInt(conn, (int) msgLen, 4, FROM_FRONTEND);
+ if (conn->Pfdebug)
+ pqLogFrontendMsg(conn);
+
msgLen = pg_hton32(msgLen);
memcpy(conn->outBuffer + conn->outMsgStart, &msgLen, 4);
}
@@ -600,6 +743,374 @@ pqPutMsgEnd(PGconn *conn)
return 0;
}
+/* -------------------------
+ * FE/BE trace support
+ *
+ * We accumulate frontend message pieces in an array as the libpq code writes
+ * them, and log the complete message when pqLogFrontendMsg is called.
+ * For backend, we print the pieces as soon as we receive them from the server.
+ * -------------------------
+ */
+
+/*
+ * Set up state so that we can trace. NB -- this might be called mutiple
+ * times in a process; make sure it's idempotent. We don't release memory
+ * on PQuntrace(), as that would be useless.
+ */
+bool
+pqTraceInit(PGconn *conn)
+{
+ /* already done? */
+ if (conn->be_msg != NULL)
+ {
+ if (conn->fe_msg)
+ conn->fe_msg->field_num = 0;
+ conn->be_msg->state = LOG_FIRST_BYTE;
+ conn->be_msg->length = 0;
+ return true;
+ }
+
+ conn->be_msg = malloc(sizeof(pqBackendMessage));
+ if (conn->be_msg == NULL)
+ return false;
+ conn->be_msg->state = LOG_FIRST_BYTE;
+ conn->be_msg->length = 0;
+
+ conn->fe_msg = malloc(sizeof(pqFrontendMessage) +
+ MAX_FRONTEND_MSGS * sizeof(pqFrontendMessageField));
+ conn->fe_msg->field_num = 0;
+ if (conn->fe_msg == NULL)
+ {
+ free(conn->be_msg);
+ /* NULL out for the case that fe_msg malloc fails */
+ conn->be_msg = NULL;
+ return false;
+ }
+ conn->fe_msg->field_num = 0;
+
+ return true;
+}
+
+/*
+ * pqGetProtocolMsgType:
+ * Get a protocol type from first byte identifier
+ */
+static const char *
+pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
+{
+ if (commsource == FROM_BACKEND && c < lengthof(protocol_message_type_b))
+ return protocol_message_type_b[c];
+ else if (commsource == FROM_FRONTEND && c < lengthof(protocol_message_type_f))
+ return protocol_message_type_f[c];
+ else
+ return "UnknownMessage";
+}
+
+/* pqTraceResetBeMsg: Initialize backend message */
+static void
+pqTraceResetBeMsg(PGconn *conn)
+{
+ conn->be_msg->state = LOG_FIRST_BYTE;
+ conn->be_msg->length = 0;
+}
+
+/* pqLogInvalidProtocol: Print that the protocol message is invalid */
+static void
+pqLogInvalidProtocol(PGconn *conn)
+{
+ fprintf(conn->Pfdebug, ":::Invalid Protocol\n");
+ conn->be_msg->state = LOG_FIRST_BYTE;
+}
+
+/*
+ * pqTraceMaybeBreakLine:
+ * Check whether the backend message is complete. If so, print a line
+ * break and reset the buffer.
+ */
+static void
+pqTraceMaybeBreakLine(int size, PGconn *conn)
+{
+ conn->be_msg->length -= size;
+ if (conn->be_msg->length <= 0)
+ {
+ fprintf(conn->Pfdebug, "\n");
+ pqTraceResetBeMsg(conn);
+ }
+ else
+ fprintf(conn->Pfdebug, " ");
+}
+
+/*
+ * pqTraceForcelyBreakLine:
+ * If message is not completed, print a line break and reset.
+ */
+void
+pqTraceForcelyBreakLine(int size, PGconn *conn)
+{
+ fprintf(conn->Pfdebug, "\n");
+ pqTraceResetBeMsg(conn);
+}
+
+/*
+ * pqStoreFrontendMsg
+ * Store message sent by frontend for later display.
+ *
+ * We store the messages and print them all as a single line
+ * when we get the message-end.
+ *
+ * The message length is fixed after putting the last field, but message
+ * length should be print before printing any fields.So we must store the
+ * field data in memory.
+ */
+static void
+pqStoreFrontendMsg(PGconn *conn, PGLogMsgDataType type, int length)
+{
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ {
+ conn->fe_msg->type = type;
+ conn->fe_msg->fields[conn->fe_msg->field_num].offset_in_buffer = conn->outMsgEnd - length;
+ conn->fe_msg->fields[conn->fe_msg->field_num].length = length;
+ conn->fe_msg->field_num++;
+ /* make sure not to overrun the buffer when a message is too large */
+ if (conn->fe_msg->field_num >= MAX_FRONTEND_MSGS)
+ pqLogFrontendMsg(conn);
+ }
+}
+
+/*
+ * pqLogFrontendMsg
+ * Print accumulated frontend message pieces to the trace file.
+ */
+static void
+pqLogFrontendMsg(PGconn *conn)
+{
+ int i;
+ int message_addr;
+ int length;
+
+ for (i = 0; i < conn->fe_msg->field_num; i++)
+ {
+ message_addr = conn->fe_msg->fields[i].offset_in_buffer;
+ length = conn->fe_msg->fields[i].length;
+
+ switch (conn->fe_msg[i].type)
+ {
+ case LOG_BYTE1:
+ pqLogMsgByte1(conn, (char)*(conn->outBuffer + message_addr), FROM_FRONTEND);
+ break;
+
+ case LOG_STRING:
+ pqLogMsgString(conn, conn->outBuffer + message_addr,
+ length, FROM_FRONTEND);
+ break;
+
+ case LOG_NCHAR:
+ pqLogMsgnchar(conn, conn->outBuffer + message_addr,
+ length, FROM_FRONTEND);
+ break;
+
+ case LOG_INT16:
+ {
+ uint16 result16;
+ memcpy(&result16, conn->outBuffer + message_addr, length);
+ result16 = pg_ntoh16(result16);
+ pqLogMsgInt(conn, result16, length, FROM_FRONTEND);
+ break;
+ }
+
+ case LOG_INT32:
+ {
+ uint32 result32;
+ memcpy(&result32, conn->outBuffer + message_addr, length);
+ result32 = pg_ntoh32(result32);
+ pqLogMsgInt(conn, result32, length, FROM_FRONTEND);
+ break;
+ }
+ }
+ }
+ conn->fe_msg->field_num = 0;
+}
+
+/*
+ * pqLogMessageByte1: output 1 char message to the log
+ */
+static void
+pqLogMessageByte1(PGconn *conn, char v, PGCommSource commsource)
+{
+ char *message_direction = commsource == FROM_BACKEND ? "<" : ">";
+ time_t currtime;
+ struct tm *tmp;
+ char timestr[128];
+
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ {
+ switch (conn->be_msg->state)
+ {
+ case LOG_FIRST_BYTE:
+ currtime = time(NULL);
+ tmp = localtime(&currtime);
+ strftime(timestr, sizeof(timestr), "%Y-%m-%d %H:%M:%S %Z", tmp);
+
+ fprintf(conn->Pfdebug, "%s %s ", timestr, message_direction);
+ /*
+ * True type of message tagged '\0' is known when next 4 bytes is
+ * checked. So we delay printing message type to pqLogMsgInt()
+ */
+ if (v != '\0')
+ fprintf(conn->Pfdebug, "%s ",
+ pqGetProtocolMsgType((unsigned char) v, commsource));
+ /* Next, log the message length */
+ conn->be_msg->state = LOG_LENGTH;
+ conn->be_msg->command = v;
+ break;
+
+ case LOG_CONTENTS:
+ /*
+ * 'E' or 'N' message format is as the following:
+ * 'E' len [byte1-tag string(null-terminated)]* \0(eof-tag)
+ * So we detect eof-tag at pqLogMsgByte1() with LOG_CONTENTS state.
+ * The eof-tag is data so we should print it.
+ * On the way, we care other non-ascii character.
+ */
+ if (!isprint(v))
+ fprintf(conn->Pfdebug, "\\x%02x", v);
+ else
+ fprintf(conn->Pfdebug, "%c", v);
+ pqTraceMaybeBreakLine(1, conn);
+ break;
+
+ default:
+ pqLogInvalidProtocol(conn);
+ break;
+ }
+ }
+ return;
+}
+
+/*
+ * pqLogMessageInt: output a 2 or 4 bytes integer message to the log
+ */
+static void
+pqLogMessageInt(PGconn *conn, int v, int length, PGCommSource commsource)
+{
+ char *prefix = length == 4 ? "" : "#";
+ char *message_type = 0;
+ uint32 result32 = 0;
+ int result = 0;
+ int message_addr;
+
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ {
+ switch (conn->be_msg->state)
+ {
+ case LOG_LENGTH:
+ if (conn->be_msg->command == '\0')
+ {
+ /* We delayed to print message type for special message. */
+ if (conn->fe_msg->field_num > 0)
+ {
+ message_addr = conn->fe_msg->fields[0].offset_in_buffer;
+ memcpy(&result32, conn->outBuffer + message_addr, 4);
+ result = (int) pg_ntoh32(result32);
+
+ if (result == NEGOTIATE_SSL_CODE)
+ message_type = "SSLRequest";
+ else if (result == NEGOTIATE_GSS_CODE)
+ message_type = "GSSRequest";
+ else
+ message_type = "StartupMessage";
+ }
+ else
+ message_type = "UnknownMessage";
+ fprintf(conn->Pfdebug, "%s ", message_type);
+ }
+ fprintf(conn->Pfdebug, "%d", v);
+ conn->be_msg->length = v - length;
+ /* Next, log the message contents */
+ conn->be_msg->state = LOG_CONTENTS;
+ pqTraceMaybeBreakLine(0, conn);
+ break;
+
+ case LOG_CONTENTS:
+ fprintf(conn->Pfdebug, "%s%d", prefix, v);
+ pqTraceMaybeBreakLine(length, conn);
+ break;
+
+ default:
+ pqLogInvalidProtocol(conn);
+ break;
+ }
+ }
+}
+
+
+/*
+ * pqLogMessageString: output a null-terminated string to the log
+ */
+static void
+pqLogMessageString(PGconn *conn, const char *v, int length, PGCommSource commsource)
+{
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ {
+ switch (conn->be_msg->state)
+ {
+ case LOG_CONTENTS:
+ fprintf(conn->Pfdebug, "\"%s\"", v);
+ pqTraceMaybeBreakLine(length, conn);
+ break;
+
+ default:
+ pqLogInvalidProtocol(conn);
+ break;
+ }
+ }
+}
+
+static void
+pqLogBinaryMsg(PGconn *conn, const char *v, int length, PGCommSource commsource)
+{
+ int i, pin;
+ for (pin = i = 0; i < length; ++i)
+ {
+ if (isprint(v[i]))
+ continue;
+ else
+ {
+ fwrite(v + pin, 1, i - pin, conn->Pfdebug);
+ fprintf(conn->Pfdebug, "\\x%02x", v[i]);
+ pin = i + 1;
+ }
+ if (pin < length)
+ fwrite(v + pin, 1, length - pin, conn->Pfdebug);
+ }
+}
+
+/*
+ * pqLogMessagenchar: output a string of exactly len bytes message to the log
+ */
+static void
+pqLogMessagenchar(PGconn *conn, const char *v, int length, PGCommSource commsource)
+{
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ {
+ switch (conn->be_msg->state)
+ {
+ case LOG_CONTENTS:
+ fprintf(conn->Pfdebug, "\'");
+ if (!isprint(v[0]))
+ pqLogBinaryMsg(conn, v, length, commsource);
+ else
+ fwrite(v, 1, length, conn->Pfdebug);
+ fprintf(conn->Pfdebug, "\'");
+ pqTraceMaybeBreakLine(length, conn);
+ break;
+ default:
+ pqLogInvalidProtocol(conn);
+ break;
+ }
+ }
+}
+
/* ----------
* pqReadData: read more data, if any is available
* Possible return values:
@@ -1011,8 +1522,16 @@ pqSendSome(PGconn *conn, int len)
int
pqFlush(PGconn *conn)
{
+ /*
+ * There could be unsent trace messages pointing to the output area; may be
+ * overwritten after this. So we need to send stuff to the trace file
+ * before flushing the libpq buffer.
+ */
if (conn->Pfdebug)
+ {
+ pqLogFrontendMsg(conn);
fflush(conn->Pfdebug);
+ }
if (conn->outCount > 0)
return pqSendSome(conn, conn->outCount);
diff --git a/src/interfaces/libpq/fe-protocol3.c b/src/interfaces/libpq/fe-protocol3.c
index e4ee9d6..d1a74f1 100644
--- a/src/interfaces/libpq/fe-protocol3.c
+++ b/src/interfaces/libpq/fe-protocol3.c
@@ -156,7 +156,12 @@ pqParseInput3(PGconn *conn)
{
/* If not IDLE state, just wait ... */
if (conn->asyncStatus != PGASYNC_IDLE)
+ {
+ /* Terminate a half-finished logging message */
+ if (conn->Pfdebug)
+ pqTraceForcelyBreakLine(msgLength, conn);
return;
+ }
/*
* Unexpected message in IDLE state; need to recover somehow.
@@ -283,6 +288,9 @@ pqParseInput3(PGconn *conn)
* the data till we get to the end of the query.
*/
conn->inCursor += msgLength;
+ /* Terminate a half-finished logging message */
+ if (conn->Pfdebug)
+ pqTraceForcelyBreakLine(msgLength, conn);
}
else if (conn->result == NULL ||
conn->queryclass == PGQUERY_DESCRIBE)
@@ -357,6 +365,9 @@ pqParseInput3(PGconn *conn)
* tuples till we get to the end of the query.
*/
conn->inCursor += msgLength;
+ /* Terminate a half-finished logging message */
+ if (conn->Pfdebug)
+ pqTraceForcelyBreakLine(msgLength, conn);
}
else
{
@@ -366,6 +377,9 @@ pqParseInput3(PGconn *conn)
pqSaveErrorResult(conn);
/* Discard the unexpected message */
conn->inCursor += msgLength;
+ /* Terminate a half-finished logging message */
+ if (conn->Pfdebug)
+ pqTraceForcelyBreakLine(msgLength, conn);
}
break;
case 'G': /* Start Copy In */
@@ -393,6 +407,9 @@ pqParseInput3(PGconn *conn)
* early.
*/
conn->inCursor += msgLength;
+ /* Terminate a half-finished logging message */
+ if (conn->Pfdebug)
+ pqTraceForcelyBreakLine(msgLength, conn);
break;
case 'c': /* Copy Done */
@@ -454,6 +471,9 @@ handleSyncLoss(PGconn *conn, char id, int msgLength)
/* flush input data since we're giving up on processing it */
pqDropConnection(conn, true);
conn->status = CONNECTION_BAD; /* No more connection to backend */
+ /* Terminate a half-finished logging message */
+ if (conn->Pfdebug)
+ pqTraceForcelyBreakLine(msgLength, conn);
}
/*
@@ -1620,6 +1640,9 @@ getCopyDataMessage(PGconn *conn)
return 0;
break;
case 'd': /* Copy Data, pass it back to caller */
+ /* Terminate a half-finished logging message */
+ if (conn->Pfdebug)
+ pqTraceForcelyBreakLine(msgLength, conn);
return msgLength;
case 'c':
diff --git a/src/interfaces/libpq/libpq-int.h b/src/interfaces/libpq/libpq-int.h
index 4db4983..e3de550 100644
--- a/src/interfaces/libpq/libpq-int.h
+++ b/src/interfaces/libpq/libpq-int.h
@@ -155,6 +155,14 @@ typedef struct
void *noticeProcArg;
} PGNoticeHooks;
+/*
+ * Logging
+ */
+
+/* Forward declarations */
+struct pqBackendMessage;
+struct pqFrontendMessage;
+
typedef struct PGEvent
{
PGEventProc proc; /* the function to call on events */
@@ -376,6 +384,10 @@ struct pg_conn
/* Optional file to write trace info to */
FILE *Pfdebug;
+ /* unwritten protocol traces */
+ struct pqBackendMessage *be_msg;
+ struct pqFrontendMessage *fe_msg;
+
/* Callback procedures for notice message processing */
PGNoticeHooks noticeHooks;
@@ -672,6 +684,8 @@ extern int pqPutInt(int value, size_t bytes, PGconn *conn);
extern int pqPutMsgStart(char msg_type, bool force_len, PGconn *conn);
extern int pqPutMsgEnd(PGconn *conn);
extern int pqReadData(PGconn *conn);
+extern bool pqTraceInit(PGconn *conn);
+extern void pqTraceForcelyBreakLine(int size, PGconn *conn);
extern int pqFlush(PGconn *conn);
extern int pqWait(int forRead, int forWrite, PGconn *conn);
extern int pqWaitTimed(int forRead, int forWrite, PGconn *conn,
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index fb57b83..6854260 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -1521,6 +1521,7 @@ PGAlignedXLogBlock
PGAsyncStatusType
PGCALL2
PGChecksummablePage
+PGCommSource
PGContextVisibility
PGEvent
PGEventConnDestroy
@@ -1536,6 +1537,8 @@ PGFileType
PGFunction
PGLZ_HistEntry
PGLZ_Strategy
+PGLogMsgDataType
+PGLogState
PGMessageField
PGModuleMagicFunction
PGNoticeHooks
@@ -3269,6 +3272,9 @@ pointer
polymorphic_actuals
pos_trgm
post_parse_analyze_hook_type
+pqBackendMessage
+pqFrontendMessage
+pqFrontendMessageField
pqbool
pqsigfunc
printQueryOpt