Driver hangs on Next() with some tricky MySQL query

[arvenil]

Hi,

I'm trying to run some tricky MySQL query, and it would be nice if anyone could help me with problem I encounter.

I'm trying to run EXPLAIN FORMAT=JSON query but only if it is supported by MySQL version. To do that, in theory, I can use conditional comments e.g. /*!50605 <SQL code to be run since version 5.6.5>*/

Below is an example of what I'm talking about

mysql> SHOW VARIABLES LIKE "version";
+---------------+-------------+
| Variable_name | Value       |
+---------------+-------------+
| version       | 5.6.19-67.0 |
+---------------+-------------+
1 row in set (0,00 sec)

mysql> /*!50605 EXPLAIN FORMAT=JSON SELECT 1*/;
+-------------------------------------------------------------------------------------------------------+
| EXPLAIN                                                                                               |
+-------------------------------------------------------------------------------------------------------+
| {
  "query_block": {
    "select_id": 1,
    "table": {
      "message": "No tables used"
    }
  }
} |
+-------------------------------------------------------------------------------------------------------+
1 row in set, 1 warning (0,00 sec)

mysql> /*!60605 EXPLAIN FORMAT=JSON SELECT 1*/;
Query OK, 0 rows affected (0,00 sec)

Since I have version 5.6.19 then code /*!50605 (>= 5.6.5) executes explain and code /*!60605 (>= 6.6.5) doesn't.

Here are also live examples on sql fiddle:
http://sqlfiddle.com/#!2/d41d8/40716/0 version 5.5.32
http://sqlfiddle.com/#!9/d41d8/788/0 version 5.6.6

However I'm unable to get similar results with go sql driver. It hangs in case where it should return 0 rows. Here is an example code (http://play.golang.org/p/ksY-FFHg7n):

package main

import (
    "database/sql"
    "fmt"
    _ "github.com/go-sql-driver/mysql"
)

func main() {
    db, err := sql.Open("mysql", "@/")
    fmt.Println(err)
    var json string
    err = db.QueryRow("/*!50605 EXPLAIN FORMAT=JSON SELECT 1*/").Scan(&json)
    fmt.Println(err)
    fmt.Println(json)
}

Correct result when condition is fulfilled:

<nil>
<nil>
{
  "query_block": {
    "select_id": 1,
    "table": {
      "message": "No tables used"
    }
  }
}

Incorrect result when condition is not fulfilled:

go run main.go 
<nil>
(HANGS HERE, JUST AFTER FIRST NIL,  MANUALLY INTERRUPTED WITH SIGQUIT)
^\SIGQUIT: quit
PC=0x42bdc3

goroutine 17 [syscall]:
runtime.notetsleepg(0x7fa4fc0d4f60, 0xdf8475800)
    /usr/local/go/src/pkg/runtime/lock_futex.c:198 +0x46 fp=0x7fa4fc0d4f38 sp=0x7fa4fc0d4f08
runtime.MHeap_Scavenger()
    /usr/local/go/src/pkg/runtime/mheap.c:532 +0xa3 fp=0x7fa4fc0d4fa8 sp=0x7fa4fc0d4f38
runtime.goexit()
    /usr/local/go/src/pkg/runtime/proc.c:1445 fp=0x7fa4fc0d4fb0 sp=0x7fa4fc0d4fa8
created by runtime.main
    /usr/local/go/src/pkg/runtime/proc.c:207

goroutine 16 [IO wait]:
net.runtime_pollWait(0x7fa4fc246508, 0x72, 0x0)
    /usr/local/go/src/pkg/runtime/netpoll.goc:146 +0x66
net.(*pollDesc).Wait(0xc208028140, 0x72, 0x0, 0x0)
    /usr/local/go/src/pkg/net/fd_poll_runtime.go:84 +0x46
net.(*pollDesc).WaitRead(0xc208028140, 0x0, 0x0)
    /usr/local/go/src/pkg/net/fd_poll_runtime.go:89 +0x42
net.(*netFD).Read(0xc2080280e0, 0xc208068000, 0x1000, 0x1000, 0x0, 0x7fa4fc2453f0, 0xb)
    /usr/local/go/src/pkg/net/fd_unix.go:232 +0x34c
