RE: libpq debug log
Hi Alvaro san, > There are some things still to do: I worked on some to do. > 1. Is the handling of protocol 2 correct? Protocol 3.0 is implemented in PostgreSQL v7.4 or later. Therefore, most servers and clients today want to connect using 3.0. Also, wishful thinking, I think Protocol 2.0 will no longer be supported. So I didn't develop it aggressively. Another reason I'm concerned about implementing it would make the code less maintainable. > 5. Error messages are still printing the terminating zero byte. I > suggest that it should be suppressed. I suppressed to print terminating zero byte like this; 2020-12-15 00:54:09 UTC < ErrorResponse 100 S "ERROR" V "ERROR" C "42P01" M "relation "a" does not exist" P "15" F "parse_relation.c" L "1379" R "parserOpenTable" 0 I thought about not outputting it, but the document said that if zero, it was the last message, so I made it output "0". > 6. Let's redefine pqTraceMaybeBreakLine() (I renamed from > pqLogLineBreak): Sure. I redefined this function. > 7. Why does it make sense to call pqTraceMaybeBreakLine when > commsource=FROM_FRONTEND? Backend messages include break line. However frontend messages don’t have it. So I call this functions. Pending lists. > 0. XXX comments There were 4 XXX comments in Alvaro san's patch. 3 XXX comments are left in current patch. I will answer this in next e-mail. > 2. We need a mode to suppress print of time; > 3. COPY ... (FORMAT BINARY) emits "invalid protocol" ... not good. > 4. Even in text format, COPY output is not very useful. How can we improve that? Regards, Aya Iwata Fujitsu v10-0001-libpq-trace.patch Description: v10-0001-libpq-trace.patch
RE: libpq debug log
Hi all,
I update patch to v18. It has been fixed in response to Tsunakawa san's review.
> From: Tsunakawa, Takayuki/綱川 貴之
> Sent: Friday, February 12, 2021 1:53 PM
>
> (48)
>
> void PQtrace(PGconn *conn, FILE *stream);
>
>
>
> +
> + Calls PQtraceSetFlags to output with or
> without a timestamp.
> +
> +
>
>
> Why is this necessary? Even if you decide to remove this change, can you
> share your idea on why you added this just in case?
In the previous patch, we described the PQTRACE_SUPPRESS_TIMESTAMPS flag in the
PQtrace () part.
And I think PQtrace () and PQtraceSetFlag () are closely related functions.
It would be nice for the user to know both features before using the logging
feature.
So I added a description of PQtraceSetFlag () to the paragraph of PQtrace ().
However, the PQtraceSetFlag () documentation is in the next paragraph of
PQtrace (),
so users can easily notice the PQtraceSetFlag () function. So I removed it.
> (49)
> + Determine to output tracing with or without a timestamp to a
> debugging file stream.
>
> The description should be the overall functionality of this function
> considering
> the future additions of flags. Something like:
>
> Controls the tracing behavior of client/server communication.
>
> + then timestamp is not printed with each message. The default is
> output with timestamp.
>
> The default value for flags argument (0) should be described here.
>
> Also, it should be added that PQsetTraceFlags() can be called before or after
> the PQtrace() call.
I fixed documentation like this;
If set to 0 (default),tracing will be output with timestamp.
This function should be called after calling PQtrace.
> (50)
> I'd like you to consider skipLogging again, because it seems that such a
> variable is for the logging machinery to control state transitions internally
> in
> fe-logging.c.
> What I'm concerned is that those who modify libpq have to be aware of
> skipLogging and would fail to handle it.
To implement inLogging, logging skip method has been modified to be completed
within the libpq-logging.c file.
The protocol message consists of First Byte, Length, and Contents.
When the first byte and length arrive, if contents is not yet in the buffer,
the process of reading the first byte and length is repeated.
Reloading is necessary to parse the protocol message and proceed,
but we want to skip logging because it is not necessary to output the message
which already log to file.
To do this, remember the value of inCursor in the inLogging variable and record
how far logging has progressed.
In the pqTraceLogBeMsgByte1() and pqTraceLogBeMsgInt(),
the value of inCursor at that time is stored in inLogging after outputting the
log to a file.
If inCursor is smaller than inLogging, it exits the log output function without
doing anything.
If all log messages are output, initialize the inLogging.
Changed the pqTraceMaybeBreakLine() function to return whether a line break has
occurred
in order to consolidate the process of recording the cursor in one place. If it
break line,
inLogging is initialized and inCursor is not remembered inLogging.
Also, as Horiguchi san mentioned, I changed to update the value of inLogging
even in the function where the value of inCursor is changed (Ex.
pqCheckInBufferSpace () and pqReadData ()).
> (51)
> >> +typedef enum PGLogState
> >> +{
> >>
> >> This is libpq-logging.c internal type. It is not needed to be exposed.
>
> > I fixed it.
>
> How did you fix it? The typedef is still in .h file. It should be in .h,
> shouldn't
> it? Houw about the other typedefs?
I didn’t move PGLogState to .c file because PGLogState is a member of be_msg
which is referred from other files.
Regards,
Aya Iwata
Fujitsu
v18-0001-libpq-trace.patch
Description: v18-0001-libpq-trace.patch
RE: libpq debug log
Hi Tsunakawa san, I update patch to v19. > -Original Message- > From: Tsunakawa, Takayuki/綱川 貴之 > Sent: Monday, February 22, 2021 1:30 PM > (52) > + of tracing. If (flags contains > PQTRACE_SUPPRESS_TIMESTAMPS), > > () can be removed? Yes, I removed (). > (53) > + int inLogging; /* next byte of > logging */ > > I understood this variable contains a position or offset from some place. > Then, > isn't it better to call it LogPos, LogOffset, or LogCursor? I don't think you > need to prepend "In" as in InCursor, because you don't have to distinguish > between input and output unlike InCursor in PGconn. Yes, "In" is from inCursor. I change inLogging to LogCursor because this name easier to understand the meaning of this parameter. > (54) > Can't you restrict the use of the above InLogging in fe-logging.c? How about > making InLogging mean the offset from InStart, i.e. the offset from the start > of > a message? I fixed it. Remove inLogging code from pqCheckInBufferSpace() and pqReadData(). And LogCursor remember the difference between conn->inCursor and conn->inStart. And 3 bugs I noted February 2nd email are all fixed. > 1. fix 3 bugs > 1.1 -1 output in "Query" message > 1.2 two message output in "ReadyForQuery" message > 1.3 "StartupMessage" output as " UnknownMessage " If you want to know how to fix there bugs, please see my email; > Sent: Monday, February 8, 2021 11:58 PM Regards, Aya Iwata Fujitsu v19-0001-libpq-trace.patch Description: v19-0001-libpq-trace.patch
RE: libpq debug log
Hi Kirk san, Thank you for your review. I update patch to v21. > -Original Message- > From: Jamison, Kirk/ジャミソン カーク > Sent: Wednesday, February 24, 2021 1:04 PM > (1) Doc: PQtraceSetFlags > + flags contains flag bits describing the operating > mode > + of tracing. If flags contains > PQTRACE_SUPPRESS_TIMESTAMPS, > + then timestamp is not printed with each message. If set to 0 > (default),tracing will be output with timestamp. > + This function should be called after calling > PQtrace. > > Missing space. And can be paraphrased to: > "If set to 0 (default), tracing with timestamp is printed." I fixed this documentation as you suggested. > (2) > + * pqTraceMaybeBreakLine: > + * Check whether the backend message is complete. If so, print > a line > + * break and reset the buffer. If print break line, return 1. > > The 2nd & last sentence can be combined to "If so, print a line break, reset > the buffer, and return 1." I fixed it because it is more natural than previous explanation. > (3) +PQtraceSetFlags(PGconn *conn, int flags) > + /* If PQtrace() is failed, do noting. */ > > "If PQtrace() failed, do nothing." I fixed it. > (4) > > (Not sure about the use of the word "forcely") > > I think it's not necessary. Sure. > Also, I tested the flag to not print timestamp. For example, > PQtrace(conn, trace_file); > PQtraceSetFlags(conn, PQTRACE_SUPPRESS_TIMESTAMPS); > > And it did not print the timestamp. So it worked. > It also passed all the regression tests. (although PQtrace() is not tested in > existing libpq tests). Thank you for your test. Regards, Aya Iwata Fujitsu v21-0001-libpq-trace.patch Description: v21-0001-libpq-trace.patch
RE: libpq debug log
Alvaro san, Thank you very much for your updating and organizing this patch. It appears that something is still wrong. I applied lipq pipeline v27 from [1] and ran src/test/modules/test_libpq/pipeline singlerow, after patching it to do PQtrace() after PQconn(). Below is the output I get from that. The noteworthy point is that "ParseComplete" messages appear multiple times for some reason ... but that's quite odd, because if I look at the network traffic with Wireshark I certainly do not see the ParseComplete message being sent three times. I will search this cause. Please wait a minuets. I thought I could avoid multiple such outputs by using conn->LogCursor… Regards, Aya Iwata Fujitsu From: Álvaro Herrera Sent: Friday, February 26, 2021 2:49 AM To: Iwata, Aya/岩田 彩 ; Jamison, Kirk/ジャミソン カーク Cc: Tsunakawa, Takayuki/綱川 貴之 ; 'Kyotaro Horiguchi' ; pgsql-hackers@lists.postgresql.org Subject: Re: libpq debug log I tweaked this code a little bit more. I didn't like that libpq-trace.h was exposing all the internal details of the API to the world; and I liked it even less that libpq-int.h had to include the file, exposing everything everywhere. I added some forward struct declarations in libpq-int.h to avoid including libpq-trace.h in it; and I also moved a few of the definitions from libpq-trace.h to the .c file. We didn't really need them to be exposed outside the .c file. In the makefile, libpq-trace.h was being installed in the wrong place -- I changed so that it goes to includedir_internal, like libpq-int.h. The function pqLogFormatTimestamp was returning a pointer to where it printed things. But that was pointless, because the buffer is caller supplied, so the caller knows full well where the output is. There's no gain in functionality, so I made it return void. I added a description of the output format to the documentation. I renamed a lot of functions, so that it looks more like a consistent API. pqTraceMaybeBreakLine() says it returns bool, but it was using "return 1/0" rather than actual bools. That's poor style. The only thing we're missing here is some coverage. Right now, nothing in the source tree calls this at all, so if we break it, we'll never know. I think we should introduce src/test/modules/test_pqtrace or something like that. v22 attached.
RE: libpq debug log
Hi all, Following all reviewer's advice, I have created a new patch. In this patch, I add only two tracing entry points; I call pqTraceOutputMsg(PGconn conn, int msgCursor, PGCommSource commsource) in pqParseInput3 () and pqPutMsgEnd () to output log. The argument contains message first byte offset called msgCursor because it is simpler to specify the buffer pointer in the caller. In pqTraceOutputMsg(), the content common to all protocol messages (first timestamp, < or >, first 1 byte, and length) are output first and after that each protocol message contents is output. I referred to pqParseInput3 () , fe-exec.c and documentation page for that part. This fix almost eliminates if(conn->Pfdebug) that was built into the code for other features. Regards, Aya Iwata > -Original Message- > From: alvhe...@alvh.no-ip.org > Sent: Friday, March 5, 2021 10:41 PM > To: Tsunakawa, Takayuki/綱川 貴之 > Cc: 'Tom Lane' ; Iwata, Aya/岩田 彩 > ; Jamison, Kirk/ジャミソン カーク > ; 'Kyotaro Horiguchi' ; > pgsql-hackers@lists.postgresql.org > Subject: Re: libpq debug log > > On 2021-Mar-05, tsunakawa.ta...@fujitsu.com wrote: > > > From: Tom Lane > > > But I think passing the message start address explicitly might be > > > better than having it understand the buffering behavior in enough > > > detail to know where to find the message. Part of the point here > > > (IMO) is to decouple the tracing logic from the core libpq logic, in > > > hopes of not having common-mode bugs. > > > > Ouch, you're perfectly right. Then let's make the signature: > > > > void pqLogMessage(PGconn *conn, const char *message, bool > > toServer); > > Yeah, looks good! I agree that going this route will result in more > trustworthy > trace output. > > -- > Álvaro Herrera39°49'30"S 73°17'W v24-libpq-trace-log.patch Description: v24-libpq-trace-log.patch
RE: libpq debug log
Alvaro san, Tom san Horiguchi san, Tsunakawa san and Kirk san,
Thank you very much for review and advice.
> > Works for me.
>
> Pushed that. I think we're now waiting on Iwata-san to finish a new version
> of
> the tracing patch.
Thank you very much Alvaro san and Tom san. Your patch and code change makes my
work more smoothly.
And I am sorry for attaching not-good-work patch. fixsegv.patch help my
implementation.
I update this patch to v25. I fix function arguments and something which are
pointed out by reviewers.
I create protocol message reading function for each protocol message type. (Ex.
pqTraceOutputB() read Bind message)
This makes the nesting shallower and makes the code easier to read.
Each data type output functions(Ex. pqTraceOutputString() ) are called from
each protocol message type function.
Cursor operation is performed in each protocol message type function.
Like Kirk san, I share `make check` results. As far as I can see, tracing
works well.
I compare this result with current master branch trace log. It does not
miss/add any protocol message.
And Thank you Kirk san for your share of make check result and previous patch!
```
2021-03-15 08:10:44.288999 > Terminate 4
2021-03-15 08:10:44.317959 > Query 155 "CREATE TABLESPACE
regress_tblspacewith LOCATION
'/home/iwata/pgsql/postgres/src/test/regress/testtablespace' WITH
(some_nonexistent_parameter = true);"
2021-03-15 08:10:44.319121 < ErrorResponse 124 S "ERROR" V "ERROR" C
"22023" M "unrecognized parameter "some_nonexistent_parameter"" F
"reloptions.c" L "1447" R "parseRelOptionsInternal" \x00
2021-03-15 08:10:44.319161 < ReadyForQuery 5 I
2021-03-15 08:10:44.319221 > Query 144 "CREATE TABLESPACE
regress_tblspacewith LOCATION
'/home/iwata/pgsql/postgres/src/test/regress/testtablespace' WITH
(random_page_cost = 3.0);"
2021-03-15 08:10:44.320889 < CommandComplete 22 "CREATE TABLESPACE"
2021-03-15 08:10:44.320922 < ReadyForQuery 5 I
2021-03-15 08:10:44.320979 > Query 81 "SELECT spcoptions FROM
pg_tablespace WHERE spcname = 'regress_tblspacewith';"
2021-03-15 08:10:44.324296 < RowDescription 35 #1 "spcoptions" 1213 #5 1009
#65535 -1 #0
2021-03-15 08:10:44.324335 < DataRow 32 #1 22 '{random_page_cost=3.0}'
2021-03-15 08:10:44.324347 < CommandComplete 13 "SELECT 1"
2021-03-15 08:10:44.324388 < ReadyForQuery 5 I
2021-03-15 08:10:44.324516 > Query 42 "DROP TABLESPACE
regress_tblspacewith;"
2021-03-15 08:10:44.325423 < CommandComplete 20 "DROP TABLESPACE"
2021-03-15 08:10:44.325453 < ReadyForQuery 5 I
```
> From: Tsunakawa, Takayuki/綱川 貴之
> Sent: Friday, March 5, 2021 3:17 PM
...
>
> void pqLogMessage(PGconn *conn, const char *message, bool toServer);
Thank you Tsunakawa san. In v25 patch, I fixed qTraceOutputMessag() function to
this style.
I am sorry changing arguments in previous patch. That was my misunderstanding.
> From: Tom Lane
> Sent: Thursday, March 11, 2021 6:33 AM
...
> There are still some cowboy advancements of inStart in the functions
> concerned with COPY processing, but it doesn't look like there's much to be
> done about that. Those spots will need their own trace calls.
I called pqTraceOutputMessage() from pqParseInput3(), COPY process and
pqFunctionCall3(). pqFunctionCall3() is called by PQfn().
I found that there is protocol message id switch(). So I call the tracing
function there.
> From: Kyotaro Horiguchi
> Sent: Thursday, March 11, 2021 10:20 AM
Thank you Horiguchi san. Your keen review suggestions and detailed advice. It
is very helpful for updating my patch.
> The individual per-type-output functions are designed to fit to the
> corresponding pqGet*() functions. On the other hand, now that we read the
> message bytes knowing the exact format in advance as you did in
> pqTraceOutputMsg(). So the complexity exist in the functions can be
> eliminated by separating them into more type specific output functions. For
> example, pqTraceOutputInt() is far simplified by spliting it into
> pqTraceOutputInt16() and -32().
Yes, I refer to pqGet functions. To make data type output function more
simpler,
I separate output int function to pqTraceOutputInt16 and -32.
> I think we can get rid of copying in the output functions for String and
> Bytes in
> different ways.
I remove memcpy call from String and Bytes output function.
These functions just pass *message to fprintf().
> + /* Protocol 2.0 does not support tracing. */
> + if (PG_PROTOCOL_MAJOR(conn->pversion) < 3)
> + return;
>
> We can write that message out into tracing file.
>
> +void
> +PQtraceSetFlags(PGconn *conn, int flags) {
> + if (conn == NULL)
> + return;
> + /* Protocol 2.0 is not supported. */
> + if (PG_PROTOCOL_MAJOR(conn->pv
RE: libpq debug log
Hi Alvaro san, Thank you for your email. I will review this updated patch and I will let you know when I complete. Please wait a moment. Best regards, Aya Iwata > -Original Message- > From: Alvaro Herrera > Sent: Tuesday, October 27, 2020 1:23 AM > To: Iwata, Aya/岩田 彩 > Cc: pgsql-hack...@postgresql.org; t...@sss.pgh.pa.us; > robertmh...@gmail.com; pchamp...@pivotal.io; jd...@pivotal.io; > raam.s...@gmail.com; Nagaura, Ryohei/永浦 良平 > ; nag...@sraoss.co.jp; > peter.eisentr...@2ndquadrant.com; 'Kyotaro HORIGUCHI' > ; Jamison, Kirk/ジャミソン カーク > > Subject: Re: libpq debug log > > Hello Aya Iwata > > I've been hacking at this patch again. There were a few things I wasn't too > clear about, so I reordered the code and renamed the routines to try to make > it > easier to follow. > > One thing I didn't like very much is that all the structures and enums were > exposed to the world in libq-int.h. Because some enum members have > pretty generic names, I didn't like that much, so I moved the whole thing to > fe-misc.c, and renamed the structs. Also, the arrays don't take space unless > PQtrace() is called. (This is not what I was talking about in my previous > message. The idea I was trying to explain in my previous message cannot > possibly work, so I abandoned it.) > > I also renamed functions to make it clear which handles frontend and which > handles backend. With that, it was pretty obvious that we had an "reset BE > message" in the routine to handle FE, and some clearing of FE in the code that > handles BE. I fixed things in a way that I think makes the most sense. > > I noticed that it's theoretically possible to have a FE message so large (more > than MAXPGPATH pieces) that it would overrun the array; so I added a "print > message" call after adding one piece, to avoid this. Also, why MAXPGPATH? > I added a new symbol MAX_FRONTEND_MSGS for this purpose. > > There are some things still to do: > > 0. I added a XXX comment to pqFlush. Because we're storing messages in > fe_msgs that point to the libpq buffer, is it possible to end up with trace > messages that are pointing into outBuffer bytes that are already sent, and > perhaps even overwritten with newer bytes? Maybe not, but it's unclear. > Should we do pqLogFrontendMsg() preventively to avoid this problem? > > 1. Is the handling of protocol 2 correct? Since it's completely separate from > protocol 3, I have not even looked at what it produces. > But the fact that pqLogMsgByte1 completely ignores the "commsource" > argument makes me suspect that it's not correct. > 1a. How do we even test protocol 2 handling? > > 2. We need a mode to suppress print of time; this would be useful to be able > to > test libpq at a low level. Maybe instead of time we can print a > monotonically-increasing packet sequence number. With this, we could > easily add tests for libpq itself. What user interface do we want for this? > Maybe we can add an "bits32 flags" parameter to PQtrace(), with one bit for > this use. > > 3. COPY ... (FORMAT BINARY) emits "invalid protocol" ... not good. > > 4. Even in text format, COPY output is not very useful. How can we improve > that? > > 5. Error messages are still printing the terminating zero byte. I suggest > that > it should be suppressed. > > 6. Let's redefine pqTraceMaybeBreakLine() (I renamed from > pqLogLineBreak): If message is complete, print a newline; if message is not > complete, print a " ". Then, remove the whitespace after printing each > element. This should lead to lines that don't have an useless " " > at the end. > > 7. Why does it make sense to call pqTraceMaybeBreakLine when > commsource=FROM_FRONTEND?
RE: libpq debug log
Hi, Thank you for your review. I modified the code in response to those reviews. This patch includes these items: - Fix the code according to reviews - Fix COPY output issue - Change to not support Protocol v2.0 It is rarely used anymore and de-support it makes code more simpler. Please see the discussion in this thread for more details. Regards, Aya Iwata v11-0001-libpq-trace.patch Description: v11-0001-libpq-trace.patch
RE: libpq debug log
Hello, Alvaro san , Tsunakawa san Thank you for your help. It was very helpful. > Please integrate Alvaro-san's patch with yours. Next week is the last week > in this CF, so do your best to post the patch by next Monday or so (before > Alvaro-san loses interest or time.) Then I'll review it ASAP. I integrated my fix and update v12 patch. All previous review comments apply to this patch. Regards, Aya Iwata Fujitsu v13-0001-libpq-trace.patch Description: v13-0001-libpq-trace.patch
RE: libpq debug log
Tsunakawa san, > Strangely, Iwata-san's latest mail she sent today at 10:34 JST hasn't appeared > on pgsql-hackers yet after more than 6 hours. It is not reflected in the CF > entry [1]. So, I'm putting her original mail below. The v13 patch attached > to > the original mail is attached to this mail. I solved this problem. Thank you for sharing my email. Regards, Aya Iwata Fujitsu
RE: libpq debug log
Hi all,
Thank you Kirk san for creating the v14 patch.
I update the patch. I fixed all of Tsunakawa san's review comments.
I am trying to solve three bugs. Two bags were pointed out by Alvaro san
in a previous e-mail. And I found one bug.
> From: Alvaro Herrera
> Sent: Friday, January 22, 2021 6:53 AM
...
> > (5)
> > @@ -966,10 +966,6 @@ 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);
> > -
> >
> > Where is this information output instead?
>
> Hmm, seems to have been lost. I restored it, but didn't verify
> the resulting behavior carefully.
I checked log output using Matsumura san's application app.c;
---
2021-01-27 11:29:49.718 < ParameterStatus 22 "application_name" ""
pqSaveParameterStatus: 'application_name' = ''
2021-01-27 11:29:49.718 < ParameterStatus 25 "client_encoding" "UTF8"
pqSaveParameterStatus: 'client_encoding' = 'UTF8'
---
New trace log prints "ParameterStatus" which report run-time parameter status.
And new log also prints parameter name and value in " StartupMessage " message.
We can know the parameter status using these protocol messages.
So I think "pqSaveParameterStatus:" is not necessary to output.
In StartupMessage, the protocol message is output as "UnknownMessage" like
this.
[...] > UnknownMessage 38
'\x00\x03\x00\x00user\x00iwata\x00database\x00postgres\x00\x00'
To fix this, I want to move a protocol message without the first byte1 to a
frontend message logging function.
I will work on this.
> From: 'Alvaro Herrera'
> Sent: Friday, January 22, 2021 10:38 PM
> > Ah, that was the reason for separation. Then, I'm fine with either
> > keeping the separation, or integrating the two functions in fe-misc.c
> > with PQuntrace() being also there. I kind of think the latter is
> > better, because of code readability and, because tracing facility is
> > not a connection-related reature so categorizing it as "misc" feels
> > natural.
>
> Maybe we can create a new file specifically for this to avoid mixing
> unrelated stuff in fe-misc.c -- say fe-trace.c where all this new
> tracing stuff goes.
I moved PQtrace() from fe-connect.c to fe-misc.c.
And I agree with creating new file for new tracing functions. I will do this.
> From: 'Alvaro Herrera'
> Sent: Thursday, January 28, 2021 11:14 PM
...
> On 2021-Jan-28, k.jami...@fujitsu.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.
I think it is a useful suggestion. However I couldn't think of how to find out
if the logs were really in the correct order. And implementing this change
looks very complicated.
So I would like to brush up this patch at first.
> (29)
> -void PQtrace(PGconn *conn, FILE *stream);
> +void PQtrace(PGconn *conn, FILE *stream, int flags);
>
> As I said before, I'm afraid we cannot change the signature of existing API
> functions. Please leave the signature of this function unchanged, and add a
> new function like PQtraceEx() that adds the flags argument.
>
> I guess the purpose of adding the flag argument is to not output the timestamp
> by default, because getting timestamps would incur significant overhead
> (however, I'm not sure if that overhead is worth worrying about given the
> already incurred logging overhead.) So, I think it's better to have a flag
> like
> PQTRACE_OUTPUT_TIMESTAMPS instead of
> PQTRACE_SUPPRESS_TIMESTAMPS, and the functions would look like:
>
> void
> PQtrace(PGconn *conn, FILE *stream)
> {
> PQtraceEx(conn, stream, 0);
> }
>
> void
> PQtraceEx(PGconn *conn, FILE *stream, int flags)
> {
> ... the new implementation in the patch
> }
>
> Remember to add PQtraceEx in exports.txt and make sure it builds on
> Windows with Visual Studio.
I fixed just add new function.
I will look into similar changes so far and give PQtraceEx() a better name.
> But..
RE: libpq debug log
HI all,
I update the patch.
I modified code according to review comments of Tsunakawa san and Horiguchi san.
And I fixed some bugs.
> This patch should address the following:
> 1. fix 3 bugs
> 1.1 -1 output in "Query" message
The cause of this bug is that it call in pqFlush() function before flushing.
The purpose of calling pqLogFrontendMsg() here is to log the data that was in
the buffer but not logged before flushing.
The second argument of pqLogFrontendMsg() is message length, but we can't find
it in pqFlush().
Therefor, -1 was set here as a second argument and it was logged.
I thought about keeping the length as fields, but from the output Kirk san
tried, this doesn't seem to happen.
Also, the message from the frontend to the backend calls pqPutMsgEnd () in
advance, so the message should already be logged.
So I deleted this call.
> 1.2 two message output in "ReadyForQuery" message
In the pqParseInput3 (), when the state becomes PGASYNC_IDLE, it returns to the
caller.
After that, pqParseInput3 () is called again and protocol message and length
are output again by calling pqGetc(), pqGetInt().
To limit this, set the skipLogging flag when the status become PGASYNC_IDLE and
fixed to skip the next pqGetc(), pqGetInt().
> 1.3 "StartupMessage" output as " UnknownMessage "
I moved the code that handles the output of "SSLRequest", "StartupMessage",
etc.
to pqLogFrontendMsg() which is the function that outputs the front-end message.
> 2. creating new file for new tracing functions
I create new files libpq-logging.c and libpq-logging.h
> From: Tsunakawa, Takayuki/綱川 貴之
> Sent: Wednesday, February 3, 2021 10:27 AM
> (39)
> + of tracing. If (flags &
> PQTRACE_OUTPUT_TIMESTAMPS) is
> + true, then timestamp is not printed with each message.
>
> The flag name (OUTPUT) and its description (not printed) doesn't match.
I changed flag name to PQTRACE_SUPPRESS_TIMESTAMPS.
>
> I think you can use less programmatical expression like "If
> flags contains
> PQTRACE_OUTPUT_TIMESTAMPS".
I fixed.
> (40)
> diff --git a/src/interfaces/libpq/exports.txt
> b/src/interfaces/libpq/exports.txt
> +PQtraceEx 180
> \ No newline at end of file
>
> What's the second line? Isn't the file missing an empty line at the end?
I delete it.
> (41)
> +void
> +PQtraceEx(PGconn *conn, FILE *debug_port, int flags) {
> + if (conn == NULL)
> + return;
> ...
> + if (!debug_port)
> + return;
>
> The if should better be as follows to match the style of existing surrounding
> code.
>
> + if (debug_port == NULL)
I fixed it.
> (42)
> +pqLogFormatTimestamp(char *timestr, Size ts_len)
>
> I think you should use int or size_t instead of Size here, because other libpq
> code uses them. int should be enough. If the compiler gives warnings,
> prepend "(int)" before sizeof() at call sites.
I fixed it.
> (43)
> + /* append microseconds */
> + sprintf(timestr + strlen(timestr), ".%06d", (int) (tval.tv_usec /
> +1000));
>
> "/ 1000" should be removed.
I removed it.
> (44)
> + if ((conn->traceFlags & PQTRACE_OUTPUT_TIMESTAMPS) == 0)
> + timestr_p = pqLogFormatTimestamp(timestr,
> sizeof(timestr));
>
> == 0 should be removed.
I left it, referring Horiguchi san's comment.
Regards,
Aya Iwata
v16-0001-libpq-trace.patch
Description: v16-0001-libpq-trace.patch
RE: libpq debug log
Hi all,
Thank you for your review. I update patch to v17.
> From: Tsunakawa, Takayuki/綱川 貴之
> Sent: Tuesday, February 9, 2021 11:26 AM
> (45)
...
> The description of PQtrace() should be written independent of PQtraceEx().
> It is an unnecessary implementation detail to the user that PQtrace() calls
> PQtraceEx() internally. Plus, a separate entry for PQtraceEx() needs to be
> added.
I add PQtraceSetFlags() description instead of PQtraceEx() in response to
Horiguchi san's suggestion.
> (46)
>
> If skipLogging is intended for use with backend -> frontend messages only,
> shouldn't it be placed in conn->b_msg?
I moved skip flag to be_msg.
> (47)
...
> I'm not completely sure if other places interpose a block comment like this
> between if/for/while conditions, but I think it's better to put the comment
> before if.
I moved this comment to before if.
> From: Kyotaro Horiguchi
> Sent: Tuesday, February 9, 2021 5:26 PM
> +typedef enum
> +{
> + MSGDIR_FROM_BACKEND,
> + MSGDIR_FROM_FRONTEND
> +} PGCommSource;
>
> This is halfly exposed to other part of libpq. Specifically only
> MSGDIR_FROM_BACKEND is used in fe-misc.c and only for
> pgLogMessageString and pqLogMessagenchar. I would suggest to hide this
> enum from fe-misc.c.
>
> Looking into pqLogMessageString,
>
> +pqLogMessageString(PGconn *conn, const char *v, int length,
> PGCommSource source)
> +{
> + if (source == MSGDIR_FROM_BACKEND &&
> conn->be_msg->state != LOG_CONTENTS)
> + {
> + pqLogInvalidProtocol(conn, MSGDIR_FROM_BACKEND);
> + return; /* XXX ??? */
> + }
> +
> + fprintf(conn->Pfdebug, "\"%s\"", v);
> + if (source == MSGDIR_FROM_BACKEND)
> + pqTraceMaybeBreakLine(length, conn);
> +}
>
> The only part that shared by both be and fe is the fprintf(). I think
> it can be naturally split into separate functions for backend and
> frontend messages.
>
> Looking into pqLogMessagenchar,
>
> +/*
> + * pqLogMessagenchar: output a string of exactly len bytes message to the
> log
> + */
> +void
> +pqLogMessagenchar(PGconn *conn, const char *v, int len, PGCommSource
> commsource)
> +{
> + fprintf(conn->Pfdebug, "\'");
> + pqLogBinaryMsg(conn, v, len, commsource);
> + fprintf(conn->Pfdebug, "\'");
> + pqTraceMaybeBreakLine(len, conn);
> +}
>
> +static void
> +pqLogBinaryMsg(PGconn *conn, const char *v, int length, PGCommSource
> source)
> +{
> + int i,
> + pin;
> +
> + if (source == MSGDIR_FROM_BACKEND &&
> conn->be_msg->state != LOG_CONTENTS)
> + {
> + pqLogInvalidProtocol(conn, MSGDIR_FROM_BACKEND);
> + return; /* XXX ??? */
>
> # What is this???
>
> + }
> .. shared part
> +}
>
> pqLogMessagenchar is the sole caller of pqLogBinaryMsg. So we can
> refactor the two functions and have pqLogMessagenchar_for_be and
> _for_fe without a fear of the side effect to other callers. (The
> names are discussed below.)
Thank you for your advice on refactoring.
Separating pqLogMessagenchar() into pqLogMessagenchar_for_be and
pqLogMessagenchar_for_fe
seemed like adding more similar code. So I didn't work on it.
> +typedef enum PGLogState
> +{
>
> This is libpq-logging.c internal type. It is not needed to be exposed.
I fixed it.
> +extern void pqTraceForcelyBreakLine(int size, PGconn *conn);
> +extern void pqStoreFrontendMsg(PGconn *conn, PGLogMsgDataType type,
> int length)+extern void pqStoreFeMsgStart(PGconn *conn, char type);
> +extern void pqLogFrontendMsg(PGconn *conn, int msgLen);
> +extern void pqLogMessageByte1(PGconn *conn, char v);
> +extern void pqLogMessageInt(PGconn *conn, int v, int length);
> +extern void pqLogMessageString(PGconn *conn, const char *v, int length,
> +PGCommSource
> commsource);
> +extern void pqLogMessagenchar(PGconn *conn, const char *v, int length,
> + PGCommSource
> commsource);
>
> The API functions looks like randomly/inconsistently named and
> designed. I think that API should be in more structurally designed.
>
> The comments about individual function names follow.
Thank you for your advice. I changed these functions name.
>
> +/*
> + * pqTraceForcelyBreakLine:
> + * If message is not completed, print a line break and reset.
> + */
> +void
> +pqTraceForcelyBreakLine(int size, PGconn *conn)
> +{
> + fprintf(conn->Pfdebug, "\n");
> + pqTraceResetBeMsg(conn);
> +}
>
> Differently from the comment, this function doesn't work in a
> conditional way nor in a forceful way. It is just putting a new line
> and resetting the backend message variables. I would name this as
> pqTrace(Finish|Close)BeMsgLog().
This function can be used when a connection is lost or when the copyData result
is ignored according to the original code.
It is called to reset halfway logging. So I want to know that it will be forced
to
RE: libpq debug log
Hi Tsunakawa san, Alvaro san,
Thank you very much for your review. It helped me a lot to make the patch
better.
I update patch to v26.
This patch has been updated according to Tsunakawa san and Alvaro san review
comments.
The output is following;
```
2021-03-17 14:43:16.411238 > Terminate 4
2021-03-17 14:43:16.441775 > Query 155 "CREATE TABLESPACE
regress_tblspacewith LOCATION
'/home/iwata/pgsql/postgres/src/test/regress/testtablespace' WITH
(some_nonexistent_parameter = true);"
2021-03-17 14:43:16.442935 < ErrorResponse 124 S "ERROR" V "ERROR" C
"22023" M "unrecognized parameter "some_nonexistent_parameter"" F
"reloptions.c" L "1447" R "parseRelOptionsInternal" \x00 "Z"
2021-03-17 14:43:16.442977 < ReadyForQuery 5 I
2021-03-17 14:43:16.443042 > Query 144 "CREATE TABLESPACE
regress_tblspacewith LOCATION
'/home/iwata/pgsql/postgres/src/test/regress/testtablespace' WITH
(random_page_cost = 3.0);"
2021-03-17 14:43:16.444774 < CommandComplete 22 "CREATE TABLESPACE"
2021-03-17 14:43:16.444807 < ReadyForQuery 5 I
2021-03-17 14:43:16.444878 > Query 81 "SELECT spcoptions FROM
pg_tablespace WHERE spcname = 'regress_tblspacewith';"
2021-03-17 14:43:16.448117 < RowDescription 35 1 "spcoptions" 1213 5 1009
65535 -1 0
2021-03-17 14:43:16.448157 < DataRow 32 1 22 '{random_page_cost=3.0}'
2021-03-17 14:43:16.448171 < CommandComplete 13 "SELECT 1"
```
> -Original Message-
> From: Tsunakawa, Takayuki/綱川 貴之
> Sent: Tuesday, March 16, 2021 12:03 PM
> (1)
> - Enables tracing of the client/server communication to a debugging
> file stream.
> + Enables tracing of the client/server communication to a debugging file
> + stream.
> + Only available when protocol version 3 or higher is used.
>
> The last line is unnecessary now that v2 is not supported.
I removed last comment from documentation file.
> (2)
> @@ -113,6 +114,7 @@ install: all installdirs install-lib
> $(INSTALL_DATA) $(srcdir)/libpq-fe.h '$(DESTDIR)$(includedir)'
> $(INSTALL_DATA) $(srcdir)/libpq-events.h '$(DESTDIR)$(includedir)'
> $(INSTALL_DATA) $(srcdir)/libpq-int.h
> '$(DESTDIR)$(includedir_internal)'
> + $(INSTALL_DATA) $(srcdir)/libpq-trace.h
> '$(DESTDIR)$(includedir_internal)'
> $(INSTALL_DATA) $(srcdir)/pqexpbuffer.h
> '$(DESTDIR)$(includedir_internal)'
> $(INSTALL_DATA) $(srcdir)/pg_service.conf.sample
> '$(DESTDIR)$(datadir)/pg_service.conf.sample'
>
> Why is this necessary?
I think it is not necessary. I removed it.
> (3) libpq-trace.h
> +#ifdef __cplusplus
> +extern "C"
> +{
>
> This is unnecessary because pqTraceOutputMessage() is for libpq's internal
> use. This extern is for the user's C++ application to call public libpq
> functions.
>
> +#include "libpq-fe.h"
> +#include "libpq-int.h"
>
> I think these can be removed by declaring the struct and function as follows:
>
> struct pg_conn;
> extern void pqTraceOutputMessage(struct pg_conn *conn, const char
> *message, bool toServer);
>
> But... after doing the above, only this declaration is left in libpq-trace.h.
> Why
> don't you put your original declaration using PGconn in libpq-int.h and remove
> libpq-trace.h?
I remove this file.
I was wondering whether to delete this file during the development of v25
patch. I leave it because it keep scalability.
If tracing process become update and it have a lot of extern function, leave
this header file is meaningful.
However I think it does not happen. So I remove it.
> (4)
> + /* Trace message only when there is first 1 byte */
> + if (conn->Pfdebug && (conn->outCount < conn->outMsgStart))
> + pqTraceOutputMessage(conn, conn->outBuffer +
> conn->outCount, true);
>
> () surrounding the condition after && can be removed.
I removed this (). And This if () statement has been modified according to the
review comment (14).
> (5)
> +static const char *pqGetProtocolMsgType(unsigned char c,
> +
> bool toServer);
>
> This is unnecessary because the function definition precedes its only one call
> site.
Yes, I removed this definition.
> (6)
> + * We accumulate frontend message pieces in an array as the libpq code
> + writes
> + * them, and log the complete message when pqTraceOutputFeMsg is called.
> + * For backend, we print the pieces as soon as we receive them from the
> server.
>
> The first paragraph is no longer true. I think this entire comment is
> unnecessary.
I removed this explanation.
> (7)
> +static const char *
> +pqGetProtocolMsgType(unsigned char c, bool toServer) {
> + if (toServer == true &&
> + c < lengthof(protocol_message_type_f) &&
> + protocol_message_type_f[c] != NULL)
> + return protocol_message_type_f[c];
> +
> + if (toServer == false &&
> + c < lengthof(protoco
RE: libpq debug log
Hi Alvaro san and Tsunakawa san,
Thank you for your review. I updated patch to v27.
`make check` output is following. I think it is OK.
```
2021-03-18 07:02:55.090598 < ReadyForQuery 5 I
2021-03-18 07:02:55.090672 > Terminate 4
2021-03-18 07:02:55.120492 > Query 155 "CREATE TABLESPACE
regress_tblspacewith LOCATION
'/home/iwata/pgsql/postgres/src/test/regress/testtablespace' WITH
(some_nonexistent_parameter = true);"
2021-03-18 07:02:55.121624 < ErrorResponse 124 S "ERROR" V "ERROR" C
"22023" M "unrecognized parameter "some_nonexistent_parameter"" F
"reloptions.c" L "1447" R "parseRelOptionsInternal" \x00 "Z"
2021-03-18 07:02:55.121664 < ReadyForQuery 5 I
2021-03-18 07:02:55.121728 > Query 144 "CREATE TABLESPACE
regress_tblspacewith LOCATION
'/home/iwata/pgsql/postgres/src/test/regress/testtablespace' WITH
(random_page_cost = 3.0);"
2021-03-18 07:02:55.123335 < CommandComplete 22 "CREATE TABLESPACE"
2021-03-18 07:02:55.123400 < ReadyForQuery 5 I
2021-03-18 07:02:55.123460 > Query 81 "SELECT spcoptions FROM
pg_tablespace WHERE spcname = 'regress_tblspacewith';"
2021-03-18 07:02:55.126556 < RowDescription 35 1 "spcoptions" 1213 5 1009
65535 -1 0
2021-03-18 07:02:55.126594 < DataRow 32 1 22 '{random_page_cost=3.0}'
2021-03-18 07:02:55.126607 < CommandComplete 13 "SELECT 1"
2021-03-18 07:02:55.126617 < ReadyForQuery 5 I
```
> Iwata-san,
> Why don't you submit v27 patch with the current arrays kept, and then v28
> with the arrays removed soon after?
And I will try to remove byte1 type table for v28 patch.
> From: Tsunakawa, Takayuki/綱川 貴之
> Sent: Thursday, March 18, 2021 12:38 PM
> From: Alvaro Herrera
> > In pqTraceOutputString(), you can use the return value from fprintf to
> > move the cursor -- no need to count chars.
>
> Yes, precisely, 2 bytes for the double quotes needs to be subtracted as
> follows:
>
> len = fprintf(...);
> *cursor += (len - 2);
Thank you for your advice. I changed pqTraceOutputString set cursor to fprintf
return -2.
And I removed cursor movement from that function.
> From: Tsunakawa, Takayuki/綱川 貴之
> Sent: Thursday, March 18, 2021 11:52 AM
...
> I'll look at the comments from Alvaro-san and Horiguchi-san. Here are my
> review comments:
Thank you for your review. I am sorry previous patch contain some mistake.
> (23)
> + /* Trace message only when there is first 1 byte */
> + if (conn->Pfdebug && conn->outCount < conn->outMsgStart)
> + {
> + if (conn->outCount < conn->outMsgStart)
> + pqTraceOutputMessage(conn, conn->outBuffer +
> conn->outCount, true);
> + else
> + pqTraceOutputNoTypeByteMessage(conn,
> +
> conn->outBuffer + conn->outMsgStart);
> + }
>
> The inner else path doesn't seem to be reached because both the outer and
> inner if contain the same condition. I think you want to remove the second
> condition from the outer if.
Yes, I remove second condition.
> (24) pqTraceOutputNoTypeByteMessage
> + case 16:/* CancelRequest */
> + fprintf(conn->Pfdebug,
> "%s\t>\tCancelRequest\t%d", timestr, length);
> + pqTraceOutputInt32(message, &LogCursor,
> conn->Pfdebug);
> + pqTraceOutputInt32(message, &LogCursor,
> conn->Pfdebug);
> + break;
>
> Another int32 data needs to be output as follows:
>
> --
> Int32(80877102)
> The cancel request code. The value is chosen to contain 1234 in the most
> significant 16 bits, and 5678 in the least significant 16 bits. (To avoid
> confusion, this code must not be the same as any protocol version number.)
>
> Int32
> The process ID of the target backend.
>
> Int32
> The secret key for the target backend.
> --
Thank you. I read document again and I add one pqTraceOutputInt32().
> (25)
> + case 8 :/* GSSENRequest or SSLRequest */
>
> GSSENRequest -> GSSENCRequest
Thank you. I fixed.
> (26)
> +static void
> +pqTraceOutputByte1(const char *data, int *cursor, FILE *pfdebug) {
> + const char *v = data + *cursor;
> + /*
>
> +static void
> +pqTraceOutputf(const char *message, int end, FILE *f) {
> + int cursor = 0;
> + pqTraceOutputString(message, &cursor, end, f); }
>
> Put an empty line to separate the declaration part and execution part.
Thank you. I fixed this. I add space anywhere in pqTraceOutput? function.
> (27)
> + const char *message_type = "UnkownMessage";
> +
> + id = message[LogCursor++];
> +
> + memcpy(&length, message + LogCursor , 4);
> + length = (int) pg_ntoh32(length);
> + LogCursor += 4;
> + LogEn
RE: libpq debug log
Hi Horiguchi san and Tsunakawa san,
Thank you for you review.
I update patch to v28. In this patch, I removed array.
And I fixed some code according to Horiguchi san and Tsunakawa san review
comment.
> From: Tsunakawa, Takayuki/綱川 貴之
> Sent: Thursday, March 18, 2021 12:38 PM
> I sort of think so to remove the big arrays. But to minimize duplicate code,
> I
> think the code structure will look like:
>
> fprintf(timestamp, length);
> switch (type)
> {
> case '?':
> pqTraceOutput?(...);
> break;
> case '?':
> /* No message content */
> fprintf("message_type_name");
> break;
> }
>
> void
> pqTraceOutput?(...)
> {
> fprintf("message_type_name");
> print message content;
> }
The code follows above format.
And I changed .sgml documentation;
- Changed order of message length and type
- Removed byte-16 and byte-32 explanation because I removed # output in
previous patch.
Output style is following;
```
2021-03-18 08:59:36.141660 < 5 ReadyForQuery I
2021-03-18 08:59:36.141723 > 4 Terminate
2021-03-18 08:59:36.173263 > 155 Query "CREATE TABLESPACE
regress_tblspacewith LOCATION
'/home/iwata/pgsql/postgres/src/test/regress/testtablespace' WITH
(some_nonexistent_parameter = true);"
2021-03-18 08:59:36.174439 < 124 ErrorResponse S "ERROR" V "ERROR" C "22023"
M "unrecognized parameter "some_nonexistent_parameter"" F "reloptions.c" L
"1456" R "parseRelOptionsInternal" \x00 "Z"
2021-03-18 08:59:36.174483 < 5 ReadyForQuery I
2021-03-18 08:59:36.174545 > 144 Query "CREATE TABLESPACE
regress_tblspacewith LOCATION
'/home/iwata/pgsql/postgres/src/test/regress/testtablespace' WITH
(random_page_cost = 3.0);"
2021-03-18 08:59:36.176155 < 22 CommandComplete "CREATE TABLESPACE"
2021-03-18 08:59:36.176190 < 5 ReadyForQuery I
2021-03-18 08:59:36.176243 > 81 Query "SELECT spcoptions FROM pg_tablespace
WHERE spcname = 'regress_tblspacewith';"
2021-03-18 08:59:36.179286 < 35 RowDescription 1 "spcoptions" 1213 5 1009
65535 -1 0
2021-03-18 08:59:36.179326 < 32 DataRow 1 22 '{random_page_cost=3.0}'
2021-03-18 08:59:36.179339 < 13 CommandComplete "SELECT 1"
2021-03-18 08:59:36.179349 < 5 ReadyForQuery I
2021-03-18 08:59:36.179504 > 42 Query "DROP TABLESPACE
regress_tblspacewith;"
2021-03-18 08:59:36.180400 < 20 CommandComplete "DROP TABLESPACE"
2021-03-18 08:59:36.180432 < 5 ReadyForQuery I
```
> -Original Message-
> From: Kyotaro Horiguchi
> Sent: Thursday, March 18, 2021 5:30 PM
>
> At Thu, 18 Mar 2021 07:34:36 +, "tsunakawa.ta...@fujitsu.com"
> wrote in
> > From: Iwata, Aya/岩田 彩
> > > > Yes, precisely, 2 bytes for the double quotes needs to be
> > > > subtracted as
> > > > follows:
> > > >
> > > > len = fprintf(...);
> > > > *cursor += (len - 2);
> > >
> > > Thank you for your advice. I changed pqTraceOutputString set cursor
> > > to fprintf return -2.
> > > And I removed cursor movement from that function.
> >
> > Ouch, not 2 but 3, to include a single whitespace at the beginning.
> >
> > The rest looks good. I hope we're almost at the finish line.
>
> Maybe.
String is end by '\0'. So (len -2) is OK.
However it seems like mistake because fprintf output string and 3 characters.
So I added explanation here and changed (len -2) to (len -3 +1).
I think it is OK because I found similar style in ecpg code.
> > + pqTraceOutputR(const char *message, FILE *f) {
> > + int cursor = 0;
> > +
> > + pqTraceOutputInt32(message, &cursor, f);
> >
> > I don't understand the reason for spliting message and &cursor here.
> >
> > + pqTraceOutputR(const char *message, FILE *f) {
> > + char *p = message;
> > +
> > + pqTraceOutputInt32(&p, f);
> >
> > works well.
>
> Yes, that would also work. But I like the separate cursor + fixed starting
> point here, probably because it's sometimes confusing to see the pointer
> value changed inside functions. (And a pointer itself is an allergy for some
> people, not to mention a pointer to ointer...) Also, libpq uses cursors for
> network I/O buffers. So, I think the patch can be as it is now.
I think pass message and cursor is better. Because it is easy to understand and
The moving cursor style is used when libpq execute protocol message.
So I didn't make this change.
> +/* RowDescription */
> +static void
> +pqTraceOutputT(const char *message, int end, FILE *f) {
> + int cursor = 0;
> + int nfields;
> + int i;
> +
> + nfields = pqTraceOutputInt16(message, &cursor, f);
> +
> + for (i = 0; i < nf
RE: libpq debug log
Hi Tsunakawa san,
Thank you for your review. I update patch to v29.
Output is following. It is fine.
```
2021-03-19 07:21:09.917302 > 4 Terminate
2021-03-19 07:21:09.961494 > 155 Query"CREATE TABLESPACE
regress_tblspacewith LOCATION
'/home/iwata/pgsql/postgres/src/test/regress/testtablespace' WITH
(some_nonexistent_parameter = true);"
2021-03-19 07:21:09.962657 < 124 ErrorResponseS "ERROR" V "ERROR" C
"22023" M "unrecognized parameter "some_nonexistent_parameter"" F
"reloptions.c" L "1456" R "parseRelOptionsInternal" \x00 "Z"
2021-03-19 07:21:09.962702 < 5 ReadyForQueryI
2021-03-19 07:21:09.962767 > 144 Query"CREATE TABLESPACE
regress_tblspacewith LOCATION
'/home/iwata/pgsql/postgres/src/test/regress/testtablespace' WITH
(random_page_cost = 3.0);"
2021-03-19 07:21:09.967056 < 22 CommandComplete "CREATE TABLESPACE"
2021-03-19 07:21:09.967092 < 5 ReadyForQueryI
2021-03-19 07:21:09.967148 > 81 Query"SELECT spcoptions FROM
pg_tablespace WHERE spcname = 'regress_tblspacewith';"
2021-03-19 07:21:09.970338 < 35 RowDescription 1 "spcoptions" 1213 5 1009
65535 -1 0
2021-03-19 07:21:09.970402 < 32 DataRow 1 22 '{random_page_cost=3.0}'
2021-03-19 07:21:09.970420 < 13 CommandComplete "SELECT 1"
2021-03-19 07:21:09.970431 < 5 ReadyForQueryI
2021-03-19 07:21:09.970558 > 42 Query"DROP TABLESPACE
regress_tblspacewith;"
2021-03-19 07:21:09.971500 < 20 CommandComplete "DROP TABLESPACE"
2021-03-19 07:21:09.971561 < 5 ReadyForQueryI
```
> -Original Message-
> From: Tsunakawa, Takayuki/綱川 貴之
> Sent: Friday, March 19, 2021 11:37 AM
> Thanks to removing the static arrays, the code got much smaller. I'm happy
> with this result.
Thank you so much. Your advice was very helpful in refactoring the patch.
> (1)
> + (> for messages from client to server,
> + and < for messages from server to client),
>
> I think this was meant to say "> or <". So, maybe you should remove "," at
> the end of the first line, and replace "and" with "or".
I fixed.
>
>
> (2)
> + case 8 :/* GSSENCRequest or SSLRequest */
> + /* These messsage does not reach here. */
>
> messsage does -> messages do
I fixed.
> (3)
> + fprintf(f, "\tAuthentication");
>
> Why don't you move this \t in each message type to the end of:
>
> + fprintf(conn->Pfdebug, "%s\t%s\t%d", timestr, prefix, length);
I fixed.
>
> Plus, don't we say in the manual that fields (timestamp, direction, length,
> message type, and message content) are separated by a tab?
Sure. I added following documentation;
+ Non-message contents fields (timestamp, direction, length and message type)
+ are separated by a tab. Message contents are separated by a space.
> Also, the code doesn't seem to separate the message type and content with a
> tab.
I fixed to output a tab at the end of message types.
> (4)
> Where did the processing for unknown message go in
> pqTraceOutputMessage()? Add default label?
> (5)
> + case 16:/* CancelRequest */
> + fprintf(conn->Pfdebug,
> "%s\t>\t%d\tCancelRequest", timestr, length);
>
> I think this should follow pqTraceOutputMessage(). That is, each case label
> only print the message type name in case other message types are added in
> the future.
Sure. I fixed pqTraceOutputNoTypeByteMessage() following to
pqTraceOutputMessage() style.
Regards,
Aya Iwata
v29-libpq-trace-log.patch
Description: v29-libpq-trace-log.patch
RE: libpq debug log
Hi Alvaro san, Tsunakawa san Thank you for creating the v30 patch. > From: Tsunakawa, Takayuki/綱川 貴之 > Sent: Monday, March 29, 2021 9:45 AM ... > Iwata-san, > Please review Alvaro-san's code, and I think you can integrate all patches > into > one except for 0002 and 0007. Those two patches may be separate or > merged into one as a test patch. I reviewed v30 patches. I think it was good except that the documentation about the direction of the message was not changing. I also tried the v30 patch using regression test and it worked fine. I merged v30 patches and update the patch to v31. This new version patch includes the fix of libpq.smgl fix and the addition of regression test mode. In libpq.smgl, the symbol indicating the message direction has been corrected from "<" ">" to "B" "F" in the documentation. > From: alvhe...@alvh.no-ip.org > Sent: Sunday, March 28, 2021 4:28 AM ... > Maybe the easiest way is to have a new flag PQTRACE_REGRESS_MODE. To prepare for regression test, I read Message Formats documentation. https://www.postgresql.org/docs/current/protocol-message-formats.html Following protocol messages have values that depend on the code of master at that time; - BackendKeyData(B) ... includes backend PID and backend private key - ErrorResponse(B) ... includes error message line number - FunctionCall(F) ... includes function OID - NoticeResponse(B) ... includes notice message line number - NotificationResponse (B) ... includes backend PID - ParameterDescription ... includes parameter OID - Parse(F) ... includes parameter data type OID - RowDescription(B) ... includes OIDs I checked status of conn->pqTraceFlags to decide whether output version-dependent messages or not in above protocol message output functions. In ErrorResponse and NoticeResponse, I skip string type message logging only when field type code is "L". In my understanding, other field code message type does not depend on version. So I didn't skip other code type's string messages. And I also changed description of pqTraceSetFlags() by changing PQTRACE_SUPPRESS_TIMESTAMPS flag to the PQTRACE_REGRESS_MODE flag. Output of regress mode is following; B 124 ErrorResponseS "ERROR" V "ERROR" C "22023" M "unrecognized parameter "some_nonexistent_parameter"" F "reloptions.c" L R "parseRelOptionsInternal" \x00 B 14 ParameterDescription 2 Output of non-regress mode is following; 2021-03-30 12:55:31.327913 B 124 ErrorResponseS "ERROR" V "ERROR" C "22023" M "unrecognized parameter "some_nonexistent_parameter"" F "reloptions.c" L "1447" R "parseRelOptionsInternal" \x00 2021-03-30 12:56:12.691617 B 14 ParameterDescription 2 25 701 Regards, Aya Iwata v31-libpq-trace-log.patch Description: v31-libpq-trace-log.patch
RE: libpq debug log
Hi Alvaro san Thank you for your fix of trace log code. > From: 'alvhe...@alvh.no-ip.org' > Sent: Friday, April 2, 2021 11:30 AM ... > It still didn't fix it! Drongo is now reporting a difference in the expected > trace -- > and the differences all seem to be message lengths. > Now that is pretty mysterious, because the messages themselves are printed > identically. Perl's output is pretty unhelpful, but I wrote them to a file > and diffed > manually; it's attached. Do ErrorResponse and NoticeResponse vary from test to test ...? If so, it seemed difficult to make the trace logs available for regression test. I will also investigate the cause of this issue. Regards, Aya Iwata
RE: libpq debug log
Hello,
Thank you for your review.
I update patch. Please find attached my patch.
> > 2019-04-04 02:39:51.488 UTC > Query 59 "SELECT
> pg_catalog.set_config('search_path', '', false)"
>
> The "59" there seems quite odd, though.
Could you explain more detail about this?
"59" is length of protocol message contents. (It does not contain first 1
byte.)
This order is based on the message format.
https://www.postgresql.org/docs/current/protocol-message-formats.html
> * What is this in pg_conn? I don't understand why this array is of size
> MAXPGPATH.
> + PGFrontendLogMsgEntry frontend_entry[MAXPGPATH];
> This seems to make pg_conn much larger than we'd like.
Sure. I remove this and change code to use list.
> Minor review points:
I accept all these review points.
Regards,
Aya Iwata
v7-libpq-PQtrace-output-one-line.patch
Description: v7-libpq-PQtrace-output-one-line.patch
RE: libpq debug log
Hi Alvaro san,
Thank you for your update :)
> 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:
I check code, changes and email. I agree with all of this.
I will review code, feature and performance if it is needed more closely.
(I'll start it next week.)
Regards,
Aya Iwata
> -Original Message-
> From: Alvaro Herrera
> Sent: Thursday, September 17, 2020 5:42 AM
> To: Iwata, Aya/岩田 彩
> Cc: pgsql-hack...@postgresql.org; t...@sss.pgh.pa.us;
> robertmh...@gmail.com; pchamp...@pivotal.io; jd...@pivotal.io;
> raam.s...@gmail.com; Nagaura, Ryohei/永浦 良平
> ; nag...@sraoss.co.jp;
> peter.eisentr...@2ndquadrant.com; 'Kyotaro HORIGUCHI'
> ; Jamison, Kirk/ジャミソン カーク
>
> Subject: Re: libpq debug log
>
> 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 Herrerahttps://www.2ndQuadrant.com/
> PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
