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