EOF error in packets.go readPacket() not propagating

[insasho]

I'm running a query that is returning around 250k rows from a MySQL 5.1 server. Occasionally I will get incomplete result sets without an error being returned to my invocation of the API methods. The following is printed:

[MySQL] 2013/07/10 11:18:38 packets.go:67: EOF

The relevant snippet of code:

errLog.Print(err.Error())
return nil, driver.ErrBadConn

Replacing "Print" with "Panic" shows the following stack trace:

[MySQL] 2013/07/10 11:23:33 packets.go:67: EOF
panic: EOF

goroutine 1 [running]:
log.(_Logger).Panic(0xc2000aa1e0, 0x7fd696a4f460, 0x1, 0x1)
/usr/local/go/src/pkg/log/log.go:193 +0xa7
github.com/go-sql-driver/mysql.(_mysqlConn).readPacket(0xc2000c3770, 0xc200100000, 0x66, 0x1000, 0xc2000ae000, ...)
ROOT/src/github.com/go-sql-driver/mysql/packets.go:67 +0x683
github.com/go-sql-driver/mysql.(_mysqlRows).readBinaryRow(0xc2000fe540, 0xc2000f6680, 0x4, 0x4, 0x0, ...)
ROOT/src/github.com/go-sql-driver/mysql/packets.go:861 +0x4e
github.com/go-sql-driver/mysql.(_mysqlRows).Next(0xc2000fe540, 0xc2000f6680, 0x4, 0x4, 0x0, ...)
ROOT/src/github.com/go-sql-driver/mysql/rows.go:68 +0x120
database/sql.(*Rows).Next(0xc2000c24e0, 0x676020)
/usr/local/go/src/pkg/database/sql/sql.go:1310 +0xc1
main.writeBooks(0xc2000c2120, 0xc2000aa5f0)
ROOT/src/example.com/sitemap/sitemapgenerator.go:152 +0x167
main.main()
ROOT/src/example.com/sitemap/sitemapgenerator.go:280 +0x87e

goroutine 2 [syscall]:
exit status 2

It looks like readBinaryRow is not actually returning the non-nil error, and instead returning early with a nil error:

