search

krotik / eliasdb

EliasDB a graph-based database.
Mozilla Public License 2.0
994 stars 49 forks source link

Race condition in lockfile.go:219 after DiskGraphStorage.Close() #27

Closed reinkrul closed 3 years ago

reinkrul commented 3 years ago

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 3 years ago

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 3 years ago

Thanks!