Race condition in lockfile.go:219 after DiskGraphStorage.Close()
Closed this issue · 2 comments
reinkrul commented
First of all thanks for the nice piece of software. While POC-ing it in our software (https://github.com/nuts-foundation/) I came across a race condition (or rather, go test -race
found it) in common's lockfile.go:219
(devt.de/krotik/common@v1.2.1/lockutil/lockfile.go:219
) on this line:
lf.running = false
It's triggered by DiskGraphStorage.Close()
.
You can reproduce it by running the following test with the -race
flag:
import (
"devt.de/krotik/eliasdb/graph"
"devt.de/krotik/eliasdb/graph/data"
"devt.de/krotik/eliasdb/graph/graphstorage"
"github.com/stretchr/testify/assert"
"os"
"testing"
)
func TestRacy(t *testing.T) {
// Cleanup afterwards
defer os.RemoveAll("racy-testdb")
gs, err := graphstorage.NewDiskGraphStorage("racy-testdb", false)
assert.NoError(t, err)
// Taken from https://github.com/krotik/eliasdb/blob/master/embedding.md
gm := graph.NewGraphManager(gs)
node1 := data.NewGraphNode()
node1.SetAttr("key", "123")
node1.SetAttr("kind", "mynode")
node1.SetAttr("name", "Node1")
node1.SetAttr("text", "The first stored node")
gm.StoreNode("main", node1)
// This causes race condition
assert.NoError(t, gs.Close())
}
The output is as follows:
==================
WARNING: DATA RACE
Write at 0x00c000116568 by goroutine 19:
devt.de/krotik/common/lockutil.(*LockFile).Finish()
<redacted>/go/pkg/mod/devt.de/krotik/common@v1.2.1/lockutil/lockfile.go:219 +0x556
devt.de/krotik/eliasdb/storage.(*ByteDiskStorageManager).Close()
<redacted>/go/pkg/mod/devt.de/krotik/eliasdb@v1.0.5/storage/diskstoragemanager.go:627 +0x4f0
devt.de/krotik/eliasdb/storage.(*CachedDiskStorageManager).Close()
<redacted>/go/pkg/mod/devt.de/krotik/eliasdb@v1.0.5/storage/cacheddiskstoragemanager.go:229 +0x67
devt.de/krotik/eliasdb/graph/graphstorage.(*DiskGraphStorage).Close()
<redacted>/go/pkg/mod/devt.de/krotik/eliasdb@v1.0.5/graph/graphstorage/diskgraphstorage.go:202 +0x1e1
github.com/nuts-foundation/nuts-network/pkg/nextgen/distdoc/racy.TestRacy()
<redacted>/workspace/nuts-network/pkg/nextgen/distdoc/racy/eliasdb_test.go:28 +0x2e1
testing.tRunner()
/usr/local/go/src/testing/testing.go:1127 +0x202
Previous read at 0x00c000116568 by goroutine 23:
devt.de/krotik/common/lockutil.(*LockFile).watch()
<redacted>/go/pkg/mod/devt.de/krotik/common@v1.2.1/lockutil/lockfile.go:82 +0x124
Goroutine 19 (running) created at:
testing.(*T).Run()
/usr/local/go/src/testing/testing.go:1178 +0x796
testing.runTests.func1()
/usr/local/go/src/testing/testing.go:1449 +0xa6
testing.tRunner()
/usr/local/go/src/testing/testing.go:1127 +0x202
testing.runTests()
/usr/local/go/src/testing/testing.go:1447 +0x5aa
testing.(*M).Run()
/usr/local/go/src/testing/testing.go:1357 +0x4eb
main.main()
_testmain.go:43 +0x236
Goroutine 23 (running) created at:
devt.de/krotik/common/lockutil.(*LockFile).Start()
<redacted>/go/pkg/mod/devt.de/krotik/common@v1.2.1/lockutil/lockfile.go:185 +0xc5
devt.de/krotik/eliasdb/storage.initByteDiskStorageManager()
<redacted>/go/pkg/mod/devt.de/krotik/eliasdb@v1.0.5/storage/diskstoragemanager.go:655 +0x1933
devt.de/krotik/eliasdb/storage.NewByteDiskStorageManager()
<redacted>/go/pkg/mod/devt.de/krotik/eliasdb@v1.0.5/storage/diskstoragemanager.go:235 +0x370
devt.de/krotik/eliasdb/storage.NewDiskStorageManager()
<redacted>/go/pkg/mod/devt.de/krotik/eliasdb@v1.0.5/storage/diskstoragemanager.go:101 +0x278
devt.de/krotik/eliasdb/graph/graphstorage.(*DiskGraphStorage).StorageManager()
<redacted>/go/pkg/mod/devt.de/krotik/eliasdb@v1.0.5/graph/graphstorage/diskgraphstorage.go:149 +0x1b4
devt.de/krotik/eliasdb/graph.(*Manager).getNodeStorageHTree()
<redacted>/go/pkg/mod/devt.de/krotik/eliasdb@v1.0.5/graph/helpers.go:213 +0x421
devt.de/krotik/eliasdb/graph.(*Manager).storeOrUpdateNode()
<redacted>/go/pkg/mod/devt.de/krotik/eliasdb@v1.0.5/graph/graphmanager_nodes.go:216 +0x1ae
devt.de/krotik/eliasdb/graph.(*Manager).StoreNode()
<redacted>/go/pkg/mod/devt.de/krotik/eliasdb@v1.0.5/graph/graphmanager_nodes.go:187 +0x2c9
github.com/nuts-foundation/nuts-network/pkg/nextgen/distdoc/racy.TestRacy()
<redacted>/workspace/nuts-network/pkg/nextgen/distdoc/racy/eliasdb_test.go:25 +0x285
testing.tRunner()
/usr/local/go/src/testing/testing.go:1127 +0x202
==================
krotik commented
Hey there, thanks for finding this and the detailed description. This issue should be fixed with the latest EliasDB version 1.1.0 using common 1.4.0.
$ go test -race ./racy_test.go
ok command-line-arguments 1.533s
Please reopen if this issue is still there.
reinkrul commented
Thanks!