func (rows *mysqlRows) readBinaryRow(dest []driver.Value) (err error) {
data, err := rows.mc.readPacket()
if err != nil {
return
}

This bug is particularly insidious because it is happening in a call to .Next(), which means that callers will be operating on partial result sets without knowing it.

System:

• Ubuntu 13.04 64-bit
• go 1.1
• MySQL 5.1.63-0ubuntu0.10.04.1-log

This happens with both an SSH port forward and when on a proper network connection (rackspace cloud).

[arnehormann]

I don't see the problem with the code in readBinaryRow. For comparison, here's a simplified version of the same pattern in the playground which prints an error as expected. Of course we'll still have a look, but the returned value is unlikely to be the cause.
As a reminder to myself for further analysis tomorrow: maybe the io.Reader call in buffer is faulty and wrongly handles EOF. I didn't see any other probable causes at first glance.

[insasho]

Thanks for looking into this. Yes, you're right, I misread that method and it looks OK to me.

Here are the relevant snippets of code we're using to connect, query, and iterate:

func ConnectAs(credentials Credentials) (*sql.DB, error) {
    connectString := fmt.Sprintf("%s:%s@tcp4(%s:%d)/%s", credentials.Username,
        credentials.Password, *host, *port, *database)
    conn, err := sql.Open("mysql", connectString)
    return conn, err
}
conn, err := ConnectAs(config.Database)
if err != nil {
    log.Panic(err)
}
// id int unsigned not null
// title varchar(250) not null
// ts timestamp not null default 0
// url url varchar(250) not null charset ascii (table is utf8)
SQL := "select id, title, ts, url from sometable limit ?"
results, err := conn.Query(SQL, numrows)
if err != nil {
    log.Panic(err)
}
var i int
for i = 0; results.Next(); i++ {

[arnehormann]

Please update your driver version to the current master with go get -u github.com/go-sql-driver/mysql and try again. This should be fixed now. I'll close the bug, but if you still get the error, I'll reopen it. If it works now, please drop a comment anyway.
Thanks!

[julienschmidt]

go get doesn't work yet since it uses the go1 tag

[arnehormann]

So that's what you meant with release tags in the other PR... 😃
Well, I didn't get to know go get that intimately yet.

[julienschmidt]

Yes, but unfortunately it doesn't work as well as I hoped (and the documentation of the go get tool promised): https://code.google.com/p/go/issues/detail?id=5779
I hoped that we could use a go1.1 tag for the next release, but this doesn't work.

[insasho]

I did a simple "rm -fr src/github.com/go-sql-driver", removed pkg/, and then used "git clone" to fetch the latest and I'm still seeing the problem. If it would help, I can possibly provide a packet capture for you guys but I can't share it via github because it will contain proprietary data.

[julienschmidt]

Let's see if we can get some more debug info. There are several reasons which can cause an EOF error. It would be great if the error was more descriptive in general but I think for now the best approach is to make a temporary debug branch to find the exact code where the error is triggered.
Please also check whether some other component is killing the connection (e.g. server side timeout).

[arnehormann]

Is it still the same stacktrace? If I'm reading it right, readPacket can only get an io.EOF from buffer.readNext. That can only happen when the io.Reader in buffer reaches an io.EOF but there's still data missing.
So the bug should either be in net.Dial or the int parameter need is negative due to an overflow. Both are not that likely.
Looking at your stacktrace, the io.EOF originates in packets.go:67. I can't make any sense of that. Can you please doublecheck your version and maybe post a new stacktrace?

[julienschmidt]

Please re-run it with the eof-debug branch.
Any suggestions for more debug output?

[insasho]

I've rebuilt with eof-debug and re-ran. Here's the stack trace:

fill EOF (need: %d, got: %d) 76 52
panic: EOF

goroutine 1 [running]:
github.com/go-sql-driver/mysql.(*buffer).fill(0xc2000f54c0, 0x4c, 0xc2000b0000, 0xc2000af060)
        /home/username/src/example/src/go/trunk/src/github.com/go-sql-driver/mysql/buffer.go:61 +0x3e6
github.com/go-sql-driver/mysql.(*buffer).readNext(0xc2000f54c0, 0x4c, 0x0, 0x0, 0x0, ...)
        /home/username/src/example/src/go/trunk/src/github.com/go-sql-driver/mysql/buffer.go:85 +0x6e
github.com/go-sql-driver/mysql.(*mysqlConn).readPacket(0xc2000c6770, 0xc2000ff7b1, 0x4, 0x84f, 0x0, ...)
        /home/username/src/example/src/go/trunk/src/github.com/go-sql-driver/mysql/packets.go:54 +0x467
github.com/go-sql-driver/mysql.(*mysqlRows).readBinaryRow(0xc2000fd570, 0xc2000f5740, 0x4, 0x4, 0x0, ...)
        /home/username/src/example/src/go/trunk/src/github.com/go-sql-driver/mysql/packets.go:891 +0x4e
github.com/go-sql-driver/mysql.(*mysqlRows).Next(0xc2000fd570, 0xc2000f5740, 0x4, 0x4, 0x0, ...)
        /home/username/src/example/src/go/trunk/src/github.com/go-sql-driver/mysql/rows.go:64 +0xb6
database/sql.(*Rows).Next(0xc2000c5540, 0x677c60)
        /usr/local/go/src/pkg/database/sql/sql.go:1310 +0xc1
main.writeBooks(0xc2000c5300, 0xc2000ac640)
        /home/username/src/example/src/go/trunk/src/example.com/sitemapgenerator/sitemapgenerator.go:153 +0x167
main.main()
        /home/username/src/example/src/go/trunk/src/example.com/sitemapgenerator/sitemapgenerator.go:296 +0x4da

goroutine 2 [syscall]:

[julienschmidt]

There must be some other reason. The packet header said the packet body is 76 byte long but only 52 byte can be read. My guess is that something is killing the connection.