Transaction savepoints do not work

[vlanse]

After we started using transaction savepoints in business logic, we noticed that RELEASE SAVEPOINT statement began to fail when proxysql is used with error "no savepoint exists". On the other hand, when connecting directly to MySQL (Percona server in our case) all works fine.

Some examination of proxysql' repository gave me a hint that the problem could be possibly workarounded by disabling connection multiplexing, and this actually worked.

But obviously there should be a better solution for this problem.

FYI: all statements are issued from client, no stored procedures are used at all.

[renecannao]

Hi.
The error "no savepoint exists" suggests me there is a problem with routing.
Can you please send the output of :

select username,transaction_persistent from mysql_users;
select * from mysql_query_rules;

Also, please check if there is anything suspicious in the error log.

Thanks.

[vlanse]

Helo Rene

We've already set transaction_persistent to "1" to address routing problem which occurred when we started using proxysql:

select username,transaction_persistent from mysql_users\G
*************************** 1. row ***************************
username: mysqluser
transaction_persistent: 1

The query rules are trivial:

select * from mysql_query_rules\G
*************************** 1. row ***************************
              rule_id: 1
               active: 1
             username: NULL
           schemaname: NULL
               flagIN: 0
          client_addr: NULL
           proxy_addr: NULL
           proxy_port: NULL
               digest: NULL
         match_digest: NULL
        match_pattern: ^\s*^SELECT .* FOR UPDATE$
 negate_match_pattern: 0
              flagOUT: NULL
      replace_pattern: NULL
destination_hostgroup: 1
            cache_ttl: NULL
            reconnect: NULL
              timeout: NULL
              retries: NULL
                delay: NULL
       mirror_flagOUT: NULL
     mirror_hostgroup: NULL
            error_msg: NULL
                  log: NULL
                apply: 1
              comment: NULL
*************************** 2. row ***************************
              rule_id: 2
               active: 1
             username: NULL
           schemaname: NULL
               flagIN: 0
          client_addr: NULL
           proxy_addr: NULL
           proxy_port: NULL
               digest: NULL
         match_digest: NULL
        match_pattern: ^\s*SELECT
 negate_match_pattern: 0
              flagOUT: NULL
      replace_pattern: NULL
destination_hostgroup: NULL
            cache_ttl: NULL
            reconnect: NULL
              timeout: NULL
              retries: NULL
                delay: NULL
       mirror_flagOUT: NULL
     mirror_hostgroup: NULL
            error_msg: NULL
                  log: NULL
                apply: 1
              comment: NULL

[renecannao]

Hi.
Is there any chance you have an easy reproducible test case?
This will speed up the troubleshooting.
Thanks

[vlanse]

My colleague @mosquito was so kind that he prepared environment which reproduces the bug
Please see https://github.com/mosquito/docker-proxysql-multiplexing-bug

[renecannao]

Very kind! Thank you @mosquito

[mosquito]

@renecannao problem reproducing only when many workers are working with SAVEPOINTs

[renecannao]

I confirm the issue. Still investigating

[renecannao]

02:22:31.663198 IP 127.0.0.1.49962 > 127.0.0.1.6033: Flags [P.], seq 91:120, ack 101, win 342, options [nop,nop,TS val 265518733 ecr 265518733], length 29
        0x0000:  4508 0051 6fcb 4000 4006 ccd1 7f00 0001  E..Qo.@.@.......
        0x0010:  7f00 0001 c32a 1791 b0e6 11a5 4676 c69f  .....*......Fv..
        0x0020:  8018 0156 fe45 0000 0101 080a 0fd3 7e8d  ...V.E........~.
        0x0030:  0fd3 7e8d 1900 0000 0353 4156 4550 4f49  ..~......SAVEPOI
        0x0040:  4e54 2073 615f 7361 7665 706f 696e 745f  NT.sa_savepoint_
        0x0050:  31                                       1
02:22:31.663274 IP 127.0.0.1.40057 > 127.0.0.1.3306: Flags [P.], seq 701:730, ack 1966, win 368, options [nop,nop,TS val 265518733 ecr 265518733], length 29
        0x0000:  4508 0051 2372 4000 4006 192b 7f00 0001  E..Q#r@.@..+....
        0x0010:  7f00 0001 9c79 0cea bd7f 60a6 6a69 41c0  .....y....`.jiA.
        0x0020:  8018 0170 fe45 0000 0101 080a 0fd3 7e8d  ...p.E........~.
        0x0030:  0fd3 7e8d 1900 0000 0353 4156 4550 4f49  ..~......SAVEPOI
        0x0040:  4e54 2073 615f 7361 7665 706f 696e 745f  NT.sa_savepoint_
        0x0050:  31                                       1
02:22:31.663406 IP 127.0.0.1.3306 > 127.0.0.1.40057: Flags [P.], seq 1966:1977, ack 730, win 350, options [nop,nop,TS val 265518733 ecr 265518733], length 11
        0x0000:  4508 003f 44ab 4000 4006 f803 7f00 0001  E..?D.@.@.......
        0x0010:  7f00 0001 0cea 9c79 6a69 41c0 bd7f 60c3  .......yjiA...`.
        0x0020:  8018 015e fe33 0000 0101 080a 0fd3 7e8d  ...^.3........~.
        0x0030:  0fd3 7e8d 0700 0001 0000 0000 0000 00    ..~............
02:22:31.663464 IP 127.0.0.1.6033 > 127.0.0.1.49962: Flags [P.], seq 101:112, ack 120, win 342, options [nop,nop,TS val 265518733 ecr 265518733], length 11
        0x0000:  4500 003f b8bb 4000 4006 83fb 7f00 0001  E..?..@.@.......
        0x0010:  7f00 0001 1791 c32a 4676 c69f b0e6 11c2  .......*Fv......
        0x0020:  8018 0156 fe33 0000 0101 080a 0fd3 7e8d  ...V.3........~.
        0x0030:  0fd3 7e8d 0700 0001 0000 0000 0000 00    ..~............

From the OK packet it seems that SAVEPOINT does not start a transaction, therefore proxysql doesn't disable multiplexing.

