Flaky ES test - TestSpanReader_multiRead_followUp_query

[yurishkuro]

defined in plugin/storage/es/spanstore/reader_test.go:208

=== RUN   TestSpanReader_multiRead_followUp_query
--- FAIL: TestSpanReader_multiRead_followUp_query (0.00s)
panic: 
mock: Unexpected Method Call
-----------------------------
Index(string,string)
		0: "jaeger-span-2019-08-06"
		1: "jaeger-span-2019-08-05"
The closest call I have is: 
Index(mock.AnythingOfTypeArgument)
		0: "string"
Provided 1 arguments, mocked for 2 arguments
Diff: 1: FAIL:  (string=jaeger-span-2019-08-05) != (Missing) [recovered]
	panic: 
mock: Unexpected Method Call
-----------------------------
Index(string,string)
		0: "jaeger-span-2019-08-06"
		1: "jaeger-span-2019-08-05"
The closest call I have is: 
Index(mock.AnythingOfTypeArgument)
		0: "string"
Provided 1 arguments, mocked for 2 arguments
Diff: 1: FAIL:  (string=jaeger-span-2019-08-05) != (Missing)
goroutine 22 [running]:
testing.tRunner.func1(0xc00010a700)
	/home/travis/.gimme/versions/go1.12.1.linux.amd64/src/testing/testing.go:830 +0x69d
panic(0xca69c0, 0xc000135c00)
	/home/travis/.gimme/versions/go1.12.1.linux.amd64/src/runtime/panic.go:522 +0x1b5
github.com/jaegertracing/jaeger/vendor/github.com/stretchr/testify/mock.(*Mock).fail(0xc0000d5180, 0xd9d701, 0x6f, 0xc000139b40, 0x4, 0x4)
	/home/travis/gopath/src/github.com/jaegertracing/jaeger/vendor/github.com/stretchr/testify/mock/mock.go:236 +0x1ad
github.com/jaegertracing/jaeger/vendor/github.com/stretchr/testify/mock.(*Mock).MethodCalled(0xc0000d5180, 0x1394873, 0x5, 0xc00016c2c0, 0x2, 0x2, 0xc000139b00, 0x4, 0x4)
	/home/travis/gopath/src/github.com/jaegertracing/jaeger/vendor/github.com/stretchr/testify/mock/mock.go:358 +0xab5
github.com/jaegertracing/jaeger/vendor/github.com/stretchr/testify/mock.(*Mock).Called(0xc0000d5180, 0xc00016c2c0, 0x2, 0x2, 0xc00016c2a0, 0x2, 0x2)
	/home/travis/gopath/src/github.com/jaegertracing/jaeger/vendor/github.com/stretchr/testify/mock/mock.go:334 +0x1e7
github.com/jaegertracing/jaeger/pkg/es/mocks.(*MultiSearchService).Index(0xc0000d5180, 0xc00016c180, 0x2, 0x2, 0x2b1869d6f208, 0xc0000d5180)
	/home/travis/gopath/src/github.com/jaegertracing/jaeger/pkg/es/mocks/MultiSearchService.go:83 +0x1c6
github.com/jaegertracing/jaeger/plugin/storage/es/spanstore.(*SpanReader).multiRead(0xc000132c80, 0xe6f5c0, 0xc0000a2010, 0xc0000d7ac0, 0x2, 0x2, 0xbf4a4c71f26eaa02, 0x8a7f75, 0x1408be0, 0xbf4a4c71f26eaa02, ...)
	/home/travis/gopath/src/github.com/jaegertracing/jaeger/plugin/storage/es/spanstore/reader.go:340 +0xc94
github.com/jaegertracing/jaeger/plugin/storage/es/spanstore.TestSpanReader_multiRead_followUp_query.func1(0xc0000b3f40)
	/home/travis/gopath/src/github.com/jaegertracing/jaeger/plugin/storage/es/spanstore/reader_test.go:269 +0x21f7
github.com/jaegertracing/jaeger/plugin/storage/es/spanstore.withSpanReader(0xc000060f50)
	/home/travis/gopath/src/github.com/jaegertracing/jaeger/plugin/storage/es/spanstore/reader_test.go:105 +0x382
github.com/jaegertracing/jaeger/plugin/storage/es/spanstore.TestSpanReader_multiRead_followUp_query(0xc00010a700)
	/home/travis/gopath/src/github.com/jaegertracing/jaeger/plugin/storage/es/spanstore/reader_test.go:209 +0x57
testing.tRunner(0xc00010a700, 0xda1cb8)
	/home/travis/.gimme/versions/go1.12.1.linux.amd64/src/testing/testing.go:865 +0x164
created by testing.(*T).Run
	/home/travis/.gimme/versions/go1.12.1.linux.amd64/src/testing/testing.go:916 +0x65b
FAIL	github.com/jaegertracing/jaeger/plugin/storage/es/spanstore	0.022s

[pavolloffay]

Does it happen on master/head?

I think @jpkrohling fixed it in #1703

[yurishkuro]

it happened in #1704, I thought after I merged master with @jpkrohling 's fix

[yurishkuro]

Actually, I think #1703 is a different issue altogether. This failure is with unexpected call to mocked method, which can be caused by race conditions. It failed again in https://travis-ci.org/jaegertracing/jaeger/jobs/568600800#L2885

[yurishkuro]

Another recent failure https://travis-ci.org/jaegertracing/jaeger/jobs/582922510

@guanw had a potential explanation in #1786 (comment)

[yurishkuro]

This test does appear to be time-sensitive: https://travis-ci.org/jaegertracing/jaeger/jobs/593308117

[yurishkuro]

@pavolloffay #1703 didn't fix it. The fix was to be less sensitive to the order, but it seems like the issue is with 1 or 2 spans being created, due to the time of day when the test runs and ES queries 1 or 2 daily indices

Index(string,string)
		0: "jaeger-span-2019-10-04"
		1: "jaeger-span-2019-10-03"
The closest call I have is: 
Index(mock.AnythingOfTypeArgument)
		0: "string"

[yurishkuro]

One way to fix it is to pass a "clock" to ES which would always return the same time of day in the test, instead of using time.now()

[pavolloffay]

I will have a look at this one again