Getting: "Query Failed: Commands out of sync; you can't run this command now;"

[luis-fln]

I am currently testing ProxySQL for mirroring among two slaves. As a first step, I am sending traffic only to the target slave and not the mirror. I am getting the following error in my application logs:

"Query Failed: Commands out of sync; you can't run this command now;"

The query looks like this:
SELECT
1
FROM
CJ
JOIN SJ ON SJ.id = CJ.id AND SJ.uid = xxxxxx AND SJ.time IS NULL
WHERE
CJ.another_id = yyyyyy
LIMIT 1;

Including relevant tables with configuration:

Admin> select * from mysql_servers;
+--------------+----------------+------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+
| hostgroup_id | hostname       | port | status | weight | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment |
+--------------+----------------+------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+
| 110          | a.example.com  | 3306 | ONLINE | 1      | 0           | 500             | 0                   | 0       | 0              |         |
| 120          | b.example.com  | 3306 | ONLINE | 1      | 0           | 500             | 0                   | 0       | 0              |         |
+--------------+----------------+------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+

Admin> select * from mysql_users;
+---------------+-------------------------------------------+--------+---------+-------------------+----------------+---------------+------------------------+--------------+---------+----------+-----------------+
| username      | password                                  | active | use_ssl | default_hostgroup | default_schema | schema_locked | transaction_persistent | fast_forward | backend | frontend | max_connections |
+---------------+-------------------------------------------+--------+---------+-------------------+----------------+---------------+------------------------+--------------+---------+----------+-----------------+
| reports       | *SOMEMYSQLHASH121212121212121212121212121 | 1      | 0       | 110               | gaf            | 0             | 0                      | 0            | 1       | 1        | 500             |
+---------------+-------------------------------------------+--------+---------+-------------------+----------------+---------------+------------------------+--------------+---------+----------+-----------------+

Admin> SELECT * FROM mysql_replication_hostgroups;
+------------------+------------------+------------------------------+
| writer_hostgroup | reader_hostgroup | comment                      |
+------------------+------------------+------------------------------+
| 10               | 110              | main replication hostgroup   |
| 20               | 120              | mirror replication hostgroup |
+------------------+------------------+------------------------------+

Admin> select * from mysql_query_rules;
+---------+--------+---------------+------------+--------+-------------+------------+------------+--------+--------------+---------------+----------------------+---------+-----------------+-----------------------+-----------+-----------+---------+---------+-------+----------------+------------------+-----------+-----+-------+---------+
| rule_id | active | username      | schemaname | flagIN | client_addr | proxy_addr | proxy_port | digest | match_digest | match_pattern | negate_match_pattern | flagOUT | replace_pattern | destination_hostgroup | cache_ttl | reconnect | timeout | retries | delay | mirror_flagOUT | mirror_hostgroup | error_msg | log | apply | comment |
+---------+--------+---------------+------------+--------+-------------+------------+------------+--------+--------------+---------------+----------------------+---------+-----------------+-----------------------+-----------+-----------+---------+---------+-------+----------------+------------------+-----------+-----+-------+---------+
| 1       | 1      | reports       | NULL       | 0      | NULL        | NULL       | NULL       | NULL   | NULL         | NULL          | 0                    | NULL    | NULL            | 110                   | NULL      | NULL      | NULL    | NULL    | NULL  | NULL           | NULL             | NULL      | NULL| 1     | NULL    |
+---------+--------+---------------+------------+--------+-------------+------------+------------+--------+--------------+---------------+----------------------+---------+-----------------+-----------------------+-----------+-----------+---------+---------+-------+----------------+------------------+-----------+-----+-------+---------+

Admin> SELECT * FROM stats.stats_mysql_connection_pool;
+-----------+----------------+----------+--------+----------+----------+--------+---------+---------+-----------------+-----------------+------------+
| hostgroup | srv_host       | srv_port | status | ConnUsed | ConnFree | ConnOK | ConnERR | Queries | Bytes_data_sent | Bytes_data_recv | Latency_us |
+-----------+----------------+----------+--------+----------+----------+--------+---------+---------+-----------------+-----------------+------------+
| 110       | a.example.com  | 3306     | ONLINE | 0        | 1        | 1      | 0       | 20      | 160             | 120             | 1451       |
| 120       | b.example.com  | 3306     | ONLINE | 0        | 0        | 0      | 0       | 0       | 0               | 0               | 366        |
+-----------+----------------+----------+--------+----------+----------+--------+---------+---------+-----------------+-----------------+------------+

