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

lib/db: Add closeWaitGroup to allow async operation #6317

Merged
merged 2 commits into from Feb 11, 2020

Conversation

@imsodin
Copy link
Member

imsodin commented Feb 10, 2020

Looking into https://forum.syncthing.net/t/test-panic-on-go1-14beta1/14462 (fruitlessly) I saw lots of gc runners in the backtrace. Turns out we never close databases in tests. Closing then turns up a race in goleveldb:

==================
WARNING: DATA RACE
Read at 0x00c00014a8b0 by goroutine 64:
  runtime.chansend()
      /media/ext4_data/Linux/source/go/src/runtime/chan.go:142 +0x0
  github.com/syndtr/goleveldb/leveldb.cAuto.ack()
      /media/ext4_data/Coding/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20190923125748-758128399b1d/leveldb/db_compaction.go:686 +0xab
  github.com/syndtr/goleveldb/leveldb.(*DB).mCompaction()
      /media/ext4_data/Coding/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20190923125748-758128399b1d/leveldb/db_compaction.go:778 +0xc9

Previous write at 0x00c00014a8b0 by goroutine 65:
  runtime.closechan()
      /media/ext4_data/Linux/source/go/src/runtime/chan.go:335 +0x0
  github.com/syndtr/goleveldb/leveldb.(*DB).compTriggerWait()
      /media/ext4_data/Coding/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20190923125748-758128399b1d/leveldb/db_compaction.go:730 +0x4eb
  github.com/syndtr/goleveldb/leveldb.(*DB).rotateMem()
      /media/ext4_data/Coding/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20190923125748-758128399b1d/leveldb/db_write.go:39 +0x7f
  github.com/syndtr/goleveldb/leveldb.(*DB).CompactRange()
      /media/ext4_data/Coding/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20190923125748-758128399b1d/leveldb/db_write.go:422 +0x415
  github.com/syncthing/syncthing/lib/db/backend.(*leveldbBackend).Compact()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/backend/leveldb_backend.go:107 +0xa8
  github.com/syncthing/syncthing/lib/db.(*Lowlevel).gcBlocks()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/lowlevel.go:590 +0x647
  github.com/syncthing/syncthing/lib/db.(*Lowlevel).gcRunner()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/lowlevel.go:483 +0x278

Goroutine 64 (running) created at:
  github.com/syndtr/goleveldb/leveldb.openDB()
      /media/ext4_data/Coding/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20190923125748-758128399b1d/leveldb/db.go:156 +0x971
  github.com/syndtr/goleveldb/leveldb.Open()
      /media/ext4_data/Coding/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20190923125748-758128399b1d/leveldb/db.go:203 +0x1e5
  github.com/syncthing/syncthing/lib/db/backend.OpenLevelDBMemory()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/backend/leveldb_open.go:63 +0xd7
  github.com/syncthing/syncthing/lib/db/backend.OpenMemory()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/backend/backend.go:122 +0x132
  github.com/syncthing/syncthing/lib/db.TestDeviceKey()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/keyer_test.go:21 +0x133
  testing.tRunner()
      /media/ext4_data/Linux/source/go/src/testing/testing.go:993 +0x1eb

Goroutine 65 (running) created at:
  github.com/syncthing/syncthing/lib/db.NewLowlevel()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/lowlevel.go:65 +0x369
  github.com/syncthing/syncthing/lib/db.TestDeviceKey()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/keyer_test.go:21 +0x137
  testing.tRunner()
      /media/ext4_data/Linux/source/go/src/testing/testing.go:993 +0x1eb
==================

Apparently it doesn't like when the db is closed while a compaction is ongoing. Easy, use the releaser in the compaction. That then more reliably brings up a race for WaitGroup (I have seen that before on TC very seldomly):

==================
WARNING: DATA RACE
Write at 0x00c000098550 by goroutine 85:
  internal/race.Write()
      /media/ext4_data/Linux/source/go/src/internal/race/race.go:41 +0x114
  sync.(*WaitGroup).Wait()
      /media/ext4_data/Linux/source/go/src/sync/waitgroup.go:128 +0x115
  github.com/syncthing/syncthing/lib/db/backend.(*leveldbBackend).Close()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/backend/leveldb_backend.go:59 +0x42
  github.com/syncthing/syncthing/lib/db.(*Lowlevel).Close()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/lowlevel.go:71 +0x78
  github.com/syncthing/syncthing/lib/db.TestNamespacedInt()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/namespaced_test.go:62 +0x6a2
  testing.tRunner()
      /media/ext4_data/Linux/source/go/src/testing/testing.go:993 +0x1eb

