Mysql: packets.go:336: Busy buffer. Commands out of sync. Did you run multiple statements at once?

[rocketkittens]

I am trying to build a web server using this package and when i try to log hits into database too quickly i get the error:

packets.go:336: Busy buffer. Commands out of sync. Did you run multiple statements at once?

My code works fine untill i make too many requests too quickly... Whats going on here?

res, err := db.Exec("INSERT INTO hits VALUES('', ?, ?, ?, ?)", ipaddress, useragent, path, timestamp)

[julienschmidt]

This bug was previously reported in https://github.com/go-sql-driver/mysql/issues/185#issuecomment-43951384 but there was never an issue opened for this specific bug.

@arnehormann seems to have found _one_ situation where this is triggered, as confirmed by @rmulley:

@arnehormann seems to be correct. The issue happens when attempting to use the same transaction for multiple queries while a rows object is still open

package main

import (
    "database/sql"

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

func main() {
    db, _ := sql.Open("mysql", "/")
    defer db.Close()
    tx, err := db.Begin()
    if err != nil {
        panic(err)
    }
    defer tx.Commit()
    stmt1, err := tx.Prepare("SELECT 1")
    if err != nil {
        panic(err)
    }
    rows1, err := stmt1.Query()
    if err != nil {
        panic(err)
    }
    stmt2, err := tx.Prepare("SELECT 2")
    if err != nil {
        // rows1 is not closed -> triggers busy buffer because transaction is on one connection
        // and stmt1, stmt2 use the same one.
        // Move rows1.Close() in front of tx.Prepare and it disappears
        panic(err)
    }
    rows2, err := stmt2.Query()
    if err != nil {
        panic(err)
    }
    rows1.Close()
    rows2.Close()
    stmt1.Close()
    stmt2.Close()
}

But this seems also to happen without the usage of database/sql's tx (transactions) API.

Can you maybe provide a minimal Go program with which you can trigger this bug?
Please also report us your Go and MySQL server version and your platform (e.g. linux/amd64)

[rocketkittens]

https://play.golang.org/p/aWRBMSjk1z (Hope this works, and is good enough)
go version: go1.4.1 windows/amd64
mysql server version: 10.0.16-MariaDB-1~trusty-log

[ajays20078]

Happening with me too. i have http api where there are multiple statements executed using a transaction object(*sql.Tx) and i get the following error:
MySQL] packets.go:355: Busy buffer
[MySQL] packets.go:336: Busy buffer
http: panic driver: bad connection

[rocketkittens]

ajays20078, I have a fix I am using to deal with this issue for now, check it out :)

import "sync"
var mutex = &sync.Mutex{}
mutex.Lock()
// ... db stuff here
mutex.Unlock()

Let me know your results please.

[ajays20078]

@alandroid - If you are using Mutex lock as a alternate for mysql transaction i am afraid thats not the right way as it does not acquire a DB lock.

If you meant using Mutex along with the transaction code, NO its not working with me.

[methane]

@alandroid Can you really reproduce it with only this code? https://play.golang.org/p/aWRBMSjk1z
If you can, could you show me create table hits?

[PuppyKhan]

I am getting a big blank with @alandroid 's link. Do we have any other code to reproduce this issue? I am running into the same problem, but comes and goes randomly in my application.

[mstetson]

I just ran into this error, but I've traced it to a bug in my own code: I closed a *sql.Stmt which still had an open *sql.Rows and then tried to read the rows. Bad idea. It only misbehaves for me in a transaction, though I'm sure closing the Stmt first is a bug in any case. The exact behavior seems to depend on the query. Example:

package main

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

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

func main() {
    db, err := sql.Open("mysql", "root@/mysql")
    fmt.Println("sql.Open:", err)
    tx, err := db.Begin()
    fmt.Println("db.Begin:", err)
    stmt, err := tx.Prepare(os.Args[1])
    fmt.Println("tx.Prepare:", err)
    rs, err := stmt.Query()
    fmt.Println("stmt.Query:", err)
    fmt.Println("stmt.Close:", stmt.Close()) // Doh!
    for rs.Next() {
        var dst interface{}
        fmt.Println("rs.Scan:", rs.Scan(&dst))
    }
    fmt.Println("rs.Err:", rs.Err())
    fmt.Println("rs.Close:", rs.Close())
    fmt.Println("tx.Commit:", tx.Commit())
    fmt.Println("db.Close:", db.Close())
}

