time: TestChan/asynctimerchan=1/Ticker failures #66322

gopherbot · 2024-03-14T21:56:27Z

#!watchflakes
default <- pkg == "time" && test ~ `TestChan`

Issue created automatically to collect these failures.

Example (log):

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:438: missing tick
    tick_test.go:526: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.27s)

— watchflakes

The text was updated successfully, but these errors were encountered:

gopherbot · 2024-03-14T21:56:28Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-14 20:20 gotip-linux-amd64-longtest go@386dcf4c time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:438: missing tick
    tick_test.go:526: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.27s)

2024-03-14 20:28 gotip-linux-amd64-boringcrypto go@1d96895c time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:526: drain
    tick_test.go:557: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.11s)

— watchflakes

gopherbot · 2024-03-15T05:03:57Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-14 23:23 gotip-linux-amd64-longtest-race go@502347f1 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:464: len(C) = 0, want 1
    tick_test.go:465: missing tick
    tick_test.go:526: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.40s)

2024-03-15 03:39 gotip-linux-amd64-longtest-race go@9a9b110f time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.07s)

— watchflakes

gopherbot · 2024-03-15T06:14:56Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-15 04:32 gotip-linux-amd64-longtest-race go@a29c30f6 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.07s)

— watchflakes

gopherbot · 2024-03-15T17:21:28Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-15 15:45 gotip-linux-amd64-longtest-race go@c764d56f time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.14s)

2024-03-15 15:59 gotip-linux-ppc64le go@49204af3 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:526: drain
    tick_test.go:557: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.09s)

— watchflakes

gopherbot · 2024-03-15T18:34:12Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-15 16:11 gotip-windows-amd64-race go@88480fad time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:438: missing tick
    tick_test.go:526: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (1.33s)

2024-03-15 17:12 gotip-linux-amd64-longtest-race go@6f121623 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:526: drain
    tick_test.go:557: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.10s)

2024-03-15 17:57 gotip-linux-amd64-staticlockranking go@c7065bb9 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:526: drain
    tick_test.go:557: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.10s)

— watchflakes

gopherbot · 2024-03-15T23:24:05Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-15 18:30 gotip-openbsd-amd64 go@4605dfaf time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:526: drain
    tick_test.go:557: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.14s)

— watchflakes

gopherbot · 2024-03-17T09:54:41Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-15 15:59 gotip-linux-riscv64 go@49204af3 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.09s)

— watchflakes

gopherbot · 2024-03-17T17:10:00Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-16 00:34 gotip-windows-386 go@b822f098 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:438: missing tick
    tick_test.go:526: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (1.49s)

2024-03-16 02:25 gotip-windows-386 go@68d3a9e4 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:464: len(C) = 0, want 1
    tick_test.go:465: missing tick
    tick_test.go:526: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (2.45s)

— watchflakes

gopherbot · 2024-03-18T04:08:52Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-15 03:39 gotip-netbsd-arm64 go@9a9b110f time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.30s)

— watchflakes

gopherbot · 2024-03-18T18:42:16Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-18 16:57 gotip-linux-amd64-clang15 go@f40bf748 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.08s)

2024-03-18 16:57 gotip-linux-amd64-longtest-race go@af0ebdd4 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.06s)

— watchflakes

gopherbot · 2024-03-18T19:53:48Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-18 17:08 gotip-linux-amd64-race go@b40dc30d time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:526: drain
    tick_test.go:557: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.09s)

— watchflakes

gopherbot · 2024-03-18T22:30:11Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-18 18:59 gotip-linux-amd64-longtest-race go@dc6a5cfc time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:526: drain
    tick_test.go:557: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.11s)

2024-03-18 19:33 gotip-linux-amd64-longtest-race go@0d7afc2e time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.07s)

2024-03-18 19:36 gotip-linux-amd64-longtest-race go@3c78ace2 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:526: drain
    tick_test.go:557: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.10s)

2024-03-18 21:29 gotip-windows-amd64 go@3bd95485 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:438: missing tick
    tick_test.go:526: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (1.38s)

— watchflakes

gopherbot · 2024-03-19T00:57:20Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-18 23:40 gotip-linux-386-longtest go@190d0d3e time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:464: len(C) = 0, want 1
    tick_test.go:465: missing tick
    tick_test.go:526: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (2.25s)

— watchflakes

gopherbot · 2024-03-19T02:08:45Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-18 19:36 gotip-linux-riscv64 go@3c78ace2 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.06s)

— watchflakes

gopherbot · 2024-03-19T10:29:44Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-18 23:57 gotip-linux-riscv64 go@1e9875ca time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:526: drain
    tick_test.go:557: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.12s)