net.(*conn).Read(0xc20803c028, 0xc208068000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/local/go/src/pkg/net/net.go:122 +0xe7
github.com/go-sql-driver/mysql.(*buffer).fill(0xc208048200, 0x4, 0x0, 0x0)
    /home/kdz/local/libs/go/src/github.com/go-sql-driver/mysql/buffer.go:55 +0x25b
github.com/go-sql-driver/mysql.(*buffer).readNext(0xc208048200, 0x4, 0x0, 0x0, 0x0, 0x0, 0x0)
    /home/kdz/local/libs/go/src/github.com/go-sql-driver/mysql/buffer.go:76 +0x6c
github.com/go-sql-driver/mysql.(*mysqlConn).readPacket(0xc208048200, 0x0, 0x0, 0x0, 0x0, 0x0)
    /home/kdz/local/libs/go/src/github.com/go-sql-driver/mysql/packets.go:30 +0x9d
github.com/go-sql-driver/mysql.(*textRows).readRow(0xc2080420a0, 0x770b00, 0x0, 0x0, 0x0, 0x0)
    /home/kdz/local/libs/go/src/github.com/go-sql-driver/mysql/packets.go:588 +0x68
github.com/go-sql-driver/mysql.(*textRows).Next(0xc2080420a0, 0x770b00, 0x0, 0x0, 0x0, 0x0)
    /home/kdz/local/libs/go/src/github.com/go-sql-driver/mysql/rows.go:80 +0x8c
database/sql.(*Rows).Next(0xc208004240, 0x59dce0)
    /usr/local/go/src/pkg/database/sql/sql.go:1542 +0xe5
database/sql.(*Row).Scan(0xc2080420c0, 0x7fa4fc0b6f20, 0x1, 0x1, 0x0, 0x0)
    /usr/local/go/src/pkg/database/sql/sql.go:1660 +0x23c
main.main()
    /home/kdz/local/libs/go/src/github.com/arvenil/db/main.go:14 +0x1bd

goroutine 19 [finalizer wait]:
runtime.park(0x4132c0, 0x770568, 0x76f049)
    /usr/local/go/src/pkg/runtime/proc.c:1369 +0x89
runtime.parkunlock(0x770568, 0x76f049)
    /usr/local/go/src/pkg/runtime/proc.c:1385 +0x3b
runfinq()
    /usr/local/go/src/pkg/runtime/mgc0.c:2644 +0xcf
runtime.goexit()
    /usr/local/go/src/pkg/runtime/proc.c:1445

goroutine 20 [chan receive]:
database/sql.(*DB).connectionOpener(0xc208048100)
    /usr/local/go/src/pkg/database/sql/sql.go:583 +0x48
created by database/sql.Open
    /usr/local/go/src/pkg/database/sql/sql.go:442 +0x27c

rax     0xfffffffffffffffc
rbx     0x0
rcx     0xffffffffffffffff
rdx     0x0
rdi     0x7fa4fc0d4f60
rsi     0x0
rbp     0x3c
rsp     0x7fa4fc0d4ea0
r8      0x0
r9      0x0
r10     0x7fa4fc0d4ed0
r11     0x216
r12     0x5ed9a0
r13     0x7fff47c715e0
r14     0x0
r15     0x0
rip     0x42bdc3
rflags  0x216
cs      0x33
fs      0x0
gs      0x0
exit status 2

First, I've tried to rewrite code to use Query instead of QueryRow, but it hang on Next() (as you can actually see in stacktrace).

Any ideas if this is bug in driver, MySQL or maybe in my code?

EDIT: tried with old version of driver and with 1.2 7094cf0

[arnehormann]

I assume your code is correct - I'd still like to know if it looks different than what I expect. Can you post a link?

I just tried to replicate it with your QueryRow program - it worked in MySQL 5.6.19 and failed in MariaDB (10.0.11-MariaDB) - but with an error:

<nil>
Error 1064: You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '=JSON SELECT 1*/' at line 1

I don't have another version at hand.

Did you take a look at the protocol level yet - Wireshark or tcpdump?
What Go version are you using?

[arvenil]

I just tried to replicate it with your QueryRow program - it worked in MySQL 5.6.19

If you have MySQL version 5.6.19 then to test that just change check in code to /*!50620 and it will hang on rows.Next. Press Ctrl+\ to send SIGQUIT and get stacktrace.
Here is your version of code with changed code check for MySQL version: http://play.golang.org/p/o7c5-D4U2H

(I have 5.6.19 version too)

$ mysql -e 'SHOW VARIABLES LIKE "version";'
+---------------+-------------+
| Variable_name | Value       |
+---------------+-------------+
| version       | 5.6.19-67.0 |
+---------------+-------------+
$ cat main.go
package main

import (
    "database/sql"
    "fmt"
    "os"

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

func main() {
    db, _ := sql.Open("mysql", "@/")
    defer db.Close()
    var json string
    rows, err := db.Query("/*!50620 EXPLAIN FORMAT=JSON SELECT 1*/")
    if err != nil {
        fmt.Fprintf(os.Stderr, "ERR[Query] %s\n", err)
        return
    }
    defer rows.Close()
    for rows.Next() {
        err = rows.Scan(&json)
        if err != nil {
            fmt.Fprintf(os.Stderr, "ERR[Scan] %s\n", err)
            return
        }
        fmt.Println(json)
    }
}
$ go run main.go
^\SIGQUIT: quit
PC=0x42bfc3

goroutine 17 [syscall]:
runtime.notetsleepg(0x7f1a6235df60, 0xdf8475800)
    /usr/local/go/src/pkg/runtime/lock_futex.c:198 +0x46 fp=0x7f1a6235df38 sp=0x7f1a6235df08
runtime.MHeap_Scavenger()
    /usr/local/go/src/pkg/runtime/mheap.c:532 +0xa3 fp=0x7f1a6235dfa8 sp=0x7f1a6235df38
