Date: Wed, 10 Mar 2021 18:26:52 -0300
From: "'alvherre@alvh.no-ip.org'" <alvherre@alvh.no-ip.org>
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: "iwata.aya@fujitsu.com" <iwata.aya@fujitsu.com>,
	"tsunakawa.takay@fujitsu.com" <tsunakawa.takay@fujitsu.com>,
	"k.jamison@fujitsu.com" <k.jamison@fujitsu.com>,
	'Kyotaro Horiguchi' <horikyota.ntt@gmail.com>,
	"pgsql-hackers@lists.postgresql.org" <pgsql-hackers@lists.postgresql.org>
Subject: Re: libpq debug log
Message-ID: <20210310212652.GA3207@alvherre.pgsql>
MIME-Version: 1.0
Content-Type: text/plain; charset=iso-8859-1
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: <2189612.1615406615@sss.pgh.pa.us>
User-Agent: Mutt/1.10.1 (2018-07-13)
Archived-At: 
 <https://www.postgresql.org/message-id/20210310212652.GA3207%40alvherre.pgsql>
Precedence: bulk

On 2021-Mar-10, Tom Lane wrote:

> "'alvherre@alvh.no-ip.org'" <alvherre@alvh.no-ip.org> writes:
> > After staring at it a couple of times, I think that the places in
> > pqParseInput3() where there's a comment "... moves inStart itself" and
> > then "continue;" should have a call to pqTraceOutputMsg(), since AFAIU
> > those are the places where the message in question would not reach the
> > "Successfully consumed this message" block that prints each message.
> 
> Yeah, the whole business of just when a message has been "consumed"
> is a stumbling block for libpq tracing.  It was a real mess with the
> existing code and v2 protocol, because we could actually try to parse
> a message more than once, with the first few tries deciding that the
> message wasn't all here yet (but nonetheless emitting partial trace
> output).

Hmm, that makes sense, but the issue I'm reporting is not the same,
unless I misunderstand you.

> Now that v2 is dead, the logic to abort because of the message not
> being all arrived yet is basically useless: only the little bit of
> code concerned with the message length word really needs to cope with
> that.  It's tempting to go through and get rid of all the now-unreachable
> "return"s and such, but it seemed like it would be a lot of code churn for
> not really that much gain.

That sounds like an interesting exercise, and I bet it'd bring a lot of
code readability improvements.

> I didn't look at the new version of the patch yet, so I'm not
> sure whether the issues it still has are related to this.

The issues I noticed are related to separate messages rather than one
message split in pieces -- for example several DataRow messages are
processed internally in a loop, rather than each individually.  The
number of places that need to be adjusted for things to AFAICT work
correctly are few enough; ISTM that the attached patch is sufficient.

(The business with the "logged" boolean is necessary so that we print to
the trace file any of those messages even if they are deviating from the
protocol.)

-- 
Álvaro Herrera       Valdivia, Chile
"La experiencia nos dice que el hombre peló millones de veces las patatas,
pero era forzoso admitir la posibilidad de que en un caso entre millones,
las patatas pelarían al hombre" (Ijon Tichy)