diff --git a/src/interfaces/libpq/fe-connect.c b/src/interfaces/libpq/fe-connect.c index d001bc5..6bdf2df 100644 --- a/src/interfaces/libpq/fe-connect.c +++ b/src/interfaces/libpq/fe-connect.c @@ -325,6 +325,15 @@ static const internalPQconninfoOption PQconninfoOptions[] = { "Target-Session-Attrs", "", 11, /* sizeof("read-write") = 11 */ offsetof(struct pg_conn, target_session_attrs)}, + /* libpq trace log options */ + {"logdir", "PGLOGDIR", NULL, NULL, + "Logdir", "", MAXPGPATH - 4, + offsetof(struct pg_conn, logdir)}, + + {"logsize", "PGLOGSIZE", NULL, NULL, + "Logsize", "", 5, + offsetof(struct pg_conn, logsize_str)}, + /* Terminating entry --- MUST BE LAST */ {NULL, NULL, NULL, NULL, NULL, NULL, 0} @@ -1128,6 +1137,19 @@ connectOptions2(PGconn *conn) } /* + * If both size and directory of trace log was given, + * initialize a trace log. + */ + if (conn->logsize_str && conn->logsize_str[0] != '\0') + conn->logsize = atoi(conn->logsize_str); + + if (conn->logdir != NULL && conn->logsize > 0 && conn->logsize < 2048) + { + conn->logsize = conn->logsize * 1024 * 1024; + initTraceLog(conn); + } + + /* * If password was not given, try to look it up in password file. Note * that the result might be different for each host/port pair. */ @@ -3687,6 +3709,14 @@ freePGconn(PGconn *conn) termPQExpBuffer(&conn->errorMessage); termPQExpBuffer(&conn->workBuffer); + /* clean up libpq trace log structures */ + if (conn->logsize_str) + free(conn->logsize_str); + if (conn->logdir) + free(conn->logdir); + if (conn->traceDebug) + fclose(conn->traceDebug); + free(conn); #ifdef WIN32 @@ -3722,6 +3752,8 @@ sendTerminateConn(PGconn *conn) */ if (conn->sock != PGINVALID_SOCKET && conn->status == CONNECTION_OK) { + if (conn->Pfdebug || conn->traceDebug) + traceLog_fprintf(conn, true, "Send connection terminate message to backend: "); /* * Try to send "close connection" message to backend. Ignore any * error. @@ -4124,6 +4156,9 @@ int pqPacketSend(PGconn *conn, char pack_type, const void *buf, size_t buf_len) { + if (conn->Pfdebug || conn->traceDebug) + traceLog_fprintf(conn, true, "Send connection start message to backend: "); + /* Start the message. */ if (pqPutMsgStart(pack_type, true, conn)) return STATUS_ERROR; diff --git a/src/interfaces/libpq/fe-exec.c b/src/interfaces/libpq/fe-exec.c index 6aed8c8..d326e66 100644 --- a/src/interfaces/libpq/fe-exec.c +++ b/src/interfaces/libpq/fe-exec.c @@ -879,7 +879,7 @@ pqInternalNotice(const PGNoticeHooks *hooks, const char *fmt,...) res->errMsg = (char *) pqResultAlloc(res, strlen(msgBuf) + 2, false); if (res->errMsg) { - sprintf(res->errMsg, "%s\n", msgBuf); + sprintf(res->errMsg, "NOTICE: %s\n", msgBuf); /* * Pass to receiver, then free it. @@ -991,9 +991,9 @@ 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); + if (conn->Pfdebug || conn->traceDebug) + traceLog_fprintf(conn, false, "pqSaveParameterStatus: '%s' = '%s'\n", + name, value); /* * Forget any old information about the parameter @@ -1219,6 +1219,9 @@ PQsendQuery(PGconn *conn, const char *query) return 0; } + if (conn->traceDebug) + traceLog_fprintf(conn, false, "Query: %s \n",query); + /* construct the outgoing Query message */ if (pqPutMsgStart('Q', false, conn) < 0 || pqPuts(query, conn) < 0 || @@ -1337,6 +1340,9 @@ PQsendPrepare(PGconn *conn, return 0; } + if (conn->traceDebug) + traceLog_fprintf(conn, false, "Statement name: %s, Query: %s \n",stmtName, query); + /* construct the Parse message */ if (pqPutMsgStart('P', false, conn) < 0 || pqPuts(stmtName, conn) < 0 || @@ -1507,6 +1513,9 @@ PQsendQueryGuts(PGconn *conn, if (command) { + if (conn->traceDebug) + traceLog_fprintf(conn, false, "Statement name: %s, Command: %s \n",stmtName, command); + /* construct the Parse message */ if (pqPutMsgStart('P', false, conn) < 0 || pqPuts(stmtName, conn) < 0 || @@ -1820,6 +1829,7 @@ PQgetResult(PGconn *conn) /* Parse it. */ parseInput(conn); + } /* Return the appropriate thing. */ @@ -2006,6 +2016,9 @@ PQexecStart(PGconn *conn) { PGresult *result; + if (conn->traceDebug) + traceLog_fprintf(conn, true, "Start :"); + if (!conn) return false; @@ -2120,6 +2133,9 @@ PQexecFinish(PGconn *conn) break; } + if (conn->traceDebug) + traceLog_fprintf(conn, true, "End :"); + return lastResult; } @@ -2218,6 +2234,9 @@ PQsendDescribe(PGconn *conn, char desc_type, const char *desc_target) return 0; } + if (conn->traceDebug) + traceLog_fprintf(conn, false, "Describe type: %c, target: %s \n",desc_type, desc_target); + /* construct the Describe message */ if (pqPutMsgStart('D', false, conn) < 0 || pqPutc(desc_type, conn) < 0 || diff --git a/src/interfaces/libpq/fe-misc.c b/src/interfaces/libpq/fe-misc.c index 46ece1a..fcf7c8e 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 #else #include #include @@ -45,6 +46,7 @@ #endif #ifdef HAVE_SYS_SELECT_H #include +#include #endif #include "libpq-fe.h" @@ -60,6 +62,168 @@ 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 getTraceLogFilename(PGconn *conn,char* filename); +static void traceLog_fputnbytes(PGconn *conn, const char *head, const char *str, size_t n); +static void fputnbytes(FILE *f, const char *str, size_t n); +static void getCurrentTime(char* currenttime,int type); +#define TRACELOG_TIME_SIZE 28 + +/* + * getCurrentTime: get current time for trace log output + * + * type=0 currenttime formate %Y-%m-%d_%H%M%S + * type=1 currenttime formate %Y/%m/%d %H:%M:%S.%Milliseconds + */ +static void +getCurrentTime(char* currenttime,int type) +{ +#ifdef WIN32 + SYSTEMTIME localTime; + GetLocalTime(&localTime); + if(type==0) + snprintf(currenttime,TRACELOG_TIME_SIZE,"%4d-%02d-%02d_%02d%02d%02d", + localTime.wYear,localTime.wMonth,localTime.wDay, + localTime.wHour,localTime.wMinute,localTime.wSecond); + else if(type==1) + snprintf(currenttime,TRACELOG_TIME_SIZE,"%4d/%02d/%02d %02d:%02d:%02d.%03d", + localTime.wYear,localTime.wMonth,localTime.wDay, + localTime.wHour,localTime.wMinute,localTime.wSecond, + localTime.wMilliseconds); +#else + struct timeb localTime; + struct tm *tm; + ftime(&localTime); + tm = localtime(&localTime.time); + if(type == 0) + snprintf(currenttime, TRACELOG_TIME_SIZE,"%4d-%02d-%02d_%02d%02d%02d", + 1900+ tm->tm_year,1 + tm->tm_mon, tm->tm_mday, + tm->tm_hour, tm->tm_min, tm->tm_sec); + else if(type==1) + snprintf(currenttime, TRACELOG_TIME_SIZE,"%4d/%02d/%02d %02d:%02d:%02d.%03d", + 1900+ tm->tm_year,1 + tm->tm_mon, tm->tm_mday, + tm->tm_hour, tm->tm_min, tm->tm_sec, localTime.millitm); +#endif +} + +/* + * getTraceLogFilename: build trace log file name + * The name is libpq-%ProcessID-%Y-%m-%d_%H%M%S.log. + */ +static void +getTraceLogFilename(PGconn *conn,char* filename) +{ + char currenttime[TRACELOG_TIME_SIZE]; /* %Y-%m-%d_%H%M%S */ + getCurrentTime(currenttime,0); + +#ifdef WIN32 + snprintf(filename, MAXPGPATH, "%s\\libpq-%d-%s.log", conn->logdir,getpid(),currenttime); +#else + snprintf(filename, MAXPGPATH, "%s/libpq-%d-%s.log", conn->logdir,getpid(),currenttime); +#endif +} + +/* + * initTraceLog: initialize a trace log file + */ +void +initTraceLog(PGconn *conn) +{ + char logfilename[MAXPGPATH]; + getTraceLogFilename(conn,logfilename); + conn->traceDebug=fopen(logfilename,"w"); +} + +/* + * traceLog_fprintf: output trace log to file + * If PQtrace() is called, PQtrace() is output followed by libpq trace log. + */ +void +traceLog_fprintf(PGconn *conn, bool addTime, const char *fmt,...) +{ + char logfilename[MAXPGPATH]; + char msgBuf[MAXPGPATH]; + va_list args; + int ret; + char currenttime[TRACELOG_TIME_SIZE]; + + va_start(args, fmt); + vsnprintf(msgBuf, sizeof(msgBuf), fmt, args); + msgBuf[sizeof(msgBuf) - 1] = '\0'; + va_end(args); + + if(conn->Pfdebug) + { + fprintf(conn->Pfdebug, "%s", msgBuf); + } + else if(conn->traceDebug) + { + if((int)ftell(conn->traceDebug) >= conn->logsize) + { + fclose(conn->traceDebug); + getTraceLogFilename(conn,logfilename); + conn->traceDebug = fopen(logfilename,"w"); + if(conn->traceDebug == NULL) + return; + } + + /* Select trace log message style */ + if(addTime) + { + getCurrentTime(currenttime,1); + ret = fprintf(conn->traceDebug, "%s %s\n", msgBuf, currenttime); + } + else + { + ret = fprintf(conn->traceDebug, "%s",msgBuf); + } + + if(ret < 0) + { + fclose(conn->traceDebug); + conn->traceDebug = NULL; + return; + } + fflush(conn->traceDebug); + } +} +/* + * traceLog_fputnbytes: output trace log to file using fputnbytes() + */ +static void +traceLog_fputnbytes(PGconn *conn,const char *head, const char *str, size_t n) +{ + char logfilename[MAXPGPATH]; + int ret; + + if (conn->Pfdebug) + { + fprintf(conn->Pfdebug, "%s", head); + fputnbytes(conn->Pfdebug,str, n); + fprintf(conn->Pfdebug, "\n"); + } + else if(conn->traceDebug) + { + if((int)ftell(conn->traceDebug) >= conn->logsize) + { + fclose(conn->traceDebug); + getTraceLogFilename(conn,logfilename); + conn->traceDebug = fopen(logfilename,"w"); + if(conn->traceDebug == NULL) + return; + } + ret = fprintf(conn->traceDebug, "%s", head); + if(ret < 0) + { + fclose(conn->traceDebug); + conn->traceDebug = NULL; + return; + } + fputnbytes(conn->traceDebug,str,n); + fprintf(conn->traceDebug,"\n"); + fflush(conn->traceDebug); + } +} + /* * PQlibVersion: return the libpq version number */ @@ -98,8 +262,8 @@ pqGetc(char *result, PGconn *conn) *result = conn->inBuffer[conn->inCursor++]; - if (conn->Pfdebug) - fprintf(conn->Pfdebug, "From backend> %c\n", *result); + if(conn->Pfdebug||conn->traceDebug) + traceLog_fprintf(conn, false, "From backend> %c\n", *result); return 0; } @@ -114,8 +278,8 @@ pqPutc(char c, PGconn *conn) if (pqPutMsgBytes(&c, 1, conn)) return EOF; - if (conn->Pfdebug) - fprintf(conn->Pfdebug, "To backend> %c\n", c); + if(conn->Pfdebug||conn->traceDebug) + traceLog_fprintf(conn, false, "To backend> %c\n", c); return 0; } @@ -152,9 +316,9 @@ pqGets_internal(PQExpBuffer buf, PGconn *conn, bool resetbuffer) conn->inCursor = ++inCursor; - if (conn->Pfdebug) - fprintf(conn->Pfdebug, "From backend> \"%s\"\n", - buf->data); + if(conn->Pfdebug||conn->traceDebug) + traceLog_fprintf(conn, false, "From backend> \"%s\"\n", + buf->data); return 0; } @@ -181,8 +345,8 @@ pqPuts(const char *s, PGconn *conn) if (pqPutMsgBytes(s, strlen(s) + 1, conn)) return EOF; - if (conn->Pfdebug) - fprintf(conn->Pfdebug, "To backend> \"%s\"\n", s); + if(conn->Pfdebug||conn->traceDebug) + traceLog_fprintf(conn, false, "To backend> \"%s\"\n", s); return 0; } @@ -194,6 +358,7 @@ pqPuts(const char *s, PGconn *conn) int pqGetnchar(char *s, size_t len, PGconn *conn) { + char buf[100]; if (len > (size_t) (conn->inEnd - conn->inCursor)) return EOF; @@ -202,11 +367,10 @@ pqGetnchar(char *s, size_t len, PGconn *conn) conn->inCursor += len; - if (conn->Pfdebug) + if(conn->Pfdebug||conn->traceDebug) { - fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len); - fputnbytes(conn->Pfdebug, s, len); - fprintf(conn->Pfdebug, "\n"); + sprintf(buf, "From backend (%lu)> ", (unsigned long) len); + traceLog_fputnbytes(conn,buf,s, len); } return 0; @@ -228,7 +392,7 @@ pqSkipnchar(size_t len, PGconn *conn) if (conn->Pfdebug) { - fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len); + fprintf(conn->Pfdebug, "(pqSkipnchar)From backend (%lu)> ", (unsigned long) len); fputnbytes(conn->Pfdebug, conn->inBuffer + conn->inCursor, len); fprintf(conn->Pfdebug, "\n"); } @@ -245,14 +409,14 @@ pqSkipnchar(size_t len, PGconn *conn) int pqPutnchar(const char *s, size_t len, PGconn *conn) { + char buf[100]; if (pqPutMsgBytes(s, len, conn)) return EOF; - if (conn->Pfdebug) + if(conn->Pfdebug||conn->traceDebug) { - fprintf(conn->Pfdebug, "To backend> "); - fputnbytes(conn->Pfdebug, s, len); - fprintf(conn->Pfdebug, "\n"); + sprintf(buf,"To backend (%lu)> ", (unsigned long) len); + traceLog_fputnbytes(conn,buf,s,len); } return 0; @@ -292,8 +456,8 @@ 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); + if(conn->Pfdebug||conn->traceDebug) + traceLog_fprintf(conn, false, "From backend (#%lu)> %d\n", (unsigned long) bytes, *result); return 0; } @@ -328,8 +492,8 @@ pqPutInt(int value, size_t bytes, PGconn *conn) return EOF; } - if (conn->Pfdebug) - fprintf(conn->Pfdebug, "To backend (%lu#)> %d\n", (unsigned long) bytes, value); + if(conn->Pfdebug||conn->traceDebug) + traceLog_fprintf(conn, false, "To backend (%lu#)> %d\n", (unsigned long) bytes, value); return 0; } @@ -548,9 +712,9 @@ 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 : ' '); + if(conn->Pfdebug||conn->traceDebug) + traceLog_fprintf(conn, false, "To backend> Msg %c\n", + msg_type ? msg_type : ' '); return 0; } @@ -586,9 +750,9 @@ 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); + if(conn->Pfdebug||conn->traceDebug) + traceLog_fprintf(conn, false, "To backend> Msg complete, length %u\n", + conn->outMsgEnd - conn->outCount); /* Fill in length word if needed */ if (conn->outMsgStart >= 0) @@ -677,9 +841,16 @@ pqReadData(PGconn *conn) } /* OK, try to read some data */ + + if (conn->traceDebug) + traceLog_fprintf(conn, true, "Start receiving message from backend:"); retry3: nread = pqsecure_read(conn, conn->inBuffer + conn->inEnd, conn->inBufSize - conn->inEnd); + + if (conn->traceDebug) + traceLog_fprintf(conn, true, "End receiving message from backend:"); + if (nread < 0) { if (SOCK_ERRNO == EINTR) @@ -767,9 +938,16 @@ retry3: * Still not sure that it's EOF, because some data could have just * arrived. */ + + if (conn->traceDebug) + traceLog_fprintf(conn, true, "Start receiving message from backend:"); retry4: nread = pqsecure_read(conn, conn->inBuffer + conn->inEnd, conn->inBufSize - conn->inEnd); + + if (conn->traceDebug) + traceLog_fprintf(conn, true, "End receiving message from backend:"); + if (nread < 0) { if (SOCK_ERRNO == EINTR) @@ -846,6 +1024,9 @@ pqSendSome(PGconn *conn, int len) { int sent; + if (conn->traceDebug) + traceLog_fprintf(conn, true, "Start sending message to backend:"); + #ifndef WIN32 sent = pqsecure_write(conn, ptr, len); #else @@ -858,6 +1039,9 @@ pqSendSome(PGconn *conn, int len) sent = pqsecure_write(conn, ptr, Min(len, 65536)); #endif + if (conn->traceDebug) + traceLog_fprintf(conn, true, "End sending message to backend:"); + if (sent < 0) { /* Anything except EAGAIN/EWOULDBLOCK/EINTR is trouble */ diff --git a/src/interfaces/libpq/libpq-int.h b/src/interfaces/libpq/libpq-int.h index 975ab33..2aa8a51 100644 --- a/src/interfaces/libpq/libpq-int.h +++ b/src/interfaces/libpq/libpq-int.h @@ -499,6 +499,11 @@ struct pg_conn /* Buffer for receiving various parts of messages */ PQExpBufferData workBuffer; /* expansible string */ + + char *logsize_str; /* Trace log maximum size (string) */ + int logsize; /* Trace log maximum size */ + char *logdir; /* Trace log directory to save log */ + FILE *traceDebug; /* Trace log file to write trace info */ }; /* PGcancel stores all data necessary to cancel a connection. A copy of this @@ -665,6 +670,10 @@ extern void pq_reset_sigpipe(sigset_t *osigset, bool sigpipe_pending, bool got_epipe); #endif +/* libpq trace log */ +extern void initTraceLog(PGconn *conn); +extern void traceLog_fprintf(PGconn *conn, bool addTime, const char *fmt,...) pg_attribute_printf(3, 4); + /* === SSL === */ /*