"another row available" error for single row query

[leslie-wang]

Probably similiar with #681. It also show another row available. It can show up with below simple codes. You can also check source codes at https://github.com/leslie-wang/samples/blob/master/go-sqlite3/main.go.

func dbMain(args []string) int {
	db, err := sql.Open("sqlite3_tracing", ":memory:")
	if err != nil {
		fmt.Printf("Failed to open database: %#+v\n", err)
		return 1
	}
	defer db.Close()

	err = db.Ping()
	if err != nil {
		log.Panic(err)
	}

	if _, err := db.Exec(`
CREATE TABLE IF NOT EXISTS user (
 id INTEGER PRIMARY KEY AUTOINCREMENT,
 user_name TEXT NOT NULL
);
CREATE TABLE IF NOT EXISTS token(
 token TEXT NOT NULL,
 user_id INTEGER NOT NULL,
 device_id INTEGER NOT NULL
);
insert into user (user_name) values ("alice");
insert into token(token, user_id, device_id) values ("1234", 1, 1);

insert into user (user_name) values ("bob");
insert into token(token, user_id, device_id) values ("4321", 2, 2);
`); err != nil {
		log.Panic(err)
	}

	ctx, cancel := context.WithTimeout(context.Background(), time.Minute)
	defer cancel()

	tx, err := db.Begin()
	if err != nil {
		log.Panic(err)
	}
	defer tx.Rollback()

	stmt, err := tx.Prepare("select token, user_id, device_id from token as t inner join (select id from user where user_name = ?) as u on u.id = t.user_id")
	if err != nil {
		log.Printf("prepare select token got error: %s\n", err)
		log.Panic(err)
	}
	defer stmt.Close()

	var (
		tokenQuery string
		userid     int
		deviceid   int
	)
	if err := stmt.QueryRowContext(ctx, "alice").Scan(&tokenQuery, &userid, &deviceid); err != nil {
		log.Printf("query context got error: %s\n", err)
		log.Panic(err)
	}
	if err := tx.Commit(); err != nil {
		log.Panic(err)
	}
	fmt.Printf("--------- Receive: %s, %d, %d\n", tokenQuery, userid, deviceid)
	fmt.Println("--------- complete --------")

	return 1
}

Got below output.

Added trace config {0x410e2a0 15 true}: handle 0x7300080.
Trace: ev 1 -AC- conn 0x7300080, stmt 0x7301e00 {"\nCREATE TABLE IF NOT EXISTS user (\n id INTEGER PRIMARY KEY AUTOINCREMENT,\n user_name TEXT NOT NULL\n);"} = exp.
Trace: ev 4 -AC- conn 0x7300080, stmt 0x466a130 {""}.
Trace: ev 4 -AC- conn 0x7300080, stmt 0x46689c0 {""}.
Trace: ev 2 -AC- conn 0x7300080, stmt 0x7301e00 {""}; time 0.
Trace: ev 1 -AC- conn 0x7300080, stmt 0x7301e00 {"CREATE TABLE IF NOT EXISTS token(\n token TEXT NOT NULL,\n user_id INTEGER NOT NULL,\n device_id INTEGER NOT NULL\n);"} = exp.
Trace: ev 4 -AC- conn 0x7300080, stmt 0x4660680 {""}.
Trace: ev 2 -AC- conn 0x7300080, stmt 0x7301e00 {""}; time 0.
Trace: ev 1 -AC- conn 0x7300080, stmt 0x4668e70 {"insert into user (user_name) values (\"alice\");"} = exp.
Trace: ev 2 -AC- conn 0x7300080, stmt 0x4668e70 {""}; time 0.
Trace: ev 1 -AC- conn 0x7300080, stmt 0x4661940 {"insert into token(token, user_id, device_id) values (\"1234\", 1, 1);"} = exp.
Trace: ev 2 -AC- conn 0x7300080, stmt 0x4661940 {""}; time 0.
Trace: ev 1 -AC- conn 0x7300080, stmt 0x4661490 {"insert into user (user_name) values (\"bob\");"} = exp.
Trace: ev 2 -AC- conn 0x7300080, stmt 0x4661490 {""}; time 0.
Trace: ev 1 -AC- conn 0x7300080, stmt 0x4660680 {"insert into token(token, user_id, device_id) values (\"4321\", 2, 2);"} = exp.
Trace: ev 2 -AC- conn 0x7300080, stmt 0x4660680 {""}; time 0.
Trace: ev 1 -AC- conn 0x7300080, stmt 0x4660680 {"BEGIN"} = exp.
Trace: ev 2 +Tx+ conn 0x7300080, stmt 0x4660680 {""}; time 0.
Trace: ev 1 +Tx+ conn 0x7300080, stmt 0x4665630 {"select token, user_id, device_id from token as t inner join (select id from user where user_name = ?) as u on u.id = t.user_id"} expanded {"select token, user_id, device_id from token as t inner join (select id from user where user_name = 'alice') as u on u.id = t.user_id"}.
Trace: ev 4 +Tx+ conn 0x7300080, stmt 0x4665630 {""}.
Trace: ev 2 +Tx+ conn 0x7300080, stmt 0x4665630 {""}; time 0; DB error: sqlite3.Error{Code:100, ExtendedCode:100, err:"another row available"}
Trace: ev 1 +Tx+ conn 0x7300080, stmt 0x4668510 {"COMMIT"} = exp.
Trace: ev 2 -AC- conn 0x7300080, stmt 0x4668510 {""}; time 0.
--------- Receive: 1234, 1, 1
--------- complete --------
Pop handle 0x7300080: deleted trace config {0x410e2a0 15 true}.
Trace: ev 8 -AC- conn 0x7300080, stmt 0x0 {""}.

