Uploaded image for project: 'MariaDB MaxScale'
  1. MariaDB MaxScale
  2. MXS-3229

Hang with COM_SET_OPTION

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed (View Workflow)
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: 2.5.4
    • Fix Version/s: 2.5.5
    • Component/s: Protocol
    • Labels:
      None
    • Environment:
      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.

        Attachments

          Activity

            People

            Assignee:
            markus makela markus makela
            Reporter:
            ccalender Chris Calender
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved:

                Git Integration