Hello Aya Iwata,
I like this patch, and I think we should have it. I have updated it, as
it had conflicts.
In 0002, I remove use of ftime(), because that function is obsolete.
However, with that change we lose printing of milliseconds in the trace
lines. I think that's not great, but I also think we can live without
them until somebody gets motivated to write the code for that. It seems
a little messy so I'd prefer to leave that for a subsequent commit.
(Maybe we can just use pg_strftime.)
Looking at the message type tables, I decided to get rid of the "bf"
table, which had only two bytes, and instead put CopyData and CopyDone
in the other two tables. That seems simpler. Also, the COMMAND_x_MAX
macros were a bit pointless; I just expanded at the only caller of each,
using lengthof(). And since the message type is unsigned, there's no
need to do "c >= 0" since it must always be true.
I added setlinebuf() to the debug file. Works better than without,
because "tail -f /tmp/libpqtrace.log" works as you'd expect.
One thing that it might be good to do is to avoid creating the message
type tables as const but instead initialize them if and only if tracing
is enabled, on the first call. I think that would not only save space
in the constant area of the library for the 99.99% of the cases where
tracing isn't used, but also make the initialization code be more
sensible (since presumably you wouldn't have to initialize all the
zeroes.)
Opinions? I experimented by patching psql as below (not intended for
commit) and it looks good. Only ErrorResponse prints the terminator as
a control character, or something:
2020-09-16 13:27:29.072 -03 < ErrorResponse 117 S "ERROR" V "ERROR" C "42704"
M "no existe el slot de replicación «foobar»" F "slot.c" L "408" R
"ReplicationSlotAcquireInternal" ^@
diff --git a/src/bin/psql/startup.c b/src/bin/psql/startup.c
index 8232a0143b..01728ba8e8 100644
--- a/src/bin/psql/startup.c
+++ b/src/bin/psql/startup.c
@@ -301,6 +301,11 @@ main(int argc, char *argv[])
psql_setup_cancel_handler();
+ {
+ FILE *trace = fopen("/tmp/libpqtrace.log", "a+");
+ PQtrace(pset.db, trace);
+ }
+
PQsetNoticeProcessor(pset.db, NoticeProcessor, NULL);
SyncVariables();
--
Álvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
>From ae0e3853a805d186abdd9e06acceca7ada48107a 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 v8 1/2] libpq trace v8
---
doc/src/sgml/libpq.sgml | 1 +
src/interfaces/libpq/fe-connect.c | 1 +
src/interfaces/libpq/fe-misc.c | 509 ++++++++++++++++++++++++++--
src/interfaces/libpq/fe-protocol3.c | 8 +
src/interfaces/libpq/libpq-int.h | 52 +++
src/tools/pgindent/typedefs.list | 5 +
6 files changed, 547 insertions(+), 29 deletions(-)
diff --git a/doc/src/sgml/libpq.sgml b/doc/src/sgml/libpq.sgml
index a397073526..0d365f3bb3 100644
--- a/doc/src/sgml/libpq.sgml
+++ b/doc/src/sgml/libpq.sgml
@@ -5854,6 +5854,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 724076a310..0795861c92 100644
--- a/src/interfaces/libpq/fe-connect.c
+++ b/src/interfaces/libpq/fe-connect.c
@@ -6813,6 +6813,7 @@ PQtrace(PGconn *conn, FILE *debug_port)
return;
PQuntrace(conn);
conn->Pfdebug = debug_port;
+ setlinebuf(conn->Pfdebug);
}
void
diff --git a/src/interfaces/libpq/fe-misc.c b/src/interfaces/libpq/fe-misc.c
index ff840b7730..de84da6e83 100644
--- a/src/interfaces/libpq/fe-misc.c
+++ b/src/interfaces/libpq/fe-misc.c
@@ -35,6 +35,7 @@
#ifdef WIN32
#include "win32.h"
+#include <windows.h>
#else
#include <unistd.h>
#include <sys/time.h>
@@ -45,6 +46,7 @@
#endif
#ifdef HAVE_SYS_SELECT_H
#include <sys/select.h>
+#include <sys/timeb.h>
#endif
#include "libpq-fe.h"
@@ -53,11 +55,304 @@
#include "pg_config_paths.h"
#include "port/pg_bswap.h"
+/*
+ * 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 pqLogMsgByte1(PGconn *conn, char v, 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);
+static void pqLogMsgInt(PGconn *conn, int v, int length, PGCommSource commsource);
+static void pqGetCurrentTime(char *currenttime);
+#define TRACELOG_TIME_SIZE 33
+
+/*
+ * pqGetProtocolMsgType:
+ * Get a protocol type from first byte identifier
+ */
+static const char *
+pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
+{
+ const char *message_type;
+
+ if (commsource == FROM_BACKEND && c < lengthof(protocol_message_type_b))
+ message_type = protocol_message_type_b[c];
+ else if (commsource == FROM_FRONTEND && c < lengthof(protocol_message_type_f))
+ message_type = protocol_message_type_f[c];
+ else
+ return "UnknownCommand";
+}
+
+/* pqInitMsgLog: Initializing logging message */
+static void
+pqInitMsgLog(PGconn *conn)
+{
+ conn->logging_message.state = LOG_FIRST_BYTE;
+ conn->logging_message.length = 0;
+}
+
+/* pqLogInvalidProtocol: Output a message the protocol is invalid */
+static void
+pqLogInvalidProtocol(PGconn *conn)
+{
+ fprintf(conn->Pfdebug, ":::Invalid Protocol\n");
+ conn->logging_message.state = LOG_FIRST_BYTE;
+}
+
+/*
+ * pqLogLineBreak:
+ * Check whether message formats is complete. If so,
+ * break the line.
+ */
+void
+pqLogLineBreak(int size, PGconn *conn)
+{
+ conn->logging_message.length -= size;
+ if (conn->logging_message.length <= 0)
+ {
+ fprintf(conn->Pfdebug, "\n");
+ pqInitMsgLog(conn);
+ }
+}
+
+/*
+ * pqStoreFrontendMsg: Store message addresses that frontend sends.
+ *
+ * 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->frontend_entry[conn->nMsgEntries].type = type;
+ conn->frontend_entry[conn->nMsgEntries].message_addr = conn->outMsgEnd - length;
+ conn->frontend_entry[conn->nMsgEntries].message_length = length;
+ conn->nMsgEntries++;
+ }
+ else
+ {
+ /* Output one content per one 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:
+ * Output frontend message contents after the message length.
+ */
+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->nMsgEntries; i++)
+ {
+ message_addr = conn->frontend_entry[i].message_addr;
+ length = conn->frontend_entry[i].message_length;
+
+ switch (conn->frontend_entry[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;
+ }
+ }
+ pqInitMsgLog(conn);
+}
+
+/*
+ * pqGetCurrentTime: get current time for trace log output
+ */
+static void
+pqGetCurrentTime(char *currenttime)
+{
+#ifdef WIN32
+ SYSTEMTIME localTime;
+ TIME_ZONE_INFORMATION TimezoneInfo;
+
+ GetLocalTime(&localTime);
+
+ GetTimeZoneInformation(&TimezoneInfo);
+ snprintf(currenttime, TRACELOG_TIME_SIZE, "%4d-%02d-%02d %02d:%02d:%02d.%03d %s ",
+ localTime.wYear, localTime.wMonth, localTime.wDay,
+ localTime.wHour, localTime.wMinute, localTime.wSecond,
+ localTime.wMilliseconds, TimezoneInfo.Bias);
+#else
+ struct timeb localTime;
+ struct tm *tm;
+ char timezone[100];
+
+ ftime(&localTime);
+ tm = localtime(&localTime.time);
+
+ strftime(timezone, sizeof(timezone), "%Z", tm);
+ snprintf(currenttime, TRACELOG_TIME_SIZE, "%4d-%02d-%02d %02d:%02d:%02d.%03d %s ",
+ 1900 + tm->tm_year, 1 + tm->tm_mon, tm->tm_mday,
+ tm->tm_hour, tm->tm_min, tm->tm_sec, localTime.millitm, timezone);
+#endif
+}
/*
* PQlibVersion: return the libpq version number
@@ -85,12 +380,11 @@ 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;
}
-
/*
* pqPutc: write 1 char to the current message
*/
@@ -101,11 +395,56 @@ 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;
}
+/*
+ * pqLogMsgByte1: output 1 char message to the log
+ */
+static void
+pqLogMsgByte1(PGconn *conn, char v, PGCommSource commsource)
+{
+ const char *protocol_message_type;
+ char *message_source = commsource == FROM_BACKEND ? "<" : ">";
+ char current_time[TRACELOG_TIME_SIZE];
+
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ {
+ switch (conn->logging_message.state)
+ {
+ case LOG_FIRST_BYTE:
+ pqGetCurrentTime(current_time);
+ fprintf(conn->Pfdebug, "%s %s ", current_time, message_source);
+ /* If there is no first 1 byte protocol message, */
+ if (v == ' ')
+ return;
+
+ protocol_message_type = pqGetProtocolMsgType((unsigned char) v, commsource);
+ fprintf(conn->Pfdebug, "%s ", protocol_message_type);
+ /* Change the state to get protocol message length */
+ conn->logging_message.state = LOG_LENGTH;
+ conn->logging_message.command = v;
+ conn->nMsgEntries = 0;
+ break;
+
+ case LOG_CONTENTS:
+ fprintf(conn->Pfdebug, "%c ", v);
+ pqLogLineBreak(sizeof(v), conn);
+ break;
+
+ default:
+ pqLogInvalidProtocol(conn);
+ break;
+ }
+ }
+ else
+ fprintf(conn->Pfdebug, "FROM backend> %c\n", v);
+
+ return;
+}
+
/*
* pqGets[_append]:
@@ -139,8 +478,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,11 +506,38 @@ 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;
}
+/*
+ * pqLogMsgString: output a 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->logging_message.state)
+ {
+ case LOG_CONTENTS:
+ fprintf(conn->Pfdebug, "\"%s\" ", v);
+ pqLogLineBreak(length, conn);
+ break;
+
+ default:
+ pqLogInvalidProtocol(conn);
+ break;
+ }
+ }
+ else
+ fprintf(conn->Pfdebug, "To backend> \"%s\"\n", v);
+}
+
/*
* pqGetnchar:
* get a string of exactly len bytes in buffer s, no null termination
@@ -189,11 +554,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 +574,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,15 +592,42 @@ 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;
}
+/*
+ * 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->logging_message.state)
+ {
+ case LOG_CONTENTS:
+ fprintf(conn->Pfdebug, "\'");
+ fwrite(v, 1, length, conn->Pfdebug);
+ fprintf(conn->Pfdebug, "\' ");
+ pqLogLineBreak(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");
+ }
+}
+
+
/*
* pqGetInt
* read a 2 or 4 byte integer and convert from network byte order
@@ -279,7 +663,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 +685,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,13 +701,69 @@ 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;
}
+/*
+ * 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->logging_message.state)
+ {
+ /*
+ * Output message type here for protocol messages that do not
+ * have the first byte.
+ */
+ case LOG_FIRST_BYTE:
+ if (conn->nMsgEntries > 0)
+ {
+ message_addr = conn->frontend_entry[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->logging_message.state = LOG_LENGTH;
+ /* fall-through */
+
+ case LOG_LENGTH:
+ fprintf(conn->Pfdebug, "%d ", v);
+ conn->logging_message.length = v - length;
+ /* Change the state to log protocol message contents */
+ conn->logging_message.state = LOG_CONTENTS;
+ pqLogLineBreak(0, conn);
+ break;
+
+ case LOG_CONTENTS:
+ fprintf(conn->Pfdebug, "%s%d ", prefix, v);
+ pqLogLineBreak(length, conn);
+ break;
+
+ default:
+ pqLogInvalidProtocol(conn);
+ break;
+ }
+ }
+ else
+ fprintf(conn->Pfdebug, "To backend (#%d)> %d\n", length, v);
+}
+
/*
* Make sure conn's output buffer can hold bytes_needed bytes (caller must
* include already-stored data into the value!)
@@ -535,8 +979,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 ? msg_type : ' ', FROM_FRONTEND);
return 0;
}
@@ -572,15 +1015,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);
}
diff --git a/src/interfaces/libpq/fe-protocol3.c b/src/interfaces/libpq/fe-protocol3.c
index 1696525475..2b8b9921ee 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)
+ pqLogLineBreak(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)
+ pqLogLineBreak(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..8af4163aa1 100644
--- a/src/interfaces/libpq/libpq-int.h
+++ b/src/interfaces/libpq/libpq-int.h
@@ -155,6 +155,52 @@ typedef struct
void *noticeProcArg;
} PGNoticeHooks;
+/*
+ * Logging
+ */
+
+/* Log message source */
+typedef enum
+{
+ FROM_BACKEND,
+ FROM_FRONTEND
+} PGCommSource;
+
+/* PGLogState defines the state of the Logging message state machine */
+typedef enum
+{
+ 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;
+
+/* Protocol message */
+typedef struct PGLogMsg
+{
+ PGLogState state; /* state of logging message state machine */
+ int length; /* protocol message length */
+ char command; /* first one byte of protocol message */
+} PGLogMsg;
+
+/* Frontend message data type */
+typedef enum
+{
+ LOG_BYTE1,
+ LOG_STRING,
+ LOG_NCHAR,
+ LOG_INT16,
+ LOG_INT32
+} PGLogMsgDataType;
+
+/* Store frontend message address */
+typedef struct PGFrontendLogMsgEntry
+{
+ PGLogMsgDataType type;
+ int message_addr;
+ int message_length;
+} PGFrontendLogMsgEntry;
+
typedef struct PGEvent
{
PGEventProc proc; /* the function to call on events */
@@ -376,6 +422,11 @@ struct pg_conn
/* Optional file to write trace info to */
FILE *Pfdebug;
+ /* pending log message */
+ PGLogMsg logging_message;
+ PGFrontendLogMsgEntry frontend_entry[MAXPGPATH];
+ int nMsgEntries;
+
/* Callback procedures for notice message processing */
PGNoticeHooks noticeHooks;
@@ -674,6 +725,7 @@ extern int pqWaitTimed(int forRead, int forWrite, PGconn *conn,
time_t finish_time);
extern int pqReadReady(PGconn *conn);
extern int pqWriteReady(PGconn *conn);
+extern void pqLogLineBreak(int size, PGconn *conn);
/* === in fe-secure.c === */
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index b1afb345c3..61f22404e8 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -1504,6 +1504,7 @@ PGAlignedXLogBlock
PGAsyncStatusType
PGCALL2
PGChecksummablePage
+PGCommSource
PGContextVisibility
PGEvent
PGEventConnDestroy
@@ -1516,9 +1517,13 @@ PGEventResultCreate
PGEventResultDestroy
PGFInfoFunction
PGFileType
+PGFrontendLogMsgEntry
PGFunction
PGLZ_HistEntry
PGLZ_Strategy
+PGLogMsg
+PGLogMsgDataType
+PGLogState
PGMessageField
PGModuleMagicFunction
PGNoticeHooks
--
2.20.1
>From ebed26d8e90744b46d2903a8f0449f748cdbeb1a Mon Sep 17 00:00:00 2001
From: Alvaro Herrera <alvhe...@alvh.no-ip.org>
Date: Wed, 16 Sep 2020 17:06:32 -0300
Subject: [PATCH v8 2/2] Remove use of obsolete ftime()
Loses output of milliseconds :-(
---
src/interfaces/libpq/fe-misc.c | 47 ++++++----------------------------
1 file changed, 8 insertions(+), 39 deletions(-)
diff --git a/src/interfaces/libpq/fe-misc.c b/src/interfaces/libpq/fe-misc.c
index de84da6e83..ee479d7863 100644
--- a/src/interfaces/libpq/fe-misc.c
+++ b/src/interfaces/libpq/fe-misc.c
@@ -35,7 +35,6 @@
#ifdef WIN32
#include "win32.h"
-#include <windows.h>
#else
#include <unistd.h>
#include <sys/time.h>
@@ -46,7 +45,6 @@
#endif
#ifdef HAVE_SYS_SELECT_H
#include <sys/select.h>
-#include <sys/timeb.h>
#endif
#include "libpq-fe.h"
@@ -159,8 +157,6 @@ static void pqLogMsgString(PGconn *conn, const char *v, int length,
static void pqLogMsgnchar(PGconn *conn, const char *v, int length,
PGCommSource commsource);
static void pqLogMsgInt(PGconn *conn, int v, int length, PGCommSource commsource);
-static void pqGetCurrentTime(char *currenttime);
-#define TRACELOG_TIME_SIZE 33
/*
* pqGetProtocolMsgType:
@@ -322,38 +318,6 @@ pqLogFrontendMsg(PGconn *conn)
pqInitMsgLog(conn);
}
-/*
- * pqGetCurrentTime: get current time for trace log output
- */
-static void
-pqGetCurrentTime(char *currenttime)
-{
-#ifdef WIN32
- SYSTEMTIME localTime;
- TIME_ZONE_INFORMATION TimezoneInfo;
-
- GetLocalTime(&localTime);
-
- GetTimeZoneInformation(&TimezoneInfo);
- snprintf(currenttime, TRACELOG_TIME_SIZE, "%4d-%02d-%02d %02d:%02d:%02d.%03d %s ",
- localTime.wYear, localTime.wMonth, localTime.wDay,
- localTime.wHour, localTime.wMinute, localTime.wSecond,
- localTime.wMilliseconds, TimezoneInfo.Bias);
-#else
- struct timeb localTime;
- struct tm *tm;
- char timezone[100];
-
- ftime(&localTime);
- tm = localtime(&localTime.time);
-
- strftime(timezone, sizeof(timezone), "%Z", tm);
- snprintf(currenttime, TRACELOG_TIME_SIZE, "%4d-%02d-%02d %02d:%02d:%02d.%03d %s ",
- 1900 + tm->tm_year, 1 + tm->tm_mon, tm->tm_mday,
- tm->tm_hour, tm->tm_min, tm->tm_sec, localTime.millitm, timezone);
-#endif
-}
-
/*
* PQlibVersion: return the libpq version number
*/
@@ -408,15 +372,20 @@ pqLogMsgByte1(PGconn *conn, char v, PGCommSource commsource)
{
const char *protocol_message_type;
char *message_source = commsource == FROM_BACKEND ? "<" : ">";
- char current_time[TRACELOG_TIME_SIZE];
+ time_t currtime;
+ struct tm *tmp;
+ char timestr[128];
if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
{
switch (conn->logging_message.state)
{
case LOG_FIRST_BYTE:
- pqGetCurrentTime(current_time);
- fprintf(conn->Pfdebug, "%s %s ", current_time, message_source);
+ 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 == ' ')
return;
--
2.20.1
