ErrPktSyncMul is returned when the client is blocked by the server

[koshatul]

Issue description

Connecting to a server when the server has blocked the client for too many failed connections returns commands out of sync. Did you run multiple statements at once?. The mysql client returns a much more clearer and easier to repair message ERROR 1129 (HY000): Host 'X.X.X.X' is blocked because of many connection errors; unblock with 'mysqladmin flush-hosts'.

Is it possible to return better errors, or even retrieve the message returned by the server ?

I know this isn't a fix, but changing the check in packets.go to this:

if data[3] != mc.sequence && data[3] != 0b1 {
	if data[3] > mc.sequence {
		return nil, ErrPktSyncMul
	}
	return nil, ErrPktSync
}
mc.sequence++

changes the output of my example to:

2019/12/09 14:02:41 Initial Ping Error: %!s(<nil>)
2019/12/09 14:02:41 Final Ping Error: Error 1129: Host '172.17.0.1' is blocked because of many connection errors; unblock with 'mysqladmin flush-hosts'

which is far more readable.

Example code

• mysql.sh to start a mysql server under docker to make the test repeatable.

package main

import (
	"crypto/tls"
	"crypto/x509"
	"database/sql"
	"io/ioutil"
	"log"

	mysql "github.com/go-sql-driver/mysql"
)

func main() {
	rootCertPool := x509.NewCertPool()

	pem, err := ioutil.ReadFile("ssl/ca.pem")
	if err != nil {
		log.Fatal(err)
	}

	if ok := rootCertPool.AppendCertsFromPEM(pem); !ok {
		log.Fatal("Failed to append PEM.")
	}

	if err := mysql.RegisterTLSConfig("custom", &tls.Config{RootCAs: rootCertPool}); err != nil {
		panic(err)
	}

	dsn := "localuser:localpass@tcp(mysql.localtest.me:3306)/localtest?tls=custom"
	func() {
		db, _ := sql.Open("mysql", dsn)
		defer db.Close()

		err := db.Ping()
		log.Printf("Initial Ping Error: %s", err)
	}()

	dsn = "localuser:localpass@tcp(mysql2.localtest.me:3306)/localtest?tls=custom"
	for i := 0; i < 110; i++ {
		func() {
			dsn := dsn
			db, _ := sql.Open("mysql", dsn)
			defer db.Close()
			_ = db.Ping()
		}()
	}

	dsn = "localuser:localpass@tcp(mysql.localtest.me:3306)/localtest?tls=custom"
	func() {
		db, _ := sql.Open("mysql", dsn)
		defer db.Close()

		err := db.Ping()
		log.Printf("Final Ping Error: %s", err)
	}()
}

Error log

2019/12/09 13:39:39 Initial Ping Error: %!s(<nil>)
2019/12/09 13:39:40 Final Ping Error: commands out of sync. Did you run multiple statements at once?

Configuration

Go version: go version go1.13.1 darwin/amd64

Server version: 10.4.10-MariaDB-1:10.4.10+maria~bionic

Server OS: macOS/docker for repeating test.

Testing Repository: koshatul/go-mysql-sync-issue

[koshatul]

I tested across versions, and it seems to be a bug with MariaDB 10.2+

Server Version	Output
10.0.38-MariaDB-1~xenial	Final Ping Error: Error 1129: Host '172.17.0.1' is blocked because of many connection errors; unblock with 'mysqladmin flush-hosts'
10.1.43-MariaDB-1~bionic	Final Ping Error: Error 1129: Host '172.17.0.1' is blocked because of many connection errors; unblock with 'mysqladmin flush-hosts'
10.2.29-MariaDB-1:10.2.29+maria~bionic	Final Ping Error: commands out of sync. Did you run multiple statements at once?
10.3.20-MariaDB-1:10.3.20+maria~bionic	Final Ping Error: commands out of sync. Did you run multiple statements at once?
10.4.10-MariaDB-1:10.4.10+maria~bionic	Final Ping Error: commands out of sync. Did you run multiple statements at once?
MySQL 5.7.28	Final Ping Error: Error 1129: Host '172.17.0.1' is blocked because of many connection errors; unblock with 'mysqladmin flush-hosts'
MySQL 8.0.18	Final Ping Error: Error 1129: Host '172.17.0.1' is blocked because of many connection errors; unblock with 'mysqladmin flush-hosts'

I'll leave it up to the maintainer that reads the issue if it's something that needs to be handled, but I'll also report the issue to MariaDB.

[koshatul]

I posted an issue in the MariaDB bug tracker as well.

[iangcarroll]

It would be nice if this could be handled by the library -- I hit this quite frequently for various reasons and it makes debugging a pain (you can only really debug this with tcpdump, and that would be impossible over TLS).

[methane]

I don't know why other clients can read error message although packet number is wrong.
Would ypu provide a packet capture?

[koshatul]

There's an extract of the packet capture in the MariaDB issue (but it really isn't much, it's the 4 bytes in the response).