Here's the output from a couple of queries using an up-to-date master on Go 1.4, MySQL 5.6.17, Mac OS X 10.10.2:

% go run test.go 'select Db from db'
sql.Open: <nil>
db.Begin: <nil>
tx.Prepare: <nil>
stmt.Query: <nil>
[MySQL] 2015/03/25 23:39:49 packets.go:376: Busy buffer
stmt.Close: <nil>
rs.Err: Commands out of sync. Did you run multiple statements at once?
rs.Close: <nil>
[MySQL] 2015/03/25 23:39:49 packets.go:355: Busy buffer
tx.Commit: driver: bad connection
[MySQL] 2015/03/25 23:39:49 packets.go:336: Busy buffer
db.Close: driver: bad connection
% go run test.go 'select 1'
sql.Open: <nil>
db.Begin: <nil>
tx.Prepare: <nil>
stmt.Query: <nil>
[MySQL] 2015/03/25 23:40:07 packets.go:376: Busy buffer
stmt.Close: <nil>
 ... here it hangs and you have to interrupt the process ...

[arnehormann]

@mstetson thank you! I can't tell if that's the reason for ALL the busy buffer problems, but at least it's a solid hint. This really stumped Julien and me.

[methane]

I think database/sql should have option for detecting such bugs.

[arnehormann]

This happens even without transactions.
Small reproducers:

const mydsn = `/`

func TestBBFreeze(t *testing.T) {
    dsts := []driver.Value{sql.NullInt64{}}
    conn, _ := MySQLDriver{}.Open(mydsn)
    stmt, _ := conn.Prepare("SELECT 1")
    rows, _ := stmt.Query(nil)
    stmt.Close() // busy buffer
    rows.Next(dsts)
    rows.Close() // freeze
    conn.Close()
}

func TestBBTwice(t *testing.T) {
    dsts := []driver.Value{sql.NullInt64{}}
    conn, _ := MySQLDriver{}.Open(mydsn)
    stmt, _ := conn.Prepare("SELECT 1")
    rows, _ := stmt.Query(nil)
    rows.Next(dsts)
    stmt.Close() // busy buffer 1
    rows.Close()
    conn.Close() // busy buffer 2
}

[PuppyKhan]

I have been having this problem and trying to diagnose it without much progress, but I'll share my observations thus far in case it helps.

First, "Busy buffer" and "Commands out of sync" are disjoint issues I think. I have seen both occur without the other a majority of the time in my system.

Thoroughly checking for proper closing and error handling has reduced the frequency (I originally missed a few and thought that was the cause) but then so has running the exact same code on a different system. The problem occurrence is entirely intermittent - I could not even recreate the problem at all when I dedicated a couple of days to investigating it, either in a test program or my original code, but it came back in my original code after I went on to other things.

I never close prepared statements in my code and not using transactions so this exact scenario described by @mstetson is not the only cause.

It consistently only occurs in only 3 places, out of 18 calls to Query. 2 are preparedStatement.Query() and the other preparedStatement.QueryRow().

The only commonality in the usage of these 3 functions is that a slice of interfaces is passed as the variadic parameter list: preparedStatement.Query(params...), but I have the same in other locations without this error ever appearing so that may just be coincidence. There are no open issues I could find about undefined behavior with variadic functions in Go, and the usage does not resemble the known problems with them in C/C++ I've read about.

It also only occurs when doing functional testing that hits multiple operations sequentially, never when testing a single function which does at most 3 db queries.

I am using a fork of the driver with the Stored Procedure hack described here: https://github.com/go-sql-driver/mysql/issues/66#issuecomment-17214290 My SPs only return 1 result set and this is working in all places I use it. The issue does appear on both SP calls and standard SELECT statements.

I'll update further if I find a way to replicate the issue consistently. Right now it is infrequent, inconsistent, and seemingly random.

[PuppyKhan]

