Hello Aya Iwata
I've been hacking at this patch again. There were a few things I wasn't
too clear about, so I reordered the code and renamed the routines to try
to make it easier to follow.
One thing I didn't like very much is that all the structures and enums
were exposed to the world in libq-int.h. Because some enum members have
pretty generic names, I didn't like that much, so I moved the whole
thing to fe-misc.c, and renamed the structs. Also, the arrays don't
take space unless PQtrace() is called. (This is not what I was talking
about in my previous message. The idea I was trying to explain in my
previous message cannot possibly work, so I abandoned it.)
I also renamed functions to make it clear which handles frontend and
which handles backend. With that, it was pretty obvious that we had an
"reset BE message" in the routine to handle FE, and some clearing of FE
in the code that handles BE. I fixed things in a way that I think makes
the most sense.
I noticed that it's theoretically possible to have a FE message so large
(more than MAXPGPATH pieces) that it would overrun the array; so I added
a "print message" call after adding one piece, to avoid this. Also, why
MAXPGPATH? I added a new symbol MAX_FRONTEND_MSGS for this purpose.
There are some things still to do:
0. I added a XXX comment to pqFlush. Because we're storing messages in
fe_msgs that point to the libpq buffer, is it possible to end up with
trace messages that are pointing into outBuffer bytes that are already
sent, and perhaps even overwritten with newer bytes? Maybe not, but
it's unclear. Should we do pqLogFrontendMsg() preventively to avoid
this problem?
1. Is the handling of protocol 2 correct? Since it's completely
separate from protocol 3, I have not even looked at what it produces.
But the fact that pqLogMsgByte1 completely ignores the "commsource"
argument makes me suspect that it's not correct.
1a. How do we even test protocol 2 handling?
2. We need a mode to suppress print of time; this would be useful to
be able to test libpq at a low level. Maybe instead of time we can
print a monotonically-increasing packet sequence number. With this, we
could easily add tests for libpq itself. What user interface do we want
for this? Maybe we can add an "bits32 flags" parameter to PQtrace(),
with one bit for this use.
3. COPY ... (FORMAT BINARY) emits "invalid protocol" ... not good.
4. Even in text format, COPY output is not very useful. How can we
improve that?
5. Error messages are still printing the terminating zero byte. I
suggest that it should be suppressed.
6. Let's redefine pqTraceMaybeBreakLine() (I renamed from
pqLogLineBreak): If message is complete, print a newline; if message is
not complete, print a " ". Then, remove the whitespace after printing
each element. This should lead to lines that don't have an useless " "
at the end.
7. Why does it make sense to call pqTraceMaybeBreakLine when
commsource=FROM_FRONTEND?
>From 61e135006c3f48d6d5fb3e5a5400fca448e4cbc4 Mon Sep 17 00:00:00 2001
From: Alvaro Herrera <alvhe...@alvh.no-ip.org>
Date: Wed, 16 Sep 2020 13:13:45 -0300
Subject: [PATCH v9] libpq trace
---
doc/src/sgml/libpq.sgml | 1 +
src/interfaces/libpq/fe-connect.c | 12 +-
src/interfaces/libpq/fe-misc.c | 576 ++++++++++++++++++++++++++--
src/interfaces/libpq/fe-protocol3.c | 8 +
src/interfaces/libpq/libpq-int.h | 15 +
src/tools/pgindent/typedefs.list | 5 +
6 files changed, 588 insertions(+), 29 deletions(-)
diff --git a/doc/src/sgml/libpq.sgml b/doc/src/sgml/libpq.sgml
index de60281fcb..bd6d89cf0f 100644
--- a/doc/src/sgml/libpq.sgml
+++ b/doc/src/sgml/libpq.sgml
@@ -5844,6 +5844,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 b0ca37c2ed..856e011d9a 100644
--- a/src/interfaces/libpq/fe-connect.c
+++ b/src/interfaces/libpq/fe-connect.c
@@ -6809,7 +6809,17 @@ PQtrace(PGconn *conn, FILE *debug_port)
if (conn == NULL)
return;
PQuntrace(conn);
- conn->Pfdebug = debug_port;
+ if (pqTraceInit(conn))
+ {
+ conn->Pfdebug = debug_port;
+ 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-misc.c b/src/interfaces/libpq/fe-misc.c
index 4ffc7f33fb..a6bb64dd5a 100644
--- a/src/interfaces/libpq/fe-misc.c
+++ b/src/interfaces/libpq/fe-misc.c
@@ -53,11 +53,154 @@
#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 pqFrontendMessage
+{
+ PGLogMsgDataType type;
+ int message_addr;
+ int message_length;
+} 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, 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 pqLogMsgByte1(PGconn *conn, char v, PGCommSource commsource);
+static void pqLogMsgInt(PGconn *conn, int v, int length, PGCommSource commsource);
+static void pqLogMsgString(PGconn *conn, const char *v, int length,
+ PGCommSource commsource);
+static void pqLogMsgnchar(PGconn *conn, const char *v, int length,
+ PGCommSource commsource);
+
/*
* PQlibVersion: return the libpq version number
@@ -85,7 +228,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 +244,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;
}
@@ -139,8 +282,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;
}
@@ -168,7 +310,7 @@ pqPuts(const char *s, PGconn *conn)
return EOF;
if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> \"%s\"\n", s);
+ pqStoreFrontendMsg(conn, LOG_STRING, strlen(s) + 1);
return 0;
}
@@ -189,11 +331,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;
}
@@ -213,11 +351,7 @@ pqSkipnchar(size_t len, PGconn *conn)
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;
@@ -235,11 +369,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;
}
@@ -279,7 +409,7 @@ pqGetInt(int *result, size_t bytes, PGconn *conn)
}
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;
}
@@ -301,11 +431,15 @@ pqPutInt(int value, size_t bytes, PGconn *conn)
tmp2 = pg_hton16((uint16) value);
if (pqPutMsgBytes((const char *) &tmp2, 2, conn))
return EOF;
+ if (conn->Pfdebug)
+ pqStoreFrontendMsg(conn, LOG_INT16, 2);
break;
case 4:
tmp4 = pg_hton32((uint32) value);
if (pqPutMsgBytes((const char *) &tmp4, 4, conn))
return EOF;
+ if (conn->Pfdebug)
+ pqStoreFrontendMsg(conn, LOG_INT32, 4);
break;
default:
pqInternalNotice(&conn->noticeHooks,
@@ -313,10 +447,6 @@ pqPutInt(int value, size_t bytes, PGconn *conn)
(unsigned long) bytes);
return EOF;
}
-
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend (%lu#)> %d\n", (unsigned long) bytes, value);
-
return 0;
}
@@ -535,8 +665,7 @@ pqPutMsgStart(char msg_type, bool force_len, PGconn *conn)
/* 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 +701,23 @@ pqPutMsgBytes(const void *buf, size_t len, PGconn *conn)
int
pqPutMsgEnd(PGconn *conn)
{
- if (conn->Pfdebug)
+ if (conn->Pfdebug && PG_PROTOCOL_MAJOR(conn->pversion) < 3)
+ {
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;
+ if (conn->Pfdebug)
+ {
+ pqLogMsgInt(conn, (int) msgLen, 4, FROM_FRONTEND);
+ pqLogFrontendMsg(conn);
+ }
+
msgLen = pg_hton32(msgLen);
memcpy(conn->outBuffer + conn->outMsgStart, &msgLen, 4);
}
@@ -600,6 +737,383 @@ 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)
+ {
+ conn->n_fe_msgs = 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(MAX_FRONTEND_MSGS * sizeof(pqFrontendMessage));
+ if (conn->fe_msg == NULL)
+ {
+ free(conn->be_msg);
+ return false;
+ }
+ conn->n_fe_msgs = 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 "UnknownCommand";
+}
+
+/* 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.
+ */
+void
+pqTraceMaybeBreakLine(int size, PGconn *conn)
+{
+ conn->be_msg->length -= size;
+ if (conn->be_msg->length <= 0)
+ {
+ fprintf(conn->Pfdebug, "\n");
+ pqTraceResetBeMsg(conn);
+ }
+}
+
+/*
+ * pqStoreFrontendMsg
+ * Store message sent by frontend for later display.
+ *
+ * In protocol v2, we immediately print each message as we receive it.
+ * (XXX why?)
+ * In protocol v3, we store the messages and print them all as a single
+ * line when we get the message-end.
+ *
+ * XXX -- ??
+ * Message length is added at the last if message is sent by the frontend.
+ * To arrange the log output format, frontend message contents are stored in the list.
+ */
+static void
+pqStoreFrontendMsg(PGconn *conn, PGLogMsgDataType type, int length)
+{
+ char message;
+ uint16 result16 = 0;
+ uint32 result32 = 0;
+ int result = 0;
+
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ {
+ conn->fe_msg[conn->n_fe_msgs].type = type;
+ conn->fe_msg[conn->n_fe_msgs].message_addr = conn->outMsgEnd - length;
+ conn->fe_msg[conn->n_fe_msgs].message_length = length;
+ conn->n_fe_msgs++;
+ /* make sure not to overrun the buffer when a message is too large */
+ if (conn->n_fe_msgs >= MAX_FRONTEND_MSGS)
+ pqLogFrontendMsg(conn);
+ }
+ else
+ {
+ /* Output one content per line in older protocol version */
+ switch (type)
+ {
+ case LOG_BYTE1:
+ memcpy(&message, conn->outBuffer + conn->outMsgEnd - length, length);
+ fprintf(conn->Pfdebug, "To backend> %c\n", message);
+ break;
+
+ case LOG_STRING:
+ memcpy(&message, conn->outBuffer + conn->outMsgEnd - length, length);
+ fprintf(conn->Pfdebug, "To backend> \"%c\"\n", message);
+ break;
+
+ case LOG_NCHAR:
+ fprintf(conn->Pfdebug, "To backend (%d)> ", length);
+ fwrite(conn->outBuffer + conn->outMsgEnd - length, 1, length, conn->Pfdebug);
+ fprintf(conn->Pfdebug, "\n");
+ break;
+
+ case LOG_INT16:
+ memcpy(&result16, conn->outBuffer + conn->outMsgEnd - length, length);
+ result = (int) pg_ntoh16(result16);
+ fprintf(conn->Pfdebug, "To backend (#%d)> %c\n", length, result);
+ break;
+
+ case LOG_INT32:
+ memcpy(&result32, conn->outBuffer + conn->outMsgEnd - length, length);
+ result = (int) pg_ntoh32(result32);
+ fprintf(conn->Pfdebug, "To backend (#%d)> %c\n", length, result);
+ break;
+ }
+ }
+}
+
+/*
+ * pqLogFrontendMsg
+ * Print accumulated frontend message pieces to the trace file.
+ */
+static void
+pqLogFrontendMsg(PGconn *conn)
+{
+ int i;
+ int message_addr;
+ int length;
+ char message;
+ uint16 result16 = 0;
+ uint32 result32 = 0;
+ int result = 0;
+
+ for (i = 0; i < conn->n_fe_msgs; i++)
+ {
+ message_addr = conn->fe_msg[i].message_addr;
+ length = conn->fe_msg[i].message_length;
+
+ switch (conn->fe_msg[i].type)
+ {
+ case LOG_BYTE1:
+ memcpy(&message, conn->outBuffer + message_addr, length);
+ pqLogMsgByte1(conn, message, 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:
+ memcpy(&result16, conn->outBuffer + message_addr, length);
+ result = (int) pg_ntoh16(result16);
+ pqLogMsgInt(conn, result, length, FROM_FRONTEND);
+ break;
+
+ case LOG_INT32:
+ memcpy(&result32, conn->outBuffer + message_addr, length);
+ result = (int) pg_ntoh32(result32);
+ pqLogMsgInt(conn, result, length, FROM_FRONTEND);
+ break;
+ }
+ }
+ conn->n_fe_msgs = 0;
+}
+
+/*
+ * pqLogMsgByte1: output 1 char message to the log
+ */
+static void
+pqLogMsgByte1(PGconn *conn, char v, PGCommSource commsource)
+{
+ char *message_source = 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_source);
+ /* If there is no first 1 byte protocol message, */
+ if (v == '\0')
+ return;
+
+ 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:
+ fprintf(conn->Pfdebug, "%c ", v);
+ pqTraceMaybeBreakLine(sizeof(v), conn);
+ break;
+
+ default:
+ pqLogInvalidProtocol(conn);
+ break;
+ }
+ }
+ else
+ fprintf(conn->Pfdebug, "FROM backend> %c\n", v);
+
+ return;
+}
+
+/*
+ * pqLogMsgInt: output a 2 or 4 bytes integer message to the log
+ */
+static void
+pqLogMsgInt(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_FIRST_BYTE:
+
+ /*
+ * Output message type here for protocol messages that do not
+ * have the first byte.
+ */
+ if (conn->n_fe_msgs > 0)
+ {
+ message_addr = conn->fe_msg[0].message_addr;
+ memcpy(&result32, conn->outBuffer + message_addr, 4);
+ result = (int) pg_ntoh32(result32);
+
+ if (result == NEGOTIATE_SSL_CODE)
+ message_type = "SSLRequest";
+ else
+ message_type = "StartupMessage";
+ }
+ else
+ message_type = "UnknownCommand";
+ fprintf(conn->Pfdebug, "%s ", message_type);
+ conn->be_msg->state = LOG_LENGTH;
+ break;
+
+ case LOG_LENGTH:
+ 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;
+ }
+ }
+ else
+ fprintf(conn->Pfdebug, "To backend (#%d)> %d\n", length, v);
+}
+
+
+/*
+ * pqLogMsgString: output a null-terminated string to the log
+ */
+static void
+pqLogMsgString(PGconn *conn, const char *v, int length, PGCommSource commsource)
+{
+ if (length < 0)
+ length = strlen(v) + 1;
+
+ 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;
+ }
+ }
+ else
+ fprintf(conn->Pfdebug, "To backend> \"%s\"\n", v);
+}
+
+/*
+ * pqLogMsgnchar: output a string of exactly len bytes message to the log
+ */
+static void
+pqLogMsgnchar(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, "\'");
+ fwrite(v, 1, length, conn->Pfdebug);
+ fprintf(conn->Pfdebug, "\' ");
+ pqTraceMaybeBreakLine(length, conn);
+ break;
+
+ default:
+ pqLogInvalidProtocol(conn);
+ break;
+ }
+ }
+ else
+ {
+ fprintf(conn->Pfdebug, "From backend (%d)> ", length);
+ fwrite(v, 1, length, conn->Pfdebug);
+ fprintf(conn->Pfdebug, "\n");
+ }
+}
+
/* ----------
* pqReadData: read more data, if any is available
* Possible return values:
@@ -1011,6 +1525,12 @@ pqSendSome(PGconn *conn, int len)
int
pqFlush(PGconn *conn)
{
+ /*
+ * XXX I don't think fflush here is sufficient: 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)
fflush(conn->Pfdebug);
diff --git a/src/interfaces/libpq/fe-protocol3.c b/src/interfaces/libpq/fe-protocol3.c
index 1696525475..1d4fa7840c 100644
--- a/src/interfaces/libpq/fe-protocol3.c
+++ b/src/interfaces/libpq/fe-protocol3.c
@@ -123,6 +123,9 @@ pqParseInput3(PGconn *conn)
*/
handleSyncLoss(conn, id, msgLength);
}
+ /* Terminate a half-finished logging message */
+ if (conn->Pfdebug)
+ pqTraceMaybeBreakLine(msgLength, conn);
return;
}
@@ -156,7 +159,12 @@ pqParseInput3(PGconn *conn)
{
/* If not IDLE state, just wait ... */
if (conn->asyncStatus != PGASYNC_IDLE)
+ {
+ /* Terminate a half-finished logging message */
+ if (conn->Pfdebug)
+ pqTraceMaybeBreakLine(msgLength, conn);
return;
+ }
/*
* Unexpected message in IDLE state; need to recover somehow.
diff --git a/src/interfaces/libpq/libpq-int.h b/src/interfaces/libpq/libpq-int.h
index 1de91ae295..bc38fcfce8 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,11 @@ struct pg_conn
/* Optional file to write trace info to */
FILE *Pfdebug;
+ /* unwritten protocol traces */
+ struct pqBackendMessage *be_msg;
+ struct pqFrontendMessage *fe_msg;
+ int n_fe_msgs;
+
/* Callback procedures for notice message processing */
PGNoticeHooks noticeHooks;
@@ -668,6 +681,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 pqTraceMaybeBreakLine(int size, PGconn *conn); /* XXX dubious */
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 ff853634bc..7d39acb770 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -1505,6 +1505,7 @@ PGAlignedXLogBlock
PGAsyncStatusType
PGCALL2
PGChecksummablePage
+PGCommSource
PGContextVisibility
PGEvent
PGEventConnDestroy
@@ -1520,6 +1521,8 @@ PGFileType
PGFunction
PGLZ_HistEntry
PGLZ_Strategy
+PGLogMsgDataType
+PGLogState
PGMessageField
PGModuleMagicFunction
PGNoticeHooks
@@ -3240,6 +3243,8 @@ pointer
polymorphic_actuals
pos_trgm
post_parse_analyze_hook_type
+pqBackendMessage
+pqFrontendMessage
pqbool
pqsigfunc
printQueryOpt
--
2.20.1
