k6
k6 copied to clipboard
grafana
Flaky tests
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.
@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 (https://github.com/grafana/k6/issues/1357), which I think would still make sense to consolidate all of them.
Mocking time would help (https://github.com/grafana/k6/issues/1986), but for a lot of these, we need a non-time-based way of making assertions, which is tricky in most cases. :confused:
@inancgumus:
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
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
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
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"
TestTracer seems to also be flaky: https://github.com/grafana/k6/pull/2960#issuecomment-1460021143
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
