Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
2.5.4
-
None
-
MaxScale 2.5.4
MariaDB backend server 10.5.4 Enterprise (but this is not required)
PHP 5.5, PHP 5.4 (presumably any PHP < 7.3)
---
X5 Platform was used.
Description
Whenever a COM_SET_OPTION is executed, the server seems to respond with an EOF packet instead of an OK packet as is documented. This in turn causes a hang as the result state is not updated correctly due to it being in a state that's not expected.
This seems to be undocumented behavior as even the Wireshark MySQL protocol decoder doesn't expect an EOF packet as a response to a COM_SET_OPTION.
The MySQL documentation documents the response as an EOF packet whereas the MariaDB documentation documents it as an OK packet. Given that the observed behavior, even without Maxscale, is that the server sends an EOF packet, it's likely that this is a mistake in the MariaDB protocol documentation.
Original description:
In the latest MaxScale 2.5.4, queries from PHP connections (at least from older clients) just hang.
In MaxScale 2.5.3, the queries were outright refused with a "failed to connect" error.
However, in 2.5.4, MXS-3171/MXS-3110 was fixed which seems to allow the "connection", however, it does not execute the queries, and the PHP script will just hang indefinitely.
The PHP script works fine in MaxScale 2.4.12.
Script that is run:
<?php
|
// The database or MaxScale server to query
|
$server = "192.168.1.179:4006";
|
// the schema to look for
|
$db = mysql;
|
$user = 'chris';
|
$pwd = 'chris';
|
|
|
$handle = mysql_connect($server, $user, $pwd);
|
if ($handle === false) {
|
echo "Failed to connect to $server\n";
|
exit;
|
} else {
|
echo "Connected to $server\n";
|
}
|
$status = mysql_select_db('information_schema', $handle);
|
if ($status === false) {
|
echo "Failed to connect to information_schema\n";
|
exit;
|
} else {
|
echo "Connect to the schema information_schema\n";
|
}
|
echo "Query information_schema.schemata for count of schema\n";
|
// Will return 0 if it does not exist
|
$stmt = "select count(schema_name) from schemata where schema_name='$db'";
|
$result = mysql_result(mysql_query($stmt),0);
|
if ($result == '1') {
|
echo "A schema already exists for $db\n";
|
} else {
|
echo "Schema $db does not exist\n";
|
}
|
|
|
echo "\nQuery information_schema.schemata for schema name\n";
|
mysql_select_db('information_schema', $handle);
|
// Will return NULL if it does not exist
|
$stmt = "select schema_name from schemata where schema_name='$db'";
|
$exists = mysql_result(mysql_query($stmt),0);
|
if ($exists == $db) {
|
echo "A schema already exists for $db\n";
|
} else {
|
echo "Schema $db does not exist\n";
|
}
|
|
|
// Another method
|
echo "\nUsing SHOW SCHEMA\n";
|
// Will return NULL if it does not exist
|
$stmt = "show schemas like '$db'";
|
$exists = mysql_result(mysql_query($stmt),0);
|
//$result = mysql_query($stmt);
|
//$rows = mysql_num_rows($result);
|
if ($exists == $db) {
|
//if ($rows > 0) {
|
echo "A schema already exists for $db\n";
|
} else {
|
echo "Schema $db does not exist\n";
|
}
|
|
|
mysql_close($handle);
|
exit;
|
?>
|
When using MaxScale 2.4.12, it returns:
Connected to server1
|
Connect to the schema information_schema
|
Query information_schema.schemata for count of schema
|
A schema already exists for mysql
|
|
|
Query information_schema.schemata for schema name
|
A schema already exists for mysql
|
|
|
Using SHOW SCHEMA
|
A schema already exists for mysql
|
When using MaxScale 2.5.3, it returns:
Failed to connect to 192.168.1.179:4006
|
When using MaxScale 2.5.4, it simply hangs and does not return anything,
Error logs:
Error log from 2.4.12 (working):
chris@area51:~$ tail -f /var/log/maxscale/maxscale.log
|
2020-10-08 16:05:54 info : [MariaDBAuth] Added user: ssluser@localhost db: NULL global: yes
|
2020-10-08 16:05:54 info : [MariaDBAuth] Added user: chris1@127.0.0.1 db: NULL global: yes
|
2020-10-08 16:05:54 info : [MariaDBAuth] Added user: chris1@% db: NULL global: yes
|
2020-10-08 16:05:54 info : [MariaDBAuth] Added user: chris1@% db: NULL global: yes
|
2020-10-08 16:05:54 info : [MariaDBAuth] Added user: chris1@localhost db: NULL global: yes
|
2020-10-08 16:05:54 info : [MariaDBAuth] Added user: chris1@127.0.0.1 db: NULL global: yes
|
2020-10-08 16:05:54 info : [MariaDBAuth] Added user: chris1@% db: NULL global: yes
|
2020-10-08 16:05:54 notice : Listening for connections at [::]:4006
|
2020-10-08 16:05:54 notice : Service 'Read-Write-Service' started (2/2)
|
2020-10-08 16:05:54 notice : Loaded server states from journal file: /var/lib/maxscale/MariaDB-Monitor/monitor.dat
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Servers and router connection counts:
|
2020-10-08 16:06:04 info : (1) [readwritesplit] current operations : 0 in [127.0.0.1]:3312 Master, Running
|
2020-10-08 16:06:04 info : (1) [readwritesplit] current operations : 0 in [127.0.0.1]:3310 Running
|
2020-10-08 16:06:04 info : (1) [readwritesplit] current operations : 0 in [127.0.0.1]:3308 Running
|
2020-10-08 16:06:04 info : (1) [readwritesplit] current operations : 0 in [127.0.0.1]:3306 Running
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Connected to 'server1'
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Selected Master: server1
|
2020-10-08 16:06:04 info : (1) Started Read-Write-Service client session [1] for 'chris1' from ::ffff:192.168.1.160
|
2020-10-08 16:06:04 info : (1) Connected to 'server1' with thread id 71
|
2020-10-08 16:06:04 info : (1) > Autocommit: [enabled], trx is [not open], cmd: (0x02) COM_INIT_DB, plen: 23, type: QUERY_TYPE_SESSION_WRITE, stmt:
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Session write, routing to all servers.
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Route query to master: server1 [127.0.0.1]:3312
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply complete, last reply from server1
|
2020-10-08 16:06:04 info : (1) > Autocommit: [enabled], trx is [not open], cmd: (0x1b) COM_SET_OPTION, plen: 7, type: QUERY_TYPE_SESSION_WRITE, stmt:
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Session write, routing to all servers.
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Route query to master: server1 [127.0.0.1]:3312
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply complete, last reply from server1
|
2020-10-08 16:06:04 info : (1) > Autocommit: [enabled], trx is [not open], cmd: (0x03) COM_QUERY, plen: 70, type: QUERY_TYPE_READ, stmt: select count(schema_name) from schemata where schema_name='mysql'
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Route query to master: server1 [127.0.0.1]:3312 <
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply not yet complete. Waiting for 1 replies, got one from server1
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply not yet complete. Waiting for 1 replies, got one from server1
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply not yet complete. Waiting for 1 replies, got one from server1
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply not yet complete. Waiting for 1 replies, got one from server1
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply complete, last reply from server1
|
2020-10-08 16:06:04 info : (1) > Autocommit: [enabled], trx is [not open], cmd: (0x02) COM_INIT_DB, plen: 23, type: QUERY_TYPE_SESSION_WRITE, stmt:
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Session write, routing to all servers.
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Route query to master: server1 [127.0.0.1]:3312
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply complete, last reply from server1
|
2020-10-08 16:06:04 info : (1) > Autocommit: [enabled], trx is [not open], cmd: (0x03) COM_QUERY, plen: 63, type: QUERY_TYPE_READ, stmt: select schema_name from schemata where schema_name='mysql'
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Route query to master: server1 [127.0.0.1]:3312 <
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply not yet complete. Waiting for 1 replies, got one from server1
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply not yet complete. Waiting for 1 replies, got one from server1
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply not yet complete. Waiting for 1 replies, got one from server1
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply not yet complete. Waiting for 1 replies, got one from server1
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply complete, last reply from server1
|
2020-10-08 16:06:04 info : (1) > Autocommit: [enabled], trx is [not open], cmd: (0x03) COM_QUERY, plen: 30, type: QUERY_TYPE_SHOW_DATABASES, stmt: show schemas like 'mysql'
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Route query to master: server1 [127.0.0.1]:3312 <
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply not yet complete. Waiting for 1 replies, got one from server1
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply not yet complete. Waiting for 1 replies, got one from server1
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply not yet complete. Waiting for 1 replies, got one from server1
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply not yet complete. Waiting for 1 replies, got one from server1
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Reply complete, last reply from server1
|
2020-10-08 16:06:04 info : (1) > Autocommit: [enabled], trx is [not open], cmd: (0x01) COM_QUIT, plen: 5, type: QUERY_TYPE_SESSION_WRITE, stmt:
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Session write, routing to all servers.
|
2020-10-08 16:06:04 info : (1) [readwritesplit] Route query to master: server1 [127.0.0.1]:3312
|
2020-10-08 16:06:04 info : Stopped Read-Write-Service client session [1]
|
Error log from 2.5.3 (failure to connect):
chris@area51:~$ tail -f /var/log/maxscale/maxscale.log
|
2020-10-08 16:00:56 notice : Server 'server2' charset: latin1
|
2020-10-08 16:00:56 info : Server variables loaded from 'server2', next update in 600 seconds.
|
2020-10-08 16:00:56 notice : Server 'server2' version: 10.3.23-7-MariaDB-enterprise
|
2020-10-08 16:00:56 notice : Starting a total of 2 services...
|
2020-10-08 16:00:56 notice : (Read-Write-Listener) Listening for connections at [::]:4006
|
2020-10-08 16:00:56 notice : Service 'Read-Write-Service' started (1/2)
|
2020-10-08 16:00:56 notice : (Read-Only-Listener) Listening for connections at [::]:4008
|
2020-10-08 16:00:56 notice : Service 'Read-Only-Service' started (2/2)
|
2020-10-08 16:00:56 notice : Read 8 user@host entries from 'server1' for service 'Read-Write-Service'.
|
2020-10-08 16:00:56 notice : Read 8 user@host entries from 'server1' for service 'Read-Only-Service'.
|
2020-10-08 16:01:25 error : (1) [mariadbclient] Client (::ffff:192.168.1.160) sent an invalid HandShakeResponse.
|
2020-10-08 16:01:25 info : Stopped Read-Write-Service client session [1]
|
Error log from 2.5.4 (connect, but failure to read results):
2020-10-08 15:42:57 info : (2) Found matching user 'chris1'@'%' for client 'chris1'@'::ffff:192.168.1.160' with sufficient privileges.
|
2020-10-08 15:42:57 info : (2) [readwritesplit] (Read-Write-Service) Target connection counts:
|
2020-10-08 15:42:57 info : (2) [readwritesplit] (Read-Write-Service) current operations : 1 in server1 Master, Running
|
2020-10-08 15:42:57 info : (2) [readwritesplit] (Read-Write-Service) current operations : 0 in server2 Running
|
2020-10-08 15:42:57 info : (2) [readwritesplit] (Read-Write-Service) current operations : 0 in server3 Running
|
2020-10-08 15:42:57 info : (2) [readwritesplit] (Read-Write-Service) current operations : 0 in server4 Running
|
2020-10-08 15:42:57 info : (2) [readwritesplit] (Read-Write-Service) Connected to 'server1'
|
2020-10-08 15:42:57 info : (2) [readwritesplit] (Read-Write-Service) Selected Master: server1
|
2020-10-08 15:42:57 info : (2) Started Read-Write-Service client session [2] for 'chris1' from ::ffff:192.168.1.160
|
2020-10-08 15:42:57 info : (2) Connected to 'server1' with thread id 62
|
2020-10-08 15:42:57 info : (2) Authentication to 'server1' succeeded.
|
2020-10-08 15:42:57 info : (2) (Read-Write-Service) > Autocommit: [enabled], trx is [not open], cmd: (0x02) COM_INIT_DB, plen: 23, type: QUERY_TYPE_SESSION_WRITE, stmt:
|
2020-10-08 15:42:57 info : (2) [readwritesplit] (Read-Write-Service) Session write, routing to all servers.
|
2020-10-08 15:42:57 info : (2) (Read-Write-Service) Execute sescmd 1 on 'server1':
|
2020-10-08 15:42:57 info : (2) [readwritesplit] (Read-Write-Service) Route query to master: server1
|
2020-10-08 15:42:57 info : (2) [readwritesplit] (Read-Write-Service) Will return response from 'server1' to the client
|
2020-10-08 15:42:57 info : (2) [readwritesplit] (Read-Write-Service) Reply complete, last reply from server1
|
2020-10-08 15:42:57 info : (2) (Read-Write-Service) > Autocommit: [enabled], trx is [not open], cmd: (0x1b) COM_SET_OPTION, plen: 7, type: QUERY_TYPE_SESSION_WRITE, stmt:
|
2020-10-08 15:42:57 info : (2) [readwritesplit] (Read-Write-Service) Session write, routing to all servers.
|
2020-10-08 15:42:57 info : (2) (Read-Write-Service) Execute sescmd 2 on 'server1':
|
2020-10-08 15:42:57 info : (2) [readwritesplit] (Read-Write-Service) Route query to master: server1
|
2020-10-08 15:42:57 info : (2) [readwritesplit] (Read-Write-Service) Will return response from 'server1' to the client
|
2020-10-08 15:42:57 info : (2) [readwritesplit] (Read-Write-Service) Reply not yet complete. Waiting for 1 replies, got one from server1
|
2020-10-08 15:42:57 info : (2) [readwritesplit] (Read-Write-Service) Session command response from server1 not yet complete
|
2020-10-08 15:42:57 info : (2) [readwritesplit] (Read-Write-Service) Storing query (len: 70 cmd: 3), expecting 1 replies to current command: select count(schema_name) from schemata where schema_name='mysql'
|
In the latter, we see it never even completes the "COM_SET_OPTION, plen: 7, type: QUERY_TYPE_SESSION_WRITE" and so when it gets to the first SELECT, it has to store it (i.e., "Storing query"), and this is when the hanging begins.