Re: libpq debug log

Hi,

I'm going to propose libpq debug log for analysis of queries on the application side.
I think that it is useful to determine whether the cause is on the application side or the server side when a slow query occurs.

The provided information is "date and time" at which execution of processing is started, "query", "application side processing", which is picked up information from PQtrace(), and "connection id", which is for uniquely identifying the connection.

To collect the log, set the connection string or environment variable.
- logdir or PGLOGDIR : directory where log file written
- logsize or PGLOGSIZE : maximum log size

What do you think about this? Do you think that such feature is necessary?

Regards,
Aya Iwata

"Iwata, Aya" <iwata(dot)aya(at)jp(dot)fujitsu(dot)com> writes:
> I'm going to propose libpq debug log for analysis of queries on the application side.
> I think that it is useful to determine whether the cause is on the application side or the server side when a slow query occurs.

Hm, how will you tell that really? And what's the advantage over the
existing server-side query logging capability?

> The provided information is "date and time" at which execution of processing is started, "query", "application side processing", which is picked up information from PQtrace(), and "connection id", which is for uniquely identifying the connection.

PQtrace() is utterly useless for anything except debugging libpq
internals, and it's not tremendously useful even for that. Don't
bother with that part.

Where will you get a "unique connection id" from?

How will you deal with asynchronously-executed queries --- either
the PQgetResult style, or the single-row-at-a-time style?

regards, tom lane

On Fri, 24 Aug 2018 04:38:22 +0000
"Iwata, Aya" <iwata(dot)aya(at)jp(dot)fujitsu(dot)com> wrote:

> Hi,
>
> I'm going to propose libpq debug log for analysis of queries on the application side.
> I think that it is useful to determine whether the cause is on the application side or the server side when a slow query occurs.

Do you mean you want to monitor the protocol message exchange at
the client side to analyze performance issues, right? Actually,
this might be useful to determin where is the problem, for example,
the client application, the backend PostgreSQL, or somewhere in the
network.

Such logging can be implemented in the application, but if libpq
provides the standard way, it would be helpful to resolve a problem
without modifying the application code.

> The provided information is "date and time" at which execution of processing is started, "query", "application side processing", which is picked up information from PQtrace(), and "connection id", which is for uniquely identifying the connection.

I couldn't image how this is like. Could you show us a sample of log lines
in your head?

> To collect the log, set the connection string or environment variable.
> - logdir or PGLOGDIR : directory where log file written
> - logsize or PGLOGSIZE : maximum log size

How we can specify the log file name? What should happen if a file size
exceeds to PGLOGSIZE?

Regards,
--
Yugo Nagata <nagata(at)sraoss(dot)co(dot)jp>

On Fri, Aug 24, 2018 at 9:48 AM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> PQtrace() is utterly useless for anything except debugging libpq
> internals, and it's not tremendously useful even for that. Don't
> bother with that part.

I think that improving the output format could help with that a lot.
What it current produces is almost unreadable; adjusting it to emit
one line per protocol message would, I think, help a lot. There are
probably other improvements that could be made at the same time.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> On Fri, Aug 24, 2018 at 9:48 AM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>> PQtrace() is utterly useless for anything except debugging libpq
>> internals, and it's not tremendously useful even for that. Don't
>> bother with that part.

> I think that improving the output format could help with that a lot.
> What it current produces is almost unreadable; adjusting it to emit
> one line per protocol message would, I think, help a lot. There are
> probably other improvements that could be made at the same time.

I wouldn't mind throwing it out and reimplementing it ;-) ... tracing
at the logical message level rather than the byte level would help.
But still, I'm not really convinced that it has very much to do with
what you'd want in a user-level debug log.

Part of what's really bad about the PQtrace output is that in v2 protocol
the same output can be repeated several times as we try to parse a message
and conclude we don't have it all yet. I believe that problem is gone
in v3, but it may be hard to do a consistent redesign until we nuke libpq's
v2 support. Still, it might be past time for the latter, seeing that
we no longer promise pre-7.4 compatibility in either psql or pg_dump.

regards, tom lane

> "Iwata, Aya" <iwata(dot)aya(at)jp(dot)fujitsu(dot)com> writes:
> > I'm going to propose libpq debug log for analysis of queries on the application
> side.
> > I think that it is useful to determine whether the cause is on the application
> side or the server side when a slow query occurs.
>
> Hm, how will you tell that really? And what's the advantage over the existing
> server-side query logging capability?

The log I would like to propose is used when the performance issue happen,
system administrator knows the process of application internally and check if there is any problem.
"debug" is not the correct description of the feature. The correct one should be "trace". Should I create another thread?

> > The provided information is "date and time" at which execution of processing
> is started, "query", "application side processing", which is picked up
> information from PQtrace(), and "connection id", which is for uniquely
> identifying the connection.
>
> PQtrace() is utterly useless for anything except debugging libpq internals,
> and it's not tremendously useful even for that. Don't bother with that part.

My initial intention was to get only useful information from PQTrace () since it acquires a lot of information.
Is there another way to obtain application side information besides PQTrace() ?

> Where will you get a "unique connection id" from?

When collecting trace log file in the application side,
I think it is necessary to identify different connection.
In order to do this, when new empty PQconn structure is created, new connection id is also created.
Then we output it in the trace log file for one application.

> How will you deal with asynchronously-executed queries --- either the
> PQgetResult style, or the single-row-at-a-time style?

In my understanding, PQgetResult style outputs logs of multiple result queries at once,
While the single-row-at-a-time style outputs log for each query. Is this correct?
I think PQgetResult style is better,
because this style traces the internal process of the application.

Regards,
Aya Iwata

> > I'm going to propose libpq debug log for analysis of queries on the application
> side.
> > I think that it is useful to determine whether the cause is on the application
> side or the server side when a slow query occurs.
>
> Do you mean you want to monitor the protocol message exchange at the client
> side to analyze performance issues, right? Actually, this might be useful to
> determin where is the problem, for example, the client application, the backend
> PostgreSQL, or somewhere in the network.
>
> Such logging can be implemented in the application, but if libpq provides the
> standard way, it would be helpful to resolve a problem without modifying the
> application code.

Since I'd like to monitor the information the server and the client exchange,
I think monitoring protocol messages is good.

When a slow query is occurs, we check this client side trace log.
The purpose of this log acquisition I thought is to identify where is the problem:
server side, application side or traffic.
And if the problem is in application side, checking the trace log to identify what is the problem.

> > The provided information is "date and time" at which execution of processing
> is started, "query", "application side processing", which is picked up
> information from PQtrace(), and "connection id", which is for uniquely
> identifying the connection.
>
> I couldn't image how this is like. Could you show us a sample of log lines in
> your head?

I am roughly thinking as follows;

...
START : 2018/09/03 18:16:35.357 CONNECTION(1)
STATUS : Connection
SEND MESSAGE : 2018/09/03 18:16:35.358
<information send to backend...>
RECEIVE MESSAGE : 2018/09/03 18:16:35.359
<information receive from backend...>
END : 2018/09/03 18:16:35.360
...
START : 2018/09/03 18:16:35.357 CONNECTION(1)
QUERY : DECLARE myportal CURSOR FOR select * from pg_database
SEND MESSAGE : 2018/09/03 18:16:35.358
<information send to backend...>
RECEIVE MESSAGE : 2018/09/03 18:16:35.359
<information receive from backend...>
END : 2018/09/03 18:16:35.360
...

> > To collect the log, set the connection string or environment variable.
> > - logdir or PGLOGDIR : directory where log file written
> > - logsize or PGLOGSIZE : maximum log size
>
> How we can specify the log file name? What should happen if a file size exceeds
> to PGLOGSIZE?

The log file name is determined as follow.
libpq-%ApplicationName-%Y-%m-%d_%H%M%S.log

When the log file size exceeds to PGLOGSIZE, the log is output to another file.

Regards,
Aya Iwata

"Iwata, Aya" <iwata(dot)aya(at)jp(dot)fujitsu(dot)com> writes:
> The purpose of this log acquisition I thought is to identify where is the problem:
> server side, application side or traffic.

TBH, I think the sort of logging you're proposing would be expensive
enough that *it* would be the bottleneck in a lot of cases. A lot
of people find that the existing server-side "log_statement" support
is too expensive to keep turned on in production --- and that logs only
received SQL queries, not the returned data, and certainly not every
message passed over the wire.

regards, tom lane

On 04/09/2018 02:29, Iwata, Aya wrote:
> Since I'd like to monitor the information the server and the client exchange,
> I think monitoring protocol messages is good.
>
> When a slow query is occurs, we check this client side trace log.
> The purpose of this log acquisition I thought is to identify where is the problem:
> server side, application side or traffic.
> And if the problem is in application side, checking the trace log to identify what is the problem.

Between perf/systemtap/dtrace and wireshark, you can already do pretty
much all of that. Have you looked at those and found anything missing?

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Let me explain this trace log in a bit more detail.

This log is not turned on in the system by default.
Turn it on when an issue occurs and you want to check the information in the application in order to clarify the cause.

I will present three use cases for this log.

1. Confirmation on cause of out-of-memory
We assume that Out-of-memory occurred in the process of storing the data received from the database.
However, the contents or length of the data is not known.
A trace log is obtained to find these out and what kind of data you have in which part (i.e. query result when receiving from database).

2. Protocol error confirmation
When there is an error in the protocol transmitted from the client and an error occurs in the database server, the protocol sent by the client is checked.
When the network is unstable, log is checked whether the database server is receiving protocol messages.

3. Processing delay survey
If the processing in the application is slow and the processing in the database is fast, investigate the cause of the processing delay.
4 kind of time can be obtained by the log;

Timestamp when SQL started
Timestamp when information began to be sent to the backend
Timestamp when information is successfully received in the application
Timestamp when SQL ended

Then the difference between the time is checked to find out which part of process takes time.

I reconfirm the function I proposed.

If get the trace log, set PGLOGDIR/logdir and PGLOGSIZE/logsize.
These parameters are set in the environment variable or the connection service file.
- logdir or PGLOGDIR : directory where log file written
- logsize or PGLOGSIZE : maximum log size. When the log file size exceeds to PGLOGSIZE, the log is output to another file.

The log file name is determined as follow.
libpq-%ConnectionID-%Y-%m-%d_%H%M%S.log

This is a trace log example;

...
Start: 2018-09-03 18:16:35.357 Connection(1)
Status: Connection
Send message: 2018-09-03 18:16:35.358
<information send to backend...>
Receive message: 2018-09-03 18:16:35.359
<information receive from backend...>
End: 2018-09-03 18:16:35.360
...
Start: 2018-09-03 18:16:35.357 Connection(1) ...(1), (2)
Query: DECLARE myportal CURSOR FOR select * from pg_database ...(3)
Send message: 2018-09-03 18:16:35.358 ...(4)
<information send to backend...> ...(5)
Receive message: 2018/09/03 18:16:35.359 ...(6)
<information receive from backend...> ...(7)
End: 2018-09-03 18:16:35.360 ...(8)
...

(1) Timestamp when SQL started
(2) Connection ID (Identify the connection)
(3) SQL statement
(4) Timestamp when information began to be sent to the backend
(5) send message to backend (Result of query, Protocol messages)
(6) Timestamp when information is successfully received in the application
(7) receive message from backend (Result of query, Protocol messages)
(8) Timestamp when SQL ended

Regards,
Iwata Aya

Hi,

Sorry for my late response.

> Between perf/systemtap/dtrace and wireshark, you can already do pretty much
> all of that. Have you looked at those and found anything missing?

These commands provide detailed information to us.
However, I think the trace log is necessary from the following point.

1. ease of use for users
It is necessary to take information that is easy to understand for database users.
This trace log is retrieved on the application server side.
Not only the database developer but also application developer will get and check this log.
Also, some of these commands return detailed PostgreSQL function names.
The trace log would be useful for users who do not know the inside of PostgreSQL (e.g. application developers)

2. obtain the same information on all OS
Some commands depend on the OS.
I think that it is important that the trace log information is compatible to each OS.

Regards,
Aya Iwata

Hi,

I create a first libpq trace log patch.

In this patch,
- All message that PQtrace() gets are output to the libpq trace log file
(I maybe select more effective message in the future patch)
- Trace log output style is changed slightly from previously proposed

This patch not include documentation,
but you can see parameter detail and how to use it by looking at my previous e-mail.

If get the trace log, set PGLOGDIR/logdir and PGLOGSIZE/logsize.
These parameters are set in the environment variable or the connection service
file.
- logdir or PGLOGDIR : directory where log file written
- logsize or PGLOGSIZE : maximum log size(M). When the log file size exceeds to
PGLOGSIZE, the log is output to another file.

The log file name is determined as follow.
libpq-%ProcessID-%Y-%m-%d_%H%M%S.log