Admin> select * from global_variables;
+----------------------------------------+-------------------------------------------------+
| variable_name                          | variable_value                                  |
+----------------------------------------+-------------------------------------------------+
| admin-stats_credentials                | stats:stats                                     |
| admin-telnet_admin_ifaces              | (null)                                          |
| admin-telnet_stats_ifaces              | (null)                                          |
| admin-refresh_interval                 | 2000                                            |
| admin-read_only                        | false                                           |
| admin-hash_passwords                   | true                                            |
| admin-version                          | 1.3.6-1                                         |
| mysql-shun_on_failures                 | 5                                               |
| mysql-shun_recovery_time_sec           | 10                                              |
| mysql-query_retries_on_failure         | 1                                               |
| mysql-connect_retries_delay            | 1                                               |
| mysql-connection_max_age_ms            | 0                                               |
| mysql-eventslog_filename               |                                                 |
| mysql-eventslog_filesize               | 104857600                                       |
| mysql-default_charset                  | utf8                                            |
| mysql-session_idle_ms                  | 1000                                            |
| mysql-client_found_rows                | true                                            |
| mysql-monitor_enabled                  | true                                            |
| mysql-monitor_connect_timeout          | 200                                             |
| mysql-monitor_ping_max_failures        | 3                                               |
| mysql-monitor_ping_timeout             | 1000                                            |
| mysql-monitor_replication_lag_interval | 10000                                           |
| mysql-monitor_replication_lag_timeout  | 1000                                            |
| mysql-monitor_query_interval           | 60000                                           |
| mysql-monitor_query_timeout            | 100                                             |
| mysql-monitor_slave_lag_when_null      | 60                                              |
| mysql-monitor_writer_is_also_reader    | true                                            |
| mysql-max_allowed_packet               | 4194304                                         |
| mysql-max_transaction_time             | 14400000                                        |
| mysql-multiplexing                     | true                                            |
| mysql-enforce_autocommit_on_reads      | false                                           |
| mysql-threshold_query_length           | 524288                                          |
| mysql-threshold_resultset_size         | 4194304                                         |
| mysql-query_digests_max_digest_length  | 2048                                            |
| mysql-query_digests_max_query_length   | 65000                                           |
| mysql-wait_timeout                     | 28800000                                        |
| mysql-max_stmts_per_connection         | 20                                              |
| mysql-max_stmts_cache                  | 10000                                           |
| mysql-default_max_latency_ms           | 1000                                            |
| mysql-query_processor_iterations       | 0                                               |
| mysql-long_query_time                  | 1000                                            |
| mysql-query_cache_size_MB              | 256                                             |
| mysql-ping_interval_server_msec        | 10000                                           |
| mysql-poll_timeout_on_failure          | 100                                             |
| mysql-server_capabilities              | 45578                                           |
| mysql-session_idle_show_processlist    | false                                           |
| mysql-query_digests                    | true                                            |
| mysql-query_digests_lowercase          | false                                           |
| mysql-servers_stats                    | true                                            |
| mysql-default_reconnect                | true                                            |
| mysql-ssl_p2s_ca                       | (null)                                          |
| mysql-ssl_p2s_cert                     | (null)                                          |
| mysql-ssl_p2s_key                      | (null)                                          |
| mysql-ssl_p2s_cipher                   | (null)                                          |
| mysql-init_connect                     | (null)                                          |
| mysql-default_sql_mode                 |                                                 |
| mysql-default_time_zone                | SYSTEM                                          |
| admin-admin_credentials                | admin:*ANOTHERMYSQLHAS67676767676677676767677   |
| admin-mysql_ifaces                     | 127.0.0.1:6032;/tmp/proxysql_admin.sock         |
| mysql-threads                          | 120                                             |
| mysql-max_connections                  | 4200                                            |
| mysql-default_query_delay              | 0                                               |
| mysql-default_query_timeout            | 36000000                                        |
| mysql-have_compress                    | true                                            |
| mysql-poll_timeout                     | 2000                                            |
| mysql-interfaces                       | 0.0.0.0:3306;/tmp/proxysql.sock                 |
| mysql-default_schema                   | information_schema                              |
| mysql-stacksize                        | 1048576                                         |
| mysql-server_version                   | 5.6.33                                          |
| mysql-connect_timeout_server           | 120000                                          |
| mysql-connect_timeout_server_max       | 240000                                          |
| mysql-free_connections_pct             | 100                                             |
| mysql-monitor_history                  | 600000                                          |
| mysql-monitor_connect_interval         | 2000                                            |
| mysql-monitor_ping_interval            | 2000                                            |
| mysql-monitor_read_only_interval       | 2000                                            |
| mysql-monitor_read_only_timeout        | 500                                             |
| mysql-monitor_username                 | monitor                                         |
| mysql-monitor_password                 | cleartextpassword                               |
| mysql-ping_timeout_server              | 500                                             |
| mysql-commands_stats                   | true                                            |
| mysql-sessions_sort                    | true                                            |
| mysql-connect_retries_on_failure       | 10                                              |
| mysql-session_debug                    | (null)                                          |
+----------------------------------------+-------------------------------------------------+

Is this abnormal behaviour? Is there a parameter that I should be looking at?

