Re: libpq debug log

On 2021-Mar-15, iwata.aya@fujitsu.com wrote:

> I create protocol message reading function for each protocol message type. (Ex. pqTraceOutputB() read Bind message)
> This makes the nesting shallower and makes the code easier to read.

I'm not sure I agree with this structural change.  Yes, it is less
indentation, but these functions are all quite short and simple anyway.
But I don't disagree strongly with it either.

Four issues:
* There's no cross-check that the protocol message length word
  corresponds to what we actually print.  I think one easy way to
  cross-check that would be to return the "count" from the type-specific
  routines, and verify that it matches "length" in pqTraceOutputMessage.
  (If the separate routines are removed and the code put back in one
  giant switch, then the "count" is already available when the switch
  ends.)

* If we have separate functions for each message type, then we can have
  that function supply the message name by itself, rather than have the
  separate protocol_message_type_f / _b arrays that print it.

* If we make each type-specific function print the message name, then we
  need to make the same function print the message length, because it
  comes after.  So the function would have to receive the length (so
  that it can be printed).  But I think we should still have the
  cross-check I mentioned in my first point occur in the main
  pqTraceOutputMessage, not the type-specific function, for fear that we
  will forget the cross-check in one of the functions and never realize
  that we did.

* I would make the pqTraceOutputInt16() function and siblings advance
  the cursor themselves, actually.  I think something like this:
  static int
  pqTraceOutputInt16(const char *data, int *cursor, FILE *pfdebug)
  {
	  uint16		tmp;
	  int			result;

	  memcpy(&tmp, data + *cursor, 2);
	  *cursor += 2;
	  result = (int) pg_ntoh16(tmp);
	  fprintf(pfdebug, " #%d", result);

	  return result;
  }
  (So the caller has to pass the original "data" pointer, not
  "data+cursor").  This means the caller no longer has to do "cursor+=N"
  at each place.  Also, you get rid of the moveStrCursor() which does
  not look good.

Bikeshedding item:
* I'm not fond of the idea of prefixing "#" for 16bit ints and no
  prefix for 32bit ints.  Seems obscure and the output looks weird.
  I would use a one-letter prefix for each type, "w" for 32-bit ints
  (stands for "word") and "h" for 16-bit ints (stands for "half-word"). 
  Message length goes unadorned.  Then you'd have lines like this

2021-03-15 08:10:44.324296  <   RowDescription  35 h1 "spcoptions" w1213 h5 w1009 h65535 w-1 h0
2021-03-15 08:10:44.324335  <   DataRow 32 h1 w22 '{random_page_cost=3.0}'             

* I don't like that pqTraceOutputS/H print nothing when !toServer.  I
think they should complain.

-- 
Álvaro Herrera                            39°49'30"S 73°17'W