Trace log example;
Start : 2018/10/30 08:02:24.433 ... time(a)
Query: SELECT pg_catalog.set_config('search_path', '', false)
To backend> Msg Q
To backend> "SELECT pg_catalog.set_config('search_path', '', false)"
To backend> Msg complete, length 60
Start sending message to backend: 2018/10/30 08:02:24.433 ... time(b)
End sending message to backend: 2018/10/30 08:02:24.433 ... time(c)
Start receiving message from backend: 2018/10/30 08:02:24.434 ... time(d)
End receiving message from backend: 2018/10/30 08:02:24.434 ... time(e)
From backend> T
From backend (#4)> 35
From backend (#2)> 1
From backend> "set_config"
From backend (#4)> 0
From backend (#2)> 0
From backend (#4)> 25
From backend (#2)> 65535
From backend (#4)> -1
From backend (#2)> 0
From backend> D
From backend (#4)> 10
From backend (#2)> 1
From backend (#4)> 0
From backend> C
From backend (#4)> 13
From backend> "SELECT 1"
From backend> Z
From backend (#4)> 5
From backend> Z
From backend (#4)> 5
From backend> I
End : 2018/10/30 08:02:24.435 ... time(f)

From time(a) to time(b): time for libpq processing
From time(b) to time(c): time for traffic
From time(c) to time(d): time for backend processing
From time(d) to time(e): time for traffic
From time(e) to time(f): time for libpq processing

Regards,
Aya Iwata

Greetings,

This is my first attempt at a patch review, so I will take a pass at the
low hanging fruit.

Initial Pass
============

+ Patch applies
+ Patch builds
+ Patch behaves as described in the thread

I tried a few small things:

When I set a relative path for `PGLOGDIR`, the files were correctly
written to the directory.

When I set a path for `PGLOGDIR` that didn't exist or was not
write-able, the patch writes no files, and does not alert the user that
no files are being written.

Performance
===========

I ran two permutations of make check, one with the patch applied but not
activated, and the other with with the files being written to disk. Each
permutation was run ten times, and the stats are below (times are in
seconds):

min max median mean
not logging 50.4 57.6 53.3 53.4
logging 58.3 77.7 65.0 65.8

Cheers,
Jim Doty

On Tue, Oct 30, 2018 at 2:39 AM Iwata, Aya <iwata(dot)aya(at)jp(dot)fujitsu(dot)com> wrote:
> I create a first libpq trace log patch.

Couple additional thoughts from a read-through of the patch:

- PQtrace() and the new trace-logging machinery overlap in some places
but not others -- and if both are set, PQtrace() will take precedence.
It seems like the two should not be separate.
- It isn't immediately clear to me how the new information in the logs
is intended to be used in concert with the old information. Maybe this
goes back to the comments by Tom and Robert higher in the thread --
that an overhaul of the PQtrace system is due. This patch as presented
would make things a little worse before they got better, I think.

That said, I think the overall idea -- application performance
information that can be enabled via the environment, without requiring
debugging privileges on a machine or the need to manually correlate
traces made by other applications -- is a good one, and something I
would use.

--Jacob

On Tue, Oct 30, 2018 at 8:38 PM Iwata, Aya <iwata(dot)aya(at)jp(dot)fujitsu(dot)com> wrote:

> Hi,
>
> I create a first libpq trace log patch.
>
> In this patch,
> - All message that PQtrace() gets are output to the libpq trace log file
> (I maybe select more effective message in the future patch)
> - Trace log output style is changed slightly from previously proposed
>
> This patch not include documentation,
> but you can see parameter detail and how to use it by looking at my
> previous e-mail.
>
> If get the trace log, set PGLOGDIR/logdir and PGLOGSIZE/logsize.
> These parameters are set in the environment variable or the connection
> service
> file.
> - logdir or PGLOGDIR : directory where log file written
> - logsize or PGLOGSIZE : maximum log size(M). When the log file size
> exceeds to
> PGLOGSIZE, the log is output to another file.
>
> The log file name is determined as follow.
> libpq-%ProcessID-%Y-%m-%d_%H%M%S.log
>
> Trace log example;
> Start : 2018/10/30 08:02:24.433
> ... time(a)
> Query: SELECT pg_catalog.set_config('search_path', '', false)
> To backend> Msg Q
> To backend> "SELECT pg_catalog.set_config('search_path', '', false)"
> To backend> Msg complete, length 60
> Start sending message to backend: 2018/10/30 08:02:24.433
> ... time(b)
> End sending message to backend: 2018/10/30 08:02:24.433
> ... time(c)
> Start receiving message from backend: 2018/10/30 08:02:24.434 ... time(d)
> End receiving message from backend: 2018/10/30 08:02:24.434 ... time(e)
> From backend> T
> From backend (#4)> 35
> From backend (#2)> 1
> From backend> "set_config"
> From backend (#4)> 0
> From backend (#2)> 0
> From backend (#4)> 25
> From backend (#2)> 65535
> From backend (#4)> -1
> From backend (#2)> 0
> From backend> D
> From backend (#4)> 10
> From backend (#2)> 1
> From backend (#4)> 0
> From backend> C
> From backend (#4)> 13
> From backend> "SELECT 1"
> From backend> Z
> From backend (#4)> 5
> From backend> Z
> From backend (#4)> 5
> From backend> I
> End : 2018/10/30 08:02:24.435 ... time(f)
>
> From time(a) to time(b): time for libpq processing
> From time(b) to time(c): time for traffic
> From time(c) to time(d): time for backend processing
> From time(d) to time(e): time for traffic
> From time(e) to time(f): time for libpq processing
>

Thanks for the patch.

I have some comments related to the trace output that is getting
printed. The amount of log it is generating may not be understood
to many of the application developers. IMO, this should print
only the necessary information that can understood by any one
by default and full log with more configuration?

Regards,
Haribabu Kommi
Fujitsu Australia

Hi Jim Doty san,

Thank you for review! I'm sorry my late reply...

> Initial Pass
> ============
>
> + Patch applies
> + Patch builds
> + Patch behaves as described in the thread
Thank you for your check.

> When I set a path for `PGLOGDIR` that didn't exist or was not write-able,
> the patch writes no files, and does not alert the user that no files are being
> written.
I understand. I think it means that it is necessary to confirm how the setting is going well.
There is no warning method when connection string or the environment variable is wrong.

So I added following document:
+ If the setting of the file path by the connection string or the environment variable is
+ incorrect, the log file is not created in the intended location.
+ The maximum log file size you set is output to the beginning of the file, so you can check it.
And I added the process. Please see my v2 patch.

> Performance
> ===========
>
> I ran two permutations of make check, one with the patch applied but not
> activated, and the other with with the files being written to disk. Each
> permutation was run ten times, and the stats are below (times are in
> seconds):
>
> min max median mean
> not logging 50.4 57.6 53.3 53.4
> logging 58.3 77.7 65.0 65.8
Thank you for your measurement.
I'm thinking about adding a logging level so that only the necessary information can be printed by default. It was pointed out by Haribabu san's e-mail.
This minimizes the impact of logging on performance.

Regards,
Aya Iwata

Hi Hari san,

Thank you for your comment! And sorry my late reply…

>I have some comments related to the trace output that is getting
>printed. The amount of log it is generating may not be understood
>to many of the application developers. IMO, this should print
>only the necessary information that can understood by any one
>by default and full log with more configuration?

I understand. And I agree your opinion.
I will add feature called “log level” that changes the amount of log output information with my future version patch.

Regards,
Aya Iwata

Hi Jacob san,

Thank you for your comment! And sorry for late reply...

> Couple additional thoughts from a read-through of the patch:
>
> - PQtrace() and the new trace-logging machinery overlap in some places but
> not others -- and if both are set, PQtrace() will take precedence.
> It seems like the two should not be separate.
I understand. This log is acquired for the purpose of investigating the cause part (server side or application side) when performance is bad.
So I will search whether getting other place of PQtrace() is necessary or not.
And I will reply after the research, please wait for a while a little.

> - It isn't immediately clear to me how the new information in the logs is
> intended to be used in concert with the old information. Maybe this goes back
> to the comments by Tom and Robert higher in the thread -- that an overhaul
> of the PQtrace system is due. This patch as presented would make things a
> little worse before they got better, I think.
>
> That said, I think the overall idea -- application performance information
> that can be enabled via the environment, without requiring debugging
> privileges on a machine or the need to manually correlate traces made by other
> applications -- is a good one, and something I would use.
Thank you. I think so, too. Some applications cannot be stopped to add the PQtrace() code.

Regards,
Aya Iwata

Hi,

I created a new version patch. Please find attached my patch.

Changes:
Since v2 patch
I forgot to write the detail of v2 patch changes. So I write these.
- Fixed the " Start receiving message from backend:" message location. Because I found that message located at outside of "retry4".
- Changed location where output "start :" / "end :" messages and timestamp.　The reason of the change is that v1 patch did not correspond to Asynchronous Command Processing.
- Added documentation
- Added documentation how to check mistake of logdir and/or logsize. (Based on review comment of Jim san's)
Since v3 patch
- Fixed my mistake on fe-connect.c. Time and message were output at the place where does not output in originally PQtrace(). These messages are needed only new trace log. So I fixed it.
- Fixed two points so that new trace log overlaps all places in PQtrace(). (Based on review comment of Jacob san's)

TODO:
I will add the feature called "logging level" on next version patch. I will attach it as soon as possible.

I'm marking it as "Needs review".

Regards,
Aya Iwata

On 27/11/2018 08:42, Iwata, Aya wrote:
> I created a new version patch. Please find attached my patch.

This does not excite me. It seems mostly redundant with using tcpdump.

If I were to debug networking problems, I wouldn't even trust this very
much because it relies on the willpower of all future PostgreSQL
developers to keep this accurately up to date, whereas tcpdump gives me
the truth from the kernel.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Hi Peter,

Thank you for your reply!

> On 27/11/2018 08:42, Iwata, Aya wrote:
> > I created a new version patch. Please find attached my patch.
>
> This does not excite me. It seems mostly redundant with using tcpdump.
I will develop "log level". I'm planning not to output redundant message at the default level.

> If I were to debug networking problems, I wouldn't even trust this very much
> because it relies on the willpower of all future PostgreSQL developers to
> keep this accurately up to date, whereas tcpdump gives me the truth from the
> kernel.
I agree your concern about log trusty. It would be a good choice for only
skilled users to use tcpdump. I think libpq trace log will be used many users,
it includes users who not familiar with PostgreSQL protocols. The log would be easier to use
because it shows "start time" and "end time". On tcpdump also shows
the starting time and ending time but people need to know PostgreSQL protocol
to get them.

And this log also is useful for Windows users.
Windows does not have originally networking trace tool.

If you have any ideas about maintain this feature, I would like to know it.

Regards,
Aya Iwata

Hi,

> TODO:
> I will add the feature called "logging level" on next version patch. I will
> attach it as soon as possible.
I created v4 patch. Please find attached the patch.
This patch developed "logminlevel" parameter. level1 and level2 can be set, level1 is the default.
If level1 is set, it outputs the time in the functions. It helps to find out where it takes time.
If level2 is set, it outputs information on the protocol being exchanged in addition to level1 information.

I would appreciate if you could review my latest patch.

Regards,
Aya Iwata

Hi,

I created v5 patch. Please find attached the patch.

This patch updated following items;
- Changed "else if" to "if" in traceLog_fprintf(). This means that both PQtrace() and new trace log are set, you can get both log result.
- Implemented loglevel with enum. This change makes it easier if you want to add new log levels.
- Checked http://commitfest.cputube.org/, I modified the code slightly.

I would appreciate if you could review my latest patch.

Regards,
Aya Iwata

Hi,

I have developed a new libpq trace logging aimed at checking which side (server or client) is causing the performance issue.

The new libpq trace log can do the following things;
- Setting whether to get log or not by using connection strings or environment variables. It means that application source code changes is not needed to get the log.
- Getting time when receive and send process start/end. Functions too.
- Setting log level; When level1(default) is set, it outputs the time in the function and connection time. When level2 is set, it outputs information on the protocol message being exchanged, in addition to level1 information.

I updated patch, but I am not sure if these changes and implementation are correct or not. So I need your comment and advice.
I would appreciate your advice and develop/fix my patch further.

Regards,
Aya Iwata

Hi Iwata-san,

I used your patch for my private work, so I write my opinion and four feedback below.
On Fri, Jan 18, 2019 at 8:19 AM, Iwata, Aya wrote:
> - Setting whether to get log or not by using connection strings or environment
> variables. It means that application source code changes is not needed to get
> the log.
> - Getting time when receive and send process start/end. Functions too.
This merit was very helpful for my use, so I want your proposal function in postgres.

The followings are feedback from me.

1)
It would be better making the log format the same as the server log format, I think.
Your log format:
2019/01/22 04:15:25.496 ...
Server log format:
2019-01-22 04:15:25.496 UTC ...
There are two differences:
One is separator character of date, "/" and "-".
The another is standard time information.

2)
It was difficult for me to understand the first line message in the log file.
"Max log size is 10B, log min level is LEVEL1"
Does this mean as follows?
"The maximum size of this file is 10 Bytes, the parameter 'log min level' is set to LEVEL 1."

3)
Under the circumstance that the environment variables "PGLOGDIR" and "PGLOGSIZE" are set correctly,
the log file will also be created when the user connect the server with "psql".
Does this follow the specification you have thought?
Is there any option to unset only in that session when you want to connect with "psql"?

4)
Your patch affects the behavior of PQtrace().
The log of the existing PQtrace() is as follows:
From backend> "id"
From backend (#4)> 16387
From backend (#2)> 1
From backend (#4)> 23
...
Your patch makes PQtrace() including the following log in addition to the above.
To backend> Msg complete, length 27
Start sending message to backend:End sending message to backend:PQsendQuery end :PQgetResult start :Start receiving message from backend:End receiving message from backend:From backend> T
...

For your information.
Best regards,
---------------------
Ryohei Nagaura

Hi,

On 2018-11-28 23:20:03 +0100, Peter Eisentraut wrote:
> This does not excite me. It seems mostly redundant with using tcpdump.

I think the one counter-argument to this is that using tcpdump in
real-world scenarios has become quite hard, due to encryption. Even with
access to the private key you cannot decrypt the stream. Wonder if the
solution to that would be an option to write out the decrypted data into
a .pcap or such.

Greetings,

Andres Freund

On Thu, Feb 14, 2019 at 10:17 AM Andres Freund <andres(at)anarazel(dot)de> wrote:
> On 2018-11-28 23:20:03 +0100, Peter Eisentraut wrote:
> > This does not excite me. It seems mostly redundant with using tcpdump.
>
> I think the one counter-argument to this is that using tcpdump in
> real-world scenarios has become quite hard, due to encryption.

+1. Another difficulty is having the OS permissions to do the raw
packet dumps in the first place.

--Jacob

On February 14, 2019 6:16 PM +0000, Andres Freund wrote:

> Hi,

> On 2018-11-28 23:20:03 +0100, Peter Eisentraut wrote:
> > This does not excite me. It seems mostly redundant with using tcpdump.

> I think the one counter-argument to this is that using tcpdump in real-world
> scenarios has become quite hard, due to encryption. Even with access to the
> private key you cannot decrypt the stream. Wonder if the solution to that
> would be an option to write out the decrypted data into a .pcap or such.

I agree that network debug trace logs would be useful for users not knowledgeable
of postgres internals, so I understand the value of the feature,
as long as only necessary/digestible information is outputted.
I'll also check the patch later.

For Andres, I haven't looked into tcpdump yet, but I'd like to ask whether
or not the decrypted output to .pcap (if implemented) may be useful to
application users. What could be the limitations?
Could you explain a bit further on the idea?

Regards,
Kirk Jamison

Hi,

On 2019-02-18 02:23:12 +0000, Jamison, Kirk wrote:
> For Andres, I haven't looked into tcpdump yet, but I'd like to ask whether
> or not the decrypted output to .pcap (if implemented) may be useful to
> application users. What could be the limitations?
> Could you explain a bit further on the idea?

Well, wireshark (and also tcpdump in a less comfortable manner) has a
dissector for the postgresql protocol. That allows to dig into various
parts. See e.g. the attached as an example of what you can see as the
response to a SELECT 1;

Right now that's not usable if the connection is via TLS, as pretty much
all encrypted connection use some form of forward secrecy, so even if
you had access the the private key, we'd not be able to parse it into an
unencrypted manner.

Greetings,

Andres Freund

Hi,

Because I mistook something about how to reply to e-mails,
my last reply is not reflected in the thread.

Response to Nagaura san's review point, I fixed all his review notes, except for pointing out about psql.
Please see the attached updated patch.

> 1)
> It would be better making the log format the same as the server log format,
I changed date style and added timezone.

> 2)
> It was difficult for me to understand the first line message in the log file.
I changed the message as "The maximum size of this log is 3 Bytes, the parameter 'logminlevel' is set to level2 ".

> 3)
> Under the circumstance that the environment variables "PGLOGDIR" and
> "PGLOGSIZE" are set correctly, the log file will also be created when the
> user connect the server with "psql".
> Does this follow the specification you have thought?
> Is there any option to unset only in that session when you want to connect
> with "psql"?
By separating session using Tera Term or screen command, you can do what you want.
So I didn't make the code complicated by implementing the option.

> 4)
> Your patch affects the behavior of PQtrace().
Thank you. I fixed.

Regards,
Aya Iwata

Hi,

I have tested the trace log implementation.Please find my feedback for the
same.

Issues found while testing
---------------------------------
1) If invalid value is given to PGLOGMINLEVEL, empty log file is created
which should not happen.
2) If log file size exceeds the value configured in PGLOGSIZE, new log file
is not getting created.
3) If PGLOGSIZE is greater than 2048 bytes, log file is not created.Is this
expected behaviour?
4) In the log file, an extra new line is present whenever the query is
printed.Is this intentional?
5)Documentation for this feature is having grammatical errors and some
spelling errors which can be looked into.

Feedback in the code
----------------------------------
1) if else statement should be used for checking log levels rather than
multiple if statements
2) Across the code, sufficient space need to be left between parameters in
functions and while using comparison operators
3) In libpq-fe.h in the comments section it should trace rather than trce

Suggestions
----------------------
-> Will it better if the logs of all processes are written to a single log
file with the log message containing the process id rather than one log
file per process?

Hi Iwata-san,

Currently, the patch fails to build according to CF app.
As you know, it has something to do with the misspelling of function.
GetTimezoneInformation --> GetTimeZoneInformation

It sounds more logical to me if there is a parameter that switches on/off the logging
similar to other postgres logs. I suggest trace_log as the parameter name.
Like, this parameter needs to be enabled for logdir, logsize and loglevel, etc. to work.
The default is off.

If you're going to introduce that parameter, then the docs should be updated as well.
i.e. "When <literal>trace_log</literal> is enabled, this parameter..."

How about changing the following parameter names:
logdir --> log_directory
logsize --> log_size
logminlevel --> log_min_level

If it's helpful, you might want to look into how the other postgres logs (i.e. syslogger)
allow setting either absolute or relative path for log directory, and how the parameters
cover some of the comments above by Ramanarayana.

Regards,
Kirk Jamison

On Mon, Feb 18, 2019 at 10:06 PM Jamison, Kirk <k(dot)jamison(at)jp(dot)fujitsu(dot)com> wrote:
> It sounds more logical to me if there is a parameter that switches on/off the logging
> similar to other postgres logs. I suggest trace_log as the parameter name.

I'm not really sure that I like the design of this patch in any way.
But leaving that aside, trace_log seems like a poor choice of name,
because it's got two words telling you what kind of thing we are doing
(tracing, logging) and zero words describing the nature of the thing
being traced or logged (the wire protocol communication with the
client). A tracing facility for the planner, or the executor, or any
other part of the system would have an equally good claim on the same
name. That can't be right.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Hi Ramanarayana,

Thank you for your review and suggestion. Please see the attached updated patch.

> Issues found while testing
>1) If invalid value is given to PGLOGMINLEVEL, empty log file is created which should not happen.
Thank you for your test. However in my dev environment, empty log file is not created.
Could you explain more detail about 1)? I will check it again.

>2) If log file size exceeds the value configured in PGLOGSIZE, new log file is not getting created.
About 2) (and may be 1) ), perhaps is this something like that?

There are my mistake about first line information of created log file
"The maximum size of this log is %s *Bytes*, the parameter 'logminlevel' is set to %s\n".
- Maximum size is not bytes but megabytes.
- Display logminlevel which set by user. Internally, an invalid value is not set to logminlevel.

So trust the created log file first line info, if you set PGLOGSIZE=1000 as the meaning of "set maximum log size to 1000 Bytes",
a new file was not created even if it exceeds 1000 bytes.
If it is correct, I fixed the comment to output internal setting log maximum size and user setting value.

And if you set PGLOGMINLEVEL to invalid value (ex. "aaa"), it is not set to the parameter; The default value (level1) is set internally.
I fixed first line comment to output notification " if invalid value, level1(default) is set".

>3) If PGLOGSIZE is greater than 2048 bytes, log file is not created. Is this expected behavior?
Yes. I limit log file size.

>4) In the log file, an extra new line is present whenever the query is printed. Is this intentional?
Thank you, I fixed.

>5)Documentation for this feature is having grammatical errors and some spelling errors which can be looked into.
Thank you. I am checking my documentation now. I will fix it.

> Feedback in the code
Thank you. I fixed my code issue.

> Suggestions
I'll consider that...
Could you explain more about the idea?

Regards,
Aya Iwata

Hi Robert,

> I'm not really sure that I like the design of this patch in any way.
Aside from problems with my current documentation which I will fix,
could you explain more detail about the problem of the design?
I would like to improve my current implementation based from feedback.

Regards,
Aya Iwata

On Wednesday, February 20, 2019 12:56 PM GMT+9, Robert Haas wrote:

> On Mon, Feb 18, 2019 at 10:06 PM Jamison, Kirk <k(dot)jamison(at)jp(dot)fujitsu(dot)com> wrote:
> > It sounds more logical to me if there is a parameter that switches
> > on/off the logging similar to other postgres logs. I suggest trace_log as the parameter name.

> I'm not really sure that I like the design of this patch in any way.
> But leaving that aside, trace_log seems like a poor choice of name,
> because it's got two words telling you what kind of thing we are doing
> (tracing, logging) and zero words describing the nature of the thing
> being traced or logged (the wire protocol communication with the client).
> A tracing facility for the planner, or the executor, or any other part
> of the system would have an equally good claim on the same name. That
> can't be right.

Agreed about the argument with trace_log parameter name. I just shootout
a quick idea. I didn't think about it too deeply, but just thought of a
switch that will enable or disable the feature. So there are
definitely better names other than that. And as you suggested, should
describe specifically what the feature does.

Regards,
Kirk Jamison

On Thu, Feb 21, 2019 at 7:52 PM Iwata, Aya <iwata(dot)aya(at)jp(dot)fujitsu(dot)com> wrote:
> > I'm not really sure that I like the design of this patch in any way.
> Aside from problems with my current documentation which I will fix,
> could you explain more detail about the problem of the design?
> I would like to improve my current implementation based from feedback.

Well, I believe that what you've got here is something that could,
perhaps, be occasionally useful. However, I don't think it would be
useful to very many people very often, and we'd still have to maintain
the code, so that's not a great situation.

We already have a PQtrace() facility that could be improved, and it
has been previously suggested that you work on improving this facility
rather than inventing something new. I still think that's a good
idea. Instead you've created a second way of producing similar
information, and then coupled it to very specific ideas about how that
information should be logged: it is triggered by new libpq parameters,
there is log rotation logic, etc. Those might not be right for
everyone, and there's no flexibility in the mechanism.

I am not sure that it's a good idea to have facilities that write to
the local filesystem that can be triggered by libpq parameters. Seems
like that might have possible security consequences, or at least annoy
people who want to accept connection strings from users without having
to sanitize them for these sorts of options.

I do sometimes want to know what's going on at the protocol level.
Sometimes it's possible to use wireshark for that (as mentioned
upthread) and when it isn't, the thing I'd really like is for the
command-line clients that already exist have an option to enable
PQtrace without me having to hack the C code. We could go through and
add a long-form command-line option, --libpq-trace, to every
command-line tool we ship, for example. Then we could, as a separate
patch, improve the format of that tracing output. For me that would
be more useful than this.

I don't necessarily think there's anything deeply wrong with this
approach. It's not like your patch will bring about the end of
civilization or anything like that. It just doesn't excite me very
much. And since I agree that we have a problem in this area, I would
ideally like to have a solution to that problem that I feel excited
about.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> On Thu, Feb 21, 2019 at 7:52 PM Iwata, Aya <iwata(dot)aya(at)jp(dot)fujitsu(dot)com> wrote:
>> Aside from problems with my current documentation which I will fix,
>> could you explain more detail about the problem of the design?

> We already have a PQtrace() facility that could be improved, and it
> has been previously suggested that you work on improving this facility
> rather than inventing something new. I still think that's a good
> idea.

Me too. PQtrace as currently constituted might be helpful for debugging
libpq itself, but it's nigh useless for any higher-level purpose. I'd
gladly toss overboard any hypothetical use-case for what it does now,
in favor of having something that dumps stuff at the logical level of
messages. (It's not even very consistent, because somebody did add a
more-or-less-message-level printout to pqSaveParameterStatus, which
I believe is duplicative of what fe-misc.c will print about the
same interaction at the byte level.)

> Instead you've created a second way of producing similar
> information, and then coupled it to very specific ideas about how that
> information should be logged: it is triggered by new libpq parameters,
> there is log rotation logic, etc. Those might not be right for
> everyone, and there's no flexibility in the mechanism.

Good point. To the extent that people want any of that, they'd probably
want to have application control over it. Maybe, in addition to
PQtrace(FILE *) that'd just dump to a stdio stream, there should be a way
to create a callback similar to a notice-message hook, and let the
application implement such features in a custom callback.

> I am not sure that it's a good idea to have facilities that write to
> the local filesystem that can be triggered by libpq parameters.

Oy. That seems like a *very* serious objection. I agree with Robert's
thought that it'd be better to insist on application involvement in
enabling trace output.

regards, tom lane

Hi,

Thank you for your comments and advice.

I'd like to consider your suggestions.
I am planning to change libpq logging like this;

1. Expand PQtrace() facility and improve libpq logging.

2. Prepare "output level". There are 3 type of levels;
- TRADITIONAL : if set, outputs protocol messages
- LEVEL1 : if set, outputs phase and time
- LEVEL2 : if set, outputs both info TRADITIONAL and LEVEL1

3. Add "output phase" information; This is the processing flow. (ex. When PQexec() start and end )

4. Change output method to callback style; Default is stdout, and prepare other callback functions that will be used more frequently.

5. Initialization method;
In current one: PQtrace(PGconn *conn, FILE *stream);
Proposed change: PQtraceEx(PGconn *conn, FILE *stream, PQloggingProcessor callback_func , void *callback_arg, PGLogminlevel level);
PQtrace() can be use as it is to consider compatibility with previous applications,
so I leave PQtrace() and created a new function PQtraceEx().

After discussing the abovementioned, then maybe we can discuss more about enabling trace output and changing the output style.

What do you think? I would appreciate your comments and suggestions.

Regards,
Aya Iwata

Hello.

I came up with some random comments.

At Mon, 4 Mar 2019 08:13:00 +0000, "Iwata, Aya" <iwata(dot)aya(at)jp(dot)fujitsu(dot)com> wrote in <71E660EB361DF14299875B198D4CE5423DEF1844(at)g01jpexmbkw25>
> Hi,
>
> Thank you for your comments and advice.
>
> I'd like to consider your suggestions.
> I am planning to change libpq logging like this;
>
> 1. Expand PQtrace() facility and improve libpq logging.
>
> 2. Prepare "output level". There are 3 type of levels;
> - TRADITIONAL : if set, outputs protocol messages
> - LEVEL1 : if set, outputs phase and time
> - LEVEL2 : if set, outputs both info TRADITIONAL and LEVEL1

You appear to want to segregate the "traditional" output from
what you want to emit. At least Tom is explicitly suggesting to
throw away the hypothtical use cases for it. You may sort out
what kind of information you/we want to emit as log messages from
scratch:p

You may organize log kinds into hierachical levels like server
log messages or into orthogonal types that are individually
turned on. But it is not necessarily be a parameter of a logging
processor. (mentioned below)

> 3. Add "output phase" information; This is the processing flow. (ex. When PQexec() start and end )

What is the advantage of it against just two independent messages
like PQexec_start and PQexec_end? (I don't see any advantage.)

> 4. Change output method to callback style; Default is stdout, and prepare other callback functions that will be used more frequently.

Are you going to make something less-used the default behavior? I
think no one is opposing rich functionality as far as it is
replaceable.

> 5. Initialization method;
> In current one: PQtrace(PGconn *conn, FILE *stream);
> Proposed change: PQtraceEx(PGconn *conn, FILE *stream, PQloggingProcessor callback_func , void *callback_arg, PGLogminlevel level);

I'm not sure we should add a new *EX() function. Couldn't we
just change the signature of PQtrace()?

callback_funs seems to be a single function. I think it's better
to have individual function for each message type. Not
callback_func(PQLOG_EXEC_START, param_1, param_2,...) ,but
PQloggingProcessor.PQexec_start(param_1, param_2, ...).

It is because the caller can simply pass values in its own type
to the function without casting or other transformations and
their types are checked statically.

I also think it's better that logger-specific paramters are not
passed in this level. Maybe stream and level are logger-specific
paratmer, which can be combined into callback_arg, or can be
given via an API function.

> PQtrace() can be use as it is to consider compatibility with previous applications,
> so I leave PQtrace() and created a new function PQtraceEx().
>
> After discussing the abovementioned, then maybe we can discuss more about enabling trace output and changing the output style.

I'm not sure what you mean by "output style" but you can change
everything by replacing the whole callback processor, which may
be a dynamic loaded file which is loaded by the instruction in
both ~/.libpqrc and some API, like PQloadLoggingProcessor()?

> What do you think? I would appreciate your comments and suggestions.

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

On Mon, Mar 4, 2019 at 3:13 AM Iwata, Aya <iwata(dot)aya(at)jp(dot)fujitsu(dot)com> wrote:
> 2. Prepare "output level". There are 3 type of levels;
> - TRADITIONAL : if set, outputs protocol messages
> - LEVEL1 : if set, outputs phase and time
> - LEVEL2 : if set, outputs both info TRADITIONAL and LEVEL1

I am not impressed by this proposal. I think what we should be
focusing on here is how to clearly display the contents of a message.
I think we should be looking for a way to display each message on a
single line in a way that indicates the data types of the constituent
fields. For example, here's a DataRow message as output by PQtrace
today:

From backend> D
From backend (#4)> 42
From backend (#2)> 4
From backend (#4)> 6
From backend (6)> public
From backend (#4)> 4
From backend (4)> tab1
From backend (#4)> 5
From backend (5)> table
From backend (#4)> 5
From backend (5)> rhaas

What I'd like to see for a case like this is something like:

<<< 'D' 42 #4 6 'public' 4 'tab1' 5 'table' 5 'rhaas'

And here's a RowDescription message today:

From backend> T
From backend (#4)> 101
From backend (#2)> 4
From backend> "Schema"
From backend (#4)> 2615
From backend (#2)> 2
From backend (#4)> 19
From backend (#2)> 64
From backend (#4)> -1
From backend (#2)> 0
From backend> "Name"
From backend (#4)> 1259
From backend (#2)> 2
From backend (#4)> 19
From backend (#2)> 64
From backend (#4)> -1
From backend (#2)> 0
From backend> "Type"
From backend (#4)> 0
From backend (#2)> 0
From backend (#4)> 25
From backend (#2)> 65535
From backend (#4)> -1
From backend (#2)> 0
From backend> "Owner"
From backend (#4)> 0
From backend (#2)> 0
From backend (#4)> 19
From backend (#2)> 64
From backend (#4)> -1
From backend (#2)> 0

And I propose that it should look like this:

<<< 'T' 101 4 "Schema" 2615 #2 19 #64 -1 #0 "Name" 1259 #2 19 #64 -1
#0 "Owner" 0 #0 19 #64 -1 #0

The basic idea being:

- Each line is a whole message.
- The line begins with <<< for a message received and >>> for a message sent.
- Strings in single quotes are those sent/received as a fixed number of bytes.
- Strings in double quotes are those sent/received as a string.
- 4-byte integers are printed unadorned.
- 2-byte integers are prefixed by #.
- I guess 1-byte integers would need some other prefix, maybe @ or ##.

Now if we want to timestamp those lines too, that'd be fine:

2019-03-04 21:33:39.338 EST <<< 'T' 101 4 "Schema" 2615 #2 19 #64 -1
#0 "Name" 1259 #2 19 #64 -1 #0 "Owner" 0 #0 19 #64 -1 #0
2019-03-04 21:33:39.342 EST <<< 'D' 42 #4 6 'public' 4 'tab1' 5
'table' 5 'rhaas'

But I still don't really see a need for different levels or whatever.
I mean, you either want a dump of all of the protocol traffic, or you
don't, I think. Or maybe I am confused as to what the goal of all
this really is.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> The basic idea being:

> - Each line is a whole message.
> - The line begins with <<< for a message received and >>> for a message sent.

+1, though do we really need to repeat the direction marker thrice?

> - Strings in single quotes are those sent/received as a fixed number of bytes.
> - Strings in double quotes are those sent/received as a string.
> - 4-byte integers are printed unadorned.
> - 2-byte integers are prefixed by #.
> - I guess 1-byte integers would need some other prefix, maybe @ or ##.

I doubt that anybody gives a fig for those distinctions, except when
they're writing actual code that speaks the protocol --- and I do not
think that that's the target use-case. So strings and integers seem
like plenty. I'd also suggest that just because the protocol has
single-letter codes for message types doesn't mean that average users
have memorized those codes; and that framing data like the message
length is of no interest.

In short, rather than

<<< 'T' 101 4 "Schema" 2615 #2 19 #64 -1 #0 "Name" 1259 #2 19 #64 -1 #0 "Owner" 0 #0 19 #64 -1 #0

I'd envision something more like

< RowDescription "Schema" 2615 2 19 64 -1 0 "Name" 1259 2 19 64 -1 0 "Owner" 0 0 19 64 -1 0

> But I still don't really see a need for different levels or whatever.
> I mean, you either want a dump of all of the protocol traffic, or you
> don't, I think. Or maybe I am confused as to what the goal of all
> this really is.

Yeah, me too. But a lot of this detail would only be useful if you
were trying to diagnose something like a discrepancy between the server
and libpq as to the width of some field. And the number of users for
that can be counted without running out of fingers. I think what would
be of use for a trace facility is as high-level a view as possible of
the message contents.

Or, in other words: a large part of the problem with the existing PQtrace
facility is that it *was* designed to help debug libpq itself, and that
use-case is no longer very interesting. We should assume that the library
knows how to parse protocol messages.

regards, tom lane

On Mon, Mar 4, 2019 at 10:25 PM Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> > The basic idea being:
> > - Each line is a whole message.
> > - The line begins with <<< for a message received and >>> for a message sent.
>
> +1, though do we really need to repeat the direction marker thrice?

Perhaps not.

> > - Strings in single quotes are those sent/received as a fixed number of bytes.
> > - Strings in double quotes are those sent/received as a string.
> > - 4-byte integers are printed unadorned.
> > - 2-byte integers are prefixed by #.
> > - I guess 1-byte integers would need some other prefix, maybe @ or ##.
>
> I doubt that anybody gives a fig for those distinctions, except when
> they're writing actual code that speaks the protocol --- and I do not
> think that that's the target use-case. So strings and integers seem
> like plenty. I'd also suggest that just because the protocol has
> single-letter codes for message types doesn't mean that average users
> have memorized those codes; and that framing data like the message
> length is of no interest.

I don't agree with that. For one thing, I'm someone, and I give a fig.

I would put it this way: with a very small amount of additional
notation it's possible to preserve the level of detail that we have
currently, and I think that's worth it. Your proposed format for the
sample message I showed is very slightly shorter, which will almost
certainly not matter to anyone, but it leaves some slight ambiguity
about what was happening at the protocol level, which might. If you
don't care, the additional detail in my proposed format is easy enough
to ignore.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Hi Horiguchi-san,

Thank you for your reply and suggestions.

> > 1. Expand PQtrace() facility and improve libpq logging.
> >
> > 2. Prepare "output level". There are 3 type of levels;
> > - TRADITIONAL : if set, outputs protocol messages
> > - LEVEL1 : if set, outputs phase and time
> > - LEVEL2 : if set, outputs both info TRADITIONAL and LEVEL1
>
> You appear to want to segregate the "traditional" output from what you want
> to emit. At least Tom is explicitly suggesting to throw away the hypothtical
> use cases for it. You may sort out what kind of information you/we want to
> emit as log messages from scratch:p
>
> You may organize log kinds into hierachical levels like server log messages
> or into orthogonal types that are individually turned on. But it is not
> necessarily be a parameter of a logging processor. (mentioned below)

It is intended for old application users who use PQtrace() expect the existing/default/traditional log output style.
That’s why I separated other information(ex. phase and timestamp).
But since you mentioned the level is not necessary,
I will follow your advice and include those information in the reformatted PQtrace().

> > 3. Add "output phase" information; This is the processing flow. (ex.
> > When PQexec() start and end )
>
> What is the advantage of it against just two independent messages like
> PQexec_start and PQexec_end? (I don't see any advantage.)

I think the purpose of this logging improvement is to make it useful for analysis at performance deterioration.
When query delay happens, we want to know from which side(server or client) is the cause of it,
and then people want to know which process takes time.
I think the phase and time information are useful for diagnosis.
For example, when command processing function (ex. PQexec()) etc. start/end
and when client receive/send protocol messages.
/*my intended output here */

> > 4. Change output method to callback style; Default is stdout, and prepare
> other callback functions that will be used more frequently.
>
> Are you going to make something less-used the default behavior? I think no
> one is opposing rich functionality as far as it is replaceable.
I am sorry, my explanation was not clear.
I just wanted to say I intend to provide several output method functions which users likely need.
ex. output to stdout, or output to file, or output to log directory.

> > 5. Initialization method;
> > In current one: PQtrace(PGconn *conn, FILE *stream); Proposed change:
> > PQtraceEx(PGconn *conn, FILE *stream, PQloggingProcessor callback_func
> > , void *callback_arg, PGLogminlevel level);
>
> I'm not sure we should add a new *EX() function. Couldn't we just change the
> signature of PQtrace()?
I intended to add new *EX() function for compatibility purposes specially for old version of libpq.
I would like to avoid making changes to old applications for this.
But if we insist on changing the PQtrace() itself, then I will follow your advice.

>
> callback_funs seems to be a single function. I think it's better to have
> individual function for each message type. Not
> callback_func(PQLOG_EXEC_START, param_1, param_2,...) ,but
> PQloggingProcessor.PQexec_start(param_1, param_2, ...).
>
> It is because the caller can simply pass values in its own type to the function
> without casting or other transformations and their types are checked
> statically.
>
> I also think it's better that logger-specific paramters are not passed in
> this level. Maybe stream and level are logger-specific paratmer, which can
> be combined into callback_arg, or can be given via an API function.

Thank you for your advice. I will consider it.

Regards,
Aya Iwata

Hi everyone,

I appreciate all the helpful advice.

I agree to display message more clearly. I will follow your advice.

I would like to add timestamp per line and when command processing function start/end.
I think it is useful to know the application process start/end for diagnosis.
So I will implement like this;

2019-03-03 07:24:54.142 UTC PQgetResult start
2019-03-03 07:24:54.143 UTC < 'T' 35 1 "set_config" 0 #0 25 #65535 -1 #0
2019-03-03 07:24:54.144 UTC PQgetResult end

> > But I still don't really see a need for different levels or whatever.
> > I mean, you either want a dump of all of the protocol traffic, or you
> > don't, I think. Or maybe I am confused as to what the goal of all
> > this really is.
>
> Yeah, me too. But a lot of this detail would only be useful if you were trying
> to diagnose something like a discrepancy between the server and libpq as to
> the width of some field. And the number of users for that can be counted
> without running out of fingers. I think what would be of use for a trace
> facility is as high-level a view as possible of the message contents.
>
> Or, in other words: a large part of the problem with the existing PQtrace
> facility is that it *was* designed to help debug libpq itself, and that
> use-case is no longer very interesting. We should assume that the library
> knows how to parse protocol messages.

Since I explained the reason in the previous email, I am copy-pasting it again here.

I think the purpose of the leveling is to provide an optional information for the user,
which is useful for diagnosis during the performance deterioration.
When query delay happens, we want to know from which side(server or client) is the cause of it,
and then people want to know which process takes time.
I think the phase and time information are useful for diagnosis.
For example, when command processing function (ex. PQexec()) etc. start/end
and when client receive/send protocol messages.

So is it alright to add these information to the new/proposed PQtrace() default output?

Regards,
Aya Iwata

On 3/5/19 11:48 AM, Iwata, Aya wrote:
>
> So is it alright to add these information to the new/proposed PQtrace() default output?

I agree with Andres [1] that it's not very clear where this patch is
going and we should push the target to PG13.

Regards,
--
-David
david(at)pgmasters(dot)net

[1]
https://www.postgresql.org/message-id/raw/20190214203752.t4hl574k6jlu4t25%40alap3.anarazel.de

On 3/5/19 5:28 PM, David Steele wrote:
> On 3/5/19 11:48 AM, Iwata, Aya wrote:
>>
>> So is it alright to add these information to the new/proposed
>> PQtrace() default output?
>
> I agree with Andres [1] that it's not very clear where this patch is
> going and we should push the target to PG13.

Hearing no opinions to the contrary, I have set the target version to PG13.

Regards,
--
-David
david(at)pgmasters(dot)net

Hi,

> The basic idea being:
>
> - Each line is a whole message.
> - The line begins with <<< for a message received and >>> for a message sent.
> - Strings in single quotes are those sent/received as a fixed number of bytes.
> - Strings in double quotes are those sent/received as a string.
> - 4-byte integers are printed unadorned.
> - 2-byte integers are prefixed by #.
> - I guess 1-byte integers would need some other prefix, maybe @ or ##.

I created v1 patch to improve PQtrace(); output log message in one line.
Please find my attached patch.

Log output examples;

In current PQtrace log:

To backend> Msg Q
To backend> "SELECT pg_catalog.set_config('search_path', '', false)"
To backend> Msg complete, length 60

I changed like this:

2019-04-04 02:39:51.488 UTC > Query 59 "SELECT pg_catalog.set_config('search_path', '', false)"

In current PQtrace log:

From backend> T
From backend (#4)> 35
From backend (#2)> 1
From backend> "set_config"
From backend (#4)> 0
From backend (#2)> 0
From backend (#4)> 25
From backend (#2)> 65535
From backend (#4)> -1
From backend (#2)> 0

I changed like this:

2019-04-04 02:39:51.489 UTC < RowDescription 35 #1 "set_config" 0 #0 25 #65535 -1 #0

> I would like to add timestamp per line and when command processing function
> start/end.
> I think it is useful to know the application process start/end for diagnosis.
> So I will implement like this;
>
> 2019-03-03 07:24:54.142 UTC PQgetResult start
> 2019-03-03 07:24:54.143 UTC < 'T' 35 1 "set_config" 0 #0 25 #65535 -1 #0
> 2019-03-03 07:24:54.144 UTC PQgetResult end
I would like to add this in next patch if there are not any disagreement.

Regards,
Aya Iwata

Hi,

I update patch to improve PQtrace(); output log message in one line.
Please find my attached patch.

How it changed:
> > The basic idea being:
> >
> > - Each line is a whole message.
> > - The line begins with <<< for a message received and >>> for a message
> sent.
> > - Strings in single quotes are those sent/received as a fixed number of
> bytes.
> > - Strings in double quotes are those sent/received as a string.
> > - 4-byte integers are printed unadorned.
> > - 2-byte integers are prefixed by #.
> > - I guess 1-byte integers would need some other prefix, maybe @ or ##.

New log output examples:
The message sent from frontend is like this;
2019-04-04 02:39:51.488 UTC > Query 59 "SELECT pg_catalog.set_config('search_path', '', false)"

The message sent from backend is like this;
2019-04-04 02:39:51.489 UTC < RowDescription 35 #1 "set_config" 0 #0 25 #65535 -1 #0

Regards,
Aya Iwata

Hello. Thank you for the new patch.

At Tue, 9 Apr 2019 06:19:32 +0000, "Iwata, Aya" <iwata(dot)aya(at)jp(dot)fujitsu(dot)com> wrote in <71E660EB361DF14299875B198D4CE5423DF161BA(at)g01jpexmbkw25>
> Hi,
>
> I update patch to improve PQtrace(); output log message in one line.
> Please find my attached patch.
>
> How it changed:
> > > The basic idea being:
> > >
> > > - Each line is a whole message.
> > > - The line begins with <<< for a message received and >>> for a message
> > sent.
> > > - Strings in single quotes are those sent/received as a fixed number of
> > bytes.
> > > - Strings in double quotes are those sent/received as a string.
> > > - 4-byte integers are printed unadorned.
> > > - 2-byte integers are prefixed by #.
> > > - I guess 1-byte integers would need some other prefix, maybe @ or ##.
>
> New log output examples:
> The message sent from frontend is like this;
> 2019-04-04 02:39:51.488 UTC > Query 59 "SELECT pg_catalog.set_config('search_path', '', false)"
>
> The message sent from backend is like this;
> 2019-04-04 02:39:51.489 UTC < RowDescription 35 #1 "set_config" 0 #0 25 #65535 -1 #0

I had a brief look on this.

+/* protocol message name */
+static char *command_text_b[] = {

Couldn't the name be more descriptive? The comment just above
doesn't seem consistent with the variable. The tables are very
sparse. I think the definition could be in more compact form.

+ /* y */ 0,
+ /* z */ 0
+};
+#define COMMAND_BF_MAX (sizeof(command_text_bf) / sizeof(*command_text_bf))

It seems that at least the trailing 0-elements are not required.

+ * message_get_command_text:
+ * Get Protocol message text from byte1 identifier
+ */
+static char *
+message_get_command_text(unsigned char c, CommunicationDirection direction)
..
+message_nchar(PGconn *conn, const char *v, int length, CommunicationDirection direction)

Also the function names are not very descriptive.

+message_Int(PGconn *conn, int v, int length, CommunicationDirection direct)

We are not using names mixing CamelCase and undercored there.

+ if (c >= 0 && c < COMMAND_BF_MAX)
+ {
+ text = command_text_bf[c];
+ if (text)
+ return text;
+ }
+
+ if (direction == FROM_BACKEND && c >= 0 && c < COMMAND_B_MAX)
+ {
+ text = command_text_b[c];
+ if (text)
..
+ if (direction == FROM_FRONTEND && c >= 0 && c < COMMAND_F_MAX)

This code is assuming that elements of command_text_bf is
mutually exclusive with command_text_b or _bf. That is, the first
has an element for 'C', others don't have an element in the same
position. But _bf[C] = "CommandComplete" and _f[C] = "Close". Is
it working correctly?

+typedef enum CommunicationDirection

The type CommunicationDirection is two-member enum which is
equivalent to just a boolean. Is there a reason you define that?

+typedef enum State
+typedef enum Type

The name is too generic.
+typedef struct _LoggingMsg
...
+} LoggingMsg;

Why the tag name is prefixed with an underscore?

+typedef struct _Frontend_Entry

The name doesn't give an idea of its characteristics.

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

Hi Horiguchi-san,

Thank you for your reviewing.
I updated patch. Please see my attached patch.

> +/* protocol message name */
> +static char *command_text_b[] = {
>
> Couldn't the name be more descriptive? The comment just above doesn't seem
> consistent with the variable. The tables are very sparse. I think the
> definition could be in more compact form.
Thank you. I changed the description more clear.

>
> + /* y */ 0,
> + /* z */ 0
> +};
> +#define COMMAND_BF_MAX (sizeof(command_text_bf) /
> +sizeof(*command_text_bf))
>
> It seems that at least the trailing 0-elements are not required.
Sure. I removed.

> + * message_get_command_text:
> + * Get Protocol message text from byte1 identifier
> + */
> +static char *
> +message_get_command_text(unsigned char c, CommunicationDirection
> +direction)
> ..
> +message_nchar(PGconn *conn, const char *v, int length,
> +CommunicationDirection direction)
>
> Also the function names are not very descriptive.
Thank you. I fixed function names and added descriptions.

>
> +message_Int(PGconn *conn, int v, int length, CommunicationDirection
> +direct)
>
> We are not using names mixing CamelCase and undercored there.
>
>
> + if (c >= 0 && c < COMMAND_BF_MAX)
> + {
> + text = command_text_bf[c];
> + if (text)
> + return text;
> + }
> +
> + if (direction == FROM_BACKEND && c >= 0 && c < COMMAND_B_MAX)
> + {
> + text = command_text_b[c];
> + if (text)
> ..
> + if (direction == FROM_FRONTEND && c >= 0 && c < COMMAND_F_MAX)
>
>
> This code is assuming that elements of command_text_bf is mutually exclusive
> with command_text_b or _bf. That is, the first has an element for 'C', others
> don't have an element in the same position. But _bf[C] = "CommandComplete"
> and _f[C] = "Close". Is it working correctly?
Elements sent from both the backend and the frontend are 'c' and 'd'.
There is no same elements in protocol_message_type_b and _bf.
The same applies to protocol_message_type_f and _bf too. So I think it is working correctly.

> +typedef enum CommunicationDirection
>
> The type CommunicationDirection is two-member enum which is equivalent to
> just a boolean. Is there a reason you define that?
>
> +typedef enum State
> +typedef enum Type
>
> The name is too generic.
> +typedef struct _LoggingMsg
> ...
> +} LoggingMsg;
>
> Why the tag name is prefixed with an underscore?
>
> +typedef struct _Frontend_Entry
>
> The name doesn't give an idea of its characteristics.
Thank you. I fixed.

Regards,
Aya Iwata

Hi Aya-san,

I tested your v3 patch and it seemed to work on my Linux environment.
However, the CF Patch Tester detected a build failure (probably on Windows).
Refer to: http://commitfest.cputube.org/

Docs:
It would be better to have reference to the documentations of
Frontend/Backend Protocol's "Message Format".

Code:
There are some protocol message types from frontend
that you missed indicating (non BYTE1 types):
CancelRequest (F), StartupMessage (F), SSLRequest (F).

Although I haven't tested those actual protocols,
I assume it will be printed as the following since the length and
message will still be recognized.
ex. Timestamp 8 80877103

So you need to indicate these protocol message types as intended.
ex. Timestamp > SSLRequest 8 80877103

Regards,
Kirk Jamison

Hi Kirk,

Thank you for your reviewing.

> Docs:
> It would be better to have reference to the documentations of Frontend/Backend
> Protocol's "Message Format".
I added a link to "Protocol's Message Formats" and little explanation to PQtrace() documentation.

> Code:
> There are some protocol message types from frontend that you missed indicating
> (non BYTE1 types):
> CancelRequest (F), StartupMessage (F), SSLRequest (F).
>
> Although I haven't tested those actual protocols, I assume it will be printed
> as the following since the length and message will still be recognized.
> ex. Timestamp 8 80877103
>
> So you need to indicate these protocol message types as intended.
> ex. Timestamp > SSLRequest 8 80877103
Thank you. I changed code to output these information.
For that, I added code to check the int32 content which StartupMessage (F) and SSLRequest (F) have.
And CancelRequest is not targeted because it calls send() directly.

Regards,
Aya Iwata

Hi,

I rebased my patch from head. Please find my attached patch.

Regard,
Aya Iwata

Hi,

This is a summary of the whole thread.
I am currently improving PQtrace() by adjusting its output to one line per protocol message as per the advice of reviewers.

Purpose:
If a problem occurs, such as a slow query, you want to know which query takes time.
In Current libpq, there is PQtrace(FILE *filename) facility to output exchanging protocol messages to file.
But I think current PQtrace() has following issues:
* The output is confusing. It is difficult to analyze information because it is printed one by one, and only a character representing a message (ex. printed 'T' means RowDescription).
* Timestamp is not output. So we cannot identify which process took a long time. That would be possible when we compare timestamps.
* PQtrace() code must be included in libpq application's source code. If you want to get log, you should change code and re-compile it for logging. Some application cannot do this.

Compared to tcpdump:
There is tcpdump for similar use, but it has the following problems:
- Windows users cannot use it.
- If the communication is encrypted, it is possible that you may not see the information you want as explained by Andres.
- Information can only be retrieved by limited users due to OS permissions.

Solution:
Work on following improvements in order:
1. Adjusting it to emit one line per protocol message and output timestamp.
2. Enables logging control without recompiling the application.
I thought it would be better to control it with parameters. However since this method is controversial (Security implications, etc.), we will consider a good method after completing 1.

Latest patch just contains 1. Hence, the usage of this feature is the same as current PQtrace().

Example of log output:
In current PQtrace log:

To backend> Msg Q
To backend> "SELECT pg_catalog.set_config('search_path', '', false)"
To backend> Msg complete, length 60

I changed like this:

2019-04-04 02:39:51.488 UTC > Query 59 "SELECT pg_catalog.set_config('search_path', '', false)"

I appreciate your advice regarding the one line protocol message. Thank you in advance.

Regards,
Aya Iwata

Hello,

Nice patch. I think there's pretty near consensus that this is
something we want, and that the output format of one trace msg per libpq
msg is roughly okay. (I'm not sure there's 100% agreement on this last
point, but it seems close enough.)

> I changed like this:
>
> 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.

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

Minor review points:

* Do we need COMMAND_B_MIN etc to reduce the number of zeroes at the
beginning of the tables?

* The place where you define TRACELOG_TIME_SIZE seems like it'll be
unavoidably out of date if somebody changes the format string. I'd put
that #define next to where the fmt appears.

* "output a a null-terminated" has duplicated "a"

* We don't add braces around single-statement blocks (pqPutMsgEnd)

* Please pgindent.

Thanks

--
Álvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

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

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 Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

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 <alvherre(at)2ndquadrant(dot)com>
> Sent: Thursday, September 17, 2020 5:42 AM
> To: Iwata, Aya/岩田 彩 <iwata(dot)aya(at)fujitsu(dot)com>
> Cc: pgsql-hackers(at)postgresql(dot)org; tgl(at)sss(dot)pgh(dot)pa(dot)us;
> robertmhaas(at)gmail(dot)com; pchampion(at)pivotal(dot)io; jdoty(at)pivotal(dot)io;
> raam(dot)soft(at)gmail(dot)com; Nagaura, Ryohei/永浦 良平
> <nagaura(dot)ryohei(at)fujitsu(dot)com>; nagata(at)sraoss(dot)co(dot)jp;
> peter(dot)eisentraut(at)2ndquadrant(dot)com; 'Kyotaro HORIGUCHI'
> <horiguchi(dot)kyotaro(at)lab(dot)ntt(dot)co(dot)jp>; Jamison, Kirk/ジャミソン カーク
> <k(dot)jamison(at)fujitsu(dot)com>
> 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 Herrera https://www.2ndQuadrant.com/
> PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

At Wed, 16 Sep 2020 17:41:55 -0300, Alvaro Herrera <alvherre(at)2ndquadrant(dot)com> wrote in
> 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();

I saw that version and have some comments.

+pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
+{
+ const char *message_type;

Compiler complains that this is unused.

+static const char *
+pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
+{
...
+ else
+ return "UnknownCommand";
+}

Compiler complains as "control reached end of non-void function"

+pqLogMsgString(PGconn *conn, const char *v, int length, PGCommSource commsource)
+{
+ if (length < 0)
+ length = strlen(v) + 1;
+
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ {
+ switch (conn->logging_message.state)
+ {
+ case LOG_CONTENTS:
+ fprintf(conn->Pfdebug, "\"%s\" ", v);
+ pqLogLineBreak(length, conn);

pqLogMsgString(conn, str, -1, FROM_*) means actual length may be
different from the caller thinks, but the pqLogLineBreak() subtracts
that value from the message length rememberd in in logging_message.
Anyway AFAICS the patch doesn't use the code path so we should remove
the first two lines.

+ case LOG_CONTENTS:
+ fprintf(conn->Pfdebug, "%s%d ", prefix, v);

That prints #65535 for v = -1 and length = 2. I think it should be
properly expanded as a signed integer.

@@ -139,8 +447,7 @@ pqGets_internal(PQExpBuffer buf, PGconn *conn, bool resetbuffer)
conn->inCursor = ++inCursor;

if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend> \"%s\"\n",
- buf->data);
+ pqLogMsgString(conn, buf->data, buf->len + 1, FROM_BACKEND);

By the way, appendBinaryPQExpBuffer() enlarges its buffer by the size
of the exact length of the given data, but appends '\0' at the end of
the copied data. Couldn't that leads to an memory overrun?

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

On 2020-Oct-09, Kyotaro Horiguchi wrote:

> I saw that version and have some comments.
>
> +pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
> +{
> + const char *message_type;
>
> Compiler complains that this is unused.
>
> +static const char *
> +pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
> +{
> ...
> + else
> + return "UnknownCommand";
> +}
>
> Compiler complains as "control reached end of non-void function"

Yeah, those two warnings are caused by the same problem, namely that I
was editing this function to make it simpler and apparently the patch
version I sent does not include all such changes. The fix is to remove
the message_type variable and have the two assignments be "return".

> +pqLogMsgString(PGconn *conn, const char *v, int length, PGCommSource commsource)
> +{
> + if (length < 0)
> + length = strlen(v) + 1;
> +

> pqLogMsgString(conn, str, -1, FROM_*) means actual length may be
> different from the caller thinks, but the pqLogLineBreak() subtracts
> that value from the message length rememberd in in logging_message.
> Anyway AFAICS the patch doesn't use the code path so we should remove
> the first two lines.

True, +1 for removing it.

> By the way, appendBinaryPQExpBuffer() enlarges its buffer by the size
> of the exact length of the given data, but appends '\0' at the end of
> the copied data. Couldn't that leads to an memory overrun?

Doesn't enlargePQExpBuffer() include room for the trailing zero? I
think it does.

On Wed, Sep 16, 2020 at 4:41 PM Alvaro Herrera <alvherre(at)2ndquadrant(dot)com> wrote:
> 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" ^@

Ooh, that looks really nice. The ^@ at the end seems odd, though.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

At Fri, 9 Oct 2020 11:48:59 -0300, Alvaro Herrera <alvherre(at)alvh(dot)no-ip(dot)org> wrote in
> > +pqLogMsgString(PGconn *conn, const char *v, int length, PGCommSource commsource)
> > +{
> > + if (length < 0)
> > + length = strlen(v) + 1;
> > +
>
> > pqLogMsgString(conn, str, -1, FROM_*) means actual length may be
> > different from the caller thinks, but the pqLogLineBreak() subtracts
> > that value from the message length rememberd in in logging_message.
> > Anyway AFAICS the patch doesn't use the code path so we should remove
> > the first two lines.
>
> True, +1 for removing it.
>
> > By the way, appendBinaryPQExpBuffer() enlarges its buffer by the size
> > of the exact length of the given data, but appends '\0' at the end of
> > the copied data. Couldn't that leads to an memory overrun?
>
> Doesn't enlargePQExpBuffer() include room for the trailing zero? I
> think it does.

Right. I faintly recall I said the same thing before..

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

On Wed, Oct 14, 2020 at 10:18:38AM +0900, Kyotaro Horiguchi wrote:
> At Fri, 9 Oct 2020 11:48:59 -0300, Alvaro Herrera <alvherre(at)alvh(dot)no-ip(dot)org> wrote in
>> Doesn't enlargePQExpBuffer() include room for the trailing zero? I
>> think it does.
>
> Right. I faintly recall I said the same thing before..

FWIW, as pqexpbuffer.c says, it does:
needed += str->len + 1; /* total space required now */
--
Michael

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?

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 <alvherre(at)alvh(dot)no-ip(dot)org>
> Sent: Tuesday, October 27, 2020 1:23 AM
> To: Iwata, Aya/岩田 彩 <iwata(dot)aya(at)fujitsu(dot)com>
> Cc: pgsql-hackers(at)postgresql(dot)org; tgl(at)sss(dot)pgh(dot)pa(dot)us;
> robertmhaas(at)gmail(dot)com; pchampion(at)pivotal(dot)io; jdoty(at)pivotal(dot)io;
> raam(dot)soft(at)gmail(dot)com; Nagaura, Ryohei/永浦 良平
> <nagaura(dot)ryohei(at)fujitsu(dot)com>; nagata(at)sraoss(dot)co(dot)jp;
> peter(dot)eisentraut(at)2ndquadrant(dot)com; 'Kyotaro HORIGUCHI'
> <horiguchi(dot)kyotaro(at)lab(dot)ntt(dot)co(dot)jp>; Jamison, Kirk/ジャミソン カーク
> <k(dot)jamison(at)fujitsu(dot)com>
> 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?

On Tue, Oct 27, 2020 at 3:23 AM Alvaro Herrera <alvherre(at)alvh(dot)no-ip(dot)org> wrote:
>
> 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.
>

Hi,

Hopefully Iwata-san will return to looking at this soon.

I have tried the latest patch a little (using "psql" as my client),
and have a few small comments so far:

- In pqTraceInit(), in the (admittedly rare) case that fe_msg malloc()
fails, I'd NULL out be_msg too after free(), rather than leave it
dangling (because if pgTraceInit() was ever invoked again, as the
comment says it could, it would result in previously freed memory
being accessed ...)

conn->fe_msg = malloc(MAX_FRONTEND_MSGS * sizeof(pqFrontendMessage));
if (conn->fe_msg == NULL)
{
free(conn->be_msg);
conn->be_msg = NULL;
return false;
}

- >3. COPY ... (FORMAT BINARY) emits "invalid protocol" ... not good.

That seemed to happen for me only if COPYing binary format to stdout.

UnknownCommand :::Invalid Protocol

- >5. Error messages are still printing the terminating zero byte. I
>suggest that it should be suppressed.

Perhaps there's a more elegant way of doing it, but I got rid of the
logging of the zero byte using the following change to
pgLogMsgByte1(), though there still seems to be a trailing space
issue:

case LOG_CONTENTS:
- fprintf(conn->Pfdebug, "%c ", v);
+ if (v != '\0')
+ fprintf(conn->Pfdebug, "%c ", v);
pqTraceMaybeBreakLine(sizeof(v), conn);
break;

Regards,
Greg Nancarrow
Fujitsu Australia

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

On Tuesday, December 15, 2020 8:12 PM, Iwata-san wrote:
> > There are some things still to do:
> I worked on some to do.

Hi Iwata-san,

Thank you for updating the patch.
I would recommend to register this patch in the upcoming commitfest
to help us keep track of it. I will follow the thread to provide more
reviews too.

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

Though I have also not tested it with 2.0 server yet, do I have to download 7.3
version to test that isn't it? Silly question, do we still want to have this
feature for 2.0?
I understand that protocol 2.0 is still supported, but it is only used for
PostgreSQL versions 7.3 and earlier, which is not updated by fixes anymore
since we only backpatch up to previous 5 versions. However I am not sure if
it's a good idea, but how about if we just support this feature for protocol 3.
There are similar chunks of code in fe-exec.c, PQsendPrepare(), PQsendDescribe(),
etc. that already do something similar, so I just thought in hindsight if we can
do the same.
if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
{
<new code here>
}
else
{
/* Protocol 2.0 isn't supported */
printfPQExpBuffer(&conn->errorMessage,
libpq_gettext("function requires at least protocol version 3.0\n"));
return 0;
}

But if it's necessary to provide this improved trace output for 2.0 servers, then ignore what
I suggested above, and although difficult I think we should test for protocol 2.0 in older server.

Some minor code comments I noticed:
1.
+ LOG_FIRST_BYTE, /* logging the first byte identifing the
+ * protocol message type */

"identifing" should be "identifying". And closing */ should be on 3rd line.

2.
+ case LOG_CONTENTS:
+ /* Suppresses printing terminating zero byte */

--> Suppress printing of terminating zero byte

Regards,
Kirk Jamison

From: k(dot)jamison(at)fujitsu(dot)com <k(dot)jamison(at)fujitsu(dot)com>
> I understand that protocol 2.0 is still supported, but it is only used for
> PostgreSQL versions 7.3 and earlier, which is not updated by fixes anymore
> since we only backpatch up to previous 5 versions. However I am not sure if
> it's a good idea, but how about if we just support this feature for protocol 3.

+1
I thought psqlODBC (still) allows the user to choose the protocol version, it looks like the current psqlODBC disallows pre-3 protocol:

[libpq_connect()]
MYLOG(0, "libpq connection to the database established.\n");
pversion = PQprotocolVersion(pqconn);
if (pversion < 3)
{
MYLOG(0, "Protocol version %d is not supported\n", pversion);
goto cleanup;
}

> There are similar chunks of code in fe-exec.c, PQsendPrepare(),
> PQsendDescribe(),
> etc. that already do something similar, so I just thought in hindsight if we can
> do the same.
> if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
> {
> <new code here>
> }
> else
> {
> /* Protocol 2.0 isn't supported */
> printfPQExpBuffer(&conn->errorMessage,
> libpq_gettext("function requires at least protocol
> version 3.0\n"));
> return 0;
> }

I haven't looked at the patch and don't know the code structure, but I want the code clutter to be minimized. So, I think we should avoid putting if statements like above here and there.

Plus, I don't think it's not necessary to fail the processing when the protocol version is 2; we can just stop the trace output. So, how about disabling the trace output silently if the protocol turns out to be < 3 upon connection?

Regards
Takayuki Tsunakawa

Iwata-san,

On Mon, Dec 21, 2020 at 5:20 PM k(dot)jamison(at)fujitsu(dot)com
<k(dot)jamison(at)fujitsu(dot)com> wrote:
>
> On Tuesday, December 15, 2020 8:12 PM, Iwata-san wrote:
> > > There are some things still to do:
> > I worked on some to do.
>
> Hi Iwata-san,
>
> Thank you for updating the patch.
> I would recommend to register this patch in the upcoming commitfest
> to help us keep track of it. I will follow the thread to provide more
> reviews too.
>
> > > 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.
>
> Though I have also not tested it with 2.0 server yet, do I have to download 7.3
> version to test that isn't it? Silly question, do we still want to have this
> feature for 2.0?
> I understand that protocol 2.0 is still supported, but it is only used for
> PostgreSQL versions 7.3 and earlier, which is not updated by fixes anymore
> since we only backpatch up to previous 5 versions. However I am not sure if
> it's a good idea, but how about if we just support this feature for protocol 3.
> There are similar chunks of code in fe-exec.c, PQsendPrepare(), PQsendDescribe(),
> etc. that already do something similar, so I just thought in hindsight if we can
> do the same.
> if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
> {
> <new code here>
> }
> else
> {
> /* Protocol 2.0 isn't supported */
> printfPQExpBuffer(&conn->errorMessage,
> libpq_gettext("function requires at least protocol version 3.0\n"));
> return 0;
> }
>
> But if it's necessary to provide this improved trace output for 2.0 servers, then ignore what
> I suggested above, and although difficult I think we should test for protocol 2.0 in older server.
>
> Some minor code comments I noticed:
> 1.
> + LOG_FIRST_BYTE, /* logging the first byte identifing the
> + * protocol message type */
>
> "identifing" should be "identifying". And closing */ should be on 3rd line.
>
> 2.
> + case LOG_CONTENTS:
> + /* Suppresses printing terminating zero byte */
>
> --> Suppress printing of terminating zero byte
>

The patch got some review comments a couple weeks ago but the patch
was still marked as "needs review", which was incorrect. Also cfbot[1]
is unhappy with this patch. So I'm switching the patch as "waiting on
author".

Regards,

[1] http://commitfest.cputube.org/

--
Masahiko Sawada
EnterpriseDB: https://www.enterprisedb.com/

Hi Iwata-san

I reviewed v10-0001-libpq-trace.patch. (But I don't check recent discussion...)
I found some bugs.
I'm suggesting some refactoring.

****
@@ -6809,7 +6809,17 @@ PQtrace(PGconn *conn, FILE *debug_port)
+ if (pqTraceInit(conn))
+ {
+ conn->Pfdebug = debug_port;
+ setlinebuf(conn->Pfdebug);

If debug_port is NULL, setlinebuf() causes segmentation fault.
We should have policy that libpq-trace framework works only when
Pfdebug is not NULL.

For example, we should also think that PQtrace(conn, NULL) has same
effect as PQuntrace(conn).

****
+ 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, /* \x65 ... \0x6d */

There should be 9 zero, but 15 zero.

****
@@ -85,7 +228,7 @@ pqGetc(char *result, PGconn *conn)
if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend> %c\n", *result);
+ pqLogMsgByte1(conn, *result, FROM_BACKEND);

I suggest to move confirming Pfdebug to pqLogMsgByte1() and
other logging functions. If you want to avoid overhead of calling
function, use macro function like the following:

#define pqLogMsgByte1(CONN, CH, SOURCE) \
((CONN)->Pfdebug ? pqLogMsgByte1(CONN, CH, SOURCE) : 0)

****
@@ -168,7 +310,7 @@ 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);
+ pqStoreFrontendMsg(conn, LOG_STRING, strlen(s) + 1);

It's better that you store strlen(s) to local variable and use it.
strlen(s) is not cost-free.

****
@@ -301,11 +431,15 @@ pqPutInt(int value, size_t bytes, PGconn *conn)
tmp2 = pg_hton16((uint16) value);
if (pqPutMsgBytes((const char *) &tmp2, 2, conn))
return EOF;
+ if (conn->Pfdebug)
+ pqStoreFrontendMsg(conn, LOG_INT16, 2);
break;
case 4:
tmp4 = pg_hton32((uint32) value);
if (pqPutMsgBytes((const char *) &tmp4, 4, conn))
return EOF;
+ if (conn->Pfdebug)
+ pqStoreFrontendMsg(conn, LOG_INT32, 4);
break

It's better to make the style same as pqGetInt().
(It is not important.)

switch(bytes) {
case 2:
type = LOG_INT16;
break;
case 4:
type = LOG_INT32;
break;
}
pqStoreFrontendMsg(conn, type, bytes);

****
+pqTraceInit(PGconn *conn)
+{
+ conn->fe_msg = malloc(MAX_FRONTEND_MSGS * sizeof(pqFrontendMessage));
+ if (conn->fe_msg == NULL)
+ {
+ free(conn->be_msg);
+ return false;

Maybe, we need to clear conn->be_msg by NULL for next calling pqTraceInit().

****
+pqTraceInit(PGconn *conn)
+{
+ conn->fe_msg = malloc(MAX_FRONTEND_MSGS * sizeof(pqFrontendMessage));
+ conn->n_fe_msgs = 0;

Data structure design is odd.
Frontend message is basically constructed as the following:
- message type
- message length
- field
- field
- field

So the deisign may be as the follwong and remove n_fe_msg from pg_conn.

typedef struct pqFrontendMessageField
{
int offset_in_buffer; message_addr is not real address.
int length; message_length is wrong name. it is length of FIELD.
} pqFrontendMessageField;

typedef struct pqFrontendMessage
{
PGLogMsgDataType type;
int field_num;
pqFrontendMessageField fields[FLEXIBLE_ARRAY_MEMBER];
} pqFrontendMessage;

And then pqTraceInit() is as the following.
conn->fe_msg = malloc(sizeof(pqFrontendMessage) +
MAX_FRONTEND_MSG_FIELDS * sizeof(pqFrontendMessage));
conn->fe_msg->field_num = 0;

****
+pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
+ return "UnknownCommand";

It is "UnknownMessageType", isn't it?

****
+ * XXX -- ??
+ * Message length is added at the last if message is sent by the frontend.
+ * To arrange the log output format, frontend message contents are stored in the list.

I understand as the following:
* The message length is fixed after putting the last field,
* but message length should be print before printing any field.
* So we must store the field data in memory.

****
+pqStoreFrontendMsg(PGconn *conn, PGLogMsgDataType type, int length)
+ case LOG_STRING:
+ memcpy(&message, conn->outBuffer + conn->outMsgEnd - length, length);
+ fprintf(conn->Pfdebug, "To backend> \"%c\"\n", message);

%s is correct.
At least, %c is not correct.

****
+pqStoreFrontendMsg(PGconn *conn, PGLogMsgDataType type, int length)
+ case LOG_BYTE1:
+ memcpy(&message, conn->outBuffer + conn->outMsgEnd - length, length);

It is unnecessary to call memcpy().
LOG_BYTE1, LOG_STRING, and LOG_NCHAR can be passed its pointer directly to fprintf().
You can also pass LOG_INT* data with casting to fprintf() without memcpy(), but I think either is fine.

****
+ case LOG_INT16:
+ fprintf(conn->Pfdebug, "To backend (#%d)> %c\n", length, result);
+ case LOG_INT32:
+ fprintf(conn->Pfdebug, "To backend (#%d)> %c\n", length, result);

%d is correct.
At least, %c is not correct.

****
+pqStoreFrontendMsg(PGconn *conn, PGLogMsgDataType type, int length)
+ char message;
+ uint16 result16 = 0;
+ uint32 result32 = 0;
+ int result = 0;

It's better that these variables declared in each block.
Initializing result* is unnecessary.

case LOG_INT16:
{
uint16 wk;
memcpy(&wk, conn->outBuffer + conn->outMsgEnd - 2, 2);
wk = pg_ntoh16(wk);
fprintf(conn->Pfdebug, "To backend (#%d)> %h\n", 2, wk);
break;
}

****
+pqLogFrontendMsg(PGconn *conn)
+ int message_addr;
+ int length;
+ char message;
+ uint16 result16 = 0;
+ uint32 result32 = 0;
+ int result = 0;

Same as pqStoreFrontendMsg().

+ memcpy(&message, conn->outBuffer + message_addr, length);

Same as pqStoreFrontendMsg().

****
+pqLogMsgByte1(PGconn *conn, char v, PGCommSource commsource)
+ char *message_source = commsource == FROM_BACKEND ? "<" : ">";

I understand that 'commsource' means source, but message_source means direction of sending.
It is better that the variable is named message_direction.

****
+pqLogMsgByte1(PGconn *conn, char v, PGCommSource commsource)
+ case LOG_FIRST_BYTE:
+ if (v == '\0')
+ return;

Maybe is it needed for packets whose msg_type is '\0'?

I get the following output because pqLogMsgnchar() is called
at conn->be_msg->state == LENGTH. I attach a program for reproduction.

2020-12-25 00:58:48 UTC > StartupMessage :::Invalid Protocol

I think confusing transition of state causes it.
I suggest refactoring instead of fixing the above bug.

msg_type of Startup packet, SSLRequest packet, and GSSNegotiate packet
is '\0'. (I guess GSSNegotiate packet may be forgotten).
At these packet, Byte1 is not sent actually, but if libpq-trace framework consider
that it is sent, the transition may become more clear like the following:

pqLogMsgByte1(PGconn *conn, char v, PGCommSource commsource)
:
fprintf(conn->Pfdebug, "%s %s ", timestr, message_source);
/*
* True type of message tagged '\0' is known when next 4 bytes is checked.
* So we delay printing message type to pqLogMsgInt().
*/
if (v != '\0')
fprintf(conn->Pfdebug, "%s ",
pqGetProtocolMsgType((unsigned char) v, commsource));

conn->be_msg->state = LOG_LENGTH;
conn->be_msg->command = v;

pqLogMsgInt(PGconn *conn, int v, int length, PGCommSource commsource)
:

/* remove case LOG_FIRST_BYTE and... */

case LOG_LENGTH:
if (conn->be_msg->command == '\0')
{
/* We delayed to print message type for special message. */
message_addr = conn->fe_msg[0].message_addr;
memcpy(&result32, conn->outBuffer + message_addr, 4);
result = (int) pg_ntoh32(result32);

if (result == NEGOTIATE_SSL_CODE)
message_type = "SSLRequest";
else if (result == NEGOTIATE_GSS_CODE)
message_type = "GSSRequest";
else
message_type = "StartupMessage";
fprintf(conn->Pfdebug, "%s ", message_type);
}

fprintf(conn->Pfdebug, "%d", v);
conn->be_msg->length = v - length;
conn->be_msg->state = LOG_CONTENTS;
pqTraceMaybeBreakLine(0, conn);
break;

****
+pqLogMsgByte1(PGconn *conn, char v, PGCommSource commsource)
+ case LOG_CONTENTS:
+ /* Suppresses printing terminating zero byte */
+ if (v == '\0')
+ fprintf(conn->Pfdebug, "0");

Is the above code for end of 'E' or 'N' message?
We should comment because it is special case.
Additionally, we may confuse whether 0 is numerical character or '\0'.

/*
* 'E' or 'N' message format is as the following:
* 'E' len [byte1-tag string(null-terminated)]* \0(eof-tag)
*
* So we detect eof-tag at pqLogMsgByte1() with LOG_CONTENTS state.
* The eof-tag is data so we should print it.
* On the way, we care other non-ascii character.
*/
if (!isascii(v))
fprintf(conn->Pfdebug, "\\x%02x", v);

****
+pqLogMsgByte1(PGconn *conn, char v, PGCommSource commsource)
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ else
+ fprintf(conn->Pfdebug, "FROM backend> %c\n", v);

Umm. Also see the following.

+pqLogMsgInt(PGconn *conn, int v, int length, PGCommSource commsource)
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ else
+ fprintf(conn->Pfdebug, "To backend (#%d)> %d\n", length, v);

In the later case, "FROM backend" is correct.

The bug is caused by confusing design.
I suggest to refactor that:
- Move callings fprintf() in pqStoreFrontendMsg() to each pqLogMsgXXX()
- pqStoreFrontendMsg() calls each pqLogMsgXXX().

****
+pqLogMsgString(PGconn *conn, const char *v, int length, PGCommSource commsource)
+{
+ if (length < 0)
+ length = strlen(v) + 1;

I cannot find length==-1 route.

****
+pqLogMsgnchar(PGconn *conn, const char *v, int length, PGCommSource commsource)
+ fprintf(conn->Pfdebug, "\'");
+ fwrite(v, 1, length, conn->Pfdebug);
+ fprintf(conn->Pfdebug, "\'");

We should consider that 'v' is binary data.
So it is better to convert non-ascii character to ascii (e.g. x%02x format).

e.g. case of StartupPacket
2020-12-25 08:07:42 UTC > StartupMessage 40 'userk5userdatabasetemplate1'

The length of StartupPacket includes length itselft.
The length of 'user...tepmlate1' is only 27.
We could not find 8 bytes(40 - 4 - 27 = 8).

If non-ascii character is printed, we can find them.
2020-12-25 08:29:19 UTC > StartupMessage 40 '\x00\x03\x00\x00user\x00k5user\x00database\x00template1\x00\x00'

static void
pqLogMsgBinary(PGconn *conn, const char *v, int length, PGCommSource commsource)
{
int i, pin;
for (pin = i = 0; i < length; ++i)
{
if (isprint(v[i]))
continue;
else
{
fwrite(v + pin, 1, i - pin, conn->Pfdebug);
fprintf(conn->Pfdebug, "\\x%02x", v[i]);
pin = i + 1;
}
}
if (pin < length)
fwrite(v + pin, 1, length - pin, conn->Pfdebug);
}

****
@@ -123,6 +123,9 @@ pqParseInput3(PGconn *conn)
+ /* Terminate a half-finished logging message */
+ if (conn->Pfdebug)
+ pqTraceMaybeBreakLine(msgLength, conn);
return;

I understand that the above code only want to do [conn->be_msg->length = 0].
If it is true, you should create new wrapper function like pqTraceForcelyTerminateMessage()
and handleSyncLoss() itself should call pqTraceForcelyTerminateMessage().

pqTraceForcelyTerminateMessage()
{
if (conn->be_msg->length > 0)
fprintf(conn->Pfdebug, "\n");

pqTraceResetBeMsg(conn);
}

****
pqSaveParameterStatus(PGconn *conn, const char *name, const char *value)
if (conn->Pfdebug)
fprintf(conn->Pfdebug, "pqSaveParameterStatus: '%s' = '%s'\n",
name, value);

I think the above code has become to be unnecessary because new pqTrace framework
become to print it.

Regards
Ryo Matsumura

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

From: iwata(dot)aya(at)fujitsu(dot)com <iwata(dot)aya(at)fujitsu(dot)com>
> This patch includes these items:

Is there anything else in this revision that is not handled?

Below are my comments.

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 makes the test crash (core dump).

(1)
- conn->Pfdebug = debug_port;
+ if (pqTraceInit(conn))
+ {
+ conn->Pfdebug = debug_port;
+ if (conn->Pfdebug != NULL)
+ setlinebuf(conn->Pfdebug);
+ }
+ else
+ {
+ /* XXX report ENOMEM? */
+ fprintf(conn->Pfdebug, "Failed to initialize trace support\n");
+ fflush(conn->Pfdebug);
+ }
}

* When the passed debug_port is NULL, the function should return after calling PQuntrace().

* Is setlinebuf() available on Windows? Maybe you should use setvbuf() instead.

* I don't see the need for separate pqTraceInit() function, because it is only called here.

(2)
+bool
+pqTraceInit(PGconn *conn)
+{
+ /* already done? */
+ if (conn->be_msg != NULL)
+ {

What's this code for? I think it's sufficient that PQuntrace() frees b_msg and PQtrace() always allocates b_msg.

(3)
+ conn->fe_msg = malloc(sizeof(pqFrontendMessage) +
+ MAX_FRONTEND_MSGS * sizeof(pqFrontendMessageField));
+ conn->fe_msg->field_num = 0;
+ if (conn->fe_msg == NULL)
+ {
+ free(conn->be_msg);
+ /* NULL out for the case that fe_msg malloc fails */
+ conn->be_msg = NULL;
+ return false;
+ }
+ conn->fe_msg->field_num = 0;

The memory for the fields array is one entry larger than necessary. The allocation code would be:

+ conn->fe_msg = malloc(offsetof(pqFrontendMessage, fields) +
+ MAX_FRONTEND_MSGS * sizeof(pqFrontendMessageField));

Also, the line with "field_num = 0" appears twice. The first one should be removed.

(4)
+static void
+pqLogMessageByte1(PGconn *conn, char v, PGCommSource commsource)
+{
...
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ {

I think you can remove the protocol version check in various logging functions, because PQtrace() disables logging when the protocol version is 2.

(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?

(6)
+ * Set up state so that we can trace. NB -- this might be called mutiple

mutiple -> multiple

(7)
+ LOG_FIRST_BYTE, /* logging the first byte identifing the
+ protocol message type */

identifing -> identifying

(8)
+#define pqLogMsgByte1(CONN, CH, SOURCE) \
+((CONN)->Pfdebug ? pqLogMessageByte1(CONN, CH, SOURCE) : 0)

For functions that return void, follow the style of CHECK_FOR_INTERRUPTS() defined in miscadmin.h.

(9)
+ currtime = time(NULL);
+ tmp = localtime(&currtime);
+ strftime(timestr, sizeof(timestr), "%Y-%m-%d %H:%M:%S %Z", tmp);
+
+ fprintf(conn->Pfdebug, "%s %s ", timestr, message_direction);

It's better to have microsecond accuracy, because knowing the accumulation of such fine-grained timings may help to troubleshoot heavily-loaded client cases. You can mimic setup_formatted_log_time() in src/backend/utils/error/elog.c. This is used for the %m marker in log_line_prefix.

(10)
I think it's better to use tabs (or any other character that is less likely to appear in the log field) as a field separator, because it makes it easier to process the log with a spreadsheet or some other tools.

(11)
+ /*
+ * True type of message tagged '\0' is known when next 4 bytes is
+ * checked. So we delay printing message type to pqLogMsgInt()
+ */
+ if (v != '\0')
+ fprintf(conn->Pfdebug, "%s ",
+ pqGetProtocolMsgType((unsigned char) v, commsource));

In what cases does '\0' appear as a message type?

(12)
+static const char *
+pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
+{
+ if (commsource == FROM_BACKEND && c < lengthof(protocol_message_type_b))
+ return protocol_message_type_b[c];
+ else if (commsource == FROM_FRONTEND && c < lengthof(protocol_message_type_f))
+ return protocol_message_type_f[c];
+ else
+ return "UnknownMessage";
+}

This function returns NULL (=0) when protocol_message_type_b/f[c] is 0. That crashes the caller:

+ fprintf(conn->Pfdebug, "%s ",
+ pqGetProtocolMsgType((unsigned char) v, commsource));

Plus, you may as well print the invalid message type. Why don't you do something like this:

+static const char *
+pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
+{
+ static char unknown_message[64];
+ char *msg = NULL;

+ if (commsource == FROM_BACKEND && c < lengthof(protocol_message_type_b))
+ msg = protocol_message_type_b[c];
+ else if (commsource == FROM_FRONTEND && c < lengthof(protocol_message_type_f))
+ msg = protocol_message_type_f[c];
+
+ if (msg == NULL)
+ {
+ sprintf(unknown_message, "Unknown message %02x", c);
+ msg = unknown_message;
+ }
+
+ return msg;
+}

(13)
@@ -156,7 +156,12 @@ pqParseInput3(PGconn *conn)
{
/* If not IDLE state, just wait ... */
if (conn->asyncStatus != PGASYNC_IDLE)
+ {
+ /* Terminate a half-finished logging message */
+ if (conn->Pfdebug)
+ pqTraceForcelyBreakLine(msgLength, conn);
return;
+ }

/*
* Unexpected message in IDLE state; need to recover somehow.

What's this situation like? Why output a new line and reset the trace status?

(14)
+/* pqLogInvalidProtocol: Print that the protocol message is invalid */
+static void
+pqLogInvalidProtocol(PGconn *conn)
+{
+ fprintf(conn->Pfdebug, ":::Invalid Protocol\n");
+ conn->be_msg->state = LOG_FIRST_BYTE;
+}

Is it sufficient to just reset the state field? Isn't it necessary to call pqTraceResetBeMsg() instead?

(15)
@@ -212,15 +368,8 @@ pqSkipnchar(size_t len, PGconn *conn)
...
conn->inCursor += len;
-
return 0;
}

This is an unnecessary removal of an empty line.

(16)
+static void
+pqLogMessageByte1(PGconn *conn, char v, PGCommSource commsource)
+{
+ char *message_direction = commsource == FROM_BACKEND ? "<" : ">";
...
+ switch (conn->be_msg->state)

This function handles messages in both directions. But the switch condition is based on the backend message state (b_msg). How is this correct?

(17)
What's the difference between pqLogMsgString() and pqLogMsgnchar()? They both take a length argument. Do they have to be separate functions?

(18)
if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> %c\n", c);
+ pqStoreFrontendMsg(conn, LOG_BYTE1, 1);

To match the style for backend messages with pqLogMsgByte1 etc., why don't you wrap the conn->Pfdebug check in the macro?

(19)
@@ -520,8 +667,6 @@ pqPutMsgStart(char msg_type, bool force_len, PGconn *conn)
/* allow room for message length */
endPos += 4;
}
- else
- lenPos = -1;

Why is this change necessary?

(20)
+static void
+pqLogFrontendMsg(PGconn *conn)
...
+ for (i = 0; i < conn->fe_msg->field_num; i++)
+ {
+ message_addr = conn->fe_msg->fields[i].offset_in_buffer;
+ length = conn->fe_msg->fields[i].length;
+
+ switch (conn->fe_msg[i].type)
+ {
+ case LOG_BYTE1:

When I saw this switch condition, the confusion exploded. Shouldn't the type should be the attribute of each field as follows?

+ switch (conn->fe_msg->fields[i].type)

I also found the function names for frontend -> backend messages hard to grasp. Could you show the flow of function calls when sending messages to the backend?

(21)
+ uint16 result16;
+ memcpy(&result16, conn->outBuffer + message_addr, length);

You should have an empty line between the declaration part and execution part.

(22)
I couldn't understand pqLogBinaryMsg() at all. Could you explain what it does? Particularly, if all bytes in the string is printable, the function seems to do nothing:

+ if (isprint(v[i]))
+ continue;

Should the following part be placed outside the for loop? What does 'pin' mean? (I want the variable name to be more intuitive.)

+ if (pin < length)
+ fwrite(v + pin, 1, length - pin, conn->Pfdebug);

Regards
Takayuki Tsunakawa

Dear Tsunakawa-san, Iwata-san,

> * Is setlinebuf() available on Windows? Maybe you should use setvbuf() instead.

Yeah, cfbot2021 throws errors:
https://ci.appveyor.com/project/postgresql-cfbot/postgresql/build/1.0.124922

```
src/interfaces/libpq/fe-connect.c(6776): warning C4013: 'setlinebuf' undefined; assuming extern returning int [C:\projects\postgresql\libpq.vcxproj]
```

The manpage of setlinebuf() suggests how to replace it, so you should follow.

```
The setbuffer() function is the same, except that the size of the buffer is up to the caller, rather than being determined by the
default BUFSIZ. The setlinebuf() function is exactly equivalent to the call:

setvbuf(stream, NULL, _IOLBF, 0);
```

Hayato Kuroda
FUJITSU LIMITED

Hi Iwata-san,

In addition to Tsunakawa-san's comments,
The compiler also complains:
fe-misc.c:678:20: error: ‘lenPos’ may be used uninitialized in this function [-Werror=maybe-uninitialized]
conn->outMsgStart = lenPos;

There's no need for variable lenPos anymore since we have decided *not* to support pre protocol 3.0.
And by that we have to update the description of pqPutMsgStart too.
So you can remove the lenPos variable and the condition where you have to check for protocol version.

diff --git a/src/interfaces/libpq/fe-misc.c b/src/interfaces/libpq/fe-misc.c
index 8bc9966..3de48be 100644
--- a/src/interfaces/libpq/fe-misc.c
+++ b/src/interfaces/libpq/fe-misc.c
@@ -644,14 +644,12 @@ pqCheckInBufferSpace(size_t bytes_needed, PGconn *conn)
*
* The state variable conn->outMsgStart points to the incomplete message's
* length word: it is either outCount or outCount+1 depending on whether
- * there is a type byte. If we are sending a message without length word
- * (pre protocol 3.0 only), then outMsgStart is -1. The state variable
- * conn->outMsgEnd is the end of the data collected so far.
+ * there is a type byte. The state variable conn->outMsgEnd is the end of
+ * the data collected so far.
*/
int
pqPutMsgStart(char msg_type, bool force_len, PGconn *conn)
{
- int lenPos;
int endPos;

/* allow room for message type byte */
@@ -661,9 +659,8 @@ pqPutMsgStart(char msg_type, bool force_len, PGconn *conn)
endPos = conn->outCount;

/* do we want a length word? */
- if (force_len || PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ if (force_len)
{
- lenPos = endPos;
/* allow room for message length */
endPos += 4;
}
@@ -675,7 +672,7 @@ pqPutMsgStart(char msg_type, bool force_len, PGconn *conn)
if (msg_type)
conn->outBuffer[conn->outCount] = msg_type;
/* set up the message pointers */
- conn->outMsgStart = lenPos;
+ conn->outMsgStart = endPos;
conn->outMsgEnd = endPos;

At the same time, the one below lacks one more zero. (Only has 8)
There should be 9 as Matsumura-san mentioned.
+ 0, 0, 0, 0, 0, 0, 0, 0, /* \x65 ... \0x6d */

The following can be removed in pqStoreFrontendMsg():
+ * In protocol v2, we immediately print each message as we receive it.
+ * (XXX why?)

Maybe the following description can be paraphrased:
+ * The message length is fixed after putting the last field, but message
+ * length should be print before printing any fields.So we must store the
+ * field data in memory.
to:
+ * The message length is fixed after putting the last field. But message
+ * length should be printed before printing any field, so we must store
+ * the field data in memory.

In pqStoreFrontendMsg, pqLogMessagenchar, pqLogMessageString,
pqLogMessageInt, pqLogMessageByte1, maybe it is unneccessary to use
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
because you have already indicated in the PQtrace() to return
silently when protocol 2.0 is detected.
+ /* Protocol 2.0 is not supported. */
+ if (PG_PROTOCOL_MAJOR(conn->pversion) < 3)
+ return;

In pqLogMessageInt(),
+ /* We delayed to print message type for special message. */
can be paraphrased to:
/* We delay printing of the following special message_type */

Regards,
Kirk Jamison

On 2021-Jan-17, tsunakawa(dot)takay(at)fujitsu(dot)com wrote:

> * I don't see the need for separate pqTraceInit() function, because it is only called here.

That's true, but it'd require that we move PQtrace() to fe-misc.c,
because pqTraceInit() uses definitions that are private to that file.

> (2)
> +bool
> +pqTraceInit(PGconn *conn)
> +{
> + /* already done? */
> + if (conn->be_msg != NULL)
> + {
>
> What's this code for? I think it's sufficient that PQuntrace() frees b_msg and PQtrace() always allocates b_msg.

The point is to be able to cope with a connection that calls PQtrace()
multiple times, with or without an intervening PQuntrace().
We'd make no friends if we made PQtrace() crash, or leak memory if
called a second time ...

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

> (9)
> + currtime = time(NULL);
> + tmp = localtime(&currtime);
> + strftime(timestr, sizeof(timestr), "%Y-%m-%d %H:%M:%S %Z", tmp);
> +
> + fprintf(conn->Pfdebug, "%s %s ", timestr, message_direction);
>
> It's better to have microsecond accuracy, because knowing the accumulation of such fine-grained timings may help to troubleshoot heavily-loaded client cases. You can mimic setup_formatted_log_time() in src/backend/utils/error/elog.c. This is used for the %m marker in log_line_prefix.

Yeah, it was me that removed printing of milliseconds -- Iwata-san's
original patch used ftime() which is not portable. I had looked for
portable ways to get this but couldn't find anything that didn't involve
linking backend files, so I punted. But looking again now, it is quite
simple: just use standard strftime and localtime and just concatenate
both together. Similar to what setup_formatted_log_time except we don't
worry about the TZ at all.

> (10)
> I think it's better to use tabs (or any other character that is less likely to appear in the log field) as a field separator, because it makes it easier to process the log with a spreadsheet or some other tools.

I can buy that. I changed it to have some tabs; the lines are now:

timestamp "> or <" <tab> "message type" <tab> length <space> message contents

I think trying to apply tabs inside the message contents is going to be
more confusing than helpful.

> (12)
> [...]
> Plus, you may as well print the invalid message type. Why don't you do something like this:
>
> +static const char *
> +pqGetProtocolMsgType(unsigned char c, PGCommSource commsource)
> +{
> + static char unknown_message[64];
> + char *msg = NULL;
>
> + if (commsource == FROM_BACKEND && c < lengthof(protocol_message_type_b))
> + msg = protocol_message_type_b[c];
> + else if (commsource == FROM_FRONTEND && c < lengthof(protocol_message_type_f))
> + msg = protocol_message_type_f[c];
> +
> + if (msg == NULL)
> + {
> + sprintf(unknown_message, "Unknown message %02x", c);
> + msg = unknown_message;
> + }
> +
> + return msg;
> +}

Right. I had written something like this, but in the end decided not to
bother because it doesn't seem terribly important. You can't do exactly
what you suggest, because it has the problem that you're returning a
stack-allocated variable even though your stack is about to be blown
away. My copy had a static buffer that was malloc()ed on first use (and
if allocation fails, return a const string). Anyway, I fixed the
crasher problem.

The protocol_message_type_b array had the serious problem it confused
the entry for byte 1 (0x01) with that of char '1' (and 2 and 3), so it
printed a lot of 'Unknown message' lines. Clearly, the maintenance of
this array is going to be a pain point of this patch (counting number of
zeroes is no fun), and I think we're going to have some way to have an
explicit initializer, where we can do things like
protocol_message_type_b['A'] = "NotificationResponse";
etc instead of the current way, which is messy, hard to maintain.
I'm not sure how to do that and not make things worse, however.

> (16)
> +static void
> +pqLogMessageByte1(PGconn *conn, char v, PGCommSource commsource)
> +{
> + char *message_direction = commsource == FROM_BACKEND ? "<" : ">";
> ...
> + switch (conn->be_msg->state)
>
> This function handles messages in both directions. But the switch condition is based on the backend message state (b_msg). How is this correct?

It's not.

I split things so that this function only prints backend messages; when
frontend messages are to be printed, we use a single fprintf() instead.
See about (20), below.

>
> (17)
> What's the difference between pqLogMsgString() and pqLogMsgnchar()? They both take a length argument. Do they have to be separate functions?

nchar are not null-terminated and we escape !isprint() characters. I'm
not sure that the difference is significant enough, but I'm also not
sure if they can be merged into one.

> (18)
> if (conn->Pfdebug)
> - fprintf(conn->Pfdebug, "To backend> %c\n", c);
> + pqStoreFrontendMsg(conn, LOG_BYTE1, 1);
>
> To match the style for backend messages with pqLogMsgByte1 etc., why don't you wrap the conn->Pfdebug check in the macro?

I think these macros are useless and should be removed. There's more
verbosity and confusion caused by them, than the clarity they provide.

> (20)
> +static void
> +pqLogFrontendMsg(PGconn *conn)
> ...
> + for (i = 0; i < conn->fe_msg->field_num; i++)
> + {
> + message_addr = conn->fe_msg->fields[i].offset_in_buffer;
> + length = conn->fe_msg->fields[i].length;
> +
> + switch (conn->fe_msg[i].type)
> + {
> + case LOG_BYTE1:
>
> When I saw this switch condition, the confusion exploded. Shouldn't the type should be the attribute of each field as follows?
>
> + switch (conn->fe_msg->fields[i].type)
>
> I also found the function names for frontend -> backend messages hard to grasp. Could you show the flow of function calls when sending messages to the backend?

Exactly! I was super confused about this too, and eventually decided to
rewrite the whole thing so that the 'type' is in the Fields struct. And
while doing that, I noticed that it would make more sense to let the
fe_msg array be realloc'ed if it gets full, rather than making it fixed
size. This made me add pqTraceUninit(), so that we can free the array
if it has grown, to avoid reserving arbitrarily large amounts of memory
after PQuntrace() on a session that traced large messages.

> (22)
> I couldn't understand pqLogBinaryMsg() at all. Could you explain what it does? Particularly, if all bytes in the string is printable, the function seems to do nothing:
>
> + if (isprint(v[i]))
> + continue;
>
> Should the following part be placed outside the for loop? What does 'pin' mean? (I want the variable name to be more intuitive.)
>
> + if (pin < length)
> + fwrite(v + pin, 1, length - pin, conn->Pfdebug);

Yes :-( I fixed that too.

This patch needs more work still, of course.

--
Álvaro Herrera Valdivia, Chile
"Java is clearly an example of money oriented programming" (A. Stepanov)

Hello Alvaro-san, Iwata-san,

First of all, thank you Alvaro-san really a lot for your great help. I'm glad you didn't lose interest and time for this patch yet. (Iwata-san is my colleague.)

From: Alvaro Herrera <alvherre(at)alvh(dot)no-ip(dot)org>
> That's true, but it'd require that we move PQtrace() to fe-misc.c, because
> pqTraceInit() uses definitions that are private to that file.

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.

> > What's this code for? I think it's sufficient that PQuntrace() frees b_msg
> and PQtrace() always allocates b_msg.
>
> The point is to be able to cope with a connection that calls PQtrace() multiple
> times, with or without an intervening PQuntrace().
> We'd make no friends if we made PQtrace() crash, or leak memory if called a
> second time ...

HEAD's PQtrace() always call PQuntrace() and then re-initialize from scratch. So, if we keep that flow, the user can call PQtrace() multiple in a row.

> I think trying to apply tabs inside the message contents is going to be more
> confusing than helpful.

Agreed.

> > Plus, you may as well print the invalid message type. Why don't you do
> something like this:
> >
> > +static const char *
> > +pqGetProtocolMsgType(unsigned char c, PGCommSource commsource) {
> > + static char unknown_message[64];
> > + char *msg = NULL;
> >
> > + if (commsource == FROM_BACKEND && c <
> lengthof(protocol_message_type_b))
> > + msg = protocol_message_type_b[c];
> > + else if (commsource == FROM_FRONTEND && c <
> lengthof(protocol_message_type_f))
> > + msg = protocol_message_type_f[c];
> > +
> > + if (msg == NULL)
> > + {
> > + sprintf(unknown_message, "Unknown message %02x", c);
> > + msg = unknown_message;
> > + }
> > +
> > + return msg;
> > +}
>
> Right. I had written something like this, but in the end decided not to bother
> because it doesn't seem terribly important. You can't do exactly what you
> suggest, because it has the problem that you're returning a stack-allocated
> variable even though your stack is about to be blown away. My copy had a
> static buffer that was malloc()ed on first use (and if allocation fails, return a
> const string). Anyway, I fixed the crasher problem.

My suggestion included static qualifier to not use the stack, but it doesn't work anyway in multi-threaded applications. So I agree that we don't print the invalid message type value.

> > (18)
> > if (conn->Pfdebug)
> > - fprintf(conn->Pfdebug, "To backend> %c\n", c);
> > + pqStoreFrontendMsg(conn, LOG_BYTE1, 1);
> >
> > To match the style for backend messages with pqLogMsgByte1 etc., why
> don't you wrap the conn->Pfdebug check in the macro?
>
> I think these macros are useless and should be removed. There's more
> verbosity and confusion caused by them, than the clarity they provide.

Agreed.

> This patch needs more work still, of course.

Yes, she is updating the patch based on the feedback from you, Kirk-san, and me.

By the way, I just looked at the beginning of v12.

-void PQtrace(PGconn *conn, FILE *stream);
+void PQtrace(PGconn *conn, FILE *stream, bits32 flags);

Can we change the signature of an API function?

Iwata-san,
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.

Regards
Takayuki Tsunakawa

Hello, just two quick comments on this,

On 2021-Jan-22, tsunakawa(dot)takay(at)fujitsu(dot)com wrote:

> From: Alvaro Herrera <alvherre(at)alvh(dot)no-ip(dot)org>
> > That's true, but it'd require that we move PQtrace() to fe-misc.c, because
> > pqTraceInit() uses definitions that are private to that file.
>
> 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.

> > The point is to be able to cope with a connection that calls PQtrace() multiple
> > times, with or without an intervening PQuntrace().
> > We'd make no friends if we made PQtrace() crash, or leak memory if called a
> > second time ...
>
> HEAD's PQtrace() always call PQuntrace() and then re-initialize from
> scratch. So, if we keep that flow, the user can call PQtrace()
> multiple in a row.

Oh, of course.

--
Álvaro Herrera Valdivia, Chile
"No necesitamos banderas
No reconocemos fronteras" (Jorge González)

First, some possibly major questions:

(23)
From: 'Alvaro Herrera' <alvherre(at)alvh(dot)no-ip(dot)org>
> 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.

What do you think about this suggestion? I think this is reasonable, including moving PQtrace/PQuntrace to the new file.

OTOH, fe-misc also has humble reasons to contain them. One is that the file header comment is as follows, accepting miscellaneous stuff. Another is that although most functions in fe-misc.c are related to protocol data transmission and receipt, several functions at the end of the file are already not related.

* fe-misc.c
*
* DESCRIPTION
* miscellaneous useful functions

(24)
-void PQtrace(PGconn *conn, FILE *stream);
+void PQtrace(PGconn *conn, FILE *stream, bits32 flags);
</synopsis>
</para>

+ <para>
+ <literal>flags</literal> contains flag bits describing the operating mode
+ of tracing. If <literal>(flags & TRACE_SUPPRESS_TIMESTAMPS)</literal> is
+ true, then timestamps are not printed with each message.
+ </para>

As I asked in the previous mail, I'm afraid we cannot change the signature of existing API functions. If we want this flag bits, we have to add something like PQtraceEx(), don't we?

The flag name differs between in the manual and in the source code:

+#define PQTRACE_SUPPRESS_TIMESTAMPS (1 << 0)

P.S.
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).

Regards
Takayuki Tsunakawa

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

Iwata-san, all,

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 guess only Alvaro-san and me, who are listed in To:, received the original mail.

Iwata-san,
Please ask pgsql-www list about this problem.

[1]
https://commitfest.postgresql.org/31/2889/

Regards
Takayuki Tsunakawa

> -----Original Message-----
> From: Iwata, Aya/岩田 彩 <iwata(dot)aya(at)fujitsu(dot)com>
> Sent: Monday, January 25, 2021 10:34 AM
> To: 'Alvaro Herrera' <alvherre(at)alvh(dot)no-ip(dot)org>; Tsunakawa, Takayuki/綱川 貴
> 之 <tsunakawa(dot)takay(at)fujitsu(dot)com>
> Cc: 'pgsql-hackers(at)lists(dot)postgresql(dot)org'
> <pgsql-hackers(at)lists(dot)postgresql(dot)org>
> Subject: 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

Hello,

I have not tested nor review the latest patch changes yet, but I am reporting the compiler errors.
I am trying to compile the patch since V12 (Alvaro's version), but the following needs to
be fixed too because of the complaints: doc changes and undeclared INT_MAX

libpq.sgml:5893: parser error : xmlParseEntityRef: no name
of tracing. If <literal>(flags & TRACE_SUPPRESS_TIMESTAMPS)</literal> is
^
libpq.sgml:8799: parser error : chunk is not well balanced
postgres.sgml:195: parser error : Failure to process entity libpq
&libpq;
^
postgres.sgml:195: parser error : Entity 'libpq' not defined
&libpq;
^
...
fe-misc.c: In function ‘pqStoreFrontendMsg’:
fe-misc.c:903:35: error: ‘INT_MAX’ undeclared (first use in this function)
if (conn->fe_msg->max_fields > INT_MAX / 2)

Regards,
Kirk Jamison

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

Iwata-san,

(25)
+ conn->fe_msg = malloc(sizeof(offsetof(pqFrontendMessage, fields)) +
+ DEF_FE_MSGFIELDS * sizeof(pqFrontendMessageField));

It's incorrect that offsetof() is nested in sizeof(). See my original review comment.

(26)
+bool
+pqTraceInit(PGconn *conn, bits32 flags)
+{
...
+ conn->be_msg->state = LOG_FIRST_BYTE;
+ conn->be_msg->length = 0;
+ }
...
+ conn->be_msg->state = LOG_FIRST_BYTE;
+ conn->be_msg->length = 0;

The former is redundant?

(27)
+/*
+ * Deallocate frontend-message tracking memory. We only do this because
+ * it can grow arbitrarily large, and skip it in the initial state, because
+ * it's likely pointless.
+ */
+void
+pqTraceUninit(PGconn *conn)
+{
+ if (conn->fe_msg &&
+ conn->fe_msg->num_fields != DEF_FE_MSGFIELDS)
+ {
+ pfree(conn->fe_msg);
+ conn->fe_msg = NULL;
+ }
+}

I thought this function plays the reverse role of pqTraceInit(), but it only frees memory for frontend messages. Plus, use free() instead of pfree(), because malloc() is used to allocate memory.

(28)
+void PQtrace(PGconn *conn, FILE *stream, bits32 flags);

bits32 can't be used because it's a data type defined in c.h, which should not be exposed to applications. I think you can just int or something.

Considering these and the compilation error Kirk-san found, I'd like you to do more self-review before I resume this review.

Regards
Takayuki Tsunakawa

On 2021-Jan-25, tsunakawa(dot)takay(at)fujitsu(dot)com wrote:

> Iwata-san,

[...]

> Considering these and the compilation error Kirk-san found, I'd like
> you to do more self-review before I resume this review.

Kindly note that these errors are all mine.

Thanks for the review

--
Álvaro Herrera 39°49'30"S 73°17'W
#error "Operator lives in the wrong universe"
("Use of cookies in real-time system development", M. Gleixner, M. Mc Guire)

On Mon, Jan 25, 2021 10:11 PM (JST), Alvaro Herrera wrote:
> On 2021-Jan-25, tsunakawa(dot)takay(at)fujitsu(dot)com wrote:
>
> > Iwata-san,
>
> [...]
>
> > Considering these and the compilation error Kirk-san found, I'd like
> > you to do more self-review before I resume this review.
>
> Kindly note that these errors are all mine.
>
> Thanks for the review
>
Hello,
To make the CFBot happy, I fixed the compiler errors.
I have not included here the change proposal to move the tracing functions
to a new file: fe-trace.c or something, so I retained the changes .
Maybe Iwata-san can consider the proposal.
Currently, both pqTraceInit() and pqTraceUninit() are called only by one function.

Summary:
1. I changed the bits32 flags to int flags
2. I assumed INT_MAX value is the former MAX_FRONTEND_MSGS
I defined it to solve the compile error. Please tell if the value was wrong.
3. Fixed the doc errors
4. Added freeing of be_msg in pqTraceUninit()
5. Addressed the following comments:

> (25)
> + conn->fe_msg =
> malloc(sizeof(offsetof(pqFrontendMessage, fields)) +
> +
> DEF_FE_MSGFIELDS * sizeof(pqFrontendMessageField));
>
> It's incorrect that offsetof() is nested in sizeof(). See my original
> review comment.

I removed the initial sizeof().

> (26)
> +bool
> +pqTraceInit(PGconn *conn, bits32 flags) {
> ...
> + conn->be_msg->state = LOG_FIRST_BYTE;
> + conn->be_msg->length = 0;
> + }
> ...
> + conn->be_msg->state = LOG_FIRST_BYTE;
> + conn->be_msg->length = 0;
>
> The former is redundant?

Right. I've removed the former.

> (27)
> +/*
> + * Deallocate frontend-message tracking memory. We only do this
> +because
> + * it can grow arbitrarily large, and skip it in the initial state,
> +because
> + * it's likely pointless.
> + */
> +void
> +pqTraceUninit(PGconn *conn)
> +{
> + if (conn->fe_msg &&
> + conn->fe_msg->num_fields != DEF_FE_MSGFIELDS)
> + {
> + pfree(conn->fe_msg);
> + conn->fe_msg = NULL;
> + }
> +}
>
> I thought this function plays the reverse role of pqTraceInit(), but
> it only frees memory for frontend messages. Plus, use free() instead
> of pfree(), because
> malloc() is used to allocate memory.

Fixed to use free(). Also added the freeing of be_msg.

> (28)
> +void PQtrace(PGconn *conn, FILE *stream, bits32 flags);
>
> bits32 can't be used because it's a data type defined in c.h, which
> should not be exposed to applications. I think you can just int or something.

I used int. It still works to suppress the timestamp when flags is true.

In my environment, when flags is false(0):
2021-01-28 06:26:11.368 > Query 27 "COPY country TO STDOUT"
2021-01-28 06:26:11.368 > Query -1
2021-01-28 06:26:11.369 < CopyOutResponse 13 \x00 #3 #0 #0 #0
2021-01-28 06:26:11.369 < CopyDone 4

2021-01-28 06:26:11.369 < CopyDone 4
2021-01-28 06:26:11.369 < CopyDone 4
2021-01-28 06:26:11.369 < CommandComplete 11 "COPY 0"
2021-01-28 06:26:11.369 < ReadyForQuery 5
2021-01-28 06:26:11.369 > Terminate 4
2021-01-28 06:26:11.369 > Terminate -1

When flags is true(1), running the same query:
> Query 27 "COPY country TO STDOUT"
> Query -1
< CopyOutResponse 13 \x00 #3 #0 #0 #0
< CopyDone 4

< CopyDone 4
< CopyDone 4
< CommandComplete 11 "COPY 0"
< ReadyForQuery 5
> Terminate 4
> Terminate -1

Regards,
Kirk Jamison

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

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"

From: Jamison, Kirk/ジャミソン カーク <k(dot)jamison(at)fujitsu(dot)com>
> To make the CFBot happy, I fixed the compiler errors.
> I have not included here the change proposal to move the tracing functions to a
> new file: fe-trace.c or something, so I retained the changes .
> Maybe Iwata-san can consider the proposal.
> Currently, both pqTraceInit() and pqTraceUninit() are called only by one
> function.

I confirmed all mentioned points have been fixed. Additional comments are:

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

But... can you evaluate the overhead for getting timestamps and see if we can turn it on by default, or further, if we need such a flag and PQtraceEx()? For example, how about comparing the times to run the regression test with and without timestamps?

(30)
+/*
+ * Deallocate FE/BE message tracking memory. We only do this because
+ * FE message can grow arbitrarily large, and skip it in the initial state,
+ * because it's likely pointless.
+ */
+void
+pqTraceUninit(PGconn *conn)
+{
+ if (conn->fe_msg &&
+ conn->fe_msg->num_fields != DEF_FE_MSGFIELDS)
+ {
+ free(conn->fe_msg);
+ conn->fe_msg = NULL;
+ }

What does the second if condition mean? If it's not necessary, change the comment accordingly.

(31)
@@ -1011,11 +1615,16 @@ pqSendSome(PGconn *conn, int len)
int
pqFlush(PGconn *conn)
{
- if (conn->Pfdebug)
- fflush(conn->Pfdebug);
-
if (conn->outCount > 0)
+ {
+ /* XXX comment */
+ if (conn->Pfdebug)
+ {
+ pqLogFrontendMsg(conn, -1);
+ fflush(conn->Pfdebug);
+ }
return pqSendSome(conn, conn->outCount);
+ }

Remove the comment line.

(32)
+#define INT_MAX (2048/2) /* maximum array size */

INT_MAX is available via:
#include <limits.h>

(33)
/* realloc failed. Probably out of memory */
- appendPQExpBufferStr(&conn->errorMessage,
- "cannot allocate memory for input buffer\n");
+ appendPQExpBuffer(&conn->errorMessage,
+ "cannot allocate memory for input buffer\n");

This change appears to be irrelevant.

(34)
+static void
+pqStoreFeMsgStart(PGconn *conn, char type)
+{
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ conn->fe_msg->msg_type = type;
+}

Protocol version check is unnecessary because this tracing takes effect only in v3 protocol?

(35)
+ conn->fe_msg =
+ realloc(conn->fe_msg,
+ sizeof(pqFrontendMessage) +
+ 2 * conn->fe_msg->max_fields * sizeof(pqFrontendMessageField));

Align this size calculation with that in pqTraceInit().

(36)
+ /* append milliseconds */
+ sprintf(timestr + strlen(timestr), ".%03d", (int) (tval.tv_usec / 1000));

Output microsecond instead. As your example output shows, many lines show the exactly same timestamps and thus they are not distinguishable in time.

(37)
+static char *
+pqLogFormatTimestamp(char *timestr)
+{
...
+#define FORMATTED_TS_LEN 128
+ strftime(timestr, FORMATTED_TS_LEN,

Add an argument to this function that indicates the size of timestr. Define FORMATTED_TS_LEN globally in this source file, and have callers use it. That is, the code like:

+ char timestr[128];
+
+ fprintf(conn->Pfdebug, "%s\t>\t%s\t%d",
+ pqLogFormatTimestamp(timestr),

becomes:

+ char timestr[FORMATTED_TS_LEN];
+
+ fprintf(conn->Pfdebug, "%s\t>\t%s\t%d",
+ pqLogFormatTimestamp(timestr, sizeof(timestr)),

(38)
+ if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
+ {
+ char timestr[128];
+
+ fprintf(conn->Pfdebug, "%s\t>\t%s\t%d",
+ pqLogFormatTimestamp(timestr),
+ pqGetProtocolMsgType(conn->fe_msg->msg_type,
+ MSGDIR_FROM_FRONTEND),
+ msgLen);
+ }
+ else
+ fprintf(conn->Pfdebug, ">\t%s\t%d",
+ pqGetProtocolMsgType(conn->fe_msg->msg_type,
+ MSGDIR_FROM_FRONTEND),
+ msgLen);

To reduce the code for easier modification, change the above code to something like:

+ char timestr[128];
+ char *timestr_p = "";
+
+ if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
+ timestr_p = pqLogFormatTimestamp(timestr);
+ fprintf(conn->Pfdebug, "%s\t>\t%s\t%d",
+ timestr_p,
+ pqGetProtocolMsgType(conn->fe_msg->msg_type,
+ MSGDIR_FROM_FRONTEND),
+ msgLen);

Regards
Takayuki Tsunakawa

From: Jamison, Kirk/ジャミソン カーク <k(dot)jamison(at)fujitsu(dot)com>
> 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.

To run the tracing code in much more extensive cases, can you try running the whole SQL regression test with the tracing enabled? That is, run "make check-world" in the top directory of the source tree.

To enable tracing in every connection, you can probably insert PQtrace() call just before the return statement here in connectDBComplete(). If you have enough disk space, it's better to accumulate the trace output by passing "a" to fopen().

switch (flag)
{
case PGRES_POLLING_OK:
return 1; /* success! */

Regards
Takayuki Tsunakawa

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 <alvherre(at)alvh(dot)no-ip(dot)org>
> 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' <alvherre(at)alvh(dot)no-ip(dot)org>
> 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' <alvherre(at)alvh(dot)no-ip(dot)org>
> Sent: Thursday, January 28, 2021 11:14 PM
...
> 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.

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... can you evaluate the overhead for getting timestamps and see if we can
> turn it on by default, or further, if we need such a flag and PQtraceEx()? For
> example, how about comparing the times to run the regression test with and
> without timestamps?

I will check it. And decide which is better by default.
In my understanding, one of the purpose of this flag is to make sure
the log order is correct regardless of timestamp. (for example, it is useful auto-regression test)
I think PQtraceEx() and this flag is necessary as a developer option at least.

> (30)
> +/*
> + * Deallocate FE/BE message tracking memory. We only do this because
> + * FE message can grow arbitrarily large, and skip it in the initial state,
> + * because it's likely pointless.
> + */
> +void
> +pqTraceUninit(PGconn *conn)
> +{
> + if (conn->fe_msg &&
> + conn->fe_msg->num_fields != DEF_FE_MSGFIELDS)
> + {
> + free(conn->fe_msg);
> + conn->fe_msg = NULL;
> + }
>
> What does the second if condition mean? If it's not necessary, change the
> comment accordingly.

I fix the comment and remove second if.

> (31)
> @@ -1011,11 +1615,16 @@ pqSendSome(PGconn *conn, int len)
> int
> pqFlush(PGconn *conn)
> {
> - if (conn->Pfdebug)
> - fflush(conn->Pfdebug);
> -
> if (conn->outCount > 0)
> + {
> + /* XXX comment */
> + if (conn->Pfdebug)
> + {
> + pqLogFrontendMsg(conn, -1);
> + fflush(conn->Pfdebug);
> + }
> return pqSendSome(conn, conn->outCount);
> + }
>
> Remove the comment line.

I remove it.

> (32)
> +#define INT_MAX (2048/2) /* maximum array size */
>
> INT_MAX is available via:
> #include <limits.h>

I fixed it.

> (33)
> /* realloc failed. Probably out of memory */
> - appendPQExpBufferStr(&conn->errorMessage,
> - "cannot allocate memory
> for input buffer\n");
> + appendPQExpBuffer(&conn->errorMessage,
> + "cannot allocate memory for input
> buffer\n");
>
> This change appears to be irrelevant.

I remove this code.

> (34)
> +static void
> +pqStoreFeMsgStart(PGconn *conn, char type)
> +{
> + if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
> + conn->fe_msg->msg_type = type;
> +}
>
> Protocol version check is unnecessary because this tracing takes effect only in
> v3 protocol?

Yes, in PQtrace(), it is checked whether protocol 2.0 or 3.0 and tracing works only in v3.0. I remove it.

> (35)
> + conn->fe_msg =
> + realloc(conn->fe_msg,
> + sizeof(pqFrontendMessage) +
> + 2 * conn->fe_msg->max_fields *
> sizeof(pqFrontendMessageField));
>
> Align this size calculation with that in pqTraceInit().

I fixed it like this;
+ conn->fe_msg =
+ realloc(conn->fe_msg,
+ offsetof(pqFrontendMessage, fields) +
+ 2 * conn->fe_msg->max_fields * sizeof(pqFrontendMessageField));

> (36)
> + /* append milliseconds */
> + sprintf(timestr + strlen(timestr), ".%03d", (int) (tval.tv_usec / 1000));
>
> Output microsecond instead. As your example output shows, many lines
> show the exactly same timestamps and thus they are not distinguishable in
> time.

I changed %03d to %06d for microsecond.

> (37)
> +static char *
> +pqLogFormatTimestamp(char *timestr)
> +{
> ...
> +#define FORMATTED_TS_LEN 128
> + strftime(timestr, FORMATTED_TS_LEN,
>
> Add an argument to this function that indicates the size of timestr. Define
> FORMATTED_TS_LEN globally in this source file, and have callers use it.
> That is, the code like:
>
> + char timestr[128];
> +
> + fprintf(conn->Pfdebug, "%s\t>\t%s\t%d",
> + pqLogFormatTimestamp(timestr),
>
> becomes:
>
> + char timestr[FORMATTED_TS_LEN];
> +
> + fprintf(conn->Pfdebug, "%s\t>\t%s\t%d",
> + pqLogFormatTimestamp(timestr,
> sizeof(timestr)),

I fixed it.

> (38)
> + if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
> + {
> + char timestr[128];
> +
> + fprintf(conn->Pfdebug, "%s\t>\t%s\t%d",
> + pqLogFormatTimestamp(timestr),
> +
> pqGetProtocolMsgType(conn->fe_msg->msg_type,
> +
> MSGDIR_FROM_FRONTEND),
> + msgLen);
> + }
> + else
> + fprintf(conn->Pfdebug, ">\t%s\t%d",
> +
> pqGetProtocolMsgType(conn->fe_msg->msg_type,
> +
> MSGDIR_FROM_FRONTEND),
> + msgLen);
>
> To reduce the code for easier modification, change the above code to
> something like:
>
> + char timestr[128];
> + char *timestr_p = "";
> +
> + if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
> + timestr_p = pqLogFormatTimestamp(timestr);
> + fprintf(conn->Pfdebug, "%s\t>\t%s\t%d",
> + timestr_p,
> + pqGetProtocolMsgType(conn->fe_msg->msg_type,
> +
> MSGDIR_FROM_FRONTEND),
> + msgLen);

I fixed it.

This patch should address the following:
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 "
2. creating new file for new tracing functions

Regards,
Aya Iwata
Fujitsu

On 2021-Jan-29, tsunakawa(dot)takay(at)fujitsu(dot)com wrote:

> (30)
> +/*
> + * Deallocate FE/BE message tracking memory. We only do this because
> + * FE message can grow arbitrarily large, and skip it in the initial state,
> + * because it's likely pointless.
> + */
> +void
> +pqTraceUninit(PGconn *conn)
> +{
> + if (conn->fe_msg &&
> + conn->fe_msg->num_fields != DEF_FE_MSGFIELDS)
> + {
> + free(conn->fe_msg);
> + conn->fe_msg = NULL;
> + }
>
> What does the second if condition mean? If it's not necessary, change the comment accordingly.

The rationale for that second condition is this: if the memory allocated
is the initial size, we don't free memory, because it would just be
allocated of the same size next time, and that size is not very big, so
it's not a big deal if we just let it be, so that it is reused if we
call PQtrace() again later. However, if the allocated size is larger
than default, then it is possible that some previous tracing run has
enlarged the trace struct to a very large amount of memory, and we don't
want to leave that in place.

--
Álvaro Herrera Valdivia, Chile

(39)
+ of tracing. If (<literal>flags</literal> &amp; <literal>PQTRACE_OUTPUT_TIMESTAMPS</literal>) is
+ true, then timestamp is not printed with each message.

The flag name (OUTPUT) and its description (not printed) doesn't match.

I think you can use less programmatical expression like "If <literal>flags</literal> contains <literal>PQTRACE_OUTPUT_TIMESTAMPS</literal>".

(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?

(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)

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

(43)
+ /* append microseconds */
+ sprintf(timestr + strlen(timestr), ".%06d", (int) (tval.tv_usec / 1000));

"/ 1000" should be removed.

(44)
+ if ((conn->traceFlags & PQTRACE_OUTPUT_TIMESTAMPS) == 0)
+ timestr_p = pqLogFormatTimestamp(timestr, sizeof(timestr));

== 0 should be removed.

Regards
Takayuki Tsunakawa