I'm mostly concerned about the line which should not be an error.

Trace: ev 2 +Tx+ conn 0x7300080, stmt 0x4665630 {""}; time 0; DB error: sqlite3.Error{Code:100, ExtendedCode:100, err:"another row available"}

[leslie-wang]

I print stack, which shows below. Keep debugging

Trace: ev 2 -AC- conn 0x45004f0, stmt 0x72b1680 {""}; time 0.
Trace: ev 1 -AC- conn 0x45004f0, stmt 0x72b1680 {"BEGIN"} = exp.
Trace: ev 2 +Tx+ conn 0x45004f0, stmt 0x72b1680 {""}; time 0.
Trace: ev 1 +Tx+ conn 0x45004f0, stmt 0x72b6630 {"select token, user_id, device_id from token as t inner join (select id from user where user_name = ?) as u on u.id = t.user_id"} expanded {"select token, user_id, device_id from token as t inner join (select id from user where user_name = 'alice') as u on u.id = t.user_id"}.
Trace: ev 4 +Tx+ conn 0x45004f0, stmt 0x72b6630 {""}.
goroutine 1 [running, locked to thread]:
runtime/debug.Stack(0x43b5560, 0x44bb188, 0xc0000bf810)
	/usr/local/go/src/runtime/debug/stack.go:24 +0x9d
runtime/debug.PrintStack()
	/usr/local/go/src/runtime/debug/stack.go:16 +0x22
main.traceCallback(0x2, 0x45004f0, 0x72b6630, 0x0, 0x0, 0x0, 0x0, 0x0, 0x64, 0x64, ...)
	/Users/qiwa/workspace/golang/src/github.com/leslie-wang/samples/go-sqlite3/main.go:21 +0x46
github.com/mattn/go-sqlite3.traceCallbackTrampoline(0xc000000002, 0x45004f0, 0x72b6630, 0x7ffeefbff768, 0xc000000300)
	/Users/qiwa/workspace/golang/src/github.com/mattn/go-sqlite3/sqlite3_trace.go:195 +0x197
github.com/mattn/go-sqlite3._cgoexpwrap_0afbd1cd2704_traceCallbackTrampoline(0x2, 0x45004f0, 0x72b6630, 0x7ffeefbff768, 0x7ffeefbff750)
	_cgo_gotypes.go:1368 +0x47
github.com/mattn/go-sqlite3._Cfunc_sqlite3_reset(0x72b6630, 0x0)
	_cgo_gotypes.go:974 +0x49
