Repository: sysown/proxysql (language: cpp)

Issue:
Connections killed by incorrect implementation of `max_transaction_time`
## Overview

A connection with many transactions can (and does) get killed by the `max_transaction_time` implementation, even though each individual transaction takes much shorter than `max_transaction_time`. This is likely caused by the fact that `max_transaction_time` depends on a periodic check in a maintenance loop instead of watching every `BEGIN` and `COMMIT`/`ROLLBACK`, and thus does not notice the boundaries between transactions.

### Issue tracker guidelines

If you are submitting a reproducible bug report, please provide:
- [x] A clear description of the issue: given below
- [x] ProxySQL version: git master `1c51cac80accc4d0afe70e19d25b95250559e5d9`. This is however not very relevant, as we observe this behaviour in `2.2.0-72-ge14accd`, too.
- [x] OS version: a recent Arch Linux
- [x] The steps to reproduce the issue: given below
- [x] The **full** ProxySQL error log (default location: `/var/lib/proxysql/proxysql.log`): https://gist.github.com/matus-chordify/6b735ad3cda9d253a80169de8aa1856a -- this is the terminal output

## Reproduction

In one terminal, run ProxySQL:
```bash
proxysql --foreground
```

In another terminal, run a MySQL server, skipping grant tables for convenience.
```bash
dir="$(realpath db)"  # mysql wants absolute path
mkdir -p "$dir"
mysql_install_db "$dir"
mysqld --datadir="$dir" --port 3307 --socket="${dir}/mysqld.sock" --skip-grant-tables
```

In a third terminal, initialise the ProxySQL configuration, setting `max_transaction_time` to 10 seconds:
```sql
mysql -u admin -padmin -h 127.0.0.1 -P6032 <<EOF
INSERT INTO mysql_servers(hostgroup_id,hostname,port)
VALUES (1, '127.0.0.1', 3307);

LOAD MYSQL SERVERS TO RUNTIME;

update global_variables
set variable_value = 10000  -- 10 seconds
where variable_name = 'mysql-max_transaction_time';

LOAD MYSQL VARIABLES TO RUNTIME;

INSERT INTO mysql_users(username,password,default_hostgroup)
VALUES ('user','',1);

LOAD MYSQL USERS TO RUNTIME;
EOF
```

Run a couple of 1-second transactions:
```bash
for i in $(seq 15); do
  echo -e 'BEGIN;\nSELECT SLEEP(1);\nCOMMIT;'
done | mysql -h 127.0.0.1 --port 6033 -u user
```

Observe that the connection gets killed:
```
$ for i in $(seq 15); do echo -e 'BEGIN;\nSELECT SLEEP(1);\nCOMMIT;'; done | mysql -h 127.0.0.1 --port 6033 -u user
SLEEP(1)
0
  [ ...omitted for brevity... ]
SLEEP(1)
0
ERROR 2013 (HY000) at line 30: Lost connection to server during query
```

ProxySQL reports:
```
2022-08-23 11:41:09 MySQL_Thread.cpp:3713:ProcessAllSessions_MaintenanceLoop(): [WARNING] Killing client connection 127.0.0.1:49756 because of (possible) transaction running for 10012ms
```

However, there has been no transaction running for 10 seconds.

## Likely cause

