go icon indicating copy to clipboard operation
go copied to clipboard
Published 3 weeks ago • verified publisher icon golang

runtime/trace: TestSubscribers failures

Open gopherbot opened this issue 2 months ago • 10 comments 

#!watchflakes
default <- pkg == "runtime/trace" && test ~ `TestSubscribers`

Issue created automatically to collect these failures.

Example (log):

=== RUN   TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)
    subscribe_test.go:41: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
--- FAIL: TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (0.01s)

— watchflakes

gopherbot avatar Sep 30 '25 08:09 gopherbot

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "runtime/trace" && test == "TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)"
2025-09-29 21:06 gotip-netbsd-arm64 go@fc88e18b runtime/trace.TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)
    subscribe_test.go:41: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
--- FAIL: TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (0.01s)

— watchflakes

gopherbot avatar Sep 30 '25 08:09 gopherbot

Let's wait for another failure, but in the meantime we should change the test to dump the trace.

mknyszek avatar Oct 08 '25 20:10 mknyszek

Change https://go.dev/cl/710755 mentions this issue: runtime/trace: dump test traces on validation failure

gopherbot avatar Oct 09 '25 21:10 gopherbot

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "runtime/trace" && test == "TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)"
2025-11-20 23:01 gotip-linux-amd64_avx512 go@d58b7336 runtime/trace.TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)
    subscribe_test.go:41: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
--- FAIL: TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (0.00s)

— watchflakes

gopherbot avatar Nov 20 '25 23:11 gopherbot

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "runtime/trace" && test == "TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)"
2025-11-21 20:42 gotip-netbsd-arm64 go@e15800c0 runtime/trace.TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)
    subscribe_test.go:41: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
--- FAIL: TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (0.01s)

— watchflakes

gopherbot avatar Nov 24 '25 04:11 gopherbot

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "runtime/trace" && test == "TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)"
2025-11-24 20:09 gotip-linux-amd64-nogreenteagc go@a9914886 runtime/trace.TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)
    subscribe_test.go:41: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
--- FAIL: TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (0.03s)

— watchflakes

gopherbot avatar Nov 24 '25 21:11 gopherbot

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "runtime/trace" && test == "TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)"
2025-12-03 20:43 gotip-linux-amd64-nosizespecializedmalloc go@9ac524ab runtime/trace.TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)
    subscribe_test.go:41: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
--- FAIL: TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (0.01s)

— watchflakes

gopherbot avatar Dec 03 '25 23:12 gopherbot

Change https://go.dev/cl/728200 mentions this issue: runtime/trace: update TestSubscribers to dump traces

gopherbot avatar Dec 08 '25 18:12 gopherbot

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "runtime/trace" && test == "TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)"
2025-12-08 18:56 gotip-darwin-amd64-race go@4837bcc9 runtime/trace.TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)
    subscribe_test.go:41: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
--- FAIL: TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (0.04s)

— watchflakes

gopherbot avatar Dec 08 '25 22:12 gopherbot

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "runtime/trace" && test ~ `TestSubscribers`
2025-12-08 15:59 gotip-windows-386 go@4122d3e9 runtime/trace.TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (log) 
=== RUN   TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace)
    subscribe_test.go:41: unexpected error reading trace for tracer: expected a goroutine but didn't have one
--- FAIL: TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (0.05s)

— watchflakes

gopherbot avatar Dec 09 '25 02:12 gopherbot

Change https://go.dev/cl/729400 mentions this issue: runtime: dropg after emitting trace event in preemptPark

