core-geth icon indicating copy to clipboard operation
core-geth copied to clipboard

Race Condition Testing eth/ package

Open AusIV opened this issue 2 years ago • 1 comments
trafficstars

On v1.12.9, I've found that running

go test ./eth

Has intermittent failures such as:

--- FAIL: TestArtificialFinalityFeatureEnablingDisabling_NoDisable (23.20s)
panic: runtime error: invalid memory address or nil pointer dereference [recovered]
	panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0xd8 pc=0xfbad5f]

goroutine 4393 [running]:
testing.tRunner.func1.2({0x11ba6a0, 0x223f3b0})
	/usr/local/go/src/testing/testing.go:1396 +0x24e
testing.tRunner.func1()
	/usr/local/go/src/testing/testing.go:1399 +0x39f
panic({0x11ba6a0, 0x223f3b0})
	/usr/local/go/src/runtime/panic.go:884 +0x212
github.com/ethereum/go-ethereum/eth/protocols/eth.(*Peer).Head(0x0)
	/home/circleci/project/eth/protocols/eth/peer.go:145 +0x5f
github.com/ethereum/go-ethereum/eth.peerToSyncOp(...)
	/home/circleci/project/eth/sync.go:261
github.com/ethereum/go-ethereum/eth.TestArtificialFinalityFeatureEnablingDisabling_NoDisable(0xc002450d00)
	/home/circleci/project/eth/sync_test.go:290 +0x6d4
testing.tRunner(0xc002450d00, 0x1bba898)
	/usr/local/go/src/testing/testing.go:1446 +0x10b
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:1493 +0x35f
FAIL	github.com/ethereum/go-ethereum/eth	78.118s
FAIL

Running with multiple cores this only shows up occasionally, but running with

GOMAXPROCS=1 go test ./eth

It appears much more regularly.

AusIV avatar Jan 30 '23 19:01 AusIV

Thanks for the report!

Just for reference, here's another failing racy test command

go test -race ./eth
[...]
INFO [01-30|12:26:51.846] Rebuilding state snapshot                                          
INFO [01-30|12:26:51.847] Resuming state snapshot generation       root=97688d..33485c accoun
ts=0 slots=0 storage=0.00B  dangling=0 elapsed=1.232ms                                       
INFO [01-30|12:26:51.847] Generated state snapshot                 accounts=1 slots=0 storage=41.00B dangling=0 elapsed=1.533ms                                                           
INFO [01-30|12:26:57.034] Imported new chain segment               blocks=1024 txs=0 mgas=0.0
00 elapsed=3.037s  mgasps=0.000 number=1024 hash=62c91f..999d67 dirty=56.98KiB               
==================                                                                           
WARNING: DATA RACE                                                                           Read at 0x00000222ce68 by goroutine 2389:                                                    
  github.com/ethereum/go-ethereum/eth.(*chainSyncer).nextSyncOp()                            
      /home/ia/go/src/github.com/ethereum/go-ethereum/eth/sync.go:218 +0x224                 
  github.com/ethereum/go-ethereum/eth.(*chainSyncer).loop()                                        /home/ia/go/src/github.com/ethereum/go-ethereum/eth/sync.go:160 +0x40f                 
  github.com/ethereum/go-ethereum/eth.(*handler).Start.func3()                               
      /home/ia/go/src/github.com/ethereum/go-ethereum/eth/handler.go:559 +0x39               
                                                                                             
Previous write at 0x00000222ce68 by goroutine 321:                                           
  github.com/ethereum/go-ethereum/eth.TestArtificialFinalityFeatureEnablingDisabling()       
      /home/ia/go/src/github.com/ethereum/go-ethereum/eth/sync_test.go:180 +0x1f3              testing.tRunner()                                                                          
      /home/ia/go1.19.2.linux-amd64/src/testing/testing.go:1446 +0x216                       
  testing.(*T).Run.func1()                                                                   
      /home/ia/go1.19.2.linux-amd64/src/testing/testing.go:1493 +0x47                        
                                                                                             Goroutine 2389 (running) created at:                                                         
  github.com/ethereum/go-ethereum/eth.(*handler).Start()                                     
      /home/ia/go/src/github.com/ethereum/go-ethereum/eth/handler.go:559 +0x3f7              
  github.com/ethereum/go-ethereum/eth.newTestHandlerWithBlocksWithOpts()                     
      /home/ia/go/src/github.com/ethereum/go-ethereum/eth/sync_test.go:83 +0x82f               github.com/ethereum/go-ethereum/eth.TestArtificialFinalityFeatureEnablingDisabling()       
      /home/ia/go/src/github.com/ethereum/go-ethereum/eth/sync_test.go:166 +0x5e             
  testing.tRunner()                                                                          
      /home/ia/go1.19.2.linux-amd64/src/testing/testing.go:1446 +0x216                         testing.(*T).Run.func1()                                                                   
      /home/ia/go1.19.2.linux-amd64/src/testing/testing.go:1493 +0x47                        
                                                                                             
Goroutine 321 (running) created at:                                                          
  testing.(*T).Run()                                                                         
      /home/ia/go1.19.2.linux-amd64/src/testing/testing.go:1493 +0x75d                       
  testing.runTests.func1()                                                                   
      /home/ia/go1.19.2.linux-amd64/src/testing/testing.go:1846 +0x99                        
  testing.tRunner()
      /home/ia/go1.19.2.linux-amd64/src/testing/testing.go:1446 +0x216
  testing.runTests()
      /home/ia/go1.19.2.linux-amd64/src/testing/testing.go:1844 +0x7ec
  testing.(*M).Run()
      /home/ia/go1.19.2.linux-amd64/src/testing/testing.go:1726 +0xa84
  main.main()
      _testmain.go:101 +0x2e9
==================

meowsbits avatar Jan 30 '23 20:01 meowsbits