[renecannao]

This should be fixed in 62180d7

[totalcharge]

Thank you for looking into this @renecannao. Unfortunately, 62180d7 did not resolve the aforementioned problem for us. We are still seeing intermittent "Commands out of sync” errors when funneling traffic through ProxySQL.

[renecannao]

Right this morning I came across a log where client was sending command 28 , despite ProxySQL sends that no cursor exists.
This sounds mostly an application/driver bug (trying to use a cursor despite the fact that ProxySQL says there is no cursor), but I acknowledge that ProxySQL should try to cope with misbehaving applications/drivers.

Do you have a reproducible test case to help me troubleshoot this issue?

Reopening this issue

[totalcharge]

The following test script will return a "Commands out of sync" error when funneled through ProxySQL. MySQL on the other hand has no problem with it. I suspect the semicolon before the comment is somewhat relevant.

<?php
$link = mysqli_init();
mysqli_real_connect($link, '<snip>', '<snip>', '<snip>', '<snip>');
$sql = 'SELECT 1; -- comment';

for ($x = 0; $x <= 5; $x++) {
  $result = mysqli_query($link, $sql, MYSQLI_STORE_RESULT);

  if ($result === false) {
    echo mysqli_errno($link);
  }
}
?>

[renecannao]

Thank you for the script: it allows to reproduce it.
This is the query sent from the script to proxysql, and from proxysql to the mysqld:

	0x0030:            1500 0000 0353 454c 4543 5420  ...{.....SELECT.
	0x0040:  313b 202d 2d20 636f 6d6d 656e 74         1;.--.comment

	0x0030:            1500 0000 0353 454c 4543 5420  ...|.....SELECT.
	0x0040:  313b 202d 2d20 636f 6d6d 656e 74         1;.--.comment

And these the reply from mysqld to proxysql, and from proxysql to client:

17:31:27.972638 IP 127.0.0.1.3306 > 127.0.0.1.34504: Flags [P.], seq 122:178, ack 226, win 350, options [nop,nop,TS val 2983456637 ecr 2983456636], length 56
...
	0x0030:            0100 0001 0117 0000 0203 6465  ...|..........de
	0x0040:  6600 0000 0131 000c 3f00 0100 0000 0881  f....1..?.......
	0x0050:  0000 0000 0500 0003 fe00 000a 0002 0000  ................
	0x0060:  0401 3105 0000 05fe 0000 0a00            ..1.........
17:31:27.972675 IP 127.0.0.1.6033 > 127.0.0.1.37872: Flags [P.], seq 90:146, ack 119, win 342, options [nop,nop,TS val 2983456637 ecr 2983456635], length 56
...
	0x0030:            0100 0001 0117 0000 0203 6465  ...{..........de
	0x0040:  6600 0000 0131 000c 3f00 0100 0000 0881  f....1..?.......
	0x0050:  0000 0000 0500 0003 fe00 000a 0002 0000  ................
	0x0060:  0401 3105 0000 05fe 0000 0a00            ..1.........

So far, all looks consistent: proxysql is sending to client what received from mysqld.
Although, running the script directly against mysqld, the query is the same, but the result is different:

	0x0030:            1500 0000 0353 454c 4543 5420  .........SELECT.
	0x0040:  313b 202d 2d20 636f 6d6d 656e 74         1;.--.comment

17:42:50.375547 IP 127.0.0.1.3306 > 127.0.0.1.36010: Flags [P.], seq 335:391, ack 241, win 342, options [nop,nop,TS val 2983627237 ecr 2983627237], length 56
...
	0x0030:            0100 0001 0117 0000 0203 6465  ..............de
	0x0040:  6600 0000 0131 000c 3f00 0100 0000 0881  f....1..?.......
	0x0050:  0000 0000 0500 0003 fe00 0002 0002 0000  ................
	0x0060:  0401 3105 0000 05fe 0000 0200            ..1.........

What is different?
The status flags in EOF packet.
When using proxysql, the server sends SERVER_MORE_RESULTS_EXIST , that means that the server wants to send another resultset.
I will investigate why this happen

[renecannao]

Client capabilities when client connects to mysqld and/or proxysql: 8da2 0a00 .

Client capabilities when proxysql connects to mysqld: 8fa2 9f80 .

There are few differences, but what really matter is that proxysql sets CLIENT_MULTI_STATEMENTS and CLIENT_MULTI_RESULTS (well, CLIENT_MULTI_RESULTS is automatically added when CLIENT_MULTI_STATEMENTS is set).
Currently, ProxySQL always enables CLIENT_MULTI_STATEMENTS , but as commented in the code it should be configurable.
For 1.4.x , we can make this option configurable.
For 2.0 , proxysql should track the option required by the client.

[pondix]

Fixed in https://github.com/sysown/proxysql/releases/tag/v1.4.9