gopherbot avatar Dec 11 '25 19:12 gopherbot

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "runtime/trace" && test ~ `TestSubscribers`
2025-12-11 17:34 go1.26-linux-amd64-asan-clang15 release-branch.go1.26@00642ee2 runtime/trace.TestSubscribers [SKIP] (log) 
=== RUN   TestSubscribers
2025-12-11 17:35 go1.26-linux-amd64-race release-branch.go1.26@9de64687 runtime/trace.TestSubscribers [SKIP] (log) 
=== RUN   TestSubscribers
2025-12-11 17:37 gotip-windows-amd64 go@5818c9d7 runtime/trace.TestSubscribers/start(flight)_start(trace)_stop(trace)_stop(flight) [SKIP] (log) 
=== RUN   TestSubscribers/start(flight)_start(trace)_stop(trace)_stop(flight)
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    subscribe_test.go:50: event validation failed: timestamp out-of-order (want > 496436813287) for M=0 P=0 G=0 Bad Time=0
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    subscribe_test.go:50: event validation failed: timestamp out-of-order (want > 496436813287) for M=0 P=0 G=0 Bad Time=0
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    subscribe_test.go:50: event validation failed: timestamp out-of-order (want > 496436813287) for M=0 P=0 G=0 Bad Time=0
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    subscribe_test.go:50: event validation failed: timestamp out-of-order (want > 496436813287) for M=0 P=0 G=0 Bad Time=0
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
...
panic: test timed out after 9m0s
	running tests:
		TestSubscribers (8m54s)
		TestSubscribers/start(flight)_start(trace)_stop(trace)_stop(flight) (8m54s)

goroutine 146 gp=0x10aea1809a40 m=8 mp=0x10aea17d3808 [running]:
panic({0x7ff729a08e00?, 0x10aea1980040?})
	C:/b/s/w/ir/x/w/goroot/src/runtime/panic.go:879 +0x16f fp=0x10aea1865f10 sp=0x10aea1865e60 pc=0x7ff7298d222f
testing.(*M).startAlarm.func1()
	C:/b/s/w/ir/x/w/goroot/src/testing/testing.go:2802 +0x34b fp=0x10aea1865fe0 sp=0x10aea1865f10 pc=0x7ff7299615eb
...
runtime/trace_test.TestSubscribers.func7(0x10aea1a18400)
	C:/b/s/w/ir/x/w/goroot/src/runtime/trace/subscribe_test.go:103 +0x1bd fp=0x10aea1c89f70 sp=0x10aea1c89ec8 pc=0x7ff7299de29d
testing.tRunner(0x10aea1a18400, 0x10aea18f42d0)
	C:/b/s/w/ir/x/w/goroot/src/testing/testing.go:2036 +0xc3 fp=0x10aea1c89fc0 sp=0x10aea1c89f70 pc=0x7ff72995ce43
testing.(*T).Run.gowrap1()
	C:/b/s/w/ir/x/w/goroot/src/testing/testing.go:2101 +0x1b fp=0x10aea1c89fe0 sp=0x10aea1c89fc0 pc=0x7ff72995df9b
runtime.goexit({})
	C:/b/s/w/ir/x/w/goroot/src/runtime/asm_amd64.s:1771 +0x1 fp=0x10aea1c89fe8 sp=0x10aea1c89fe0 pc=0x7ff7298d9f21
created by testing.(*T).Run in goroutine 133
	C:/b/s/w/ir/x/w/goroot/src/testing/testing.go:2101 +0x4be
2025-12-11 18:11 go1.26-linux-amd64-race release-branch.go1.26@2622d295 runtime/trace.TestSubscribers [SKIP] (log) 
=== RUN   TestSubscribers
2025-12-11 18:11 gotip-linux-amd64-race go@2622d295 runtime/trace.TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) [SKIP] (log) 
=== RUN   TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)
    subscribe_test.go:47: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
    subscribe_test.go:50: event validation failed: timestamp out-of-order (want > 175132029696) for M=0 P=0 G=0 Bad Time=0
    subscribe_test.go:47: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
    subscribe_test.go:50: event validation failed: timestamp out-of-order (want > 175132029696) for M=0 P=0 G=0 Bad Time=0
    subscribe_test.go:47: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
    subscribe_test.go:50: event validation failed: timestamp out-of-order (want > 175132029696) for M=0 P=0 G=0 Bad Time=0
    subscribe_test.go:47: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
    subscribe_test.go:50: event validation failed: timestamp out-of-order (want > 175132029696) for M=0 P=0 G=0 Bad Time=0
    subscribe_test.go:47: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
...
panic: test timed out after 6m0s
	running tests:
		TestSubscribers (5m53s)
		TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (5m53s)

