MySQL Bugs: #81199: mysqlx plugin logging comments

Bug #81199	mysqlx plugin logging comments
Submitted:	26 Apr 2016 5:45	Modified:	23 Jun 2016 4:50
Reporter:	Simon Mudd (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Document Store: X Plugin	Severity:	S4 (Feature request)
Version:	5.7.12	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	mysqlx

Description:
You need to add a category: mysqlx plugin. I don't see one.

Minor detail but I notice that for example Innodb logs:

2016-04-12T18:10:39.024760Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 766269ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)

whereas the mysqlx plugin logs:

2016-04-15T07:32:42.918961Z 0 [Note] Plugin mysqlx reported: 'Supervision timeout - started client state verification'

I was playing with the plugin and saw:

2016-04-21T03:35:14.908209Z 0 [Note] Plugin mysqlx reported: 'Supervision timeout - started client state verification'
2016-04-21T03:42:40.314488Z 0 [Note] Plugin mysqlx reported: '12: EOF reading message body'
2016-04-21T03:42:55.199010Z 0 [Note] Plugin mysqlx reported: 'Supervision timeout - started client state verification'
2016-04-21T03:44:50.563026Z 0 [Note] Plugin mysqlx reported: '13: EOF reading message body'
2016-04-21T03:45:17.296990Z 0 [Note] Plugin mysqlx reported: 'Supervision timeout - started client state verification'

The error messages are not very clear. What does "12: EOF ..." or "13: EOF ..." mean? I suspect these are MySQL X protocol errors due to my testing but the errors are not clear.

How to repeat:
see above.

Suggested fix:
It would seem better to change the text "Plugin mysqlx reported:" to simply "Plugin mysqlx:".
I'd possibly prefer the clearer "mysqlx plugin:" and ensure that other plugins log the same way (that is "XXXX plugin:" ....) [ .e.g. "group_replication plugin:" ]

It's clear that there can be failures in the protocol for a number of reasons, e.g. due to bad clients, people testing etc. It would be good to document the errors which the mysqx plugin will report and under what circumstances they will happen. I don't believe there's any current list of such errors at the moment, probably because the code assumes "perfect clients" will "behave perfectly", so at least it should be clear when an unexpected disconnection happens, and it should also be clear when the protocol breaks, because someone doesn't use protobufs properly etc.

Are there counters for the different types of failures? For the old protocol there are counts of aborted connections? It seems there are some, but I do not see status variables for e.g. mysqlx_aborted_connects.

Also the status variable: Mysqlx_connection_accept_errors is not consistent with the variable Connection_errors_accept. I'm assuming these variables represent the same thing for the legacy and mysqlx connections. Please ensure the names are consistent.

Please also add a counter of protocol errors when something is sent which does not match the mysqlx protocol, or if the protobuf message that's sent is not the one that is expected.
e.g. mysqlx_protocol_errors

Thanks for the report.  We can see the numbers are client_id.

log_info("%s: Invalid message %i received during client initialization", client_id(), request.get_type());
log_info("%s: Client rejected: blocked host %s\n", client_id(), m_client_addr.c_str());
log_info("%s: closing client because of shutdown (state: %i)", client_id(), m_state.load());
log_info("%s: ERROR reading from socket %s (%i) %i", client_id(), strerr.c_str(), err, m_close_reason);
log_info("%s: EOF reading message body", client_id());
log_info("%s: ERROR reading from socket %s (%i)", client_id(), strerr.c_str(), err);
log_info("%s.%u: Invalid authentication method %s", m_client.client_id(), m_id, authm.mech_name().c_str());
log_info("%s: Unexpected message of type %i received during authentication", m_client.client_id(), type);

[17 Jun 2016 2:05] David Moss

Thanks for your feedback. This has been fixed in upcoming versions and the
following was added to the 5.7.13 change log:
 
Client disconnections were being logged as EOF. The log message has been
improved to Peer disconnection.