runtime.goexit()
    /usr/local/go/src/pkg/runtime/proc.c:1445 fp=0x7f1a6235dfb0 sp=0x7f1a6235dfa8
created by runtime.main
    /usr/local/go/src/pkg/runtime/proc.c:207

goroutine 16 [IO wait]:
net.runtime_pollWait(0x7f1a624cf508, 0x72, 0x0)
    /usr/local/go/src/pkg/runtime/netpoll.goc:146 +0x66
net.(*pollDesc).Wait(0xc2080280d0, 0x72, 0x0, 0x0)
    /usr/local/go/src/pkg/net/fd_poll_runtime.go:84 +0x46
net.(*pollDesc).WaitRead(0xc2080280d0, 0x0, 0x0)
    /usr/local/go/src/pkg/net/fd_poll_runtime.go:89 +0x42
net.(*netFD).Read(0xc208028070, 0xc208068000, 0x1000, 0x1000, 0x0, 0x7f1a624ce3f0, 0xb)
    /usr/local/go/src/pkg/net/fd_unix.go:232 +0x34c
net.(*conn).Read(0xc20803c020, 0xc208068000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/local/go/src/pkg/net/net.go:122 +0xe7
github.com/go-sql-driver/mysql.(*buffer).fill(0xc208048200, 0x4, 0x0, 0x0)
    /home/kdz/local/libs/go/src/github.com/go-sql-driver/mysql/buffer.go:55 +0x25b
github.com/go-sql-driver/mysql.(*buffer).readNext(0xc208048200, 0x4, 0x0, 0x0, 0x0, 0x0, 0x0)
    /home/kdz/local/libs/go/src/github.com/go-sql-driver/mysql/buffer.go:76 +0x6c
github.com/go-sql-driver/mysql.(*mysqlConn).readPacket(0xc208048200, 0x0, 0x0, 0x0, 0x0, 0x0)
    /home/kdz/local/libs/go/src/github.com/go-sql-driver/mysql/packets.go:30 +0x9d
github.com/go-sql-driver/mysql.(*textRows).readRow(0xc2080420a0, 0x771b00, 0x0, 0x0, 0x0, 0x0)
    /home/kdz/local/libs/go/src/github.com/go-sql-driver/mysql/packets.go:588 +0x68
github.com/go-sql-driver/mysql.(*textRows).Next(0xc2080420a0, 0x771b00, 0x0, 0x0, 0x0, 0x0)
    /home/kdz/local/libs/go/src/github.com/go-sql-driver/mysql/rows.go:80 +0x8c
database/sql.(*Rows).Next(0xc208004240, 0x66d9d0)
    /usr/local/go/src/pkg/database/sql/sql.go:1542 +0xe5
main.main()
    /home/kdz/local/libs/go/src/github.com/arvenil/db2/main.go:21 +0x249

goroutine 19 [finalizer wait]:
runtime.park(0x4134c0, 0x771568, 0x770049)
    /usr/local/go/src/pkg/runtime/proc.c:1369 +0x89
runtime.parkunlock(0x771568, 0x770049)
    /usr/local/go/src/pkg/runtime/proc.c:1385 +0x3b
runfinq()
    /usr/local/go/src/pkg/runtime/mgc0.c:2644 +0xcf
runtime.goexit()
    /usr/local/go/src/pkg/runtime/proc.c:1445

goroutine 20 [chan receive]:
database/sql.(*DB).connectionOpener(0xc208048100)
    /usr/local/go/src/pkg/database/sql/sql.go:583 +0x48
created by database/sql.Open
    /usr/local/go/src/pkg/database/sql/sql.go:442 +0x27c

rax     0xfffffffffffffffc
rbx     0x0
rcx     0xffffffffffffffff
rdx     0x0
rdi     0x7f1a6235df60
rsi     0x0
rbp     0x3c
rsp     0x7f1a6235dea0
r8      0x0
r9      0x0
r10     0x7f1a6235ded0
r11     0x216
r12     0x5ee9a0
r13     0x7fff64724f10
r14     0x0
r15     0x0
rip     0x42bfc3
rflags  0x216
cs      0x33
fs      0x0
gs      0x0
exit status 2

and failed in MariaDB (10.0.11-MariaDB) - but with an error:

Interesting. I didn't tried this on MariaDB, maybe they don't have support for EXPLAIN FORMAT=JSON (they don't mention it here: https://mariadb.com/kb/en/mariadb/mariadb-documentation/sql-commands/administration-commands/explain/). In any case I would focus on MySQL right now as MariaDB diverged far away from MySQL with version 10.

Did you take a look at the protocol level yet - Wireshark or tcpdump?

No. To be honest when I saw stack trace hangs somewhere in net package I thought I will give a chance of figuring out this to someone more familiar with this MySQL driver ;) Digging into this is too complicated for me:/

What Go version are you using?

I've checked that on 1.2 and 1.3

[arnehormann]

fixed when #255 lands

[arvenil]

Just to confirm - it works! Thanks! :) 👍