goroutine 85 gp=0xc000104d20 m=7 mp=0xc0000b8808 [running]:
panic({0x6a0180?, 0xc00054e040?})
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/panic.go:879 +0x16f fp=0xc000097ef8 sp=0xc000097e48 pc=0x4c0b4f
testing.(*M).startAlarm.func1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:2802 +0x605 fp=0xc000097fe0 sp=0xc000097ef8 pc=0x594fe5
...
runtime/trace_test.TestSubscribers.func8(0xc000384008)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/trace/subscribe_test.go:117 +0x291 fp=0xc000033ee0 sp=0xc000033dd8 pc=0x66c731
testing.tRunner(0xc000384008, 0xc0002fa000)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:2036 +0x21d fp=0xc000033fb0 sp=0xc000033ee0 pc=0x58c73d
testing.(*T).Run.gowrap1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:2101 +0x39 fp=0xc000033fe0 sp=0xc000033fb0 pc=0x58e739
runtime.goexit({})
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/asm_amd64.s:1771 +0x1 fp=0xc000033fe8 sp=0xc000033fe0 pc=0x4c8c21
created by testing.(*T).Run in goroutine 115
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:2101 +0xb13
2025-12-11 18:37 gotip-linux-amd64_avx512 go@89614ad2 runtime/trace.TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (log) 
=== RUN   TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace)
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=51 m=18446744073709551615 time=370855781703 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=46 mono=23734770031919 sec=1765478767 nsec=250882044
        EventBatch gen=51 m=956077 time=370855785223 size=15
        ProcStatus dt=1 p=5 pstatus=2
        ProcStart dt=2 p=5 p_seq=1
...
        String id=75
        	data="runtime.bgsweep"
        String id=76
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mgcsweep.go"
        String id=77
        	data="runtime.forcegchelper"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (0.01s)
2025-12-11 19:57 go1.26-linux-386-longtest release-branch.go1.26@ae62a1bd runtime/trace.TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)
    subscribe_test.go:47: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=39 m=18446744073709551615 time=95723794757 size=25
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=111 mono=6126322871528 sec=1765843654 nsec=625077118
        EventBatch gen=39 m=1425757 time=95723794931 size=212
        ProcStatus dt=101 p=3 pstatus=1
        GoStatus dt=5 g=117 m=1425757 gstatus=2
...
        String id=63
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/tracecpu.go"
        String id=64
        	data="runtime.runFinalizers"
        String id=65
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mfinal.go"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (0.04s)
2025-12-11 19:57 go1.26-linux-amd64-clang15 release-branch.go1.26@ae62a1bd runtime/trace.TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (log) 
=== RUN   TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace)
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=50 m=18446744073709551615 time=2603004334 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=124 mono=166592285295 sec=1765839183 nsec=620295464
        EventBatch gen=50 m=26054 time=2603004597 size=248
        ProcStatus dt=106 p=3 pstatus=1
        GoStatus dt=4 g=127 m=26054 gstatus=2
...
        String id=70
        	data="main.main"
        String id=71
        	data="_testmain.go"
        String id=72
        	data="runtime.forcegchelper"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (0.02s)
2025-12-11 19:57 go1.26-linux-amd64_avx512 release-branch.go1.26@ae62a1bd runtime/trace.TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (log) 
=== RUN   TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace)
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=50 m=18446744073709551615 time=486185115023 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=49 mono=31115847364587 sec=1765839470 nsec=70430135
        EventBatch gen=50 m=1431076 time=486185119188 size=15
        ProcStatus dt=1 p=7 pstatus=1
        GoBlock dt=2 reason_string=16 stack=0
...
        String id=75
        	data="runtime/trace.(*FlightRecorder).WriteTo"
        String id=76
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/trace/flightrecorder.go"
        String id=77
        	data="runtime/trace_test.TestSubscribers.func5"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (0.03s)
2025-12-11 19:57 gotip-linux-amd64-newinliner go@ae62a1bd runtime/trace.TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (log) 
=== RUN   TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace)
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=50 m=18446744073709551615 time=1694542357 size=23
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=98 mono=108450717075 sec=1765483767 nsec=6138431
        EventBatch gen=50 m=19314 time=1694542513 size=198
        ProcStatus dt=96 p=3 pstatus=1
        GoStatus dt=2 g=75 m=19314 gstatus=2
