Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

BatchSet runtime slice bounds out of range #308

Closed
odeke-em opened this issue Nov 6, 2017 · 10 comments
Closed

BatchSet runtime slice bounds out of range #308

odeke-em opened this issue Nov 6, 2017 · 10 comments
Assignees
Labels
kind/bug Something is broken.

Comments

@odeke-em
Copy link

odeke-em commented Nov 6, 2017

Thank you very much for all the work on badgerDB, nice!

I'd like to report an issue that I noticed while doing work for @tendermint /cc @ebuchman @melekes:

Given the code below

package repro_test

import (
	"crypto/rand"
	"os"
	"testing"

	"github.com/dgraph-io/badger"
)

func randBytes(n int) []byte {
	recv := make([]byte, n)
	in, _ := rand.Reader.Read(recv)
	return recv[:in]
}

var benchmarkData = []struct {
	key, value []byte
}{
	{randBytes(100), nil},
	{randBytes(1000), []byte("foo")},
	{[]byte("foo"), randBytes(1000)},
	{[]byte(""), randBytes(1000)},
	{nil, randBytes(1000000)},
	{randBytes(100000), nil},
	{randBytes(1000000), nil},
}

func BenchmarkIt(b *testing.B) {
	dir := "testbadger_db"
	if err := os.MkdirAll(dir, 0755); err != nil {
		b.Fatal(err)
	}
	defer os.RemoveAll(dir)

	opts := new(badger.Options)
	*opts = badger.DefaultOptions
	opts.ValueLogFileSize = 1024 * 1024 * 1024
	opts.Dir = dir
	opts.ValueDir = dir

	db, err := badger.NewKV(opts)
	if err != nil {
		b.Fatal(err)
	}
	var batchEntries []*badger.Entry
	for i := 0; i < b.N; i++ {
		for _, kv := range benchmarkData {
			batchEntries = append(batchEntries, &badger.Entry{Key: kv.key, Value: kv.value})
		}
		if err := db.BatchSet(batchEntries); err != nil {
			b.Fatalf("#%d: batchSet err: %v", i, err)
		}
	}
}

If I run it, I consistently get a runtime panic

$ go test -v -bench=.
goos: darwin
goarch: amd64
BenchmarkIt-4   	panic: runtime error: slice bounds out of range

