Events unit test intermittently failing with timeout or `CallContext` mock rejections

[nguyer]

I ran a docker build on main and had a unit test fail. After running the same exact command again, the test passed, leading me to believe that it's intermittent... which is concerning given that it's a unit test. Full test log is attached.

etheconnect_log.txt

[nguyer]

I hit this again today on a release build: https://github.com/hyperledger/firefly-ethconnect/runs/4288464013?check_suite_focus=true

build_log.txt

[peterbroadhurst]

The changes in #175 should address these intermittent failures in the events and subscriptions tests 🤞 Or at the very least, we should get those merged and then revisit if there's still failures.

[peterbroadhurst]

Copying out a summary of the first error here - which was a timeout in TestUpdateStreamInProgress:

goroutine 538 [semacquire]:
sync.runtime_SemacquireMutex(0xc000028334, 0x69a700, 0x1)
    /usr/local/go/src/runtime/sema.go:71 +0x47
sync.(*Mutex).lockSlow(0xc000028330)
    /usr/local/go/src/sync/mutex.go:138 +0x105
sync.(*Mutex).Lock(0xc000028330)
    /usr/local/go/src/sync/mutex.go:81 +0x47
github.com/hyperledger/firefly-ethconnect/internal/events.(*eventStream).preUpdateStream(0xc0001be160, 0x4, 0xd3a6ea)
    /ethconnect/internal/events/eventstream.go:224 +0x4b
github.com/hyperledger/firefly-ethconnect/internal/events.(*eventStream).update(0xc0001be160, 0xc0001cbe70, 0xc00000ea80, 0xc0000282c8, 0x1)
    /ethconnect/internal/events/eventstream.go:252 +0xc5
github.com/hyperledger/firefly-ethconnect/internal/events.TestUpdateStreamInProgress(0xc000492f00)
    /ethconnect/internal/events/eventstream_test.go:1359 +0x232
testing.tRunner(0xc000492f00, 0xd653f0)
    /usr/local/go/src/testing/testing.go:1193 +0xef
created by testing.(*T).Run
    /usr/local/go/src/testing/testing.go:1238 +0x2b3

[peterbroadhurst]

Second error was an overrun of the background processing in one of the events test, beyond where the mocks had been cleaned up (a number of these were fixed in #175 ):

time="2021-11-22T15:30:22Z" level=info msg="Event stream subscription manager shutting down"
panic: 
assert: mock: I don't know what to return because the method call was unexpected.
    Either do Mock.On("CallContext").Return(...) first, or remove the CallContext() call.
    This method was unexpected:
        CallContext(*context.timerCtx,*hexutil.Big,string)
        0: &context.timerCtx{cancelCtx:context.cancelCtx{Context:(*context.valueCtx)(0xc000290000), mu:sync.Mutex{state:0, sema:0x0}, done:(chan struct {})(nil), children:map[context.canceler]struct {}(nil), err:error(nil)}, timer:(*time.Timer)(0xc000260190), deadline:time.Time{wall:0xc05f0bcb23a95a2f, ext:31286472326, loc:(*time.Location)(0x1163da0)}}
        1: &hexutil.Big{neg:false, abs:big.nat(nil)}
        2: "eth_blockNumber"
    at: [rpc_client.go:21 subscription.go:168 eventstream.go:405 asm_amd64.s:1371]

goroutine 625 [running]:
github.com/stretchr/testify/mock.(*Mock).fail(0xc000260dc0, 0xd56a09, 0xc1, 0xc00031e300, 0x4, 0x4)
    /go/pkg/mod/github.com/stretchr/testify@v1.7.0/mock/mock.go:254 +0x17f
github.com/stretchr/testify/mock.(*Mock).MethodCalled(0xc000260dc0, 0xe9f680, 0xb, 0xc0002900f0, 0x3, 0x3, 0xc00031e080, 0x4, 0x4)
    /go/pkg/mod/github.com/stretchr/testify@v1.7.0/mock/mock.go:418 +0xe7f
github.com/stretchr/testify/mock.(*Mock).Called(0xc000260dc0, 0xc0002900f0, 0x3, 0x3, 0x0, 0x0, 0x0)
    /go/pkg/mod/github.com/stretchr/testify@v1.7.0/mock/mock.go:383 +0x1ab
github.com/hyperledger/firefly-ethconnect/mocks/ethmocks.(*RPCClient).CallContext(0xc000260dc0, 0xe041e8, 0xc00028a000, 0xcd9880, 0xc0002cc000, 0xd35d91, 0xf, 0x0, 0x0, 0x0, ...)
    /ethconnect/mocks/ethmocks/rpc_client.go:21 +0x1cf
github.com/hyperledger/firefly-ethconnect/internal/events.(*subscription).setInitialBlockHeight(0xc0002e8900, 0xe04220, 0xc00028a000, 0x0, 0x0, 0x0)
    /ethconnect/internal/events/subscription.go:168 +0x2c4
github.com/hyperledger/firefly-ethconnect/internal/events.(*eventStream).eventPoller(0xc000264210)
    /ethconnect/internal/events/eventstream.go:405 +0x3c5
created by github.com/hyperledger/firefly-ethconnect/internal/events.(*eventStream).startEventHandlers
    /ethconnect/internal/events/eventstream.go:207 +0xcc

[peterbroadhurst]

Updated title to be more specific, so we don't end up with a catch-all issue for all unit test failures