From 5f1919b40f66818206c5f02eab30706ada5e2f54 Mon Sep 17 00:00:00 2001
From: Jacob Hoffman-Andrews <github@hoffman-andrews.com>
Date: Thu, 20 Oct 2016 07:29:29 -0700
Subject: [PATCH] Use max_statement_time for timeouts. (#2263)

This means that we get a more useful log message for slow queries, and don't
need to close the MySQL connection. It also means that the query is actually
killed on the MySQL side, rather than just timing out and returning on the
client side.

We set the max_statement_time to 95% of the `readTimeout`.

Also set the `long_query_time` to 80% of the `readTimeout`, so that queries that are
close to timing out will be logged by MySQL's slow query logging.
---
 sa/database.go      | 17 ++++++++++++++++-
 sa/database_test.go | 21 +++++++++++++++++++++
 2 files changed, 37 insertions(+), 1 deletion(-)

diff --git a/sa/database.go b/sa/database.go
index b568450d2..08177682c 100644
--- a/sa/database.go
+++ b/sa/database.go
@@ -67,10 +67,25 @@ func NewDbMapFromConfig(config *mysql.Config, maxOpenConns int) (*gorp.DbMap, er
 	dbmap := &gorp.DbMap{Db: db, Dialect: dialect, TypeConverter: BoulderTypeConverter{}}
 
 	initTables(dbmap)
-	_, err = dbmap.Exec("SET sql_mode = 'STRICT_ALL_TABLES';")
+	_, err = dbmap.Exec("SET SESSION sql_mode = 'STRICT_ALL_TABLES';")
 	if err != nil {
 		return nil, err
 	}
+	// If a read timeout is set, we set max_statement_time to 95% of that, and
+	// long_query_time to 80% of that. That way we get logs of queries that are
+	// close to timing out but not yet doing so, and our queries get stopped by
+	// max_statement_time before timing out the read. This generates clearer
+	// errors, and avoids unnecessary reconnects.
+	if config.ReadTimeout != 0 {
+		// In MariaDB, max_statement_time and long_query_time are both seconds.
+		// Note: in MySQL (which we don't use), max_statement_time is millis.
+		readTimeout := config.ReadTimeout.Seconds()
+		_, err := dbmap.Exec("SET SESSION max_statement_time = ?, long_query_time = ?;",
+			readTimeout*0.95, readTimeout*0.80)
+		if err != nil {
+			return nil, err
+		}
+	}
 
 	return dbmap, err
 }
diff --git a/sa/database_test.go b/sa/database_test.go
index 85d728cba..68741dcb9 100644
--- a/sa/database_test.go
+++ b/sa/database_test.go
@@ -73,3 +73,24 @@ func TestStrictness(t *testing.T) {
 		t.Fatalf("Got wrong type of error: %s", err)
 	}
 }
+
+func TestTimeouts(t *testing.T) {
+	dbMap, err := NewDbMap(vars.DBConnSA+"?readTimeout=100ms", 1)
+	if err != nil {
+		t.Fatal("Error setting up DB:", err)
+	}
+	// SLEEP is defined to return 1 if it was interrupted, but we want to actually
+	// get an error to simulate what would happen with a slow query. So we wrap
+	// the SLEEP in a subselect.
+	_, err = dbMap.Exec(`SELECT 1 FROM (SELECT SLEEP(1)) as subselect;`)
+	if err == nil {
+		t.Fatal("Expected error when running slow query, got none.")
+	}
+
+	// We expect to get:
+	// Error 1969: Query execution was interrupted (max_statement_time exceeded)
+	// https://mariadb.com/kb/en/mariadb/mariadb-error-codes/
+	if !strings.Contains(err.Error(), "Error 1969") {
+		t.Fatalf("Got wrong type of error: %s", err)
+	}
+}