— watchflakes

gopherbot · 2024-03-19T12:52:10Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-19 11:20 gotip-linux-386-longtest go@eb636f77 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:526: drain
    tick_test.go:557: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.10s)

— watchflakes

gopherbot · 2024-03-19T14:04:19Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-19 11:31 gotip-linux-arm go@d14cf8f9 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:526: drain
    tick_test.go:557: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.11s)

— watchflakes

gopherbot · 2024-03-19T18:55:07Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-19 11:47 gotip-darwin-amd64-longtest go@b7508419 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.07s)

— watchflakes

gopherbot · 2024-03-19T22:30:29Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-19 16:19 gotip-linux-amd64-race go@8f7df225 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:510: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.08s)

2024-03-19 20:02 gotip-linux-amd64-race go@99522de1 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:526: drain
    tick_test.go:557: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.11s)

— watchflakes

gopherbot · 2024-03-22T21:02:29Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-19 21:38 gotip-netbsd-arm64 go@f94d82b2 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:464: len(C) = 0, want 1
    tick_test.go:465: missing tick
    tick_test.go:526: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (4.41s)

2024-03-20 19:08 gotip-netbsd-arm64 go@6af27c49 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.20s)

2024-03-21 09:29 gotip-linux-arm go@f2685395 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.08s)

2024-03-21 16:12 gotip-windows-386 go@d9f97467 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:464: len(C) = 0, want 1
    tick_test.go:465: missing tick
    tick_test.go:526: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (2.34s)

2024-03-21 20:00 gotip-linux-amd64-longtest go@aa1b50e1 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:526: drain
    tick_test.go:557: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.09s)

2024-03-21 21:00 gotip-linux-amd64-longtest-race go@0c77b0d0 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:438: missing tick
    tick_test.go:526: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (1.25s)

2024-03-21 21:01 gotip-linux-amd64-longtest-race go@b4f37e18 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.07s)

2024-03-21 22:14 gotip-linux-arm64 go@4f0408a3 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.06s)

2024-03-22 04:42 gotip-darwin-amd64-nocgo go@a6ecdf29 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.05s)

2024-03-22 06:48 gotip-netbsd-arm64 go@b5e377ce time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:438: missing tick
    tick_test.go:526: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (2.48s)

2024-03-22 13:07 gotip-linux-386-longtest go@27f41bb1 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.06s)

2024-03-22 16:33 gotip-linux-arm64 go@1c864333 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:526: drain
    tick_test.go:557: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.10s)

— watchflakes

gopherbot · 2024-03-23T06:41:46Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-22 16:14 gotip-linux-riscv64 go@c2b14631 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.07s)

— watchflakes

gopherbot · 2024-03-23T10:18:03Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-23 04:07 gotip-linux-riscv64 go@83a6c13e time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:464: len(C) = 0, want 1
    tick_test.go:465: missing tick
    tick_test.go:526: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (2.31s)

— watchflakes

gopherbot · 2024-03-23T15:03:04Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-21 21:00 gotip-linux-riscv64 go@0c77b0d0 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:526: drain
    tick_test.go:557: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.09s)

— watchflakes

gopherbot · 2024-03-25T11:27:37Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-20 14:15 gotip-netbsd-arm64 go@9c94baa7 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.10s)

— watchflakes

gopherbot · 2024-03-25T20:25:02Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-25 19:21 gotip-linux-amd64-longtest-race go@2c677361 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:526: drain
    tick_test.go:557: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.12s)

— watchflakes

gopherbot · 2024-03-25T21:36:29Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test == "TestChan/asynctimerchan=1/Ticker"

2024-03-25 19:53 gotip-linux-arm64 go@4c2b1e0f time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:526: drain
    tick_test.go:557: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.10s)

— watchflakes

prattmic · 2024-03-27T17:59:52Z

cc @rsc

This seems to be one of our flakiest tests. I'm getting multiple failures within the tests on an 8 CL stack.

thanm · 2024-03-29T23:19:22Z

@rsc Hi Russ if you could take a look at this, would appreciate. Looks like it started happening more frequently around the time of your CL 568341.

gopherbot · 2024-04-23T21:45:08Z

Change https://go.dev/cl/581315 mentions this issue: time: deflake TestChan/asynctimerchan=1 tests

gopherbot · 2024-04-25T01:38:34Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test ~ `TestChan`

2024-04-25 00:46 android-386-emu go@e7aeeae0 time.TestChan (log)