...
        String id=75
        	data="testing.(*M).Run"
        String id=76
        	data="main.main"
        String id=77
        	data="_testmain.go"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (0.05s)
2025-12-11 19:57 gotip-linux-amd64-race go@ae62a1bd runtime/trace.TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (log) 
=== RUN   TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace)
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=50 m=18446744073709551615 time=91263584825 size=25
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=161 mono=5840869439068 sec=1765483543 nsec=248734881
        EventBatch gen=50 m=518005 time=91263591794 size=10
        ProcStatus dt=1 p=14 pstatus=1
        GoBlock dt=4 reason_string=16 stack=0
...
        String id=75
        	data="runtime/trace.(*FlightRecorder).WriteTo"
        String id=76
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/trace/flightrecorder.go"
        String id=77
        	data="runtime/trace_test.TestSubscribers.func5"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (0.10s)
2025-12-11 20:30 gotip-linux-arm64-race go@245bcdd4 runtime/trace.TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (log) 
=== RUN   TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace)
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=50 m=18446744073709551615 time=2460833522 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=48 mono=157493348499 sec=1765485549 nsec=623936739
        EventBatch gen=50 m=38150 time=2460837619 size=15
        ProcStatus dt=1 p=7 pstatus=1
        GoBlock dt=1 reason_string=16 stack=0
...
        String id=75
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mgc.go"
        String id=76
        	data="runtime.runFinalizers"
        String id=77
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mfinal.go"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (0.06s)
2025-12-11 20:30 gotip-linux-ppc64_power10 go@245bcdd4 runtime/trace.TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (log) 
=== RUN   TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace)
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=50 m=18446744073709551615 time=83885389432620 size=25
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=3 mono=5368664923687906 sec=1765486054 nsec=104966476
        EventBatch gen=50 m=3209891 time=83885389438589 size=10
        ProcStatus dt=2 p=1 pstatus=1
        GoBlock dt=5 reason_string=16 stack=0
...
        String id=75
        	data="_testmain.go"
        String id=76
        	data="runtime.updateMaxProcsGoroutine"
        String id=77
        	data="runtime.forcegchelper"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (0.03s)
2025-12-12 17:04 go1.26-linux-amd64-asan-clang15 release-branch.go1.26@e8a83788 runtime/trace.TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (log) 
=== RUN   TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace)
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=50 m=18446744073709551615 time=2439767100 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=112 mono=156145101562 sec=1765839602 nsec=666213354
        EventBatch gen=50 m=24554 time=2439774735 size=6
        ProcStatus dt=1 p=14 pstatus=1
        ProcStop dt=2
...
        String id=75
        	data="runtime/trace.(*FlightRecorder).WriteTo"
        String id=76
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/trace/flightrecorder.go"
        String id=77
        	data="runtime/trace_test.TestSubscribers.func5"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (0.18s)
2025-12-12 17:04 gotip-linux-arm64-asan-clang15 go@e8a83788 runtime/trace.TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)
    subscribe_test.go:47: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=39 m=18446744073709551615 time=4997291388 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=44 mono=319826651610 sec=1765559824 nsec=970134930
        EventBatch gen=39 m=65467 time=4997295732 size=15
        ProcStatus dt=1 p=7 pstatus=1
        GoBlock dt=2 reason_string=16 stack=0
...
        String id=63
        	data="runtime.gcBgMarkWorker"
        String id=64
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mgc.go"
        String id=65
        	data="runtime.(*traceAdvancerState).start.func1"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (0.06s)
2025-12-12 17:04 gotip-linux-arm64-race go@e8a83788 runtime/trace.TestSubscribers/start(flight)_start(trace)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(flight)_start(trace)_stop(trace)_stop(flight)
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=34 m=18446744073709551615 time=2358140426 size=23
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=42 mono=150920989964 sec=1765559665 nsec=58912884
        EventBatch gen=34 m=35312 time=2358144344 size=10
        ProcStatus dt=1 p=7 pstatus=1
        GoBlock dt=3 reason_string=16 stack=0
