Re: libpq debug log

On 2021-Jan-28, k(dot)jamison(at)fujitsu(dot)com wrote:

> 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.

Yeah. It seems useful to build a real test harness based on the new
tracing functionality. And that is precisely why I added the option to
suppress timestamps: so that we can write trace files that do not vary
from run to run. That allows us to have an "expected" trace to which we
can compare the trace file produced by the actual run. I had the idea
that instead of a timestamp we would print a message counter. I didn't
implement that, however.

So what we need to do now, before we cast in stone such expected files,
is ensure that the trace file produced by some program (be it
testlibpq.c or some other program) accurately matches what is sent over
the network. If the tracing infrastructure has bugs, then the trace
will contain artifacts, and that's something to avoid. For example, in
the trace you paste, why are there two "Query" messages every time, with
the second one having length -1? I think this is a bug I introduced
recently.

> 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"

And afterwards, why are always there two ReadyForQuery messages?

> 2021-01-28 09:22:28.157 < ReadyForQuery 5
> 2021-01-28 09:22:28.157 < ReadyForQuery 5 I

In ReadyForQuery, we also get a transaction status. In this case it's
"I" which means "Idle" (pretty mysterious if you don't know, as was my
case). A bunch of other values are possible. Do we want to translate
this to human-readable flags, similarly to how we translate message tag
chars to message names? Seems useful to me. Or maybe it's
overengineering, about which see below.

> 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

This is terribly unreadable, but at this point that's okay because we're
just doing tracing at a very low level. In the future we could add some
new flag PQTRACE_INTERPRET_MESSAGES or something, which changes the
output format to something more readable. Or maybe nobody cares to
spend time doing that.

Cheers

--
Álvaro Herrera Valdivia, Chile
"Para tener más hay que desear menos"