--- FAIL: TestChan (0.89s)
    --- FAIL: TestChan/asynctimerchan=1 (0.25s)
        --- FAIL: TestChan/asynctimerchan=1/Ticker (0.07s)
            tick_test.go:505: early done

— watchflakes

The overall time package tests increase from 3.85s to 4.85s on my laptop. But they should be less flaky, and the time is spent sleeping, so it won't slow down the overall machine running multiple package tests in parallel. For #66322. Change-Id: I66d6647c389c943b53045e8836ede4ba3d4670c7 Reviewed-on: https://go-review.googlesource.com/c/go/+/581315 LUCI-TryBot-Result: Go LUCI <[email protected]> Reviewed-by: Ian Lance Taylor <[email protected]> Reviewed-by: Cherry Mui <[email protected]>

gopherbot · 2024-04-25T11:45:40Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test ~ `TestChan`

2024-04-25 01:05 android-amd64-emu go@db5f2b41 time.TestChan (log)

--- FAIL: TestChan (0.86s)
    --- FAIL: TestChan/asynctimerchan=1 (0.24s)
        --- FAIL: TestChan/asynctimerchan=1/Ticker (0.06s)
            tick_test.go:505: early done

— watchflakes

gopherbot · 2024-04-26T08:50:57Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test ~ `TestChan`

2024-04-24 13:36 gotip-linux-386-longtest go@62dfa431 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:464: len(C) = 0, want 1
    tick_test.go:465: missing tick
    tick_test.go:526: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (2.25s)

2024-04-24 13:36 gotip-linux-arm64-longtest go@62dfa431 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:464: len(C) = 0, want 1
    tick_test.go:465: missing tick
    tick_test.go:526: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (2.24s)

2024-04-24 15:53 gotip-windows-amd64-race go@3aad2d07 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:464: len(C) = 0, want 1
    tick_test.go:465: missing tick
    tick_test.go:526: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (2.31s)

2024-04-24 18:15 gotip-linux-ppc64_power8 go@e6891188 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:505: early done
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.07s)

— watchflakes

gopherbot · 2024-04-26T08:57:37Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test ~ `TestChan`

2024-04-25 17:07 gotip-linux-amd64-longtest-race go@06478e4b time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:469: len(C) = 0, want 1
    tick_test.go:470: missing tick
    tick_test.go:531: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (2.55s)

— watchflakes

gopherbot · 2024-04-26T23:11:30Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test ~ `TestChan`

2024-04-26 21:32 openbsd-amd64-72 go@b439f328 time.TestChan (log)

--- FAIL: TestChan (7.27s)
    --- FAIL: TestChan/asynctimerchan=1 (5.41s)
        --- FAIL: TestChan/asynctimerchan=1/Ticker (4.69s)
            tick_test.go:469: len(C) = 0, want 1
            tick_test.go:470: missing tick
            tick_test.go:531: drain

— watchflakes

gopherbot · 2024-04-27T17:44:32Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test ~ `TestChan`

2024-04-26 15:38 gotip-linux-amd64-nocgo go@deeebf56 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:469: len(C) = 0, want 1
    tick_test.go:470: missing tick
    tick_test.go:531: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (2.44s)

— watchflakes

gopherbot · 2024-04-27T17:52:04Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test ~ `TestChan`

2024-04-26 17:08 gotip-linux-amd64-longtest-race go@19691629 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:469: len(C) = 0, want 1
    tick_test.go:470: missing tick
    tick_test.go:531: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (2.49s)

2024-04-26 18:12 gotip-windows-amd64-longtest go@b384ee7c time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:469: len(C) = 0, want 1
    tick_test.go:470: missing tick
    tick_test.go:531: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (2.73s)

2024-04-26 23:07 gotip-linux-386-softfloat go@d69f8744 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:469: len(C) = 0, want 1
    tick_test.go:470: missing tick
    tick_test.go:531: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (2.42s)

— watchflakes

gopherbot · 2024-04-30T03:04:43Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test ~ `TestChan`

2024-04-29 14:01 openbsd-arm64-jsing go@9e0685f9 time.TestChan (log)

--- FAIL: TestChan (7.13s)
    --- FAIL: TestChan/asynctimerchan=1 (5.27s)
        --- FAIL: TestChan/asynctimerchan=1/Ticker (4.53s)
            tick_test.go:469: len(C) = 0, want 1
            tick_test.go:470: missing tick
            tick_test.go:531: drain

— watchflakes

gopherbot · 2024-04-30T16:56:33Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test ~ `TestChan`

2024-04-30 12:44 gotip-linux-amd64-longtest-race go@dc164ead time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:443: missing tick
    tick_test.go:531: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (1.45s)

