RE: libpq debug log

On Mon, January 25, 2021 4:13 PM (JST), Tsunakawa-san wrote:.
> Also, please note this as:
>
> > Also, why don't you try running the regression tests with a temporary
> modification to PQtrace() to output the trace to a file? The sole purpose is
> to confirm that this patch doesn't make the test crash (core dump).

I realized that existing libpq regression tests in src/test/examples do not
test PQtrace(). At the same time, no other functions Is calling PQtrace(),
so it's expected that by default if there are no compilation errors, then it
will pass all the tests. And it did.

So to check that the tracing feature is enabled and, as requested, outputs
a trace file, I temporarily modified a bit of testlibpq.c instead **based from
my current environment settings**, and ran the regression test.

diff --git a/src/test/examples/testlibpq.c b/src/test/examples/testlibpq.c
index 0372781..ae163e4 100644
--- a/src/test/examples/testlibpq.c
+++ b/src/test/examples/testlibpq.c
@@ -26,6 +26,7 @@ main(int argc, char **argv)
int nFields;
int i,
j;
+ FILE *trace_file;

/*
* If the user supplies a parameter on the command line, use it as the
@@ -40,6 +41,9 @@ main(int argc, char **argv)
/* Make a connection to the database */
conn = PQconnectdb(conninfo);

+ trace_file = fopen("/home/postgres/tracelog/trace.out","w");
+ PQtrace(conn, trace_file, 0);
+
/* Check to see that the backend connection was successfully made */
if (PQstatus(conn) != CONNECTION_OK)
{
@@ -127,5 +131,6 @@ main(int argc, char **argv)
/* close the connection to the database and cleanup */
PQfinish(conn);

+ fclose(trace_file);
return 0;
}

make -C src/test/examples/ PROGS=testlibpq
./src/test/examples/testlibpq

I've verified that it works (no crash) and outputs a trace file to the PATH that I set in libpqtest.

The trace file contains the following log for the testlibq:

2021-01-28 09:22:28.155 > Query 59 "SELECT pg_catalog.set_config('search_path', '', false)"
2021-01-28 09:22:28.156 > Query -1
2021-01-28 09:22:28.157 < RowDescription 35 #1 "set_config" 0 #0 25 #65535 -1 #0
2021-01-28 09:22:28.157 < DataRow 10 #1 0
2021-01-28 09:22:28.157 < CommandComplete 13 "SELECT 1"
2021-01-28 09:22:28.157 < ReadyForQuery 5
2021-01-28 09:22:28.157 < ReadyForQuery 5 I
2021-01-28 09:22:28.157 > Query 10 "BEGIN"
2021-01-28 09:22:28.157 > Query -1
2021-01-28 09:22:28.157 < CommandComplete 10 "BEGIN"
2021-01-28 09:22:28.157 < ReadyForQuery 5
2021-01-28 09:22:28.157 < ReadyForQuery 5 T
2021-01-28 09:22:28.157 > Query 58 "DECLARE myportal CURSOR FOR select * from pg_database"
2021-01-28 09:22:28.157 > Query -1
2021-01-28 09:22:28.159 < CommandComplete 19 "DECLARE CURSOR"
2021-01-28 09:22:28.159 < ReadyForQuery 5
2021-01-28 09:22:28.159 < ReadyForQuery 5 T
2021-01-28 09:22:28.159 > Query 26 "FETCH ALL in myportal"
2021-01-28 09:22:28.159 > Query -1
2021-01-28 09:22:28.159 < RowDescription 405 #14 "oid" 1262 #1 26 #4 -1 #0 "datname" 1262 #2 19 #64 -1 #0 "datdba" 1262 #3 26 #4 -1 #0 "encoding" 1262 #4 23 #4 -1 #0 "datcollate" 1262 #5 19 #64 -1 #0 "datctype" 1262 #6 19 #64 -1 #0 "datistemplate" 1262 #7 16 #1 -1 #0 "datallowconn" 1262 #8 16 #1 -1 #0 "datconnlimit" 1262 #9 23 #4 -1 #0 "datlastsysoid" 1262 #10 26 #4 -1 #0 "datfrozenxid" 1262 #11 28 #4 -1 #0 "datminmxid" 1262 #12 28 #4 -1 #0 "dattablespace" 1262 #13 26 #4 -1 #0 "datacl" 1262 #14 1034 #65535 -1 #0
2021-01-28 09:22:28.159 < DataRow 117 #14 5 '13756' 8 'postgres' 2 '10' 1 '6' 11 'en_US.UTF-8' 11 'en_US.UTF-8' 1 'f' 1 't' 2 '-1' 5 '13755' 3 '502' 1 '1' 4 '1663' -1
2021-01-28 09:22:28.159 < DataRow 149 #14 1 '1' 9 'template1' 2 '10' 1 '6' 11 'en_US.UTF-8' 11 'en_US.UTF-8' 1 't' 1 't' 2 '-1' 5 '13755' 3 '502' 1 '1' 4 '1663' 35 '{=c/postgres,postgres=CTc/postgres}'
2021-01-28 09:22:28.159 < DataRow 153 #14 5 '13755' 9 'template0' 2 '10' 1 '6' 11 'en_US.UTF-8' 11 'en_US.UTF-8' 1 't' 1 'f' 2 '-1' 5 '13755' 3 '502' 1 '1' 4 '1663' 35 '{=c/postgres,postgres=CTc/postgres}'
2021-01-28 09:22:28.159 < CommandComplete 12 "FETCH 3"
2021-01-28 09:22:28.159 < ReadyForQuery 5
2021-01-28 09:22:28.159 < ReadyForQuery 5 T
2021-01-28 09:22:28.159 > Query 19 "CLOSE myportal"
2021-01-28 09:22:28.159 > Query -1
2021-01-28 09:22:28.159 < CommandComplete 17 "CLOSE CURSOR"
2021-01-28 09:22:28.159 < ReadyForQuery 5
2021-01-28 09:22:28.159 < ReadyForQuery 5 T
2021-01-28 09:22:28.159 > Query 8 "END"
2021-01-28 09:22:28.159 > Query -1
2021-01-28 09:22:28.160 < CommandComplete 11 "COMMIT"
2021-01-28 09:22:28.160 < ReadyForQuery 5
2021-01-28 09:22:28.160 < ReadyForQuery 5 I
2021-01-28 09:22:28.160 > Terminate 4
2021-01-28 09:22:28.160 > Terminate -1

Regards,
Kirk Jamison