...
        String id=63
        	data="runtime.bgscavenge"
        String id=64
        	data="runtime/trace_test.TestSubscribers"
        String id=65
        	data="runtime/trace.(*traceMultiplexer).startLocked.func1"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(flight)_start(trace)_stop(trace)_stop(flight) (0.05s)
2025-12-12 19:09 go1.26-linux-386-longtest release-branch.go1.26@8d312445 runtime/trace.TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)
    subscribe_test.go:47: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=39 m=18446744073709551615 time=70377302422 size=26
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=184 mono=4504147366756 sec=1765842015 nsec=429106003
        EventBatch gen=39 m=778760 time=70377303290 size=43
        ProcStatus dt=144 p=13 pstatus=1
        GoStatus dt=5 g=133 m=778760 gstatus=1
...
        String id=63
        	data="runtime.bgscavenge"
        String id=64
        	data="runtime.gcBgMarkWorker"
        String id=65
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mgc.go"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (0.05s)
2025-12-12 19:09 go1.26-linux-amd64-asan-clang15 release-branch.go1.26@8d312445 runtime/trace.TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (log) 
=== RUN   TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace)
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=50 m=18446744073709551615 time=3570729575 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=114 mono=228526700120 sec=1765839251 nsec=527185559
        EventBatch gen=50 m=24316 time=3570737073 size=10
        ProcStatus dt=1 p=14 pstatus=1
        GoBlock dt=4 reason_string=16 stack=0
...
        String id=75
        	data="runtime.lock"
        String id=76
        	data="runtime.traceStartReadCPU.func1"
        String id=77
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/tracecpu.go"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (0.12s)
2025-12-12 19:09 gotip-linux-arm64-boringcrypto go@8d312445 runtime/trace.TestSubscribers/start(flight)_start(trace)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(flight)_start(trace)_stop(trace)_stop(flight)
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=34 m=18446744073709551615 time=1290315617 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=37 mono=82580201851 sec=1765567061 nsec=711958771
        EventBatch gen=34 m=9387 time=1290315672 size=185
        ProcStatus dt=36 p=2 pstatus=1
        GoStatus dt=2 g=120 m=9387 gstatus=2
...
        String id=63
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mgc.go"
        String id=64
        	data="runtime.traceStartReadCPU.func1"
        String id=65
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/tracecpu.go"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(flight)_start(trace)_stop(trace)_stop(flight) (0.03s)
2025-12-12 19:10 go1.26-linux-386-softfloat release-branch.go1.26@34af879d runtime/trace.TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)
    subscribe_test.go:47: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=39 m=18446744073709551615 time=14292924339 size=25
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=129 mono=914747165889 sec=1765838775 nsec=591292836
        EventBatch gen=39 m=139497 time=14292924885 size=42
        ProcStatus dt=123 p=13 pstatus=1
        GoStatus dt=4 g=138 m=139497 gstatus=1
...
        String id=63
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mgcsweep.go"
        String id=64
        	data="runtime.traceStartReadCPU.func1"
        String id=65
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/tracecpu.go"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (0.02s)
2025-12-12 19:10 gotip-linux-386-softfloat go@34af879d runtime/trace.TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)
    subscribe_test.go:47: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=40 m=18446744073709551615 time=8509657279 size=23
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=7 mono=544618066276 sec=1765567444 nsec=205717133
        EventBatch gen=40 m=63539 time=8509666496 size=15
        ProcStatus dt=3 p=15 pstatus=1
        GoBlock dt=4 reason_string=16 stack=0
...
        String id=63
        	data="runtime/trace_test.TestSubscribers"
        String id=64
        	data="runtime.traceStartReadCPU.func1"
        String id=65
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/tracecpu.go"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (0.03s)
2025-12-12 19:10 gotip-linux-386_debiansid go@34af879d runtime/trace.TestSubscribers/start(flight)_start(trace)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(flight)_start(trace)_stop(trace)_stop(flight)
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=34 m=18446744073709551615 time=2411712806 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=194 mono=154349631943 sec=1765567612 nsec=168066270
        EventBatch gen=34 m=35727 time=2411713071 size=253
        ProcStatus dt=107 p=12 pstatus=1
        GoStatus dt=5 g=145 m=35727 gstatus=2