2024-04-30 12:44 gotip-linux-ppc64_power8 go@dc164ead time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:443: missing tick
    tick_test.go:531: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (1.50s)

— watchflakes

gopherbot · 2024-05-03T18:10:55Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test ~ `TestChan`

2024-05-03 16:48 gotip-linux-ppc64le_power10 go@10c035ac time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:469: len(C) = 0, want 1
    tick_test.go:470: missing tick
    tick_test.go:531: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (2.47s)

— watchflakes

gopherbot · 2024-05-08T11:04:13Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test ~ `TestChan`

2024-05-07 18:03 gotip-linux-ppc64_power8 go@9c4849bf time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:469: len(C) = 0, want 1
    tick_test.go:470: missing tick
    tick_test.go:531: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (3.00s)

2024-05-07 18:42 gotip-windows-amd64-longtest go@c40bb874 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:443: missing tick
    tick_test.go:531: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (1.49s)

— watchflakes

rsc · 2024-05-08T15:04:12Z

My previous CL definitely cut out a bunch of the flakes. Mailed CL 584195 to cut the recent ones too. Perhaps that will be the end of it.

The irony here is that all the flaking is in testing the old racy semantics for compatibility. In the new semantics these kinds of races and flakes aren't possible at all.

gopherbot · 2024-05-08T15:05:22Z

Change https://go.dev/cl/584195 mentions this issue: time: more deflaking asynctimer tests

For #66322. Change-Id: I1d83c7a3cacd2ab012039d954270a7c87bbdf5ce Reviewed-on: https://go-review.googlesource.com/c/go/+/584195 Reviewed-by: Cherry Mui <[email protected]> LUCI-TryBot-Result: Go LUCI <[email protected]> Auto-Submit: Russ Cox <[email protected]>

gopherbot · 2024-05-09T18:25:39Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test ~ `TestChan`

2024-05-09 17:06 android-386-emu go@dd6dee48 time.TestChan (log)

--- FAIL: TestChan (1.79s)
    --- FAIL: TestChan/asynctimerchan=1 (0.79s)
        --- FAIL: TestChan/asynctimerchan=1/Ticker (0.40s)
            tick_test.go:471: extra tick
            tick_test.go:530: drain

— watchflakes

gopherbot · 2024-05-10T02:31:34Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test ~ `TestChan`

2024-05-09 23:28 darwin-amd64-race go@23154125 time.TestChan (log)

--- FAIL: TestChan (1.77s)
    --- FAIL: TestChan/asynctimerchan=1 (0.76s)
        --- FAIL: TestChan/asynctimerchan=1/Ticker (0.37s)
            tick_test.go:445: extra tick
            tick_test.go:530: drain

— watchflakes

gopherbot · 2024-05-10T22:57:17Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test ~ `TestChan`

2024-05-10 14:27 gotip-windows-amd64-race go@b44600f8 time.TestChan/asynctimerchan=1/Ticker (log)

=== RUN   TestChan/asynctimerchan=1/Ticker
    tick_test.go:445: extra tick
    tick_test.go:530: drain
--- FAIL: TestChan/asynctimerchan=1/Ticker (0.39s)

— watchflakes

gopherbot · 2024-05-11T22:04:21Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test ~ `TestChan`

2024-05-11 00:21 darwin-amd64-race go@74a49188 time.TestChan (log)

--- FAIL: TestChan (1.78s)
    --- FAIL: TestChan/asynctimerchan=1 (0.77s)
        --- FAIL: TestChan/asynctimerchan=1/Ticker (0.38s)
            tick_test.go:445: extra tick
            tick_test.go:530: drain

— watchflakes

gopherbot · 2024-05-12T07:28:44Z

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "time" && test ~ `TestChan`

2024-05-11 20:38 netbsd-arm64-bsiegert go@7f9edb42 time.TestChan (log)

--- FAIL: TestChan (3.15s)
    --- FAIL: TestChan/asynctimerchan=1 (1.31s)
        --- FAIL: TestChan/asynctimerchan=1/Ticker (0.62s)
            tick_test.go:471: extra tick
            tick_test.go:530: drain

— watchflakes

gopherbot · 2024-05-14T17:35:10Z

Change https://go.dev/cl/585359 mentions this issue: time: more flake removal in asynctimerchan test