There are only two places where `MySQL_Session::transaction_started_at` is written to:
* [MySQL_Session::handler()](https://github.com/sysown/proxysql/blob/v2.x/lib/MySQL_Session.cpp#L4398)
* [MySQL_Thread::ProcessAllSessions_MaintenanceLoop()](https://github.com/sysown/proxysql/blob/v2.x/lib/MySQL_Thread.cpp#L3673)

In both cases, `sess->active_transactions` must be equal to `0` before any change to `sess->transaction_started_at` can happen. Unfortunately, once `sess->active_transactions` is non-zero, it is never zeroed, except possibly [in the periodic maintenance loop](https://github.com/sysown/proxysql/blob/v2.x/lib/MySQL_Thread.cpp#L3669). This is however insufficient because if transactions come back-to-back, it is very unlikely that periodic maintenance would happen exactly between transactions. The result is that `sess->transaction_started_at` is never updated and the connection will be killed after the configured timeout.

## Possible fixes

1. I am not sure if `MySQL_Session::handler()` is called for every statement but if it is, it would probably be sufficient to rewrite [the `if` statement in `MySQL_Session::handler()`](https://github.com/sysown/proxysql/blob/v2.x/lib/MySQL_Session.cpp#L4398) so that it allows transitioning from `active_transactions > 0` to `active_transactions == 0` as well as the currently allowed transition in the other direction.
2. Another fix could be zeroing `active_transactions` in [MySQL_Session::handler_CommitRollback](https://github.com/sysown/proxysql/blob/v2.x/lib/MySQL_Session.cpp#L809).

If any of the two solutions sounds reasonable, I'm happy to send a PR.

### Workaround

For now, we're increasing `max_transaction_time` to ~1 year~ to effectively disable this feature. Edit: it turns out the maximum value is 20 days, as per [the documentation](https://proxysql.com/documentation/global-variables/mysql-variables/#mysql-max_transaction_time).


Discussion / hints:
Hi @matus-chordify .
Thank you for the report, we really appreciated detailed analysis.
I didn't try to reproduce it yet, but the description of the issue and the analysis you did seem pretty accurate.

The 2nd solution proposed won't work because it cannot handle [implicit commits](https://dev.mysql.com/doc/refman/8.0/en/implicit-commit.html).

The 1st solution proposed may work, although it may not be optimal: calling `NumActiveTransactions()` is an expensive operation and it is not optimal to call it for every iteration of `MySQL_Session::handler()` (a single query can call `handler()`many many times).
Probably a more efficient solution is to perform some computation after a query to the backend completes, specifically
in [this section of the code](https://github.com/sysown/proxysql/blob/v2.4.3/lib/MySQL_Session.cpp#L4674-L4698).
We could implement something like (not tested):
```
if (active_transactions != 0) {  // run this only if currently we think there is a transaction
   if (myconn->mysql->server_status & SERVER_STATUS_IN_TRANS) == 0) { // there is no transaction on the backend connection
       active_transactions=NumActiveTransactions(); // we check all the hostgroups/backends
       if (active_transaction==0)
         transaction_started_at = 0; // reset it
}
```

> If any of the two solutions sounds reasonable, I'm happy to send a PR.

PRs are always welcome! :) Thanks!
We will also need a TAP to verify this feature, but we can write one.

Ideally we should also try to reduce the number of time we call `NumActiveTransactions()`, because this implementation will call it twice for `COMMIT` : `NumActiveTransactions()` will be called again in `MySQL_Result_to_MySQL_wire()`.
This is a future optimization we can implement on the next refactoring.
Hi @renecannao, many thanks for the prompt reply! Your comments are very helpful.

How about putting the check that you mentioned in [`MySQL_Session::RequestEnd()`](https://github.com/sysown/proxysql/blob/v2.4.3/lib/MySQL_Session.cpp#L7137)? Would that be better (more robust) than putting it where you indicated in `MySQL_Session::handle()`, perhaps? I have tested that with [such a patch](https://github.com/sysown/proxysql/commit/f25bbea594599241be0809c565e2ec999e484ea5), I cannot reproduce the error using the above arrangement anymore.

Perhaps we could also place it in [`MySQL_Session::finishQuery()`](https://github.com/sysown/proxysql/blob/v2.4.3/lib/MySQL_Session.cpp#L7373) but I'm not sure what exactly is the difference between a "request" and a "query" in ProxySQL. I'm just slowly finding my way around the codebase and going by the comments and the doxy, `RequestEnd()` sounds a bit more fitting, although it's called in many more places.
We're also experiencing this issue at Intercom since upgrading to proxysql2, thanks for the great issue description that helped us zero in on it @matus-chordify.

Fix patch:
diff --git a/lib/MySQL_Session.cpp b/lib/MySQL_Session.cpp
index 9d8cfc04b6..a56b5ef1cf 100644
--- a/lib/MySQL_Session.cpp
+++ b/lib/MySQL_Session.cpp
@@ -1095,6 +1095,8 @@ void MySQL_Session::generate_proxysql_internal_session_json(json &j) {
 	j["autocommit_on_hostgroup"] = autocommit_on_hostgroup;
 	j["last_insert_id"] = last_insert_id;
 	j["last_HG_affected_rows"] = last_HG_affected_rows;
+	j["active_transactions"] = active_transactions;
+	j["transaction_time_ms"] = thread->curtime - transaction_started_at;
 	j["gtid"]["hid"] = gtid_hid;
 	j["gtid"]["last"] = ( strlen(gtid_buf) ? gtid_buf : "" );
 	j["qpo"]["create_new_connection"] = qpo->create_new_conn;
@@ -4691,12 +4693,6 @@ int MySQL_Session::handler() {
 	//unsigned int j;
 	//unsigned char c;
 
-	if (active_transactions == 0) {
-		active_transactions=NumActiveTransactions();
-		if (active_transactions > 0) {
-			transaction_started_at = thread->curtime;
-		}
-	}
 //	FIXME: Sessions without frontend are an ugly hack
 	if (session_fast_forward==false) {
 	if (client_myds==NULL) {
@@ -4968,6 +4964,14 @@ int MySQL_Session::handler() {
 				gtid_hid = -1;
 				if (rc==0) {
 
+					if (active_transactions != 0) {  // run this only if currently we think there is a transaction
+						if ((myconn->mysql->server_status & SERVER_STATUS_IN_TRANS) == 0) { // there is no transaction on the backend connection
+							active_transactions = NumActiveTransactions(); // we check all the hostgroups/backends
+							if (active_transactions == 0)
+								transaction_started_at = 0; // reset it
+						}
+					}
+
 					handler_rc0_Process_GTID(myconn);
 
 					// if we are locked on hostgroup, the value of autocommit is copied from the backend connection
@@ -7206,8 +7210,7 @@ void MySQL_Session::MySQL_Result_to_MySQL_wire(MYSQL *mysql, MySQL_ResultSet *My
 		int myerrno=mysql_errno(mysql);
 		if (myerrno==0) {
 			unsigned int num_rows = mysql_affected_rows(mysql);
-			unsigned int nTrx=NumActiveTransactions();
-			uint16_t setStatus = (nTrx ? SERVER_STATUS_IN_TRANS : 0 );
+			uint16_t setStatus = (active_transactions ? SERVER_STATUS_IN_TRANS : 0);
 			if (autocommit) setStatus |= SERVER_STATUS_AUTOCOMMIT;
 			if (mysql->server_status & SERVER_MORE_RESULTS_EXIST)
 				setStatus |= SERVER_MORE_RESULTS_EXIST;
diff --git a/lib/MySQL_Thread.cpp b/lib/MySQL_Thread.cpp
index 800438f289..f4df746795 100644
--- a/lib/MySQL_Thread.cpp
+++ b/lib/MySQL_Thread.cpp
@@ -3746,18 +3746,6 @@ void MySQL_Thread::ProcessAllSessions_CompletedMirrorSession(unsigned int& n, My
 // this function was inline in MySQL_Thread::process_all_sessions()
 void MySQL_Thread::ProcessAllSessions_MaintenanceLoop(MySQL_Session *sess, unsigned long long sess_time, unsigned int& total_active_transactions_) {
 	unsigned int numTrx=0;
-	sess->active_transactions=sess->NumActiveTransactions();
-	{
-		sess->active_transactions=sess->NumActiveTransactions();
-		// in case we detected a new transaction just now
-		if (sess->active_transactions == 0) {
-			sess->transaction_started_at = 0;
-		} else {
-			if (sess->transaction_started_at == 0) {
-				sess->transaction_started_at = curtime;
-			}
-		}
-	}
 	total_active_transactions_ += sess->active_transactions;
 	sess->to_process=1;
 	if ( (sess_time/1000 > (unsigned long long)mysql_thread___max_transaction_idle_time) || (sess_time/1000 > (unsigned long long)mysql_thread___wait_timeout) ) {
diff --git a/lib/mysql_connection.cpp b/lib/mysql_connection.cpp
index bede6d49be..ef4e886422 100644
--- a/lib/mysql_connection.cpp
+++ b/lib/mysql_connection.cpp
@@ -1982,6 +1982,14 @@ int MySQL_Connection::async_query(short event, char *stmt, unsigned long length,
 			return 0;
 			break;
 		case ASYNC_IDLE:
+			if (myds && myds->sess) {
+				if (myds->sess->active_transactions == 0) {
+					// every time we start a query (no matter if COM_QUERY, STMT_PREPARE or otherwise)
+					// also a transaction starts, even if in autocommit mode
+					myds->sess->active_transactions = 1;
+					myds->sess->transaction_started_at = myds->sess->thread->curtime;
+				}
+			}
 			if (stmt_meta==NULL)
 				set_query(stmt,length);
 			async_state_machine=ASYNC_QUERY_START;


Test patch:
diff --git a/test/tap/tests/test_max_transaction_time-t.cpp b/test/tap/tests/test_max_transaction_time-t.cpp
new file mode 100644
index 0000000000..3d0e00bf6d
--- /dev/null
+++ b/test/tap/tests/test_max_transaction_time-t.cpp
@@ -0,0 +1,118 @@
+/**
+ * @file test_max_transaction_time-t.cpp
+ * @brief This test verifies that 'max_transaction_time' behaves properly.
+ *
+ * @details It verifies that connection with many transactions does not get
+ * killed by the max_transaction_time implementation if each individual
+ * transaction takes shorter than max_transaction_time.
+ */
+
+#include "mysql.h"
+
+#include "proxysql_utils.h"
+#include "tap.h"
+#include "utils.h"
+
+#include <unistd.h>
+#include <iostream>
+
+using std::string;
+
+#include "json.hpp"
+
+#define NUMQUERIES	15
+
+using nlohmann::json;
+
+using namespace std;
+
+void parse_result_json_column(MYSQL_RES *result, json& j) {
+	if(!result) return;
+	MYSQL_ROW row;
+
+	while ((row = mysql_fetch_row(result))) {
+		j = json::parse(row[0]);
+	}
+}
+
+// This test was previously failing due to replication not catching up quickly enough when doing
+int main(int, char**) {
+	CommandLine cl;
+
+	plan(NUMQUERIES*2+1);
+
+	if (cl.getEnv()) {
+		diag("Failed to get the required environmental variables.");
+		return EXIT_FAILURE;
+	}
+
+	MYSQL* admin = mysql_init(NULL);
+	if (!mysql_real_connect(admin, cl.host, cl.admin_username, cl.admin_password, NULL, cl.admin_port, NULL, 0)) {
+		fprintf(stderr, "File %s, line %d, Error: %s\n", __FILE__, __LINE__, mysql_error(admin));
+		return EXIT_FAILURE;
+	}
+
+	diag("Configure ProxySQL to test mysql-max_transaction_time");
+	MYSQL_QUERY_T(
+		admin,
+		"UPDATE global_variables SET variable_value = 4000 "
+		"WHERE variable_name = 'mysql-max_transaction_time'"
+	);
+	MYSQL_QUERY_T(admin, "LOAD MYSQL VARIABLES TO RUNTIME");
+
+	mysql_close(admin);
+
+	MYSQL* proxy = mysql_init(NULL);
+	if (!mysql_real_connect(proxy, cl.host, cl.username, cl.password, NULL, cl.port, NULL, 0)) {
+		fprintf(stderr, "File %s, line %d, Error: %s\n", __FILE__, __LINE__, mysql_error(proxy));
+		return EXIT_FAILURE;
+	}
+
+	diag("Run %d 1-second transactions:", NUMQUERIES);
+	MYSQL_RES* myres;
+	for (int i = 0; i < NUMQUERIES; i++) {
+		MYSQL_QUERY_T(proxy, "BEGIN");
+
+		MYSQL_QUERY_T(proxy, "SELECT SLEEP(1)");
+		myres = mysql_store_result(proxy);
+		if (myres == nullptr) {
+			fprintf(stderr, "File %s, line %d, Error: %s\n", __FILE__, __LINE__, mysql_error(proxy));
+			return EXIT_FAILURE;
+		}
+		mysql_free_result(myres);
+
+		json j = {};
+		MYSQL_QUERY_T(proxy, "PROXYSQL INTERNAL SESSION");
+		myres = mysql_store_result(proxy);
+		parse_result_json_column(myres, j);
+		mysql_free_result(myres);
+		int active_transactions = atoi(j["active_transactions"].dump().c_str());
+		unsigned long long transaction_time_ms = atoll(j["transaction_time_ms"].dump().c_str());
+		transaction_time_ms /= 1000;
+		ok(active_transactions==1, "active_transactions = %d", active_transactions);
+		ok(transaction_time_ms >= 900 && transaction_time_ms <= 1200, "Transaction time: %llu ms" , transaction_time_ms);
+		MYSQL_QUERY_T(proxy, "COMMIT");
+	}
+
+
+	MYSQL_QUERY_T(proxy, "BEGIN");
+	diag("Sleeping for 10 seconds so that the transaction times out");
+	sleep(10);
+	diag("Issuing PROXYSQL INTERNAL SESSION : it should fail");
+	int query_err = mysql_query(proxy, "PROXYSQL INTERNAL SESSION");
+	ok(query_err != 0 && mysql_errno(proxy) == 2013 , "Failed with error code %d : %s" , mysql_errno(proxy), mysql_error(proxy));
+	if (query_err == 0) {
+		json j = {};
+		myres = mysql_store_result(proxy);
+		parse_result_json_column(myres, j);
+		mysql_free_result(myres);
+		int active_transactions = atoi(j["active_transactions"].dump().c_str());
+		unsigned long long transaction_time_ms = atoll(j["transaction_time_ms"].dump().c_str());
+		transaction_time_ms /= 1000;
+		diag("active_transactions = %d", active_transactions);
+		diag("Transaction time: %llu ms" , transaction_time_ms);
+	}
+	mysql_close(proxy);
+
+	return exit_status();
+}