RE: libpq debug log

Aya Iwata (Fujitsu) <iwata.aya@fujitsu.com>

From: "iwata.aya@fujitsu.com" <iwata.aya@fujitsu.com>
To: "tsunakawa.takay@fujitsu.com" <tsunakawa.takay@fujitsu.com>, Alvaro Herrera <alvherre@alvh.no-ip.org>
Cc: 'Tom Lane' <tgl@sss.pgh.pa.us>, 'Kyotaro Horiguchi' <horikyota.ntt@gmail.com>, "k.jamison@fujitsu.com" <k.jamison@fujitsu.com>, "pgsql-hackers@lists.postgresql.org" <pgsql-hackers@lists.postgresql.org>
Date: 2021-03-18T07:18:42Z
Lists: pgsql-hackers

Attachments

Hi Alvaro san and Tsunakawa san,

Thank you for your review. I updated patch to v27.

`make check` output is following. I think it is OK.
```
2021-03-18 07:02:55.090598  <   ReadyForQuery   5 I                             
2021-03-18 07:02:55.090672  >   Terminate   4                                   
2021-03-18 07:02:55.120492  >   Query   155 "CREATE TABLESPACE regress_tblspacewith LOCATION '/home/iwata/pgsql/postgres/src/test/regress/testtablespace' WITH (some_nonexistent_parameter = true);"
2021-03-18 07:02:55.121624  <   ErrorResponse   124 S "ERROR" V "ERROR" C "22023" M "unrecognized parameter "some_nonexistent_parameter"" F "reloptions.c" L "1447" R "parseRelOptionsInternal" \x00 "Z"
2021-03-18 07:02:55.121664  <   ReadyForQuery   5 I                             
2021-03-18 07:02:55.121728  >   Query   144 "CREATE TABLESPACE regress_tblspacewith LOCATION '/home/iwata/pgsql/postgres/src/test/regress/testtablespace' WITH (random_page_cost = 3.0);"
2021-03-18 07:02:55.123335  <   CommandComplete 22 "CREATE TABLESPACE"          
2021-03-18 07:02:55.123400  <   ReadyForQuery   5 I                             
2021-03-18 07:02:55.123460  >   Query   81 "SELECT spcoptions FROM pg_tablespace WHERE spcname = 'regress_tblspacewith';"
2021-03-18 07:02:55.126556  <   RowDescription  35 1 "spcoptions" 1213 5 1009 65535 -1 0
2021-03-18 07:02:55.126594  <   DataRow 32 1 22 '{random_page_cost=3.0}'        
2021-03-18 07:02:55.126607  <   CommandComplete 13 "SELECT 1"                   
2021-03-18 07:02:55.126617  <   ReadyForQuery   5 I                             
```

> Iwata-san,
> Why don't you submit v27 patch with the current arrays kept, and then v28
> with the arrays removed soon after?

And I will try to remove byte1 type table for v28 patch.

> From: Tsunakawa, Takayuki/綱川 貴之 <tsunakawa.takay@fujitsu.com>
> Sent: Thursday, March 18, 2021 12:38 PM
> From: Alvaro Herrera <alvherre@alvh.no-ip.org>
> > In pqTraceOutputString(), you can use the return value from fprintf to
> > move the cursor -- no need to count chars.
> 
> Yes, precisely, 2 bytes for the double quotes needs to be subtracted as
> follows:
> 
> 	len = fprintf(...);
> 	*cursor += (len - 2);

Thank you for your advice. I changed pqTraceOutputString set cursor to fprintf  return -2.
And I removed cursor movement from that function.

> From: Tsunakawa, Takayuki/綱川 貴之 <tsunakawa.takay@fujitsu.com>
> Sent: Thursday, March 18, 2021 11:52 AM
... 
> I'll look at the comments from Alvaro-san and Horiguchi-san.  Here are my
> review comments:

Thank you for your review. I am sorry previous patch contain some mistake.

