EventSub: (rarely) emits an invalid event

[RmbRT]

Location

backend/ethereum/subscription/eventsub_test.go: TestEventSub

Problem

The following test failure occurred multiple times (so far, only tested with the same root seed, and always failed at exactly the same loop iteration, with exactly the same values):

pkg/test: using rootSeed 1644320394464408683
--- FAIL: TestEventSub (0.70s)
    assertions.go:262: 
        	Error Trace:	eventsub_test.go:129
        	            				concurrent.go:223
        	            				goexit.go:88
        	            				goexit.go:90
        	            				asm_amd64.s:1374
        	Error:      	Not equal: 
        	            	expected: &peruntoken.ERC20Approval{Owner:0x7c0Eb36Aa212B175C2c2106F8dD3B236241B8cFa, Spender:0x7c0Eb36Aa212B175C2c2106F8dD3B236241B8cFa, Value:254, Raw:types.Log{Address:0x0000000000000000000000000000000000000000, Topics:[]common.Hash(nil), Data:[]uint8(nil), BlockNumber:0x0, TxHash:0x0000000000000000000000000000000000000000000000000000000000000000, TxIndex:0x0, BlockHash:0x0000000000000000000000000000000000000000000000000000000000000000, Index:0x0, Removed:false}}
        	            	actual  : &peruntoken.ERC20Approval{Owner:0x7c0Eb36Aa212B175C2c2106F8dD3B236241B8cFa, Spender:0x7c0Eb36Aa212B175C2c2106F8dD3B236241B8cFa, Value:252, Raw:types.Log{Address:0x0000000000000000000000000000000000000000, Topics:[]common.Hash(nil), Data:[]uint8(nil), BlockNumber:0x0, TxHash:0x0000000000000000000000000000000000000000000000000000000000000000, TxIndex:0x0, BlockHash:0x0000000000000000000000000000000000000000000000000000000000000000, Index:0x0, Removed:false}}
        	            	
        	            	Diff:
        	            	--- Expected
        	            	+++ Actual
        	            	@@ -12,3 +12,3 @@
        	            	   abs: (big.nat) (len=1) {
        	            	-   (big.Word) 254
        	            	+   (big.Word) 252
        	            	   }
    concurrent.go:248: Stage receiver: runtime.Goexit:
        
        goroutine 1633 [running]:
        testing.(*common).FailNow(0xc000173680)
        	/usr/local/go/src/testing/testing.go:732 +0x3c
        polycry.pt/poly-go/test.(*ConcurrentT).FailNow(0xc0001d25b0)
        	/home/rmbrt/.go/pkg/mod/polycry.pt/[email protected]/test/concurrent.go:202 +0x109
        polycry.pt/poly-go/test.(*stage).FailNow(0xc000db4cc0)
        	/home/rmbrt/.go/pkg/mod/polycry.pt/[email protected]/test/concurrent.go:110 +0x65
        github.com/stretchr/testify/require.Equal(0xc70d80, 0xc0010266e0, 0xa8d940, 0xc0011d2b60, 0xa8d940, 0xc0011cd880, 0x0, 0x0, 0x0)
        	/home/rmbrt/.go/pkg/mod/github.com/stretchr/[email protected]/require/require.go:165 +0x110
        perun.network/go-perun/backend/ethereum/subscription_test.TestEventSub.func4(0xc70140, 0xc000db4cc0, 0xc0001d25b0)
        	/home/rmbrt/.go/src/perun.network/go-perun/backend/ethereum/subscription/eventsub_test.go:129 +0x119
        polycry.pt/poly-go/test.(*ConcurrentT).StageN.func1()
        	/home/rmbrt/.go/pkg/mod/polycry.pt/[email protected]/test/concurrent.go:223 +0x43
        polycry.pt/poly-go/test.(*ConcurrentT).StageN(0xc0001d25b0, 0xb86401, 0x8, 0x1, 0xc0005a1650)
        	/home/rmbrt/.go/pkg/mod/polycry.pt/[email protected]/test/concurrent.go:222 +0x105
        polycry.pt/poly-go/test.(*ConcurrentT).Stage(0xc0001d25b0, 0xb86401, 0x8, 0xc0005a1650)
        	/home/rmbrt/.go/pkg/mod/polycry.pt/[email protected]/test/concurrent.go:263 +0x52
        created by perun.network/go-perun/backend/ethereum/subscription_test.TestEventSub
        	/home/rmbrt/.go/src/perun.network/go-perun/backend/ethereum/subscription/eventsub_test.go:111 +0xd54
panic: Fail in goroutine after TestEventSub has completed

goroutine 79 [running]:
testing.(*common).Fail(0xc000173680)
	/usr/local/go/src/testing/testing.go:688 +0x125
testing.(*common).Errorf(0xc000173680, 0xb87efd, 0xc, 0xc00115ec80, 0x2, 0x2)
	/usr/local/go/src/testing/testing.go:794 +0x93
polycry.pt/poly-go/test.(*ConcurrentT).StageN(0xc0001d25b0, 0xb85abd, 0x7, 0x1, 0xc0004dafc0)
	/home/rmbrt/.go/pkg/mod/polycry.pt/[email protected]/test/concurrent.go:248 +0x313
polycry.pt/poly-go/test.(*ConcurrentT).Stage(0xc0001d25b0, 0xb85abd, 0x7, 0xc0004dafc0)
	/home/rmbrt/.go/pkg/mod/polycry.pt/[email protected]/test/concurrent.go:263 +0x52
created by perun.network/go-perun/backend/ethereum/subscription_test.TestEventSub
	/home/rmbrt/.go/src/perun.network/go-perun/backend/ethereum/subscription/eventsub_test.go:78 +0x889

Proposal

Before the bug can be found, since it is so cryptic, the following points should be ascertained:

• Further investigate whether different seeds will fail at different indices, this could give an important hint regarding where to look for the error.
• Test whether this fails at different indices on different machines using the same seed.

[matthiasgeihs]

Could be a problem with the ordering of events.

[matthiasgeihs]

may be fixed by hyperledger-labs/go-perun#319

please check @RmbRT

[RmbRT]

may be fixed by hyperledger-labs/go-perun#319

please check @RmbRT

I let the test run for a few hours, but couldn't reproduce it. However, even previously, it was a very rare error, so that doesn't mean anything.