Flaky tests

[codebien]

We are getting some failing CI runs caused by the logs tailing tests. They are generated from the time.Sleep use that is not deterministic.

Historically, we decided to not add a mock library just to support those tests. Instead, the code is using HTTPMultiBin that has the network dependency, so Sleep is waiting for an approximate amount of time necessary for flushing messages across the WebSocket connection, but not always the used duration value is enough.

The suggestion here is to find a more deterministic approach for detecting when the sent message from the HTTPMultiBin server has been received from the client.

[inancgumus]

@imiric:
We have a couple of these: https://github.com/grafana/k6/search?q=flaky&type=issues

We used to have a single issue for all (#1357), which I think would still make sense to consolidate all of them.

Mocking time would help (#1986), but for a lot of these, we need a non-time-based way of making assertions, which is tricky in most cases. 😕

@inancgumus:

[inancgumus]

Related: #2166

[na--]

TestStreamLogsToLogger seems to also be flaky:

--- FAIL: TestStreamLogsToLogger (0.00s)
    --- FAIL: TestStreamLogsToLogger/RestoreConnFromLatestMessage (5.00s)
        logs_test.go:333: 
            	Error Trace:	logs_test.go:333
            	            				logs_test.go:225
            	            				server.go:2056
            	            				server.go:2434
            	            				server.go:2888
            	            				server.go:1938
            	            				asm_amd64.s:1446
            	Error:      	Not equal: 
            	            	expected: time.Date(2021, time.July, 27, 2, 0, 0, 1, time.Local)
            	            	actual  : time.Date(2021, time.October, 12, 15, 15, 48, 684119853, time.Local)
            	            	
            	            	Diff:
            	            	--- Expected
            	            	+++ Actual
            	            	@@ -1,4 +1,4 @@
            	            	 (time.Time) {
            	            	- wall: (uint64) 1,
            	            	- ext: (int64) 63762948000,
            	            	+ wall: (uint64) 684119853,
            	            	+ ext: (int64) 63769648548,
            	            	  loc: (*time.Location)({
            	Test:       	TestStreamLogsToLogger/RestoreConnFromLatestMessage
        logs_test.go:354: 
            	Error Trace:	logs_test.go:354
            	Error:      	Not equal: 
            	            	expected: []string{"newest logline", "second logline", "oldest logline", "error reading a log message from the cloud, trying to establish a fresh connection with the logs service...", "logline-after-restored-conn"}
            	            	actual  : []string{"error reading a log message from the cloud, trying to establish a fresh connection with the logs service...", "newest logline", "second logline", "oldest logline"}
            	            	
            	            	Diff:
            	            	--- Expected
            	            	+++ Actual
            	            	@@ -1,7 +1,6 @@
            	            	-([]string) (len=5) {
            	            	+([]string) (len=4) {
            	            	+ (string) (len=107) "error reading a log message from the cloud, trying to establish a fresh connection with the logs service...",
            	            	  (string) (len=14) "newest logline",
            	            	  (string) (len=14) "second logline",
            	            	- (string) (len=14) "oldest logline",
            	            	- (string) (len=107) "error reading a log message from the cloud, trying to establish a fresh connection with the logs service...",
            	            	- (string) (len=27) "logline-after-restored-conn"
            	            	+ (string) (len=14) "oldest logline"
            	            	 }
            	Test:       	TestStreamLogsToLogger/RestoreConnFromLatestMessage
FAIL
FAIL	go.k6.io/k6/cloudapi	5.236s

[yorugac]

TestRampingVUsHandleRemainingVUs as well:

--- FAIL: TestRampingVUsHandleRemainingVUs (0.09s)
    ramping_vus_test.go:358: 
        	Error Trace:	ramping_vus_test.go:358
        	Error:      	Not equal: 
        	            	expected: 0x1
        	            	actual  : 0x2
        	Test:       	TestRampingVUsHandleRemainingVUs
    ramping_vus_test.go:359: 
        	Error Trace:	ramping_vus_test.go:359
        	Error:      	Not equal: 
        	            	expected: 0x1
        	            	actual  : 0x0
        	Test:       	TestRampingVUsHandleRemainingVUs
FAIL
FAIL	go.k6.io/k6/lib/executor	57.215s

[codebien]

I've seen it some times

--- FAIL: TestExecutionInfoVUSharing (4.07s)
    k6execution_test.go:146: 
        	Error Trace:	k6execution_test.go:146
        	Error:      	Not equal: 
        	            	expected: 0x9
        	            	actual  : 0xa
        	Test:       	TestExecutionInfoVUSharing
    k6execution_test.go:148: 
        	Error Trace:	k6execution_test.go:148
        	Error:      	Not equal: 
        	            	expected: 0x4
        	            	actual  : 0x5
        	Test:       	TestExecutionInfoVUSharing
    k6execution_test.go:146: 
        	Error Trace:	k6execution_test.go:146
        	Error:      	Not equal: 
        	            	expected: 0x9
        	            	actual  : 0x8
        	Test:       	TestExecutionInfoVUSharing
    k6execution_test.go:148: 
        	Error Trace:	k6execution_test.go:148
        	Error:      	Not equal: 
        	            	expected: 0x4
        	            	actual  : 0x3
        	Test:       	TestExecutionInfoVUSharing
--- FAIL: TestExecutionInfoAll (0.00s)
    --- FAIL: TestExecutionInfoAll/constant-arrival-rate (1.60s)
        assertion_compare.go:323: 
            	Error Trace:	k6execution_test.go:433
            	Error:      	"0" is not greater than or equal to "1"
            	Test:       	TestExecutionInfoAll/constant-arrival-rate
            	Messages:   	[]
FAIL
FAIL	go.k6.io/k6/core/local	60.360s

[codebien]

One more

--- FAIL: TestClient (0.01s)
    --- FAIL: TestClient/ReflectUnregistered (0.02s)
        client_test.go:671: 
            	Error Trace:	/home/runner/work/k6/k6/js/modules/k6/grpc/client_test.go:671
            	            				/home/runner/work/k6/k6/js/modules/k6/grpc/client_test.go:725
            	Error:      	"GoError: can't list services: can't send request: EOF at reflect.methodValueCall (native)" does not contain "rpc error: code = Unimplemented desc = unknown service grpc.reflection.v1alpha.ServerReflection"

[na--]

TestTracer seems to also be flaky: #2960 (comment)

[olegbespalov]

The TestClient/ReflectUnregistered also became flaky, it pretty often fails with something like:

--- FAIL: TestClient (0.00s)
    --- FAIL: TestClient/ReflectUnregistered (0.08s)
        client_test.go:814: 
            	Error Trace:	/home/ubuntu/actions-runner/_work/k6/k6/js/modules/k6/grpc/client_test.go:814
            	            				/home/ubuntu/actions-runner/_work/k6/k6/js/modules/k6/grpc/client_test.go:868
            	Error:      	"GoError: can't list services: can't send request: EOF at reflect.methodValueCall (native)" does not contain "rpc error: code = Unimplemented desc = unknown service grpc.reflection.v1alpha.ServerReflection"
            	Test:       	TestClient/ReflectUnregistered

An example: https://github.com/grafana/k6/actions/runs/5386480781/jobs/9776586409