Previous read at 0x00c000098550 by goroutine 92:
  internal/race.Read()
      /media/ext4_data/Linux/source/go/src/internal/race/race.go:37 +0x1e8
  sync.(*WaitGroup).Add()
      /media/ext4_data/Linux/source/go/src/sync/waitgroup.go:71 +0x1fb
  github.com/syncthing/syncthing/lib/db/backend.newReleaser()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/backend/backend.go:158 +0x1c0
  github.com/syncthing/syncthing/lib/db/backend.(*leveldbBackend).newSnapshot()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/backend/leveldb_backend.go:41 +0x1a1
  github.com/syncthing/syncthing/lib/db/backend.(*leveldbBackend).NewWriteTransaction()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/backend/leveldb_backend.go:46 +0x50
  github.com/syncthing/syncthing/lib/db.(*Lowlevel).newReadWriteTransaction()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/transactions.go:430 +0x6f
  github.com/syncthing/syncthing/lib/db.(*Lowlevel).gcBlocks()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/lowlevel.go:525 +0xf2
  github.com/syncthing/syncthing/lib/db.(*Lowlevel).gcRunner()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/lowlevel.go:483 +0x278

Goroutine 85 (running) created at:
  testing.(*T).Run()
      /media/ext4_data/Linux/source/go/src/testing/testing.go:1044 +0x660
  testing.runTests.func1()
      /media/ext4_data/Linux/source/go/src/testing/testing.go:1286 +0xa6
  testing.tRunner()
      /media/ext4_data/Linux/source/go/src/testing/testing.go:993 +0x1eb
  testing.runTests()
      /media/ext4_data/Linux/source/go/src/testing/testing.go:1284 +0x527
  testing.(*M).Run()
      /media/ext4_data/Linux/source/go/src/testing/testing.go:1201 +0x2ff
  main.main()
      _testmain.go:156 +0x223

Goroutine 92 (running) created at:
  github.com/syncthing/syncthing/lib/db.NewLowlevel()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/lowlevel.go:65 +0x369
  github.com/syncthing/syncthing/lib/db.TestNamespacedInt()
      /media/ext4_data/Coding/go/src/github.com/syncthing/syncthing/lib/db/namespaced_test.go:17 +0x4c
  testing.tRunner()
      /media/ext4_data/Linux/source/go/src/testing/testing.go:993 +0x1eb
==================

That's because a waitgroup is not meant for async calls to Add and Wait. So I wrapped it in lib/sync as CloseWaitGroup which can be called async but can't be reuced (waiting "closes" the waitgroup).

That fixes all the races, however https://forum.syncthing.net/t/test-panic-on-go1-14beta1/14462 still occurs flakely.

Copy link
Member

calmh left a comment

Good.

@@ -82,6 +97,13 @@ func (b *leveldbBackend) Delete(key []byte) error {
}

func (b *leveldbBackend) Compact() error {
// Race is detected during testing when db is closed while compaction
// is ongoing.
rel, err := newReleaser(b.closeWG)

This comment has been minimized.

Copy link
@calmh

calmh Feb 11, 2020

Member

Releaser doesn't add much here, could be just Add/Done on the closeWG?

closeMut sync.RWMutex
}

func NewCloseWaitGroup() CloseWaitGroup {

This comment has been minimized.

Copy link
@calmh

calmh Feb 11, 2020

Member

This doesn't seem generic enough to warrant inclusion and exporting in lib/sync, could be just a private type in package backend like the releaser thing?

@imsodin imsodin changed the title lib/db, lib/sync: Add CloseWaitGroup to allow async operation lib/db: Add closeWaitGroup to allow async operation Feb 11, 2020
@calmh
calmh approved these changes Feb 11, 2020
@calmh calmh merged commit 29736b1 into syncthing:master Feb 11, 2020
13 checks passed
13 checks passed
Build (Cross Compile) (Syncthing) TeamCity build finished
Details
Build (Debian, Snap) (Syncthing) TeamCity build finished
Details
Build (Discovery Server) TeamCity build finished
Details
Build (Linux) (Syncthing) TeamCity build finished
Details
Build (Linux, Go1.12) (Syncthing) TeamCity build finished
Details
Build (Linux, Go1.14-rc) (Syncthing) TeamCity build finished
Details
Build (Mac) (Syncthing) TeamCity build finished
Details
Build (Relay Server) TeamCity build finished
Details
Build (Source) (Syncthing) TeamCity build finished
Details
Build (Windows) (Syncthing) TeamCity build finished
Details
Check Correctness (Syncthing) TeamCity build finished
Details
Coverage (Syncthing) TeamCity build finished
Details
GolangCI No issues found!
Details
@imsodin imsodin deleted the imsodin:db/antiRace branch Feb 11, 2020
@calmh calmh added this to the v1.4.0 milestone Feb 12, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked issues

Successfully merging this pull request may close these issues.

None yet

2 participants
You can’t perform that action at this time.