...
        String id=63
        	data="runtime.updateMaxProcsGoroutine"
        String id=64
        	data="runtime.traceStartReadCPU.func1"
        String id=65
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/tracecpu.go"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(flight)_start(trace)_stop(trace)_stop(flight) (0.08s)
2025-12-12 19:10 gotip-linux-amd64-nogreenteagc go@34af879d runtime/trace.TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (log) 
=== RUN   TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace)
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=50 m=18446744073709551615 time=3572345934 size=23
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=123 mono=228630147647 sec=1765567346 nsec=107000294
        EventBatch gen=50 m=36432 time=3572352152 size=10
        ProcStatus dt=1 p=14 pstatus=2
        ProcStart dt=1 p=14 p_seq=1
...
        String id=75
        	data="main.main"
        String id=76
        	data="_testmain.go"
        String id=77
        	data="runtime.(*traceAdvancerState).start.func1"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(flight)_start(trace)_stop(flight)_stop(trace) (0.07s)
2025-12-12 19:10 gotip-linux-riscv64 go@34af879d runtime/trace.TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)
    subscribe_test.go:47: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=39 m=18446744073709551615 time=48247239523996 size=26
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=16 mono=3087823329536804 sec=1765588306 nsec=745245388
        EventBatch gen=39 m=3351466 time=48247239534012 size=38
        ProcStatus dt=16 p=2 pstatus=1
        GoBlock dt=1 reason_string=16 stack=0
...
        String id=63
        	data="runtime.gcBgMarkWorker"
        String id=64
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mgc.go"
        String id=65
        	data="runtime/trace_test.TestSubscribers"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (0.03s)
2025-12-12 20:00 go1.26-linux-amd64-boringcrypto release-branch.go1.26@8f45611e runtime/trace.TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)
    subscribe_test.go:47: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=39 m=18446744073709551615 time=16410480703 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=118 mono=1050270772503 sec=1765838578 nsec=270979202
        EventBatch gen=39 m=182753 time=16410487802 size=15
        ProcStatus dt=1 p=15 pstatus=1
        GoBlock dt=2 reason_string=16 stack=0
...
        String id=63
        	data="runtime.forcegchelper"
        String id=64
        	data="runtime.runFinalizers"
        String id=65
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mfinal.go"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (0.05s)
2025-12-12 20:00 go1.26-linux-amd64-longtest-race release-branch.go1.26@8f45611e runtime/trace.TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight)
    subscribe_test.go:47: unexpected error reading trace for flightRecorder: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=39 m=18446744073709551615 time=77343048424 size=25
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=116 mono=4949955106517 sec=1765842713 nsec=476260957
        EventBatch gen=39 m=774546 time=77343048621 size=215
        ProcStatus dt=112 p=3 pstatus=1
        GoStatus dt=2 g=122 m=774546 gstatus=2
...
        String id=63
        	data="runtime.updateMaxProcsGoroutine"
        String id=64
        	data="runtime.runFinalizers"
        String id=65
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mfinal.go"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(trace)_start(flight)_stop(trace)_stop(flight) (0.05s)
2025-12-12 20:00 gotip-linux-ppc64_power10 go@8f45611e runtime/trace.TestSubscribers/start(flight)_start(trace)_stop(trace)_stop(flight) (log) 
=== RUN   TestSubscribers/start(flight)_start(trace)_stop(trace)_stop(flight)
    subscribe_test.go:47: unexpected error reading trace for tracer: expected a goroutine but didn't have one
    helpers.go:38: Trace Go1.26
        EventBatch gen=34 m=18446744073709551615 time=85200476667796 size=26
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=49 mono=5452830506742117 sec=1765570219 nsec=688020682
        EventBatch gen=34 m=175800 time=85200476667887 size=152
        ProcStatus dt=45 p=3 pstatus=1
        GoStatus dt=1 g=54 m=175800 gstatus=2
...
        String id=63
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mgc.go"
        String id=64
        	data="runtime.runFinalizers"
        String id=65
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mfinal.go"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
--- FAIL: TestSubscribers/start(flight)_start(trace)_stop(trace)_stop(flight) (0.01s)

— watchflakes

gopherbot avatar Dec 18 '25 18:12 gopherbot