I have a working hypothesis (though untested) that my occurrence of this issue is directly caused by using the Stored Procedure hack. In trying the mymysql driver, it has a comment that I needed to read an additional OK ack result set even when my SP was returning only one result set. It is possible that reading a result from a Stored Procedure means there is an additional result sitting unread in a buffer. As the result set is only an OK ack, there may be some conditions that retrieve and discard this, but others which do not.

[llooz]

I have tried to use stored procedure with single result too (using the sp hack) but i ended up with the same busy buffer error. Maybe we that use stored procedures are a bit off topic in this case because other users are encountering the error even with normal statements.

[PuppyKhan]

OK, my occurrence of this error is explicitly caused by the Stored Procedure hack, and is 100% reproducible with this test util: https://github.com/PuppyKhan/dbhammer

Use the following params to see the error in action: dbhammer -db=mysql -conns=1 -sp

You need to preset a couple of stored procedures (see docs) and basically limit the # of connections to force them to be reused by the next query and the issue appears.

Keeping score, it looks like every reproducible appearance of this issue is caused by improper use of the driver, not a bug. SP support and resulting complications being separate issue from this.

[julienschmidt]

Unless anyone reports otherwise, I assume this is only caused by the Stores Procedures hack.

[jadekler]

We are seeing this problem without the stored proc hack anywhere in our code. Just a simple .Query to LOAD DATA LOCAL INFILE. We run this command several times a second across about 5 instances of our app, and the infiles have a lot (thousands of rows) of data in them.

@julienschmidt

[methane]

@jadekler Could you file a new issue, with complete information to reproduce?
Your case may not same to this.

[bancek]

We were getting the same Busy buffer and Commands out of sync errors. For us it was a bug in MariaDB server (using Galera for replication). The problem was that server sent an error for prepared statement Close (which it shouldn't). When the next query was executed there were two replies from server and only one was read. Next write command would then get Busy buffer because there was still data to be read from the buffer.

https://jira.mariadb.org/browse/MDEV-10812

[sergey-shambir]

Thanks @julienschmidt - your comment helped me to fix issues in my code!
I had two issues caused this error:

• we attempted to process results of two SELECTs simultaneously
• there was no rows.Close() call after one of the queries

I've added defer rows.Close(), splitted SELECT results processing into different methods and now my code works without any error.

[lansana]

This bug is also caused by doing the following (running two queries in parallel with the same connection):

func (s *InvoiceService) FindByID(ctx domain.Context, invoiceId int) (*domain.Invoice, error) {
    var wg sync.WaitGroup
    wg.Add(2)

    go func() {
        defer wg.Done()
        // Make query with DB connection
    }()
    go func() {
        defer wg.Done()
        // Make query with same DB connection
    }()

    wg.Wait()

    // ...
}

[methane]

This bug is also caused by doing the following (running two queries in parallel with the same connection):

Using single connection in parallel is not supported.

[muriarte]

Well, is not the ideal solution but https://github.com/go-sql-driver/mysql/issues/257 suggests to use this configuration after creating your database connection

db.SetMaxIdleConns(0)
db.SetMaxOpenConns(500)

Actually you can set MaxOpenConns to a smaller value, like 10 for example, because this configurations makes the database drivers use only one connection but properly protected to run only one query at a time.
This works on my REST Api program but i think it is slower than using a connection pool, but when using a connection pool it fails often with the 'Buffer busy' message.

@alandroid : Before i tried this solution I used mutexes, as you suggest, to solve this problem an it worked well also, same result, same performance. 👍 But db.SetMaxIdleConns(0) is a lot cleaner, i think internally database/sql is using a mutex to protect the only connection when we use db.SetMaxIdleConns(0).

[dzpt]

@muriarte it doesn't work. the error is still there

rows, _ := db.Instance().Query("SELECT post_id, post_content FROM forum_post WHERE indexed=0 LIMIT 0,200")
defer rows.Close()
for rows.Next() {
        rx, e := db.Instance().Query("UPDATE forum_post SET indexed=1 WHERE post_id=?", r.ID)
    rx.Close()
}

if the limit is above 100, there will be the error.