when mariadb global autocommit is OFF, query though proxysql will block forever after a "set autocommit=0;"

[MOON-CLJ]

proxysql version: use source from https://github.com/sysown/proxysql/archive/v1.3.2-1.tar.gz, compile use just "make"

mariadb version:

mysql -uroot --protocol=tcp
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 263833
Server version: 5.5.5-10.0.12-MariaDB-log MariaDB Server

Copyright (c) 2000, 2016, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement
root@localhost [(none)] mysql> show global variables like "autocommit";
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| autocommit    | OFF   |
+---------------+-------+
1 row in set (0.00 sec)

proxysql conf:

datadir="/data/proxysql"

admin_variables =
{
    admin_credentials="admin:admin"
    mysql_ifaces="0.0.0.0:6032"
}

mysql_variables =
{
    default_charset="utf8mb4"
    client_found_rows=false
    commands_stats=false
    connect_retries_on_failure=3
    default_query_timeout=3600000
    enforce_autocommit_on_reads=true
    interfaces="0.0.0.0:6033;/tmp/proxysql.sock"
    long_query_time=200
    max_allowed_packet=12582912
    max_connections=6500
    max_transaction_time=3600000
    query_retries_on_failure=0
    session_idle_show_processlist=true
    threads=4
    wait_timeout=3600000
    monitor_username="dbstatus"
    monitor_password="dbstatus"
    monitor_history=600000
    monitor_connect_interval=60000
    monitor_ping_interval=10000
    monitor_read_only_interval=1500
    monitor_read_only_timeout=500
}

mysql_users = 
(
    {
        username = "root"
        password = ""
        default_hostgroup = 0
        transaction_persistent = 1
    },
    {
        username = "dbstatus"
        password = "dbstatus"
        default_hostgroup = 1
        transaction_persistent = 1
        max_connections = 1000
    }
)

mysql_servers =
(
    {
        address = "127.0.0.1"
        port = 3306
        weight = 1
        hostgroup = 0
        max_connections = 10
    },
    {
        address = "192.168.31.100"
        port = 3306
        weight = 1
        hostgroup = 1
        max_connections = 1000
        comment = "master"
    },
    {
        address = "192.168.31.101"
        port = 3306
        weight = 1
        hostgroup = 2
        max_connections = 1000
        comment = "standby"
    }
)

mysql_replication_hostgroups =
(
    {
        writer_hostgroup=1
        reader_hostgroup=2
    }
)

any statement after "set autocommit=0;" will block forever。

mysql -h192.168.31.100 -udbstatus -P6033 -pdbstatus --protocol=tcp
Warning: Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.5.30 (ProxySQL)

Copyright (c) 2000, 2016, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

dbstatus@192.168.31.100 [(none)] mysql> show variables like "autocommit";
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| autocommit    | OFF   |
+---------------+-------+
1 row in set (0.00 sec)

dbstatus@192.168.31.100 [(none)] mysql> set autocommit=0;
Query OK, 0 rows affected (0.00 sec)

dbstatus@192.168.31.100 [(none)] mysql> show variables like "autocommit";
blockling...

during the blocking there is more info from maraidb's information_schema.processlist, the proccess which id is 263841 come from the proxysql。seems like proxysql try "set autocommit=0" again and again, as you can see QUERY_ID's change and INFO's change during the blocking。

root@localhost [(none)] mysql> select * from information_schema.processlist where id= 263841;
+--------+----------+----------------------+--------------------+---------+------+----------------+------+---------+-------+-----------+----------+-------------+---------------+----------+
| ID     | USER     | HOST                 | DB                 | COMMAND | TIME | STATE          | INFO | TIME_MS | STAGE | MAX_STAGE | PROGRESS | MEMORY_USED | EXAMINED_ROWS | QUERY_ID |
+--------+----------+----------------------+--------------------+---------+------+----------------+------+---------+-------+-----------+----------+-------------+---------------+----------+
| 263841 | dbstatus | 192.168.31.100:38402 | information_schema | Query   |    0 | Writing to net | NULL |   0.022 |     0 |         0 |    0.000 |       42008 |             0 | 37754163 |
+--------+----------+----------------------+--------------------+---------+------+----------------+------+---------+-------+-----------+----------+-------------+---------------+----------+
1 row in set (0.00 sec)

root@localhost [(none)] mysql> select * from information_schema.processlist where id= 263841;
+--------+----------+----------------------+--------------------+---------+------+-------+------+---------+-------+-----------+----------+-------------+---------------+----------+
| ID     | USER     | HOST                 | DB                 | COMMAND | TIME | STATE | INFO | TIME_MS | STAGE | MAX_STAGE | PROGRESS | MEMORY_USED | EXAMINED_ROWS | QUERY_ID |
+--------+----------+----------------------+--------------------+---------+------+-------+------+---------+-------+-----------+----------+-------------+---------------+----------+
| 263841 | dbstatus | 192.168.31.100:38402 | information_schema | Sleep   |    0 |       | NULL |   0.030 |     0 |         0 |    0.000 |       42008 |             0 | 37767903 |
+--------+----------+----------------------+--------------------+---------+------+-------+------+---------+-------+-----------+----------+-------------+---------------+----------+
1 row in set (0.00 sec)