goroutine 53 [running]:
github.com/dgraph-io/badger/table.(*blockIterator).parseKV(0xc4256d01b0, 0xa86a00000, 0xffffffff)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:115 +0x4fa
github.com/dgraph-io/badger/table.(*blockIterator).Next(0xc4256d01b0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:153 +0x1a3
github.com/dgraph-io/badger/table.(*blockIterator).Init(0xc4256d01b0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:54 +0x3d
github.com/dgraph-io/badger/table.(*blockIterator).SeekToLast(0xc4256d01b0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:105 +0x49
github.com/dgraph-io/badger/table.(*Iterator).seekToLast(0xc4256aa210)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:257 +0x139
github.com/dgraph-io/badger/table.(*Iterator).Rewind(0xc4256aa210)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:407 +0x33
github.com/dgraph-io/badger/table.OpenTable(0xc42568e008, 0x1, 0x0, 0x0, 0x0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/table.go:167 +0x220
github.com/dgraph-io/badger.(*KV).flushMemtable(0xc4200e0300, 0xc4256a6160, 0x0, 0x0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/kv.go:1121 +0x2cb
created by github.com/dgraph-io/badger.NewKV
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/kv.go:181 +0xcdb
exit status 2
FAIL	_/Users/emmanuelodeke/Desktop/openSrc/bugs/badgerdb	0.334s
Emmanuels-MacBook-Pro-2:badgerdb emmanuelodeke$ go test -v -bench=.
goos: darwin
goarch: amd64
BenchmarkIt-4   	panic: runtime error: slice bounds out of range

goroutine 12 [running]:
github.com/dgraph-io/badger/table.(*blockIterator).parseKV(0xc4256ec1b0, 0xa86a00000, 0xffffffff)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:115 +0x4fa
github.com/dgraph-io/badger/table.(*blockIterator).Next(0xc4256ec1b0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:153 +0x1a3
github.com/dgraph-io/badger/table.(*blockIterator).Init(0xc4256ec1b0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:54 +0x3d
github.com/dgraph-io/badger/table.(*blockIterator).SeekToLast(0xc4256ec1b0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:105 +0x49
github.com/dgraph-io/badger/table.(*Iterator).seekToLast(0xc42ab701b0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:257 +0x139
github.com/dgraph-io/badger/table.(*Iterator).Rewind(0xc42ab701b0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:407 +0x33
github.com/dgraph-io/badger/table.OpenTable(0xc42ab66000, 0x1, 0x0, 0x0, 0x0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/table.go:167 +0x220
github.com/dgraph-io/badger.(*KV).flushMemtable(0xc420358300, 0xc42000c320, 0x0, 0x0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/kv.go:1121 +0x2cb
created by github.com/dgraph-io/badger.NewKV
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/kv.go:181 +0xcdb
exit status 2
FAIL	_/Users/emmanuelodeke/Desktop/openSrc/bugs/badgerdb	0.332s
Emmanuels-MacBook-Pro-2:badgerdb emmanuelodeke$ go test -v -bench=. -race
goos: darwin
goarch: amd64
BenchmarkIt-4   	panic: runtime error: slice bounds out of range

goroutine 82 [running]:
github.com/dgraph-io/badger/table.(*blockIterator).parseKV(0xc43b3a81b0, 0xa86a00000, 0xffffffff)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:115 +0x9ba
github.com/dgraph-io/badger/table.(*blockIterator).Next(0xc43b3a81b0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:153 +0x2bb
github.com/dgraph-io/badger/table.(*blockIterator).Init(0xc43b3a81b0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:54 +0x62
github.com/dgraph-io/badger/table.(*blockIterator).SeekToLast(0xc43b3a81b0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:105 +0x72
github.com/dgraph-io/badger/table.(*Iterator).seekToLast(0xc43b230180)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:257 +0x2f5
github.com/dgraph-io/badger/table.(*Iterator).Rewind(0xc43b230180)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:407 +0x53
github.com/dgraph-io/badger/table.OpenTable(0xc42000e088, 0x1, 0x0, 0x0, 0x0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/table.go:167 +0x33a
github.com/dgraph-io/badger.(*KV).flushMemtable(0xc42036a600, 0xc42000c1c0, 0x0, 0x0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/kv.go:1121 +0x375
created by github.com/dgraph-io/badger.NewKV
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/kv.go:181 +0x1163
exit status 2
FAIL	_/Users/emmanuelodeke/Desktop/openSrc/bugs/badgerdb	1.685s

and the results of it seem weird after applying this patch, we get

diff --git a/table/iterator.go b/table/iterator.go
index 7e1cc87..e71e849 100644
--- a/table/iterator.go
+++ b/table/iterator.go
@@ -18,6 +18,7 @@ package table
 
 import (
 	"bytes"
+	"fmt"
 	"io"
 	"math"
 	"sort"
@@ -109,9 +110,17 @@ func (itr *blockIterator) SeekToLast() {
 
 // parseKV would allocate a new byte slice for key and for value.
 func (itr *blockIterator) parseKV(h header) {
+	allocatedTwice := ""
 	if cap(itr.key) < int(h.plen+h.klen) {
+		allocatedTwice = fmt.Sprintf("allocated twice: 2*(%d + %d)\n", h.plen, h.klen)
 		itr.key = make([]byte, 2*(h.plen+h.klen))
 	}
+	defer func() {
+		if r := recover(); r != nil {
+			fmt.Printf("itr.key: len::%d cap::%d h.plen: %d h.klen: %d at: %s\n", len(itr.key), cap(itr.key), h.plen, h.klen, allocatedTwice)
+		}
+	}()
+
 	itr.key = itr.key[:h.plen+h.klen]
 	copy(itr.key, itr.baseKey[:h.plen])
 	copy(itr.key[h.plen:], itr.data[itr.pos:itr.pos+uint32(h.klen)])
$ go test -v -bench=.
goos: darwin
goarch: amd64
BenchmarkIt-4   	itr.key: len::3392 cap::3392 h.plen: 0 h.klen: 34464 at: allocated twice: 2*(0 + 34464)

itr.key: len::35794 cap::35794 h.plen: 53591 h.klen: 62610 at: allocated twice: 2*(53591 + 62610)

2017/11/05 17:07:57 4121097541 35284
github.com/dgraph-io/badger/y.AssertTruef
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/y/error.go:62
github.com/dgraph-io/badger/table.(*blockIterator).Prev
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:181
github.com/dgraph-io/badger/table.(*blockIterator).SeekToLast
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:108
github.com/dgraph-io/badger/table.(*Iterator).seekToLast
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:266
github.com/dgraph-io/badger/table.(*Iterator).Rewind
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:416
github.com/dgraph-io/badger/table.OpenTable
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/table.go:167
github.com/dgraph-io/badger.(*KV).flushMemtable
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/kv.go:1121
runtime.goexit
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/runtime/asm_amd64.s:2374
exit status 1
FAIL	_/Users/emmanuelodeke/Desktop/openSrc/bugs/badgerdb	0.255s

Notice the logs

itr.key: len::3392 cap::3392 h.plen: 0 h.klen: 34464 at: allocated twice: 2*(0 + 34464)

itr.key: len::35794 cap::35794 h.plen: 53591 h.klen: 62610 at: allocated twice: 2*(53591 + 62610)

Ideally if

badger/table/iterator.go

Lines 112 to 114 in 6c5c932

if cap(itr.key) < int(h.plen+h.klen) {
itr.key = make([]byte, 2*(h.plen+h.klen))
}

executed, those logs would be different. Something weird is going on.

@manishrjain
Copy link
Contributor

manishrjain commented Nov 6, 2017

What version of Badger are you using (presumably v0.8)? In your tests, you should create a new tmp dir, to isolate it from any previous runs, which might have issues; which isn't happening here. Based on the stack trace, the problem is with opening the KV, not BatchSet.

Also, any reason not to use v1.0?

@odeke-em
Copy link
Author

odeke-em commented Nov 6, 2017

@manishrjain thank you for the prompt reply, so am currently using the latest from master, at commit 7f945c8 and yes, that's probably v0.8. Sorry, I started using it a month ago so thought it was the latest.

After every run, I am deleting the directory so that isolates previous failed runs.

@manishrjain
Copy link
Contributor

manishrjain commented Nov 6, 2017

If you want to stick to the older version, can you please use tag v0.8.1, and retry?

Do note that we're not actively supporting v0.8 series.

@odeke-em
Copy link
Author

odeke-em commented Nov 6, 2017

@manishrjain same problem on v0.8.1 68f31e4

$ go test -v -bench=.
goos: darwin
goarch: amd64
BenchmarkIt-4   	panic: runtime error: slice bounds out of range

goroutine 42 [running]:
github.com/dgraph-io/badger/table.(*blockIterator).parseKV(0xc431e9e1b0, 0xa86a00000, 0xffffffff)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:115 +0x4fa
github.com/dgraph-io/badger/table.(*blockIterator).Next(0xc431e9e1b0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:153 +0x1a3
github.com/dgraph-io/badger/table.(*blockIterator).Init(0xc431e9e1b0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:54 +0x3d
github.com/dgraph-io/badger/table.(*blockIterator).SeekToLast(0xc431e9e1b0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:105 +0x49
github.com/dgraph-io/badger/table.(*Iterator).seekToLast(0xc420011830)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:257 +0x139
github.com/dgraph-io/badger/table.(*Iterator).Rewind(0xc420011830)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:407 +0x33
github.com/dgraph-io/badger/table.OpenTable(0xc42ab56000, 0x1, 0x0, 0x0, 0x0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/table.go:167 +0x220
github.com/dgraph-io/badger.(*KV).flushMemtable(0xc42010e300, 0xc4256980e0, 0x0, 0x0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/kv.go:1121 +0x2cb
created by github.com/dgraph-io/badger.NewKV
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/kv.go:181 +0xcdb
exit status 2
FAIL	_/Users/emmanuelodeke/Desktop/openSrc/bugs/badgerdb	0.324s

Alright, I'll get the latest from and update the test code with it, Batches have disappeared and I think y'all replaced those with Txn's right?

@odeke-em
Copy link
Author

odeke-em commented Nov 6, 2017

And yes I can still reproduce this even on the latest 6c5c932 with the exact same stack trace

The repro modified is now

 package repro_test

import (
	"crypto/rand"
	"os"
	"testing"

	"github.com/dgraph-io/badger"
)

func randBytes(n int) []byte {
	recv := make([]byte, n)
	in, _ := rand.Reader.Read(recv)
	return recv[:in]
}

var benchmarkData = []struct {
	key, value []byte
}{
	{randBytes(100), nil},
	{randBytes(1000), []byte("foo")},
	{[]byte("foo"), randBytes(1000)},
	{[]byte(""), randBytes(1000)},
	{nil, randBytes(1000000)},
	{randBytes(100000), nil},
	{randBytes(1000000), nil},
}

func BenchmarkIt(b *testing.B) {
	dir := "testbadger_db"
	os.RemoveAll(dir)
	if err := os.MkdirAll(dir, 0755); err != nil {
		b.Fatal(err)
	}
	defer os.RemoveAll(dir)

	opts := new(badger.Options)
	*opts = badger.DefaultOptions
	opts.ValueLogFileSize = 1024 * 1024 * 1024
	opts.Dir = dir
	opts.ValueDir = dir

	db, err := badger.Open(*opts)
	if err != nil {
		b.Fatal(err)
	}
	for i := 0; i < b.N; i++ {
		tx := db.NewTransaction(true)
		for _, kv := range benchmarkData {
			tx.Set(kv.key, kv.value)
		}
		if err := tx.Commit(nil); err != nil {
			b.Fatalf("#%d: batchSet err: %v", i, err)
		}
	}
}
$ go test -v -bench=.
goos: darwin
goarch: amd64
BenchmarkIt-4   	panic: runtime error: slice bounds out of range

goroutine 81 [running]:
github.com/dgraph-io/badger/table.(*blockIterator).parseKV(0xc4383c81b0, 0x386a80000, 0xffffffff)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:115 +0x4fa
github.com/dgraph-io/badger/table.(*blockIterator).Next(0xc4383c81b0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:153 +0x1a3
github.com/dgraph-io/badger/table.(*blockIterator).Init(0xc4383c81b0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:54 +0x3d
github.com/dgraph-io/badger/table.(*blockIterator).SeekToLast(0xc4383c81b0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:105 +0x49
github.com/dgraph-io/badger/table.(*Iterator).seekToLast(0xc420010480)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:257 +0x139
github.com/dgraph-io/badger/table.(*Iterator).Rewind(0xc420010480)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/iterator.go:407 +0x33
github.com/dgraph-io/badger/table.OpenTable(0xc4257d6018, 0x1, 0x0, 0x0, 0x0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/table/table.go:166 +0x220
github.com/dgraph-io/badger.(*DB).flushMemtable(0xc42012a600, 0xc42000c360, 0x0, 0x0)
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/db.go:786 +0x2bf
created by github.com/dgraph-io/badger.Open
	/Users/emmanuelodeke/go/src/github.com/dgraph-io/badger/db.go:253 +0xa58
exit status 2
FAIL	_/Users/emmanuelodeke/Desktop/openSrc/bugs/badgerdb	0.691s

odeke-em added a commit to odeke-em/bugs that referenced this issue Nov 6, 2017
odeke-em added a commit to tendermint/tmlibs that referenced this issue Nov 6, 2017
Uncovered dgraph-io/badger#308
which perhaps will require us to use the latest BadgerDB
since they no longer use v0.8(which we started with)
plus until that issue is resolved, our benchmarks are invalid
or spuriously error out.
odeke-em added a commit to tendermint/tmlibs that referenced this issue Nov 6, 2017
Uncovered dgraph-io/badger#308
which perhaps will require us to use the latest BadgerDB
since they no longer use v0.8(which we started with)
plus until that issue is resolved, our benchmarks are invalid
or spuriously error out.
@manishrjain manishrjain added kind/bug Something is broken. and removed investigate labels Nov 6, 2017
@manishrjain manishrjain assigned manishrjain and unassigned deepakjois Nov 6, 2017
@manishrjain
Copy link
Contributor

manishrjain commented Nov 6, 2017

Cut a release: https://github.com/dgraph-io/badger/releases/tag/v1.0.1.

This should fix the issue you were seeing. Thanks for reporting it. Note that keys can't be longer than uint16, which this fix would now explicitly check.

Update: You should check the result of txn.Set, so you know which key-value pairs are being rejected.

@odeke-em
Copy link
Author

odeke-em commented Nov 6, 2017

Awesome, thank you @manishrjain for the quick fix and for the updates.

A bit of 2 cents for the future, it is not necessary now but perhaps in the future: 1<<16 as a max key size might be limiting for folks that cache public keys and session-ids for example post-quantum cryptography which require higher security
e.g with https://github.com/orijtech/prunehorst/blob/ff5453838b9ebbc49a39f4da131352fc58829e40/prunehorst.go#L33
#selfPlugged
in which one would like to cache public keys.

For now it is a far fetched example but the promises of your DB are very attractive that I can see myself and others using it in the near future for such purposes.

@manishrjain
Copy link
Contributor

manishrjain commented Nov 6, 2017

Allowing uint32 for key lengths would require a breaking change to the storage layer, which we can't do until v2.0. So, doing this would only be useful if many folks request this change.

There are ways around this limitation - one could fingerprint the session to generate key, and store the session itself as value. A case of collisions can be handled via transactions.

@odeke-em
Copy link
Author

odeke-em commented Nov 6, 2017

True true, in deed once more folks ask for it then it'll become useful. Cheers man!

@manishrjain
Copy link
Contributor

No worries! Good luck with BadgerDB.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
kind/bug Something is broken.
Development

No branches or pull requests

3 participants