Trying to write a test for the corner cases in the old async timer chan implementation may have been a mistake, especially since this isn't going to be the default timer chan implementation anymore. But let's try one more time to fix the test. I reproduced the remaining builder failures on my Mac laptop by overloading the CPU in one window and then running 48 instances of the flaky test in loops using 'stress' in another window. It turns out that, contrary to my understanding of async timers and therefore contrary to what the test expected, it is technically possible for t := time.NewTicker(1) t.Reset(1000*time.Hour) <-t.C <-t.C to observe two time values on t.C, as opposed to blocking forever. We always expect the first time value, since the ticker goes off immediately (after 1ns) and sends that value into the channel buffer. To get the second value, the ticker has to be in the process of going off (which it is doing constantly anyway), and the timer goroutine has to be about to call sendTime and then get rescheduled. Then t.Reset and the first <-t.C have to happen. Then the timer goroutine gets rescheduled and can run sendTime's non-blocking send on t.C, which finds an empty buffer and writes a value. This is unlikely, of course, but it definitely happens. This program always panics in just a second or two on my laptop: package main import ( "os" "time" ) func main() { os.Setenv("GODEBUG", "asynctimerchan=1") for { go func() { t := time.NewTicker(1) t.Reset(1000*time.Hour) <-t.C select { case <-t.C: panic("two receives") case <-time.After(1*time.Second): } }() } } Because I did not understand this nuance, the test did not expect it. This CL rewrites the test to expect that possibility. I can no longer make the test fail under 'stress' on my laptop. For #66322. Change-Id: I15c75d2c6f24197c43094da20d6ab55306a0a9f1 Reviewed-on: https://go-review.googlesource.com/c/go/+/585359 Reviewed-by: Cherry Mui <[email protected]> Reviewed-by: Ian Lance Taylor <[email protected]> Auto-Submit: Russ Cox <[email protected]> LUCI-TryBot-Result: Go LUCI <[email protected]>

rsc · 2024-05-29T16:28:00Z

We were getting reports every day or two, and now it has been 15 days without a report. Closing.

gopherbot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Mar 14, 2024

gopherbot added this to Test Flakes Mar 14, 2024

rsc closed this as completed May 29, 2024

github-project-automation bot moved this to Done in Test Flakes May 29, 2024

dmitshur added this to the Go1.23 milestone May 29, 2024

dmitshur added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels May 29, 2024

gabyhelp mentioned this issue Jun 21, 2024

iter: TestPull2/0 failures #68118

Closed

time: TestChan/asynctimerchan=1/Ticker failures #66322

time: TestChan/asynctimerchan=1/Ticker failures #66322

Comments

gopherbot commented Mar 14, 2024 • edited by cherrymui Loading

gopherbot commented Mar 14, 2024

gopherbot commented Mar 15, 2024

gopherbot commented Mar 15, 2024

gopherbot commented Mar 15, 2024

gopherbot commented Mar 15, 2024

gopherbot commented Mar 15, 2024

gopherbot commented Mar 17, 2024

gopherbot commented Mar 17, 2024

gopherbot commented Mar 18, 2024

gopherbot commented Mar 18, 2024

gopherbot commented Mar 18, 2024

gopherbot commented Mar 18, 2024

gopherbot commented Mar 19, 2024

gopherbot commented Mar 19, 2024

gopherbot commented Mar 19, 2024

gopherbot commented Mar 19, 2024

gopherbot commented Mar 19, 2024

gopherbot commented Mar 19, 2024

gopherbot commented Mar 19, 2024

gopherbot commented Mar 22, 2024

gopherbot commented Mar 23, 2024

gopherbot commented Mar 23, 2024

gopherbot commented Mar 23, 2024

gopherbot commented Mar 25, 2024

gopherbot commented Mar 25, 2024

gopherbot commented Mar 25, 2024

prattmic commented Mar 27, 2024

thanm commented Mar 29, 2024

gopherbot commented Apr 23, 2024

gopherbot commented Apr 25, 2024

gopherbot commented Apr 25, 2024

gopherbot commented Apr 26, 2024

gopherbot commented Apr 26, 2024

gopherbot commented Apr 26, 2024

gopherbot commented Apr 27, 2024

gopherbot commented Apr 27, 2024

gopherbot commented Apr 30, 2024

gopherbot commented Apr 30, 2024

gopherbot commented May 3, 2024

gopherbot commented May 8, 2024

rsc commented May 8, 2024

gopherbot commented May 8, 2024

gopherbot commented May 9, 2024

gopherbot commented May 10, 2024

gopherbot commented May 10, 2024

gopherbot commented May 11, 2024

gopherbot commented May 12, 2024

gopherbot commented May 14, 2024

rsc commented May 29, 2024

gopherbot commented Mar 14, 2024 •

edited by cherrymui

Loading