The easy solution is to automatically disable multiplexing for that HG once SAVEPOINT is executed.

A better solution is to automatically disable multiplexing for that HG once SAVEPOINT is executed, and re-enable multiplexing once COMMIT or ROLLBACK (without TO SAVEPOINT) is executed.

[vlanse]

Thank you Rene for investigation!

[vlanse]

@renecannao when you plan to release 1.4.0 with fix of the problem #948?

[broussea1901]

Hi,
I believe I'm facing the same issue using 1.4.3 (and HUE on application side)
Has the fix been included in 1.4.4?
Thanks

[zbentley]

This, or a variation of it, is occurring for me using 1.4.9 and the Django ORM. Steps to reproduce:

• In two processes, connect to the database.
• In each process, issue two nested calls to with transaction.atomic(), such that each process is running within a double-nested transaction.
• In each process, retrieve an object or objects from the ORM using objects.get() (no select_for_update necessary).
• In each process, save that object with .save().

This causes error messages like:
OperationalError: (1305, 'SAVEPOINT s140736082666368_x1 does not exist')

[zbentley]

This appears to be a regression from 1.4.3. Running the exact same script (which errors 100% of the time on 1.4.9) against 1.4.3 does not have the issue.

[benjamin-lim]

Currently, I'm facing the same issue with using 1.4.11( also reproduced at 1.4.3 ). I resolved this issue by adding below rules to mysql_query_rules. (I'm using only one HG)

mysql_query_rules:
(
    {
 		rule_id=1
 		active=1
 		match_pattern="^SAVEPOINT"
 		destination_hostgroup=0
 		apply=1
 		multiplex=0
 		log=1

 	},
 	{
 		rule_id=2
 		active=1
 		match_pattern="^COMMIT"
 		destination_hostgroup=0
 		apply=1
 		multiplex=1
 		log=1

 	},
 	{
 		rule_id=3
 		active=1
 		match_pattern="^ROLLBACK$"
 		destination_hostgroup=0
 		apply=1
 		multiplex=1
 		log=1
 	}

)

But, I'm wondering that these query rules automatically re-enable multiplexing? and is there any way to verify that connection multiplexing works well?

Thanks.

[stevenh]