> (23)
> +	/* Trace message only when there is first 1 byte */
> +	if (conn->Pfdebug && conn->outCount < conn->outMsgStart)
> +	{
> +		if (conn->outCount < conn->outMsgStart)
> +			pqTraceOutputMessage(conn, conn->outBuffer +
> conn->outCount, true);
> +		else
> +			pqTraceOutputNoTypeByteMessage(conn,
> +
> 	conn->outBuffer + conn->outMsgStart);
> +	}
> 
> The inner else path doesn't seem to be reached because both the outer and
> inner if contain the same condition.  I think you want to remove the second
> condition from the outer if.

Yes, I remove second condition.

> (24) pqTraceOutputNoTypeByteMessage
> +		case 16:	/* CancelRequest */
> +			fprintf(conn->Pfdebug,
> "%s\t>\tCancelRequest\t%d", timestr, length);
> +			pqTraceOutputInt32(message, &LogCursor,
> conn->Pfdebug);
> +			pqTraceOutputInt32(message, &LogCursor,
> conn->Pfdebug);
> +			break;
> 
> Another int32 data needs to be output as follows:
> 
> --------------------------------------------------
> Int32(80877102)
> The cancel request code. The value is chosen to contain 1234 in the most
> significant 16 bits, and 5678 in the least significant 16 bits. (To avoid
> confusion, this code must not be the same as any protocol version number.)
> 
> Int32
> The process ID of the target backend.
> 
> Int32
> The secret key for the target backend.
> --------------------------------------------------

Thank you. I read document again and I add one pqTraceOutputInt32().

> (25)
> +		case 8 :	/* GSSENRequest or SSLRequest */
> 
> GSSENRequest -> GSSENCRequest

Thank you. I fixed.


> (26)
> +static void
> +pqTraceOutputByte1(const char *data, int *cursor, FILE *pfdebug) {
> +	const char *v = data + *cursor;
> +	/*
> 
> +static void
> +pqTraceOutputf(const char *message, int end, FILE *f) {
> +	int	cursor = 0;
> +	pqTraceOutputString(message, &cursor, end, f); }
> 
> Put an empty line to separate the declaration part and execution part.

Thank you. I fixed this. I add space anywhere in pqTraceOutput? function.

> (27)
> +	const char	*message_type = "UnkownMessage";
> +
> +	id = message[LogCursor++];
> +
> +	memcpy(&length, message + LogCursor , 4);
> +	length = (int) pg_ntoh32(length);
> +	LogCursor += 4;
> +	LogEnd = length - 4;
> 
> +	/* Get a protocol type from first byte identifier */
> +	if (toServer &&
> +		id < lengthof(protocol_message_type_f) &&
> +		protocol_message_type_f[(unsigned char)id] != NULL)
> +		message_type = protocol_message_type_f[(unsigned
> char)id];
> +	else if (!toServer &&
> +		id < lengthof(protocol_message_type_b) &&
> +		protocol_message_type_b[(unsigned char)id] != NULL)
> +		message_type = protocol_message_type_b[(unsigned
> char)id];
> +	else
> +	{
> +		fprintf(conn->Pfdebug, "Unknown message: %02x\n", id);
> +		return;
> +	}
> +
> 
> The initial value "UnkownMessage" is not used.  So, you can initialize
> message_type with NULL and do like:
> 
> +	 if (...)
> +		...
> +	else if (...)
> +		...
> +
> +	if (message_type == NULL)
> +	{
> +		fprintf(conn->Pfdebug, "Unknown message: %02x\n", id);
> +		return;
> +
> 
> Plus, I think this should be done before looking at the message length.

I initialized message_type as NULL,  changed `else` to `if (message_type == NULL)`
and move message type setup code to after setting id.

> (28)
> pqTraceOutputBinary() is only used in pqTraceOutputNchar().  Do they have
> to be separated?

I see. I merged this code to pqTraceOutputBinary().

Regards,
Aya Iwata