root@localhost [(none)] mysql> select * from information_schema.processlist where id= 263841;
+--------+----------+----------------------+--------------------+---------+------+-------+------+---------+-------+-----------+----------+-------------+---------------+----------+
| ID     | USER     | HOST                 | DB                 | COMMAND | TIME | STATE | INFO | TIME_MS | STAGE | MAX_STAGE | PROGRESS | MEMORY_USED | EXAMINED_ROWS | QUERY_ID |
+--------+----------+----------------------+--------------------+---------+------+-------+------+---------+-------+-----------+----------+-------------+---------------+----------+
| 263841 | dbstatus | 192.168.31.100:38402 | information_schema | Sleep   |    0 |       | NULL |   0.046 |     0 |         0 |    0.000 |       42008 |             0 | 37776229 |
+--------+----------+----------------------+--------------------+---------+------+-------+------+---------+-------+-----------+----------+-------------+---------------+----------+
1 row in set (0.00 sec)

root@localhost [(none)] mysql> select * from information_schema.processlist where id= 263841;
+--------+----------+----------------------+--------------------+---------+------+----------------+------------------+---------+-------+-----------+----------+-------------+---------------+----------+
| ID     | USER     | HOST                 | DB                 | COMMAND | TIME | STATE          | INFO             | TIME_MS | STAGE | MAX_STAGE | PROGRESS | MEMORY_USED | EXAMINED_ROWS | QUERY_ID |
+--------+----------+----------------------+--------------------+---------+------+----------------+------------------+---------+-------+-----------+----------+-------------+---------------+----------+
| 263841 | dbstatus | 192.168.31.100:38402 | information_schema | Query   |    0 | Writing to net | SET autocommit=0 |   0.013 |     0 |         0 |    0.000 |       42008 |             0 | 37783458 |
+--------+----------+----------------------+--------------------+---------+------+----------------+------------------+---------+-------+-----------+----------+-------------+---------------+----------+
1 row in set (0.00 sec)

pls check it, thx in advance!

[renecannao]

@MOON-CLJ : thank you for the report. I am not able to reproduce this behavior in the systems I am using. Although they are all MySQL and Percona sandboxes, I do not think that the fact you are using MariaDB is relevant.
Can you please attach proxysql's error log? (/var/lib/proxysql/proxysql.log by default).
And also the output of these command in admin:

SHOW MYSQL STATUS;
SELECT * FROM stats_mysql_connection_pool;

Finally, could you attach the file resulting from this command executed on 192.168.31.100:

tcpdump -i any -s 0 -w proxy.tcp port 6033 or port 3306

Thanks

[renecannao]

@MOON-CLJ : I managed to reproduce it. The important bit to reproduce it is:

when global autocommit is OFF

Investigating.

[MOON-CLJ]

@renecannao

confirm "seems like proxysql try 'set autocommit=0' again and again" from mariadb's general_log，

a lot of

                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0
                263910 Query    SET autocommit=0

we use docker, so we use './proxysql -f -D /data/proxysql -c /etc/proxysql.cnf',

chenlijun@redis00 ~/dev/proxysql-in-docker/proxysql $ docker logs -f 4fb105ec70df
2017-01-09 23:04:44 ProxySQL_Admin.cpp:2884:flush_mysql_variables___database_to_runtime(): [ERROR] Impossible to set not existing variable session_debug with value "(null)". Deleting
Standard ProxySQL Admin rev. 0.2.0902 -- ProxySQL_Admin.cpp -- Fri Dec 30 02:47:47 2016
Standard MySQL Threads Handler rev. 0.2.0902 -- MySQL_Thread.cpp -- Fri Dec 30 02:47:47 2016
Standard MySQL Authentication rev. 0.2.0902 -- MySQL_Authentication.cpp -- Fri Dec 30 02:47:47 2016
HID: 0 , address: 127.0.0.1 , port: 3306 , weight: 1 , status: ONLINE , max_connections: 10 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:
HID: 1 , address: 192.168.31.100 , port: 3306 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: master
HID: 2 , address: 192.168.31.101 , port: 3306 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: standby
2017-01-09 23:04:44 [INFO] New mysql_replication_hostgroups table
writer_hostgroup: 1 , reader_hostgroup: 2,
Standard Query Processor rev. 0.2.0902 -- Query_Processor.cpp -- Fri Dec 30 02:47:47 2016
In memory Standard Query Cache (SQC) rev. 1.2.0905 -- Query_Cache.cpp -- Fri Dec 30 02:47:47 2016
Standard MySQL Monitor (StdMyMon) rev. 1.2.0723 -- MySQL_Monitor.cpp -- Fri Dec 30 02:47:47 2016

[MOON-CLJ]

@renecannao okay, thx。

[renecannao]

This seems a side effect of a MySQL bug

[renecannao]

This is related to a MySQL server bug that makes ProxySQL believe that autocommit=1, entering in a loop.
We will need to work around that bug.
A possible workaround is: if set autocommit=0 is successful, ignore what reported by status_flags and unset SERVER_STATUS_AUTOCOMMIT

[MOON-CLJ]

@renecannao thx for the investigation。

[renecannao]

Created workaround in v1.3.3 and v1.4.0