github.com/mattn/go-sqlite3.(*SQLiteRows).Close.func1(0xc0000f20a0, 0x43b0ce0)
	/Users/qiwa/workspace/golang/src/github.com/mattn/go-sqlite3/sqlite3.go:1942 +0x62
github.com/mattn/go-sqlite3.(*SQLiteRows).Close(0xc0000f20a0, 0xc0000b0200, 0xc0000bfd30)
	/Users/qiwa/workspace/golang/src/github.com/mattn/go-sqlite3/sqlite3.go:1942 +0x87
database/sql.(*Rows).close.func1()
	/usr/local/go/src/database/sql/sql.go:2989 +0x3c
database/sql.withLock(0x42adf40, 0xc0000cc000, 0xc0000bfd78)
	/usr/local/go/src/database/sql/sql.go:3097 +0x63
database/sql.(*Rows).close(0xc0000f0100, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/database/sql/sql.go:2988 +0x110
database/sql.(*Rows).Close(...)
	/usr/local/go/src/database/sql/sql.go:2972
database/sql.(*Row).Scan(0xc00000e080, 0xc0000bfef0, 0x3, 0x3, 0x0, 0x0)
	/usr/local/go/src/database/sql/sql.go:3053 +0x18c
main.dbMain(0xc0000a2000, 0x1, 0x1, 0x0)
	/Users/qiwa/workspace/golang/src/github.com/leslie-wang/samples/go-sqlite3/main.go:165 +0x63f
main.main()
	/Users/qiwa/workspace/golang/src/github.com/leslie-wang/samples/go-sqlite3/main.go:109 +0xc5
Trace: ev 2 +Tx+ conn 0x45004f0, stmt 0x72b6630 {""}; time 0; DB error: sqlite3.Error{Code:100, ExtendedCode:100, err:"another row available"}

[rittneje]

go-sqlite3/sqlite3_trace.go

Lines 157 to 167 in 31f5bb8

	case TraceProfile:
	info.StmtHandle = uintptr(p)
	if xValue == nil {
	panic("NULL pointer in X arg of trace_v2 callback for SQLITE_TRACE_PROFILE event")
	}
	info.RunTimeNanosec = *(*int64)(xValue)
	// sample the error //TODO: is it safe? is it useful?
	fillDBError(&info.DBError, contextDB)

This library unconditionally assigns to info.DBError when preparing the trace callback. The SQLite documentation doesn't actually specify what you get back from sqlite3_errcode, etc. if the last call didn't fail, but from the look of things, it's giving back the last result code, which in this case was SQLITE_ROW. (From your stack trace, I'm assuming what happened was you called QueryRowContext. That in turn called sqlite3_step, which returned SQLITE_ROW, and then called sqlite3_reset, which invoked the trace callback. Thus sqlite3_reset hasn't actually finished yet, which is why we get SQLITE_ROW from the previous call to sqlite3_step, instead of SQLITE_OK, which sqlite3_reset is going to return.)

https://github.com/leslie-wang/samples/blob/49dc0e7f45df687974899879da0f30fd5d806cb4/go-sqlite3/main.go#L19
For now, my suggestion would be to simply compare info.DBError.Code against 0 (SQLITE_OK), 100 (SQLITE_ROW), and 101 (SQLITE_DONE), and consider anything else to be a true failure.

@mattn I assume the proper fix for this library would be to only assign to info.DBError when the error code is not SQLITE_OK, SQLITE_ROW, or SQLITE_DONE.

go-sqlite3/sqlite3_trace.go

Lines 79 to 84 in 31f5bb8

	func fillDBError(dbErr *Error, db *C.sqlite3) {
	// See SQLiteConn.lastError(), in file 'sqlite3.go' at the time of writing (Sept 5, 2016)
	dbErr.Code = ErrNo(C.sqlite3_errcode(db))
	dbErr.ExtendedCode = ErrNoExtended(C.sqlite3_extended_errcode(db))
	dbErr.err = C.GoString(C.sqlite3_errmsg(db))
	}

[leslie-wang]

@rittneje Thanks for the detail explanation.