Been a while since there was an update, just wanted to add we identified this as the bug which breaks django admin user add functionality so bit us as well :(

[iandelahorne]

We're being bitten by this with SQLAlchemy. I tried the query rules above but no dice. @renecannao is there any work being done on this?

[twotwotwo]

I hit the missing-savepoint errors in a Django test suite, and seem to be working around OK by setting autocommit-related settings conservatively (autocommit_false_is_transaction, forward_autocommit, and enforce_autocommit_on_reads all true). This isn't live yet, so it's still possible we could find problems, but a large test suite is passing OK.

Of course, that may mean you need to tweak your app code if you're currently counting on multiplexing while autocommit is off for performance, connection count, or whatever.

[mrfaiz]

I am using ProxySQL 2.0.2 on CentOS 7 PC . Using multiple write node. Query rules are following for disabling multiplexing. But no luck for me . getting the Error during query on (1,ip,3306): 1305, SAVEPOINT TransactionBegin does not exist regular basis.

mysql_query_rules:
 (
      {
		rule_id=1
		active=1
		match_pattern="^SELECT .* FOR UPDATE$"
		destination_hostgroup=1
		apply=1
		multiplex=2
	},
 	{
 		rule_id=11
 		active=1
 		match_pattern="^(?i)(SAVEPOINT)"
 		destination_hostgroup=1
 		multiplex=0
		apply=1
 	},
 	{
 		rule_id=12
 		active=1
 		match_pattern="^(?i)(COMMIT)"
 		destination_hostgroup=1
 		multiplex=1
		apply=1
 	},
 	{
 		rule_id=13
 		active=1
 		match_pattern="^(?i)(ROLLBACK)"
 		destination_hostgroup=1
 		apply=1
 		multiplex=1
 	}
)

[rtnpro]

I did some tests with Django's nested atomic transactions (which does SAVEPOINT queries), and found that SAVEPOINT queries, COMMIT and ROLLBACK are working as expected. You can see the test results here: https://github.com/rtnpro/django-proxysql-demo#31-db. https://github.com/rtnpro/django-proxysql-demo is a demo Django app where I am testing various workflows to see how ProxySQL/Django works together.

FYI, I have set mysql-autocommit_is_transaction to true. May be because of this, the SAVEPOINT queries are getting executed when multiplexing is disabled, and somehow working. However, there are some issues with TX_ISOLATION REPEATABLE-READ though.

[renecannao]

Closing. Fixed in 2.0.13

[twotwotwo]

I am still seeing SAVEPOINT...does not exist errors like @zbentley reported under Django, under ProxySQL 2.0.18.

Unlike in my comment above, which is about 1.4.16, I haven't found a global or user setting that gets around the problem (except setting fast_forward on the user, which disables a lot of functionality we want).

I'll try to follow up with anything I'm able to figure out, like reproducers or whether I can work around it with query rules. We do have nested savepoints in multiple processes concurrently, like in zbentley's steps to reproduce. Since it seems to be new information that SAVEPOINT still doesn't work for some after 2.0.13, I figured it was worth reporting that even while I look for other info.

[renecannao]

@twotwotwo : please do not use query rules related to savepoint: they should work out of the box.
Having a reproducible test case it would be great.
Also, the way you configure proxysql may cause routing/multiplexing to not work as expected. For example, unless you have a strong reason to change them, try to use the default values for autocommit related variables.

[twotwotwo]

Nice, I had just independently decided I should test with autocommit-y variables in their default states, started the run, came back and saw this comment. The suite takes a while, but will let you know what I find.

[twotwotwo]

A run with autocommit settings at their defaults but multiplexing on did have some failures at RELEASE SAVEPOINT statements. (And this is trivial, but a run with fast_forward off and multiplexing off succeeded as you'd expect.)

I haven't yet made a minimal reproducer. I'm signing off work soon but one thread I'll dig into more when I get back to this:

Python's DB interface spec says Python must initially have autocommit off on connections. The ProxySQL code references a MySQL bug where the server misreports autocommit as on when it's off. ProxySQL uses MySQL's reported autocommit status bit as part of the test for whether it should clear STATUS_MYSQL_CONNECTION_HAS_SAVEPOINT. If MySQL is misreporting autocommit as on, that could confuse that test.

If that's what's happening, then using MySQL_Connection::IsAutoCommit() instead of trusting the server-reported status bit might work around it. (As a side note, I'm not sure that function's current assumption of autocommit==1 for a reset connection is the more conservative option in this context, though also not sure if that can/should even come up here.)

In my ProxySQL 1.4 work long ago, I did have to patch our application to not trust the Python DB interface's get_autocommit() method and instead look at the last value we set (like IsAutoCommit does), which may suggest this misreporting can come up in practice. (Removing that patch in our app does not prevent the test failures with multiplexing on under current ProxySQL.) I unfortunately don't remember the details of when and how it misreported the status.

[twotwotwo]

Just fiddling at the CLI, it looks like set autocommit=off; savepoint x; release savepoint x; works reliably with a direct connection to MySQL but produces 'savepoint does not exist' errors run through ProxySQL. No migration between backend connections is necessarily involved, the autocommit=off just isn't always relayed to the backend before the savepoint statement, and when it's not, the savepoint is immediately auto-committed (it's a no-op, essentially) so the release fails.

Django's transaction.atomic wrapper uses autocommit=0 to open the outer "transaction" with no explicit BEGIN, and uses savepoints for any nested ones.

In the context of our test suite, things work pretty often (immediately issuing show session variables like "autocommit" usually returns what you expect--maybe because something issued a BEGIN outside of the savepoints, maybe for other reasons), but the other case happens enough we have a few failures in a full test suite run.

I'm guessing we got away with Django's behavior under ProxySQL 1.4 because we enabled forward_autocommit, which is gone now. Is there anything low-impact I could do to ensure autocommit status gets passed back to the backend?

(Is this still the right bug for this issue? It might be a different one that is more about autocommit than savepoints.)

[renecannao]

I do not observe your issue when I try it myself.

Here is some output, when connecting to proxysql.

mysql> SET AUTOCOMMIT=off;
Query OK, 0 rows affected (0,00 sec)

mysql> PROXYSQL INTERNAL SESSION\G
*************************** 1. row ***************************
session_info: {
    "address": "0x7fffee738000",
    "age_ms": 5978,
    "autocommit": false,
    "autocommit_on_hostgroup": -1,
    "client": {
        "DSS": 6,
        "client_addr": {
            "address": "127.0.0.1",
            "port": 34828
        },
        "encrypted": true,
        "proxy_addr": {
            "address": "0.0.0.0",
            "port": 6033
        },
        "ssl_cipher": "ECDHE-RSA-AES128-GCM-SHA256",
        "stream": {
            "bytes_recv": 212,
            "bytes_sent": 174,
            "pkts_recv": 5,
            "pkts_sent": 4
        },
        "userinfo": {
            "password": "*2AFD99E79E4AA23DE141540F4179F64FFB3AC521",
            "username": "sbtest"
        }
    },
    "conn": {
        "action": "3",
        "autocommit": "OFF",
        "character_set_client": "utf8",
        "character_set_connection": "utf8",
        "character_set_database": "utf8",
        "character_set_results": "utf8",
        "charset": "33",
        "client_flag": {
            "client_deprecate_eof": 1,
            "client_found_rows": 0,
            "client_multi_results": 1,
            "client_multi_statements": 1,
            "value": 33533573
        },
        "collation_connection": "utf8_general_ci",
        "group_concat_max_len": "",
        "isolation_level": "",
        "max_join_size": "",
        "names": "",
        "net_write_timeout": "",
        "no_backslash_escapes": false,
        "ps": {
            "client_stmt_to_global_ids": []
        },
        "session_track_gtids": "OFF",
        "sql_auto_is_null": "",
        "sql_log_bin": "1",
        "sql_mode": "",
        "sql_safe_updates": "",
        "sql_select_limit": "",
        "status": {
            "compression": false,
            "transaction": false
        },
        "time_zone": "",
        "transaction_read": "",
        "wsrep_sync_wait": ""
    }, 
    "current_hostgroup": 0,
    "default_hostgroup": 0,
    "default_schema": "",
    "gtid": {
        "hid": -1,
        "last": ""
    }, 
    "last_HG_affected_rows": -1,
    "last_insert_id": 0,
    "locked_on_hostgroup": -1,
    "qpo": {
        "cache_timeout": -1,
        "cache_ttl": -1,
        "create_new_connection": false,
        "delay": -1,
        "destination_hostgroup": -1,
        "firewall_whitelist_mode": 0,
        "max_lag_ms": -1,
        "multiplex": -1,
        "reconnect": -1,
        "retries": -1,
        "sticky_conn": -1,
        "timeout": -1
    }, 
    "status": 4,
    "thread": "0x7fffee6ff000",
    "thread_session_id": 772,
    "transaction_persistent": true,
    "user_attributes": ""
}
1 row in set (0,00 sec)

I am using PROXYSQL INTERNAL SESSION that is a command able to show internal statuses about this specific client session.
In the above you can see that proxysql knows the client wants autocommit off. Specifically:

    "conn": {
        "action": "3",
        "autocommit": "OFF",

In the same output, you can see that there is no backends section.
Now, let's run SAVEPOINT x and see how things change.

mysql> SAVEPOINT x;
Query OK, 0 rows affected (0,00 sec)

mysql> PROXYSQL INTERNAL SESSION\G
*************************** 1. row ***************************
session_info: {
    "address": "0x7fffee738000",
    "age_ms": 109313,
    "autocommit": false,
    "autocommit_on_hostgroup": -1,
    "backends": [
        {
            "conn": {
                "MultiplexDisabled": true,
                "action": "",
                "address": "0x7fffefa39c00",
                "auto_increment_delay_token": 0,
                "autocommit": "OFF",
                "bytes_recv": 25,
                "bytes_sent": 100,
                "character_set_client": "utf8",
                "character_set_connection": "utf8",
                "character_set_database": "utf8",
                "character_set_results": "utf8",
                "charset": "33",
                "client_flag": {
                    "client_deprecate_eof": 1,
                    "client_found_rows": 0,
                    "client_multi_statements": 1,
                    "value": 2174460557
                },
                "collation_connection": "utf8_general_ci",
                "group_concat_max_len": "",
                "init_connect": "",
                "init_connect_sent": true,
                "isolation_level": "",
                "last_set_autocommit": 0,
                "max_join_size": "",
                "myconnpoll_get": 5,
                "myconnpoll_put": 4,
                "mysql": {
                    "address": "0x7fffefa8b500",
                    "affected_rows": 0,
                    "charset": 33,
                    "charset_name": "utf8",
                    "db": "information_schema",
                    "host": "127.0.0.1",
                    "host_info": "127.0.0.1 via TCP/IP",
                    "insert_id": 0,
                    "net": {
                        "fd": 46,
                        "last_errno": 0,
                        "max_packet_size": 1073741824,
                        "sqlstate": "00000"
                    },
                    "options": {
                        "charset_name": "",
                        "use_ssl": 0
                    },
                    "port": 3306,
                    "server_status": 0,
                    "server_version": "5.7.34-0ubuntu0.18.04.1-log",
                    "thread_id": 29,
                    "unix_socket": "",
                    "user": "sbtest"
                },
                "names": "",
                "net_write_timeout": "",
                "no_backslash_escapes": false,
                "ps": {
                    "backend_stmt_to_global_ids": [],
                    "global_stmt_to_backend_ids": []
                },
                "questions": 7,
                "session_track_gtids": "",
                "sql_auto_is_null": "",
                "sql_log_bin": "1",
                "sql_mode": "",
                "sql_safe_updates": "",
                "sql_select_limit": "",
                "status": {
                    "compression": false,
                    "found_rows": false,
                    "get_lock": false,
                    "has_savepoint": true,
                    "lock_tables": false,
                    "no_multiplex": false,
                    "prepared_statement": false,
                    "temporary_table": false,
                    "user_variable": false
                },
                "time_zone": "",
                "transaction_read": "",
                "wsrep_sync_wait": ""
            },
            "gtid": "",
            "hostgroup_id": 0,
            "stream": {
                "DSS": 26,
                "address": "0x7fffee744f00",
                "bytes_recv": 0,
                "bytes_sent": 11,
                "myconnpoll_get": 1,
                "myconnpoll_put": 0,
                "questions": 1
            }
        }
    ], 
    "client": {
        "DSS": 6,
        "client_addr": {
            "address": "127.0.0.1",
            "port": 34828
        },
        "encrypted": true,
        "proxy_addr": {
            "address": "0.0.0.0",
            "port": 6033
        },
        "ssl_cipher": "ECDHE-RSA-AES128-GCM-SHA256",
        "stream": {
            "bytes_recv": 258,
            "bytes_sent": 2855,
            "pkts_recv": 7,
            "pkts_sent": 9
        },
        "userinfo": {
            "password": "*2AFD99E79E4AA23DE141540F4179F64FFB3AC521",
            "username": "sbtest"
        }
    }, 
    "conn": {
        "action": "3",
        "autocommit": "OFF",
        "character_set_client": "utf8",
        "character_set_connection": "utf8",
        "character_set_database": "utf8",
        "character_set_results": "utf8",
        "charset": "33",
        "client_flag": {
            "client_deprecate_eof": 1,
            "client_found_rows": 0,
            "client_multi_results": 1,
            "client_multi_statements": 1,
            "value": 33533573
        },
        "collation_connection": "utf8_general_ci",
        "group_concat_max_len": "",
        "isolation_level": "",
        "max_join_size": "",
        "names": "",
        "net_write_timeout": "",
        "no_backslash_escapes": false,
        "ps": {
            "client_stmt_to_global_ids": []
        },
        "session_track_gtids": "OFF",
        "sql_auto_is_null": "",
        "sql_log_bin": "1",
        "sql_mode": "",
        "sql_safe_updates": "",
        "sql_select_limit": "",
        "status": {
            "compression": false,
            "transaction": false
        },
        "time_zone": "",
        "transaction_read": "",
        "wsrep_sync_wait": ""
    }, 
    "current_hostgroup": 0,
    "default_hostgroup": 0,
    "default_schema": "",
    "gtid": {
        "hid": -1,
        "last": ""
    }, 
    "last_HG_affected_rows": -1,
    "last_insert_id": 0,
    "locked_on_hostgroup": -1,
    "qpo": {
        "cache_timeout": -1,
        "cache_ttl": -1,
        "create_new_connection": false,
        "delay": -1,
        "destination_hostgroup": -1,
        "firewall_whitelist_mode": 0,
        "max_lag_ms": -1,
        "multiplex": -1,
        "reconnect": -1,
        "retries": -1,
        "sticky_conn": -1,
        "timeout": -1
    }, 
    "status": 4,
    "thread": "0x7fffee6ff000",
    "thread_session_id": 772,
    "transaction_persistent": true,
    "user_attributes": ""
}
1 row in set (0,01 sec)

In the above, what is new is that we now have a backends section. The client is now linked to a backend.
Let me highlight some important details:

    "backends": [
        {
            "conn": {
                "MultiplexDisabled": true,
...
                "autocommit": "OFF",
...
                "last_set_autocommit": 0,
...
                "status": {
...
                    "has_savepoint": true,
...

The client is now linked to a backend, multiplexing is disabled, and proxysql knows there is a savepoint!
A small detail, perhaps not relevant at this point: in MySQL there is no transaction at the moment. Contrary to what many believes, set autocommit=0 doesn't start any transaction until a transactional table is read or written.

Next, we run RELEASE SAVEPOINT:

mysql> RELEASE SAVEPOINT x;
Query OK, 0 rows affected (0,00 sec)

mysql> PROXYSQL INTERNAL SESSION\G
*************************** 1. row ***************************
session_info: {
    "address": "0x7fffee738000",
    "age_ms": 209929,
    "autocommit": false,
    "autocommit_on_hostgroup": -1,
    "backends": [
        {
            "conn": {
                "MultiplexDisabled": true,
                "action": "",
                "address": "0x7fffefa39c00",
                "auto_increment_delay_token": 0,
                "autocommit": "OFF",
                "bytes_recv": 25,
                "bytes_sent": 119,
                "character_set_client": "utf8",
                "character_set_connection": "utf8",
                "character_set_database": "utf8",
                "character_set_results": "utf8",
                "charset": "33",
                "client_flag": {
                    "client_deprecate_eof": 1,
                    "client_found_rows": 0,
                    "client_multi_statements": 1,
                    "value": 2174460557
                },
                "collation_connection": "utf8_general_ci",
                "group_concat_max_len": "",
                "init_connect": "",
                "init_connect_sent": true,
                "isolation_level": "",
                "last_set_autocommit": 0,
                "max_join_size": "",
                "myconnpoll_get": 5,
                "myconnpoll_put": 4,
                "mysql": {
                    "address": "0x7fffefa8b500",
                    "affected_rows": 0,
                    "charset": 33,
                    "charset_name": "utf8",
                    "db": "information_schema",
                    "host": "127.0.0.1",
                    "host_info": "127.0.0.1 via TCP/IP",
                    "insert_id": 0,
                    "net": {
                        "fd": 46,
                        "last_errno": 0,
                        "max_packet_size": 1073741824,
                        "sqlstate": "00000"
                    },
                    "options": {
                        "charset_name": "",
                        "use_ssl": 0
                    },
                    "port": 3306,
                    "server_version": "5.7.34-0ubuntu0.18.04.1-log",
                    "thread_id": 29,
                    "unix_socket": "",
                    "user": "sbtest"
                },
                "names": "",
                "net_write_timeout": "",
                "no_backslash_escapes": false,
                "ps": {
                    "backend_stmt_to_global_ids": [],
                    "global_stmt_to_backend_ids": []
                },
                "questions": 8,
                "session_track_gtids": "",
                "sql_auto_is_null": "",
                "sql_log_bin": "1",
                "sql_mode": "",
                "sql_safe_updates": "",
                "sql_select_limit": "",
                "status": {
                    "compression": false,
                    "found_rows": false,
                    "get_lock": false,
                    "has_savepoint": true,
                    "lock_tables": false,
                    "no_multiplex": false,
                    "prepared_statement": false,
                    "temporary_table": false,
                    "user_variable": false
                },
                "time_zone": "",
                "transaction_read": "",
                "wsrep_sync_wait": ""
            },
            "gtid": "",
            "hostgroup_id": 0,
            "stream": {
                "DSS": 26,
                "address": "0x7fffee744f00",
                "bytes_recv": 0,
                "bytes_sent": 30,
                "myconnpoll_get": 1,
                "myconnpoll_put": 0,
                "questions": 2
            }
        }
    ], 
    "client": {
        "DSS": 6,
        "client_addr": {
            "address": "127.0.0.1",
            "port": 34828
        },
        "encrypted": true,
        "proxy_addr": {
            "address": "0.0.0.0",
            "port": 6033
        },
        "ssl_cipher": "ECDHE-RSA-AES128-GCM-SHA256",
        "stream": {
            "bytes_recv": 312,
            "bytes_sent": 9161,
            "pkts_recv": 9,
            "pkts_sent": 14
        },
        "userinfo": {
            "password": "*2AFD99E79E4AA23DE141540F4179F64FFB3AC521",
            "username": "sbtest"
        }
    }, 
    "conn": {
        "action": "3",
        "autocommit": "OFF",
        "character_set_client": "utf8",
        "character_set_connection": "utf8",
        "character_set_database": "utf8",
        "character_set_results": "utf8",
        "charset": "33",
        "client_flag": {
            "client_deprecate_eof": 1,
            "client_found_rows": 0,
            "client_multi_results": 1,
            "client_multi_statements": 1,
            "value": 33533573
        },
        "collation_connection": "utf8_general_ci",
        "group_concat_max_len": "",
        "isolation_level": "",
        "max_join_size": "",
        "names": "",
        "net_write_timeout": "",
        "no_backslash_escapes": false,
        "ps": {
            "client_stmt_to_global_ids": []
        },
        "session_track_gtids": "OFF",
        "sql_auto_is_null": "",
        "sql_log_bin": "1",
        "sql_mode": "",
        "sql_safe_updates": "",
        "sql_select_limit": "",
        "status": {
            "compression": false,
            "transaction": false
        },
        "time_zone": "",
        "transaction_read": "",
        "wsrep_sync_wait": ""
    }, 
    "current_hostgroup": 0,
    "default_hostgroup": 0,
    "default_schema": "",
    "gtid": {
        "hid": -1,
        "last": ""
    }, 
    "last_HG_affected_rows": -1,
    "last_insert_id": 0,
    "locked_on_hostgroup": -1,
    "qpo": {
        "cache_timeout": -1,
        "cache_ttl": -1,
        "create_new_connection": false,
        "delay": -1,
        "destination_hostgroup": -1,
        "firewall_whitelist_mode": 0,
        "max_lag_ms": -1,
        "multiplex": -1,
        "reconnect": -1,
        "retries": -1,
        "sticky_conn": -1,
        "timeout": -1
    }, 
    "status": 4,
    "thread": "0x7fffee6ff000",
    "thread_session_id": 772,
    "transaction_persistent": true,
    "user_attributes": ""
}
1 row in set (0,00 sec)

Nothing relevant has changed in the above output after running RELEASE SAVEPOINT. ProxySQL doesn't track the name of the savepoints, so it only knows that there are savepoints and that COMMIT or ROLLBACK was not explicitly called, thus a backend connection is still linked to this client, "MultiplexDisabled": true because "has_savepoint": true .

Now let's run ROLLBACK.

mysql> ROLLBACK;
Query OK, 0 rows affected (0,00 sec)

mysql> PROXYSQL INTERNAL SESSION\G
*************************** 1. row ***************************
session_info: {
    "address": "0x7fffee738000",
    "age_ms": 367513,
    "autocommit": false,
    "autocommit_on_hostgroup": -1,
    "backends": [
        {
            "gtid": "",
            "hostgroup_id": 0,
            "stream": {
                "DSS": 0,
                "address": "0x7fffee744f00",
                "bytes_recv": 0,
                "bytes_sent": 38,
                "myconnpoll_get": 1,
                "myconnpoll_put": 1,
                "questions": 3
            }   
        }   
    ],  
    "client": {
        "DSS": 6,
        "client_addr": {
            "address": "127.0.0.1",
            "port": 34828
        },  
        "encrypted": true,
        "proxy_addr": {
            "address": "0.0.0.0",
            "port": 6033
        },  
        "ssl_cipher": "ECDHE-RSA-AES128-GCM-SHA256",
        "stream": {
            "bytes_recv": 355,
            "bytes_sent": 15468,
            "pkts_recv": 11,
            "pkts_sent": 19
        },  
        "userinfo": {
            "password": "*2AFD99E79E4AA23DE141540F4179F64FFB3AC521",
            "username": "sbtest"
        }   
    },  
    "conn": {
        "action": "3",
        "autocommit": "OFF",
        "character_set_client": "utf8",
        "character_set_connection": "utf8",
        "character_set_database": "utf8",
        "character_set_results": "utf8",
        "charset": "33",
        "client_flag": {
            "client_deprecate_eof": 1,
            "client_found_rows": 0,
            "client_multi_results": 1,
            "client_multi_statements": 1,
            "value": 33533573
        },
        "collation_connection": "utf8_general_ci",
        "group_concat_max_len": "",
        "isolation_level": "",
        "max_join_size": "",
        "names": "",
        "net_write_timeout": "",
        "no_backslash_escapes": false,
        "ps": {
            "client_stmt_to_global_ids": []
        },
        "session_track_gtids": "OFF",
        "sql_auto_is_null": "",
        "sql_log_bin": "1",
        "sql_mode": "",
        "sql_safe_updates": "",
        "sql_select_limit": "",
        "status": {
            "compression": false,
            "transaction": false
        },
        "time_zone": "",
        "transaction_read": "",
        "wsrep_sync_wait": ""
    }, 
    "current_hostgroup": 0,
    "default_hostgroup": 0,
    "default_schema": "",
    "gtid": {
        "hid": -1,
        "last": ""
    }, 
    "last_HG_affected_rows": -1,
    "last_insert_id": 0,
    "locked_on_hostgroup": -1,
    "qpo": {
        "cache_timeout": -1,
        "cache_ttl": -1,
        "create_new_connection": false,
        "delay": -1,
        "destination_hostgroup": -1,
        "firewall_whitelist_mode": 0,
        "max_lag_ms": -1,
        "multiplex": -1,
        "reconnect": -1,
        "retries": -1,
        "sticky_conn": -1,
        "timeout": -1
    }, 
    "status": 4,
    "thread": "0x7fffee6ff000",
    "thread_session_id": 772,
    "transaction_persistent": true,
    "user_attributes": ""
}
1 row in set (0,01 sec)

Now you can see that backends is removed : the client is not linked anymore to a backend connection.
To me, this works as expected!

Just fiddling at the CLI, it looks like set autocommit=off; savepoint x; release savepoint x; works reliably with a direct connection to MySQL but produces 'savepoint does not exist' errors run through ProxySQL

Please confirm with some output. Please also run PROXYSQL INTERNAL SESSION\G to get detailed information.
Please also share your current configuration.

because we enabled forward_autocommit, which is gone now

Yes, mysql-forward_autocommit is gone now. This was not the right way getting the job done.

[twotwotwo]

Progress! It turns out my trivial steps only "worked" with forward_autocommit true in 2.0.18, and with that disabled, only the test suite reproduces it. Sorry for the false lead. (I had thought the forward_autocommit setting from the old script we wrote for 1.4 was now a no-op, but that was because I was looking at the latest code, not 2.0.18's.)

With strace, I think I found that the OK response right before the failure has the autocommit bit on when I would not expect it:

sendto(10, "\23\0\0\0\3set autocommit=off", 23, 0, NULL, 0) = 23
recvfrom(10, "\7\0\0\1\0\0\0\2@\0\0", 16384, 0, NULL, NULL) = 11

PROXYSQL INTERNAL SESSION right after this also has "autocommit": true. Before and after session JSON is below.

Up to this point the app had flipped autocommit on/off several times, created and released some savepoints, and run some selects and DDL, all successfully. The immediately previous commands are proxysql internal session and before that set foreign_key_checks=on. If I remove the set foreign_key_checks statements, the test suite does not die at this early point(!), but the savepoint issue still comes up later in the suite. I haven't found a trivial reproducer using set foreign_key_checks at the CLI.

(Edit: replaced the session info since initially posting. The first version had the "After set autocommit=off" info repeated twice due to a silly typo in my debug code)

Before set autocommit=off: {
    "address": "0x7f3d68a91800",
    "age_ms": 2450,
    "autocommit": true,
    "autocommit_on_hostgroup": 1,
    "backends": [
        null,
        {
            "conn": {
                "MultiplexDisabled": true,
                "action": "",
                "address": "0x7f3d68817200",
                "auto_increment_delay_token": 0,
                "autocommit": "ON",
                "bytes_recv": 587759,
                "bytes_sent": 1605994,
                "character_set_client": "utf8mb4",
                "character_set_connection": "utf8mb4",
                "character_set_database": "utf8",
                "character_set_results": "utf8mb4",
                "charset": "45",
                "client_flag": {
                    "client_found_rows": 1,
                    "client_multi_statements": 1,
                    "value": 2157683343
                },
                "collation_connection": "utf8mb4_general_ci",
                "group_concat_max_len": "",
                "init_connect": "",
                "init_connect_sent": true,
                "isolation_level": "",
                "last_set_autocommit": 1,
                "max_join_size": "",
                "myconnpoll_get": 1769,
                "myconnpoll_put": 1768,
                "mysql": {
                    "address": "0x7f3d679e4b00",
                    "affected_rows": 18446744073709551615,
                    "charset": 45,
                    "charset_name": "utf8mb4",
                    "db": "test_dev_randall_aur",
                    "host": "127.0.0.1",
                    "host_info": "127.0.0.1 via TCP/IP",
                    "insert_id": 0,
                    "net": {
                        "fd": 81,
                        "last_errno": 0,
                        "max_packet_size": 1073741824,
                        "sqlstate": "00000"
                    },
                    "options": {
                        "charset_name": "",
                        "use_ssl": 0
                    },
                    "port": 3306,
                    "server_status": 2,
                    "server_version": "5.7.32-35",
                    "thread_id": 12994482,
                    "unix_socket": "",
                    "user": "randal_aur"
                },
                "names": "",
                "net_write_timeout": "",
                "no_backslash_escapes": false,
                "ps": {
                    "backend_stmt_to_global_ids": [],
                    "global_stmt_to_backend_ids": []
                },
                "questions": 4804,
                "session_track_gtids": "",
                "sql_auto_is_null": "",
                "sql_log_bin": "1",
                "sql_mode": "",
                "sql_safe_updates": "",
                "sql_select_limit": "",
                "status": {
                    "found_rows": false,
                    "get_lock": false,
                    "has_savepoint": false,
                    "lock_tables": false,
                    "no_multiplex": true,
                    "temporary_table": false,
                    "user_variable": true
                },
                "time_zone": "",
                "transaction_read": "",
                "wsrep_sync_wait": ""
            },
            "gtid": "",
            "hostgroup_id": 1,
            "stream": {
                "DSS": 26,
                "address": "0x7f3d68af3200",
                "bytes_recv": 266077,
                "bytes_sent": 171452,
                "myconnpoll_get": 734,
                "myconnpoll_put": 733,
                "questions": 740
            }
        }
    ],
    "client": {
        "DSS": 6,
        "client_addr": {
            "address": "127.0.0.1",
            "port": 37456
        },
        "encrypted": false,
        "proxy_addr": {
            "address": "0.0.0.0",
            "port": 11113
        },
        "stream": {
            "bytes_recv": 175623,
            "bytes_sent": 507943,
            "pkts_recv": 754,
            "pkts_sent": 795
        },
        "userinfo": {
            "username": "randal_aur"
        }
    },
    "conn": {
        "action": "1",
        "autocommit": "ON",
        "character_set_client": "utf8mb4",
        "character_set_connection": "utf8mb4",
        "character_set_database": "utf8",
        "character_set_results": "utf8mb4",
        "charset": "45",
        "client_flag": {
            "client_found_rows": 1,
            "client_multi_results": 1,
            "client_multi_statements": 1,
            "value": 29336207
        },
        "collation_connection": "utf8mb4_general_ci",
        "group_concat_max_len": "",
        "isolation_level": "",
        "max_join_size": "",
        "names": "",
        "net_write_timeout": "",
        "no_backslash_escapes": false,
        "ps": {
            "client_stmt_to_global_ids": []
        },
        "session_track_gtids": "OFF",
        "sql_auto_is_null": "",
        "sql_log_bin": "1",
        "sql_mode": "",
        "sql_safe_updates": "",
        "sql_select_limit": "",
        "status": {
            "compression": false,
            "transaction": false
        },
        "time_zone": "",
        "transaction_read": "",
        "wsrep_sync_wait": ""
    },
    "current_hostgroup": 1,
    "default_hostgroup": 1,
    "default_schema": "dev_randall_aur",
    "gtid": {
        "hid": -1,
        "last": ""
    },
    "last_HG_affected_rows": 1,
    "last_insert_id": 0,
    "locked_on_hostgroup": 1,
    "qpo": {
        "cache_timeout": -1,
        "cache_ttl": -1,
        "create_new_connection": false,
        "delay": -1,
        "destination_hostgroup": -1,
        "firewall_whitelist_mode": 0,
        "max_lag_ms": -1,
        "multiplex": -1,
        "reconnect": -1,
        "retries": -1,
        "sticky_conn": -1,
        "timeout": -1
    },
    "status": 4,
    "thread": "0x7f3d69df0000",
    "thread_session_id": 1602,
    "transaction_persistent": true
}
After set autocommit=off: {
    "address": "0x7f3d68a91800",
    "age_ms": 2450,
    "autocommit": true,
    "autocommit_on_hostgroup": 1,
    "backends": [
        null,
        {
            "conn": {
                "MultiplexDisabled": true,
                "action": "",
                "address": "0x7f3d68817200",
                "auto_increment_delay_token": 0,
                "autocommit": "ON",
                "bytes_recv": 587759,
                "bytes_sent": 1606012,
                "character_set_client": "utf8mb4",
                "character_set_connection": "utf8mb4",
                "character_set_database": "utf8",
                "character_set_results": "utf8mb4",
                "charset": "45",
                "client_flag": {
                    "client_found_rows": 1,
                    "client_multi_statements": 1,
                    "value": 2157683343
                },
                "collation_connection": "utf8mb4_general_ci",
                "group_concat_max_len": "",
                "init_connect": "",
                "init_connect_sent": true,
                "isolation_level": "",
                "last_set_autocommit": 1,
                "max_join_size": "",
                "myconnpoll_get": 1769,
                "myconnpoll_put": 1768,
                "mysql": {
                    "address": "0x7f3d679e4b00",
                    "affected_rows": 0,
                    "charset": 45,
                    "charset_name": "utf8mb4",
                    "db": "test_dev_randall_aur",
                    "host": "127.0.0.1",
                    "host_info": "127.0.0.1 via TCP/IP",
                    "insert_id": 0,
                    "net": {
                        "fd": 81,
                        "last_errno": 0,
                        "max_packet_size": 1073741824,
                        "sqlstate": "00000"
                    },
                    "options": {
                        "charset_name": "",
                        "use_ssl": 0
                    },
                    "port": 3306,
                    "server_status": 16384,
                    "server_version": "5.7.32-35",
                    "thread_id": 12994482,
                    "unix_socket": "",
                    "user": "randal_aur"
                },
                "names": "",
                "net_write_timeout": "",
                "no_backslash_escapes": false,
                "ps": {
                    "backend_stmt_to_global_ids": [],
                    "global_stmt_to_backend_ids": []
                },
                "questions": 4805,
                "session_track_gtids": "",
                "sql_auto_is_null": "",
                "sql_log_bin": "1",
                "sql_mode": "",
                "sql_safe_updates": "",
                "sql_select_limit": "",
                "status": {
                    "found_rows": false,
                    "get_lock": false,
                    "has_savepoint": false,
                    "lock_tables": false,
                    "no_multiplex": true,
                    "temporary_table": false,
                    "user_variable": true
                },
                "time_zone": "",
                "transaction_read": "",
                "wsrep_sync_wait": ""
            },
            "gtid": "",
            "hostgroup_id": 1,
            "stream": {
                "DSS": 26,
                "address": "0x7f3d68af3200",
                "bytes_recv": 266077,
                "bytes_sent": 171470,
                "myconnpoll_get": 734,
                "myconnpoll_put": 733,
                "questions": 741
            }
        }
    ],
    "client": {
        "DSS": 6,
        "client_addr": {
            "address": "127.0.0.1",
            "port": 37456
        },
        "encrypted": false,
        "proxy_addr": {
            "address": "0.0.0.0",
            "port": 11113
        },
        "stream": {
            "bytes_recv": 175676,
            "bytes_sent": 514038,
            "pkts_recv": 756,
            "pkts_sent": 801
        },
        "userinfo": {
            "username": "randal_aur"
        }
    },
    "conn": {
        "action": "1",
        "autocommit": "ON",
        "character_set_client": "utf8mb4",
        "character_set_connection": "utf8mb4",
        "character_set_database": "utf8",
        "character_set_results": "utf8mb4",
        "charset": "45",
        "client_flag": {
            "client_found_rows": 1,
            "client_multi_results": 1,
            "client_multi_statements": 1,
            "value": 29336207
        },
        "collation_connection": "utf8mb4_general_ci",
        "group_concat_max_len": "",
        "isolation_level": "",
        "max_join_size": "",
        "names": "",
        "net_write_timeout": "",
        "no_backslash_escapes": false,
        "ps": {
            "client_stmt_to_global_ids": []
        },
        "session_track_gtids": "OFF",
        "sql_auto_is_null": "",
        "sql_log_bin": "1",
        "sql_mode": "",
        "sql_safe_updates": "",
        "sql_select_limit": "",
        "status": {
            "compression": false,
            "transaction": false
        },
        "time_zone": "",
        "transaction_read": "",
        "wsrep_sync_wait": ""
    },
    "current_hostgroup": 1,
    "default_hostgroup": 1,
    "default_schema": "dev_randall_aur",
    "gtid": {
        "hid": -1,
        "last": ""
    },
    "last_HG_affected_rows": 1,
    "last_insert_id": 0,
    "locked_on_hostgroup": 1,
    "qpo": {
        "cache_timeout": -1,
        "cache_ttl": -1,
        "create_new_connection": false,
        "delay": -1,
        "destination_hostgroup": -1,
        "firewall_whitelist_mode": 0,
        "max_lag_ms": -1,
        "multiplex": -1,
        "reconnect": -1,
        "retries": -1,
        "sticky_conn": -1,
        "timeout": -1
    },
    "status": 4,
    "thread": "0x7f3d69df0000",
    "thread_session_id": 1602,
    "transaction_persistent": true
}

[renecannao]

Hi @twotwotwo ,

From the output you provided it is possible that, while you are focus on just autocommit, there are other dynamics that can play a role in what you are experiencing.
For example, I see the following:

                "MultiplexDisabled": true,
...
                    "no_multiplex": true,
...
                    "user_variable": true
...
    "locked_on_hostgroup": 1,

The above clearly states that multiplexing is disabled, for at least 2 reasons:
a) proxysql detected a variable, either a user defined variable or a session variable that was unable to parse
b) at least one query rule explicitly disables multiplexing

Furthermore, and probably because of point A, the client connection is locked on hostgroup 1 , meaning that both routing and multiplexing are disabled (error log should have details about this).

I would suggest to enable query logging in ProxySQL (see https://proxysql.com/documentation/query-logging/ ) and track down all the queries executed by a client connection that then trigger an error.
Of course, the queries log on its own won't be enough to track down the issue: it is important to cross reference the log with query rules and global configuration.

[twotwotwo]

Yep. I'm okay with multiplexing disabled in some places for now and have ideas how we could reduce that, but transaction.atomic crashing in some place is a dealbreaker. I can try a bit more to reduce it, but have spent a while on this already and may have to give up (start looking for workarounds or other approaches) instead. Thanks for you help so far.

[renecannao]

@twotwotwo : you are welcome.
What I am trying to say is that without knowing the whole context in which you get those errors, and without a reproducible test case, we can't know if there is a bug with savepoint, a misconfiguration, a bug unrelated to savepoint but that result in missed savepoint, or anything else.
ProxySQL has embedded tools to help the troubleshooting: PROXYSQL INTERNAL SESSION\G and query logging probably the most relevant here, and they can be used to better understand why the tests are failing.

[twotwotwo]

I realized part of what I'm seeing makes sense from the code--once SET FOREIGN_KEY_CHECKS locks the session to a hostgroup, the session's autocommit member is no longer updated by handler_SetAutocommit, so it makes some sense that autocommit is set to true in the session structure (maybe that explains the bit in the OK packet too). I also notice that behavior is easy to reproduce (enable autocommit, lock to hostgroup, disable multiplexing, disable autocommit, check session).

proxysql/lib/MySQL_Session.cpp

Line 1116 in 3117914

if ((locked_on_hostgroup == -1) && mysql_thread___forward_autocommit == false) {

I still don't know why the backend didn't pick up the change in my real example, whereas it does if I just force lock_hostgroup before changing autocommit at the CLI. Still interesting for the sake of potential workarounds to know that lock_hostgroup also changes how autocommit is handled.

[jfavellar90]

Hey @rtnpro are you still operating any ProxySQL instance/cluster for Django applications? are you using any specific set of configurations for ProxySQL to support transactions and SAVEPOINTS properly?

[lc0rp]

Keen to get an answer to this as well. Is no one using proxysql with Django in prod?