On 2021-Jan-17, tsunakawa.ta...@fujitsu.com wrote:
> * I don't see the need for separate pqTraceInit() function, because it is
> only called here.
That's true, but it'd require that we move PQtrace() to fe-misc.c,
because pqTraceInit() uses definitions that are private to that file.
> (2)
> +bool
> +pqTraceInit(PGconn *conn)
> +{
> + /* already done? */
> + if (conn->be_msg != NULL)
> + {
>
> What's this code for? I think it's sufficient that PQuntrace() frees b_msg
> and PQtrace() always allocates b_msg.
The point is to be able to cope with a connection that calls PQtrace()
multiple times, with or without an intervening PQuntrace().
We'd make no friends if we made PQtrace() crash, or leak memory if
called a second time ...
> (5)
> @@ -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);
> -
>
> Where is this information output instead?
Hmm, seems to have been lost. I restored it, but didn't verify
the resulting behavior carefully.
> (9)
> + 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);
>
> It's better to have microsecond accuracy, because knowing the accumulation of
> such fine-grained timings may help to troubleshoot heavily-loaded client
> cases. You can mimic setup_formatted_log_time() in
> src/backend/utils/error/elog.c. This is used for the %m marker in
> log_line_prefix.
Yeah, it was me that removed printing of milliseconds -- Iwata-san's
original patch used ftime() which is not portable. I had looked for
portable ways to get this but couldn't find anything that didn't involve
linking backend files, so I punted. But looking again now, it is quite
simple: just use standard strftime and localtime and just concatenate
both together. Similar to what setup_formatted_log_time except we don't
worry about the TZ at all.
> (10)
> I think it's better to use tabs (or any other character that is less likely
> to appear in the log field) as a field separator, because it makes it easier
> to process the log with a spreadsheet or some other tools.
I can buy that. I changed it to have some tabs; the lines are now:
timestamp "> or <" <tab> "message type" <tab> length <space> message contents
I think trying to apply tabs inside the message contents is going to be
more confusing than helpful.
> (12)
> [...]
> Plus, you may as well print the invalid message type. Why don't you do
> something like this:
>
> +static const char *
> +pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
> +{
> + static char unknown_message[64];
> + char *msg = NULL;
>
> + if (commsource == FROM_BACKEND && c < lengthof(protocol_message_type_b))
> + msg = protocol_message_type_b[c];
> + else if (commsource == FROM_FRONTEND && c <
> lengthof(protocol_message_type_f))
> + msg = protocol_message_type_f[c];
> +
> + if (msg == NULL)
> + {
> + sprintf(unknown_message, "Unknown message %02x", c);
> + msg = unknown_message;
> + }
> +
> + return msg;
> +}
Right. I had written something like this, but in the end decided not to
bother because it doesn't seem terribly important. You can't do exactly
what you suggest, because it has the problem that you're returning a
stack-allocated variable even though your stack is about to be blown
away. My copy had a static buffer that was malloc()ed on first use (and
if allocation fails, return a const string). Anyway, I fixed the
crasher problem.
The protocol_message_type_b array had the serious problem it confused
the entry for byte 1 (0x01) with that of char '1' (and 2 and 3), so it
printed a lot of 'Unknown message' lines. Clearly, the maintenance of
this array is going to be a pain point of this patch (counting number of
zeroes is no fun), and I think we're going to have some way to have an
explicit initializer, where we can do things like
protocol_message_type_b['A'] = "NotificationResponse";
etc instead of the current way, which is messy, hard to maintain.
I'm not sure how to do that and not make things worse, however.
> (16)
> +static void
> +pqLogMessageByte1(PGconn *conn, char v, PGCommSource commsource)
> +{
> + char *message_direction = commsource == FROM_BACKEND ? "<" : ">";
> ...
> + switch (conn->be_msg->state)
>
> This function handles messages in both directions. But the switch condition
> is based on the backend message state (b_msg). How is this correct?
It's not.
I split things so that this function only prints backend messages; when
frontend messages are to be printed, we use a single fprintf() instead.
See about (20), below.
>
> (17)
> What's the difference between pqLogMsgString() and pqLogMsgnchar()? They
> both take a length argument. Do they have to be separate functions?
nchar are not null-terminated and we escape !isprint() characters. I'm
not sure that the difference is significant enough, but I'm also not
sure if they can be merged into one.
> (18)
> if (conn->Pfdebug)
> - fprintf(conn->Pfdebug, "To backend> %c\n", c);
> + pqStoreFrontendMsg(conn, LOG_BYTE1, 1);
>
> To match the style for backend messages with pqLogMsgByte1 etc., why don't
> you wrap the conn->Pfdebug check in the macro?
I think these macros are useless and should be removed. There's more
verbosity and confusion caused by them, than the clarity they provide.
> (20)
> +static void
> +pqLogFrontendMsg(PGconn *conn)
> ...
> + 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:
>
> When I saw this switch condition, the confusion exploded. Shouldn't the type
> should be the attribute of each field as follows?
>
> + switch (conn->fe_msg->fields[i].type)
>
> I also found the function names for frontend -> backend messages hard to
> grasp. Could you show the flow of function calls when sending messages to
> the backend?
Exactly! I was super confused about this too, and eventually decided to
rewrite the whole thing so that the 'type' is in the Fields struct. And
while doing that, I noticed that it would make more sense to let the
fe_msg array be realloc'ed if it gets full, rather than making it fixed
size. This made me add pqTraceUninit(), so that we can free the array
if it has grown, to avoid reserving arbitrarily large amounts of memory
after PQuntrace() on a session that traced large messages.
> (22)
> I couldn't understand pqLogBinaryMsg() at all. Could you explain what it
> does? Particularly, if all bytes in the string is printable, the function
> seems to do nothing:
>
> + if (isprint(v[i]))
> + continue;
>
> Should the following part be placed outside the for loop? What does 'pin'
> mean? (I want the variable name to be more intuitive.)
>
> + if (pin < length)
> + fwrite(v + pin, 1, length - pin, conn->Pfdebug);
Yes :-( I fixed that too.
This patch needs more work still, of course.
--
Álvaro Herrera Valdivia, Chile
"Java is clearly an example of money oriented programming" (A. Stepanov)
diff --git a/doc/src/sgml/libpq.sgml b/doc/src/sgml/libpq.sgml
index 2bb3bf77e4..9fad769b0c 100644
--- a/doc/src/sgml/libpq.sgml
+++ b/doc/src/sgml/libpq.sgml
@@ -5881,12 +5881,19 @@ PGContextVisibility PQsetErrorContextVisibility(PGconn *conn, PGContextVisibilit
<listitem>
<para>
- Enables tracing of the client/server communication to a debugging file stream.
+ 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);
+void PQtrace(PGconn *conn, FILE *stream, bits32 flags);
</synopsis>
</para>
+ <para>
+ <literal>flags</literal> contains flag bits describing the operating mode
+ of tracing. If <literal>(flags & TRACE_SUPPRESS_TIMESTAMPS)</literal> is
+ true, then timestamps are not printed with each message.
+ </para>
+
<note>
<para>
On Windows, if the <application>libpq</application> library and an application are
diff --git a/src/interfaces/libpq/fe-connect.c b/src/interfaces/libpq/fe-connect.c
index 8ca0583aa9..5bc0a610c0 100644
--- a/src/interfaces/libpq/fe-connect.c
+++ b/src/interfaces/libpq/fe-connect.c
@@ -6761,12 +6761,28 @@ PQsetErrorContextVisibility(PGconn *conn, PGContextVisibility show_context)
}
void
-PQtrace(PGconn *conn, FILE *debug_port)
+PQtrace(PGconn *conn, FILE *debug_port, bits32 flags)
{
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 (!debug_port)
+ return;
+ if (pqTraceInit(conn, flags))
+ {
+ setvbuf(debug_port, NULL, _IOLBF, 0);
+ conn->Pfdebug = debug_port;
+ }
+ else
+ {
+ fprintf(debug_port, "Failed to initialize trace support: out of memory\n");
+ fflush(debug_port);
+ conn->Pfdebug = NULL;
+ }
}
void
@@ -6779,6 +6795,8 @@ PQuntrace(PGconn *conn)
fflush(conn->Pfdebug);
conn->Pfdebug = NULL;
}
+ pqTraceUninit(conn);
+ conn->traceFlags = 0;
}
PQnoticeReceiver
diff --git a/src/interfaces/libpq/fe-misc.c b/src/interfaces/libpq/fe-misc.c
index 2bfb6acd89..25efa47bc3 100644
--- a/src/interfaces/libpq/fe-misc.c
+++ b/src/interfaces/libpq/fe-misc.c
@@ -51,13 +51,168 @@
#include "libpq-int.h"
#include "mb/pg_wchar.h"
#include "pg_config_paths.h"
+#include "pgtime.h"
#include "port/pg_bswap.h"
+/* Log message source */
+typedef enum
+{
+ MSGDIR_FROM_BACKEND,
+ MSGDIR_FROM_FRONTEND
+} PGCommSource;
+
+/* Messages from backend */
+typedef enum PGLogState
+{
+ LOG_FIRST_BYTE, /* logging the first byte identifying 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 */
+typedef enum
+{
+ LOG_BYTE1,
+ LOG_STRING,
+ LOG_NCHAR,
+ LOG_INT16,
+ LOG_INT32
+} PGLogMsgDataType;
+
+typedef struct pqFrontendMessageField
+{
+ PGLogMsgDataType type;
+ int offset_in_buffer;
+ int length;
+} pqFrontendMessageField;
+
+typedef struct pqFrontendMessage
+{
+ char msg_type;
+ int num_fields; /* array used size */
+ int max_fields; /* array allocated size */
+ pqFrontendMessageField fields[FLEXIBLE_ARRAY_MEMBER];
+} pqFrontendMessage;
+#define DEF_FE_MSGFIELDS 256 /* initial fields allocation quantum */
+
+/*
+ * 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, 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 */
+ "ParseComplete", /* 1 */
+ "BindComplete", /* 2 */
+ "CloseComplete", /* 3 */
+ 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x34 ... \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, /* \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 pqStoreFeMsgStart(PGconn *conn, char type);
+static void pqLogFrontendMsg(PGconn *conn, int msgLen);
+static void pqTraceMaybeBreakLine(int size, PGconn *conn);
+static void pqLogMessageByte1(PGconn *conn, char v);
+static void pqLogMessageInt(PGconn *conn, int v, int length);
+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);
/*
* PQlibVersion: return the libpq version number
@@ -85,7 +240,7 @@ pqGetc(char *result, PGconn *conn)
*result = conn->inBuffer[conn->inCursor++];
if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend> %c\n", *result);
+ pqLogMessageByte1(conn, *result);
return 0;
}
@@ -101,7 +256,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 +294,7 @@ pqGets_internal(PQExpBuffer buf, PGconn *conn, bool resetbuffer)
conn->inCursor = ++inCursor;
if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend> \"%s\"\n",
- buf->data);
+ pqLogMessageString(conn, buf->data, buf->len + 1, MSGDIR_FROM_BACKEND);
return 0;
}
@@ -157,18 +311,19 @@ pqGets_append(PQExpBuffer buf, PGconn *conn)
return pqGets_internal(buf, conn, false);
}
-
/*
* pqPuts: write a null-terminated string to the current message
*/
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;
}
@@ -189,11 +344,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");
- }
+ pqLogMessagenchar(conn, s, len, MSGDIR_FROM_BACKEND);
return 0;
}
@@ -213,14 +364,9 @@ 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");
- }
-
+ pqLogMessagenchar(conn, conn->inBuffer + conn->inCursor, len,
+ MSGDIR_FROM_BACKEND);
conn->inCursor += len;
-
return 0;
}
@@ -235,11 +381,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 +421,7 @@ pqGetInt(int *result, size_t bytes, PGconn *conn)
}
if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend (#%lu)> %d\n", (unsigned long) bytes, *result);
+ pqLogMessageInt(conn, *result, (unsigned int) bytes);
return 0;
}
@@ -294,15 +436,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 +460,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;
}
@@ -473,8 +618,8 @@ pqCheckInBufferSpace(size_t bytes_needed, PGconn *conn)
}
/* realloc failed. Probably out of memory */
- appendPQExpBufferStr(&conn->errorMessage,
- "cannot allocate memory for input buffer\n");
+ appendPQExpBuffer(&conn->errorMessage,
+ "cannot allocate memory for input buffer\n");
return EOF;
}
@@ -535,8 +680,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 : ' ');
+ pqStoreFeMsgStart(conn, msg_type);
return 0;
}
@@ -572,15 +716,14 @@ 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;
+ if (conn->Pfdebug)
+ pqLogFrontendMsg(conn, msgLen);
+
msgLen = pg_hton32(msgLen);
memcpy(conn->outBuffer + conn->outMsgStart, &msgLen, 4);
}
@@ -600,6 +743,471 @@ 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 multiple
+ * times in a process; make sure it's idempotent.
+ */
+bool
+pqTraceInit(PGconn *conn, bits32 flags)
+{
+ conn->traceFlags = flags;
+
+ if (conn->be_msg == NULL)
+ {
+ 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;
+ }
+
+ if (conn->fe_msg == NULL)
+ {
+ conn->fe_msg = malloc(sizeof(pqFrontendMessage) +
+ DEF_FE_MSGFIELDS * sizeof(pqFrontendMessageField));
+ 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->max_fields = DEF_FE_MSGFIELDS;
+ }
+
+ conn->fe_msg->num_fields = 0;
+ conn->be_msg->state = LOG_FIRST_BYTE;
+ conn->be_msg->length = 0;
+ conn->be_msg->command = '\0';
+
+ return true;
+}
+
+/*
+ * Deallocate frontend-message tracking memory. We only do this because
+ * it can grow arbitrarily large, and skip it in the initial state, because
+ * it's likely pointless.
+ */
+void
+pqTraceUninit(PGconn *conn)
+{
+ if (conn->fe_msg &&
+ conn->fe_msg->num_fields != DEF_FE_MSGFIELDS)
+ {
+ pfree(conn->fe_msg);
+ conn->fe_msg = NULL;
+ }
+}
+
+/*
+ * pqGetProtocolMsgType:
+ * Get a protocol type from first byte identifier
+ */
+static const char *
+pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
+{
+ if (commsource == MSGDIR_FROM_BACKEND &&
+ c < lengthof(protocol_message_type_b) &&
+ protocol_message_type_b[c] != NULL)
+ return protocol_message_type_b[c];
+
+ if (commsource == MSGDIR_FROM_FRONTEND &&
+ c < lengthof(protocol_message_type_f) &&
+ protocol_message_type_f[c] != NULL)
+ return protocol_message_type_f[c];
+
+ 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, PGCommSource commsource)
+{
+ fprintf(conn->Pfdebug,
+ "%s\t:::Invalid Protocol\n",
+ commsource == MSGDIR_FROM_BACKEND ? "<" : ">");
+ 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);
+}
+
+static void
+pqStoreFeMsgStart(PGconn *conn, char type)
+{
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ conn->fe_msg->msg_type = type;
+}
+
+/*
+ * pqStoreFrontendMsg
+ * Keep track of a from-frontend message that was just written to the
+ * output buffer.
+ *
+ * Frontend messages are constructed piece by piece, and the message length
+ * is determined at the end, but sent to the server first; so for tracing
+ * purposes we store everything in memory and print to the trace file when
+ * the message is complete.
+ */
+static void
+pqStoreFrontendMsg(PGconn *conn, PGLogMsgDataType type, int length)
+{
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ {
+ /* realloc if we've exceeded available space */
+ if (conn->fe_msg->num_fields >= conn->fe_msg->max_fields)
+ {
+ if (conn->fe_msg->max_fields > INT_MAX / 2)
+ {
+ fprintf(conn->Pfdebug, "abandoning trace: field message overflow\n");
+ PQuntrace(conn);
+ }
+ conn->fe_msg =
+ realloc(conn->fe_msg,
+ sizeof(pqFrontendMessage) +
+ 2 * conn->fe_msg->max_fields * sizeof(pqFrontendMessageField));
+ if (conn->fe_msg == NULL)
+ {
+ fprintf(conn->Pfdebug, "abandoning trace: out of memory\n");
+ PQuntrace(conn);
+ }
+ conn->fe_msg->max_fields *= 2;
+ }
+
+ conn->fe_msg->fields[conn->fe_msg->num_fields].type = type;
+ conn->fe_msg->fields[conn->fe_msg->num_fields].offset_in_buffer = conn->outMsgEnd - length;
+ conn->fe_msg->fields[conn->fe_msg->num_fields].length = length;
+ conn->fe_msg->num_fields++;
+ }
+}
+
+/*
+ * Print the current time, with milliseconds, into a caller-supplied
+ * buffer. Used for PQtrace() purposes.
+ * Cribbed from setup_formatted_log_time, but much simpler.
+ */
+static char *
+pqLogFormatTimestamp(char *timestr)
+{
+ struct timeval tval;
+ pg_time_t stamp_time;
+
+ gettimeofday(&tval, NULL);
+ stamp_time = (pg_time_t) tval.tv_sec;
+
+#define FORMATTED_TS_LEN 128
+ strftime(timestr, FORMATTED_TS_LEN,
+ "%Y-%m-%d %H:%M:%S",
+ localtime(&stamp_time));
+ /* append milliseconds */
+ sprintf(timestr + strlen(timestr), ".%03d", (int) (tval.tv_usec / 1000));
+
+ return timestr;
+}
+
+/*
+ * pqLogFrontendMsg
+ * Print accumulated frontend message pieces to the trace file.
+ */
+static void
+pqLogFrontendMsg(PGconn *conn, int msgLen)
+{
+ if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
+ {
+ char timestr[128];
+
+ fprintf(conn->Pfdebug, "%s\t>\t%s\t%d",
+ pqLogFormatTimestamp(timestr),
+ pqGetProtocolMsgType(conn->fe_msg->msg_type,
+ MSGDIR_FROM_FRONTEND),
+ msgLen);
+ }
+ else
+ fprintf(conn->Pfdebug, ">\t%s\t%d",
+ pqGetProtocolMsgType(conn->fe_msg->msg_type,
+ MSGDIR_FROM_FRONTEND),
+ msgLen);
+
+ for (int i = 0; i < conn->fe_msg->num_fields; i++)
+ {
+ int message_addr;
+ int length;
+ char v;
+
+ message_addr = conn->fe_msg->fields[i].offset_in_buffer;
+ length = conn->fe_msg->fields[i].length;
+
+ fprintf(conn->Pfdebug, " ");
+
+ switch (conn->fe_msg->fields[i].type)
+ {
+ case LOG_BYTE1:
+ v = *(conn->outBuffer + message_addr);
+
+ if (isprint(v))
+ fprintf(conn->Pfdebug, "%c", v);
+ else
+ fprintf(conn->Pfdebug, "\\x%02x", v);
+ break;
+
+ case LOG_STRING:
+ pqLogMessageString(conn, conn->outBuffer + message_addr,
+ length, MSGDIR_FROM_FRONTEND);
+ break;
+
+ case LOG_NCHAR:
+ pqLogMessagenchar(conn, conn->outBuffer + message_addr,
+ length, MSGDIR_FROM_FRONTEND);
+ break;
+
+ case LOG_INT16:
+ {
+ uint16 result16;
+
+ memcpy(&result16, conn->outBuffer + message_addr, length);
+ result16 = pg_ntoh16(result16);
+ fprintf(conn->Pfdebug, "#%d", result16);
+ break;
+ }
+
+ case LOG_INT32:
+ {
+ uint32 result32;
+
+ memcpy(&result32, conn->outBuffer + message_addr, length);
+ result32 = pg_ntoh32(result32);
+ fprintf(conn->Pfdebug, "%d", result32);
+ break;
+ }
+ }
+ }
+ conn->fe_msg->num_fields = 0;
+
+ fprintf(conn->Pfdebug, "\n");
+}
+
+/*
+ * pqLogMessageByte1: output 1 char from-backend message to the log
+ */
+static void
+pqLogMessageByte1(PGconn *conn, char v)
+{
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ {
+ switch (conn->be_msg->state)
+ {
+ case LOG_FIRST_BYTE:
+ if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
+ {
+ char timestr[128];
+
+ fprintf(conn->Pfdebug, "%s\t<\t",
+ pqLogFormatTimestamp(timestr));
+ }
+ else
+ fprintf(conn->Pfdebug, "<\t");
+
+ /*
+ * True type of message tagged '\0' is known when next 4 bytes
+ * is checked. So we delay printing message type to
+ * pqLogMessageInt()
+ */
+ if (v != '\0')
+ fprintf(conn->Pfdebug, "%s\t",
+ pqGetProtocolMsgType((unsigned char) v,
+ MSGDIR_FROM_BACKEND));
+ /* Next, log the message length */
+ conn->be_msg->state = LOG_LENGTH;
+ conn->be_msg->command = v;
+ break;
+
+ case LOG_CONTENTS:
+
+ /*
+ * Show non-printable data in hex format, including the
+ * terminating \0 that completes ErrorResponse and
+ * NoticeResponse messages.
+ */
+ if (!isprint(v))
+ fprintf(conn->Pfdebug, "\\x%02x", v);
+ else
+ fprintf(conn->Pfdebug, "%c", v);
+ pqTraceMaybeBreakLine(1, conn);
+ break;
+
+ default:
+ pqLogInvalidProtocol(conn, MSGDIR_FROM_BACKEND);
+ break;
+ }
+ }
+}
+
+/*
+ * pqLogMessageInt: output a 2- or 4-byte integer from-backend msg to the log
+ */
+static void
+pqLogMessageInt(PGconn *conn, int v, int length)
+{
+ char *prefix = length == 4 ? "" : "#";
+
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ {
+ switch (conn->be_msg->state)
+ {
+ case LOG_LENGTH:
+ if (conn->be_msg->command == '\0')
+ {
+ char *message_type;
+
+ /*
+ * We delayed printing message type for special messages;
+ * they are complete now, so print them.
+ */
+ if (conn->fe_msg->num_fields > 0)
+ {
+ int message_addr;
+ uint32 result32;
+ int result;
+
+ 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, MSGDIR_FROM_BACKEND);
+ break;
+ }
+ }
+}
+
+
+/*
+ * pqLogMessageString: output a null-terminated string to the log
+ */
+static void
+pqLogMessageString(PGconn *conn, const char *v, int length, PGCommSource source)
+{
+ if (source == MSGDIR_FROM_BACKEND && conn->be_msg->state != LOG_CONTENTS)
+ {
+ pqLogInvalidProtocol(conn, MSGDIR_FROM_BACKEND);
+ return; /* XXX ??? */
+ }
+
+ fprintf(conn->Pfdebug, "\"%s\"", v);
+ if (source == MSGDIR_FROM_BACKEND)
+ pqTraceMaybeBreakLine(length, conn);
+}
+
+/*
+ * pqLogBinaryMsg: output a string possibly consisting of non-printable
+ * characters. Hex representation is used for such chars; others are
+ * printed normally.
+ */
+static void
+pqLogBinaryMsg(PGconn *conn, const char *v, int length, PGCommSource source)
+{
+ int i,
+ pin;
+
+ if (source == MSGDIR_FROM_BACKEND && conn->be_msg->state != LOG_CONTENTS)
+ {
+ pqLogInvalidProtocol(conn, MSGDIR_FROM_BACKEND);
+ return; /* XXX ??? */
+ }
+
+ 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 len, PGCommSource commsource)
+{
+ fprintf(conn->Pfdebug, "\'");
+ pqLogBinaryMsg(conn, v, len, commsource);
+ fprintf(conn->Pfdebug, "\'");
+ pqTraceMaybeBreakLine(len, conn);
+}
+
/* ----------
* pqReadData: read more data, if any is available
* Possible return values:
@@ -1011,11 +1619,16 @@ pqSendSome(PGconn *conn, int len)
int
pqFlush(PGconn *conn)
{
- if (conn->Pfdebug)
- fflush(conn->Pfdebug);
-
if (conn->outCount > 0)
+ {
+ /* XXX comment */
+ if (conn->Pfdebug)
+ {
+ pqLogFrontendMsg(conn, -1);
+ fflush(conn->Pfdebug);
+ }
return pqSendSome(conn, conn->outCount);
+ }
return 0;
}
diff --git a/src/interfaces/libpq/fe-protocol3.c b/src/interfaces/libpq/fe-protocol3.c
index e4ee9d69d2..d1a74f153b 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-fe.h b/src/interfaces/libpq/libpq-fe.h
index c266ad5b13..ad04b65513 100644
--- a/src/interfaces/libpq/libpq-fe.h
+++ b/src/interfaces/libpq/libpq-fe.h
@@ -363,7 +363,8 @@ extern PGContextVisibility PQsetErrorContextVisibility(PGconn *conn,
PGContextVisibility show_context);
/* Enable/disable tracing */
-extern void PQtrace(PGconn *conn, FILE *debug_port);
+#define PQTRACE_SUPPRESS_TIMESTAMPS (1 << 0)
+extern void PQtrace(PGconn *conn, FILE *debug_port, bits32 flags);
extern void PQuntrace(PGconn *conn);
/* Override default notice handling routines */
diff --git a/src/interfaces/libpq/libpq-int.h b/src/interfaces/libpq/libpq-int.h
index 4db498369c..1f32af8119 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 */
@@ -375,6 +383,11 @@ struct pg_conn
/* Optional file to write trace info to */
FILE *Pfdebug;
+ bits32 traceFlags;
+
+ /* pending protocol trace messages */
+ struct pqBackendMessage *be_msg;
+ struct pqFrontendMessage *fe_msg;
/* Callback procedures for notice message processing */
PGNoticeHooks noticeHooks;
@@ -672,6 +685,9 @@ 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, bits32 flags);
+extern void pqTraceUninit(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 943142ced8..bbf5022513 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -1522,6 +1522,7 @@ PGAlignedXLogBlock
PGAsyncStatusType
PGCALL2
PGChecksummablePage
+PGCommSource
PGContextVisibility
PGEvent
PGEventConnDestroy
@@ -1537,6 +1538,8 @@ PGFileType
PGFunction
PGLZ_HistEntry
PGLZ_Strategy
+PGLogMsgDataType
+PGLogState
PGMessageField
PGModuleMagicFunction
PGNoticeHooks
@@ -3271,6 +3274,9 @@ pointer
polymorphic_actuals
pos_trgm
post_parse_analyze_hook_type
+pqBackendMessage
+pqFrontendMessage
+pqFrontendMessageField
pqbool
pqsigfunc
printQueryOpt