I think it's ignored in other libraries mostly because it's an error, who cares what the packet number is, the connection isn't allowed, throw an error and handle it like any other error, and I assume they check the packet number much later in the response processing.

[koshatul]

Packet capture: mariadb.pcap.zip

MariaDB 10.1 (pre-bug):

No.     Time           Source                Destination           Protocol Length Info
      4 0.000155       172.17.0.2            172.17.0.1            MySQL    174    Server Greeting Error 1129

Frame 4: 174 bytes on wire (1392 bits), 174 bytes captured (1392 bits)
Ethernet II, Src: 02:42:ac:11:00:02 (02:42:ac:11:00:02), Dst: 02:42:15:9f:91:76 (02:42:15:9f:91:76)
Internet Protocol Version 4, Src: 172.17.0.2, Dst: 172.17.0.1
Transmission Control Protocol, Src Port: 3306, Dst Port: 55812, Seq: 1, Ack: 1, Len: 108
MySQL Protocol
    Packet Length: 104
    Packet Number: 0
    Error Code: 1129
    Error message: Host '172.17.0.1' is blocked because of many connection errors; unblock with 'mysqladmin flush-hosts'

0000  02 42 15 9f 91 76 02 42 ac 11 00 02 08 00 45 08   .B...v.B......E.
0010  00 a0 05 c9 40 00 40 06 dc 61 ac 11 00 02 ac 11   ....@.@..a......
0020  00 01 0c ea da 04 10 f4 2e 63 96 4d aa 0e 80 18   .........c.M....
0030  01 fe 58 b8 00 00 01 01 08 0a 30 31 70 95 13 a7   ..X.......01p...
0040  d6 4f 68 00 00 00 ff 69 04 48 6f 73 74 20 27 31   .Oh....i.Host '1
0050  37 32 2e 31 37 2e 30 2e 31 27 20 69 73 20 62 6c   72.17.0.1' is bl
0060  6f 63 6b 65 64 20 62 65 63 61 75 73 65 20 6f 66   ocked because of
0070  20 6d 61 6e 79 20 63 6f 6e 6e 65 63 74 69 6f 6e    many connection
0080  20 65 72 72 6f 72 73 3b 20 75 6e 62 6c 6f 63 6b    errors; unblock
0090  20 77 69 74 68 20 27 6d 79 73 71 6c 61 64 6d 69    with 'mysqladmi
00a0  6e 20 66 6c 75 73 68 2d 68 6f 73 74 73 27         n flush-hosts'

MariaDB 10.4 (post-bug added in 10.2):

No.     Time           Source                Destination           Protocol Length Info
      4 0.000544       172.17.0.2            172.17.0.1            MySQL    174    Response Error 1129

Frame 4: 174 bytes on wire (1392 bits), 174 bytes captured (1392 bits)
Ethernet II, Src: 02:42:ac:11:00:02 (02:42:ac:11:00:02), Dst: 02:42:15:9f:91:76 (02:42:15:9f:91:76)
Internet Protocol Version 4, Src: 172.17.0.2, Dst: 172.17.0.1
Transmission Control Protocol, Src Port: 3306, Dst Port: 55324, Seq: 1, Ack: 1, Len: 108
MySQL Protocol
    Packet Length: 104
    Packet Number: 1
    Response Code: ERR Packet (0xff)
    Error Code: 1129
    Error message: Host '172.17.0.1' is blocked because of many connection errors; unblock with 'mysqladmin flush-hosts'

0000  02 42 15 9f 91 76 02 42 ac 11 00 02 08 00 45 08   .B...v.B......E.
0010  00 a0 ba 05 40 00 40 06 28 25 ac 11 00 02 ac 11   ....@.@.(%......
0020  00 01 0c ea d8 1c a2 b3 30 3d 5c 3f e4 6d 80 18   ........0=\?.m..
0030  01 fe 58 b8 00 00 01 01 08 0a 30 2c 43 33 13 a2   ..X.......0,C3..
0040  a8 ed 68 00 00 01 ff 69 04 48 6f 73 74 20 27 31   ..h....i.Host '1
0050  37 32 2e 31 37 2e 30 2e 31 27 20 69 73 20 62 6c   72.17.0.1' is bl
0060  6f 63 6b 65 64 20 62 65 63 61 75 73 65 20 6f 66   ocked because of
0070  20 6d 61 6e 79 20 63 6f 6e 6e 65 63 74 69 6f 6e    many connection
0080  20 65 72 72 6f 72 73 3b 20 75 6e 62 6c 6f 63 6b    errors; unblock
0090  20 77 69 74 68 20 27 6d 79 73 71 6c 61 64 6d 69    with 'mysqladmi
00a0  6e 20 66 6c 75 73 68 2d 68 6f 73 74 73 27         n flush-hosts'

[grooverdan]

I'm sorry this too so long to fix in MariaDB (MDEV-21252). This will be included in the next releases 10.2.42, 10.3.33, 10.4.23, 10.5.14, 10.6.6, 10.7.2.