Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

runtime: mayMoreStackPreempt failures #55160

Open
rsc opened this issue Sep 20, 2022 · 60 comments
Open

runtime: mayMoreStackPreempt failures #55160

rsc opened this issue Sep 20, 2022 · 60 comments
Assignees
@mknyszek
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. early-in-cycle A change that should be done early in the 3 month dev cycle. NeedsFix The path to resolution is known, but the work has not been done.
Milestone
Go1.22

Comments

@rsc
Copy link
Contributor

rsc commented Sep 20, 2022 •
edited by cherrymui 

#!watchflakes
default <- section == "maymorestack=mayMoreStackPreempt" || pkg == "runtime:mayMoreStackPreempt"

Intermittent failures in the new mayMoreStackPreempt. This bug will replace #54778 and #55073.
@gopherbot gopherbot added the compiler/runtime Issues related to the Go compiler and/or runtime. label Sep 20, 2022
@rsc rsc added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Sep 20, 2022
@gopherbot
Copy link

gopherbot commented Sep 20, 2022 •
edited by rsc

Found new matching flaky dashboard failures.

2022-09-02 19:08 linux-386-longtest go@dbf442b1 runtime.TestVDSO (log) 
--- FAIL: TestVDSO (0.12s)
    testenv.go:468: [/workdir/tmp/go-build505441303/testprog.exe SignalInVDSO] exit status: signal: segmentation fault (core dumped)
    crash_test.go:144: output:


        wanted:
        success
2022-09-02 19:08 linux-386-longtest go@b91e3737 runtime.TestVDSO (log) 
--- FAIL: TestVDSO (0.07s)
    testenv.go:468: [/workdir/tmp/go-build4244626990/testprog.exe SignalInVDSO] exit status: signal: segmentation fault (core dumped)
    crash_test.go:144: output:


        wanted:
        success
2022-09-02 19:09 linux-386-longtest go@55ca6a20 runtime.TestVDSO (log) 
--- FAIL: TestVDSO (0.47s)
    testenv.go:468: [/workdir/tmp/go-build771899026/testprog.exe SignalInVDSO] exit status: signal: segmentation fault (core dumped)
    crash_test.go:144: output:


        wanted:
        success
2022-09-02 19:22 linux-386-longtest go@0fda8b19 runtime.TestVDSO (log) 
--- FAIL: TestVDSO (0.94s)
    testenv.go:468: [/workdir/tmp/go-build428612025/testprog.exe SignalInVDSO] exit status: signal: segmentation fault (core dumped)
    crash_test.go:144: output:


        wanted:
        success
2022-09-02 19:22 linux-386-longtest go@0fda8b19 runtime.TestCgoPprofCallback (log) 
--- FAIL: TestCgoPprofCallback (0.76s)
    testenv.go:468: [/workdir/tmp/go-build428612025/testprogcgo.exe CgoPprofCallback] exit status: signal: segmentation fault (core dumped)
    crash_cgo_test.go:228: expected "OK\n" got
2022-09-03 15:45 linux-386-longtest go@f798dc68 runtime.TestVDSO (log) 
--- FAIL: TestVDSO (0.90s)
    testenv.go:468: [/workdir/tmp/go-build1281399444/testprog.exe SignalInVDSO] exit status: signal: segmentation fault (core dumped)
    crash_test.go:144: output:


        wanted:
        success
2022-09-03 18:21 linux-386-longtest go@a0f05823 runtime.TestVDSO (log) 
--- FAIL: TestVDSO (0.46s)
    testenv.go:468: [/workdir/tmp/go-build2488815781/testprog.exe SignalInVDSO] exit status: signal: segmentation fault (core dumped)
    crash_test.go:144: output:


        wanted:
        success
2022-09-03 18:21 linux-386-longtest go@a0f05823 runtime.TestCgoPprofCallback (log) 
--- FAIL: TestCgoPprofCallback (0.50s)
    testenv.go:468: [/workdir/tmp/go-build2488815781/testprogcgo.exe CgoPprofCallback] exit status: signal: segmentation fault (core dumped)
    crash_cgo_test.go:228: expected "OK\n" got
2022-09-04 04:17 linux-386-longtest go@535fe2b2 runtime.TestVDSO (log) 
--- FAIL: TestVDSO (0.50s)
    testenv.go:468: [/workdir/tmp/go-build3332541852/testprog.exe SignalInVDSO] exit status: signal: segmentation fault (core dumped)
    crash_test.go:144: output:


        wanted:
        success
2022-09-05 07:14 linux-386-longtest go@3fbcf05d runtime.TestVDSO (log) 
--- FAIL: TestVDSO (0.14s)
    testenv.go:468: [/workdir/tmp/go-build2637521369/testprog.exe SignalInVDSO] exit status: signal: segmentation fault (core dumped)
    crash_test.go:144: output:


        wanted:
        success
2022-09-05 07:17 linux-386-longtest go@4e7e7ae1 runtime.TestVDSO (log) 
--- FAIL: TestVDSO (0.21s)
    testenv.go:468: [/workdir/tmp/go-build436015263/testprog.exe SignalInVDSO] exit status: signal: segmentation fault (core dumped)
    crash_test.go:144: output:


        wanted:
        success
2022-09-05 08:08 linux-386-longtest go@4ad55cd9 runtime.TestVDSO (log) 
--- FAIL: TestVDSO (0.91s)
    testenv.go:468: [/workdir/tmp/go-build596332148/testprog.exe SignalInVDSO] exit status: signal: segmentation fault (core dumped)
    crash_test.go:144: output:


        wanted:
        success
2022-09-05 08:08 linux-386-longtest go@af7f4176 runtime.TestVDSO (log) 
--- FAIL: TestVDSO (0.57s)
    testenv.go:468: [/workdir/tmp/go-build2390128426/testprog.exe SignalInVDSO] exit status: signal: segmentation fault (core dumped)
    crash_test.go:144: output:


        wanted:
        success
2022-09-05 08:28 linux-386-longtest go@bd5595d7 runtime.TestVDSO (log) 
--- FAIL: TestVDSO (0.36s)
    testenv.go:468: [/workdir/tmp/go-build202959485/testprog.exe SignalInVDSO] exit status: signal: segmentation fault (core dumped)
    crash_test.go:144: output:


        wanted:
        success
2022-09-05 08:28 linux-386-longtest go@bd5595d7 runtime.TestCgoPprofCallback (log) 
--- FAIL: TestCgoPprofCallback (1.14s)
    testenv.go:468: [/workdir/tmp/go-build202959485/testprogcgo.exe CgoPprofCallback] exit status: signal: segmentation fault (core dumped)
    crash_cgo_test.go:228: expected "OK\n" got
2022-09-05 21:39 linux-386-longtest go@4c1ca42a runtime.TestVDSO (log) 
--- FAIL: TestVDSO (0.43s)
    testenv.go:468: [/workdir/tmp/go-build2185756284/testprog.exe SignalInVDSO] exit status: signal: segmentation fault (core dumped)
    crash_test.go:144: output:


        wanted:
        success
2022-09-06 14:44 linux-386-longtest go@a60a3dc5 runtime.TestCgoPprofCallback (log) 
--- FAIL: TestCgoPprofCallback (0.37s)
    testenv.go:468: [/workdir/tmp/go-build1980997514/testprogcgo.exe CgoPprofCallback] exit status: signal: segmentation fault (core dumped)
    crash_cgo_test.go:228: expected "OK\n" got
2022-09-06 15:44 linux-386-longtest go@32f68b5a runtime.TestVDSO (log) 
--- FAIL: TestVDSO (0.11s)
    testenv.go:468: [/workdir/tmp/go-build1672150549/testprog.exe SignalInVDSO] exit status: signal: segmentation fault (core dumped)
    crash_test.go:144: output:


        wanted:
        success
2022-09-06 15:44 linux-386-longtest go@32f68b5a runtime.TestCgoPprofCallback (log) 
--- FAIL: TestCgoPprofCallback (0.40s)
    testenv.go:468: [/workdir/tmp/go-build1672150549/testprogcgo.exe CgoPprofCallback] exit status: signal: segmentation fault (core dumped)
    crash_cgo_test.go:228: expected "OK\n" got
2022-09-06 15:48 linux-386-longtest go@07b19bf5 runtime.TestVDSO (log) 
--- FAIL: TestVDSO (0.15s)
    testenv.go:468: [/workdir/tmp/go-build2315874385/testprog.exe SignalInVDSO] exit status: signal: segmentation fault (core dumped)
    crash_test.go:144: output:


        wanted:
        success
2022-09-02 19:08 linux-amd64-longtest go@dbf442b1 runtime.TestCgoPprofCallback (log) 
--- FAIL: TestCgoPprofCallback (0.87s)
    testenv.go:468: [/workdir/tmp/go-build2891867005/testprogcgo.exe CgoPprofCallback] exit status: signal: segmentation fault (core dumped)
    crash_cgo_test.go:228: expected "OK\n" got
2022-09-02 19:08 linux-amd64-longtest go@dbf442b1 runtime.TestCgoCCodeSIGPROF (log) 
--- FAIL: TestCgoCCodeSIGPROF (0.32s)
    testenv.go:468: [/workdir/tmp/go-build2891867005/testprogcgo.exe CgoCCodeSIGPROF] exit status: signal: segmentation fault (core dumped)
    crash_cgo_test.go:215: expected "OK\n" got
2022-09-02 19:08 linux-amd64-longtest go@b91e3737 runtime.TestCgoPprofCallback (log) 
--- FAIL: TestCgoPprofCallback (3.24s)
    testenv.go:468: [/workdir/tmp/go-build687456613/testprogcgo.exe CgoPprofCallback] exit status: signal: segmentation fault (core dumped)
    crash_cgo_test.go:228: expected "OK\n" got
2022-09-03 15:45 linux-amd64-longtest go@f798dc68 runtime.TestCgoPprofCallback (log) 
--- FAIL: TestCgoPprofCallback (2.81s)
    testenv.go:468: [/workdir/tmp/go-build4078786360/testprogcgo.exe CgoPprofCallback] exit status: signal: segmentation fault (core dumped)
    crash_cgo_test.go:228: expected "OK\n" got
2022-09-03 18:21 linux-amd64-longtest go@a0f05823 runtime.TestCgoPprofCallback (log) 
--- FAIL: TestCgoPprofCallback (0.97s)
    testenv.go:468: [/workdir/tmp/go-build956381195/testprogcgo.exe CgoPprofCallback] exit status: signal: segmentation fault (core dumped)
    crash_cgo_test.go:228: expected "OK\n" got
2022-09-04 04:17 linux-amd64-longtest go@535fe2b2 runtime.TestCgoPprofCallback (log) 
--- FAIL: TestCgoPprofCallback (3.27s)
    testenv.go:468: [/workdir/tmp/go-build2525853216/testprogcgo.exe CgoPprofCallback] exit status: signal: segmentation fault (core dumped)
    crash_cgo_test.go:228: expected "OK\n" got
2022-09-05 08:12 linux-amd64-longtest go@67e65424 runtime.TestCgoPprofCallback (log) 
--- FAIL: TestCgoPprofCallback (0.42s)
    testenv.go:468: [/workdir/tmp/go-build3155816942/testprogcgo.exe CgoPprofCallback] exit status: signal: segmentation fault (core dumped)
    crash_cgo_test.go:228: expected "OK\n" got
2022-09-05 08:12 linux-amd64-longtest go@67e65424 runtime.TestCgoCCodeSIGPROF (log) 
--- FAIL: TestCgoCCodeSIGPROF (0.18s)
    testenv.go:468: [/workdir/tmp/go-build3155816942/testprogcgo.exe CgoCCodeSIGPROF] exit status: signal: segmentation fault (core dumped)
    crash_cgo_test.go:215: expected "OK\n" got
2022-09-05 21:39 linux-amd64-longtest go@4c1ca42a runtime.TestCgoPprofCallback (log) 
--- FAIL: TestCgoPprofCallback (0.67s)
    testenv.go:468: [/workdir/tmp/go-build1237047364/testprogcgo.exe CgoPprofCallback] exit status: signal: segmentation fault (core dumped)
    crash_cgo_test.go:228: expected "OK\n" got
2022-09-06 11:14 linux-amd64-longtest go@1c504843 runtime.TestCgoPprofCallback (log) 
--- FAIL: TestCgoPprofCallback (2.60s)
    testenv.go:468: [/workdir/tmp/go-build4096451727/testprogcgo.exe CgoPprofCallback] exit status: signal: segmentation fault (core dumped)
    crash_cgo_test.go:228: expected "OK\n" got

— watchflakes

@rsc
Copy link
Contributor Author

rsc commented Sep 20, 2022

These were coming in multiple times per day and have now stopped for almost two weeks. Closing.

@rsc rsc closed this as completed Sep 20, 2022
@gopherbot
Copy link

gopherbot commented Sep 20, 2022 •
edited

Found new matching flaky dashboard failures for:

    #!watchflakes
    post <- section == "maymorestack=mayMoreStackPreempt"
2022-08-23 03:09 windows-amd64-longtest go@0a52d806 (log) 
XXXBANNERXXX:Test execution environment.
# GOARCH: amd64
# CPU: Intel(R) Xeon(R) CPU @ 2.20GHz
# GOOS: windows
# OS Version: 10.0.14393
fatal error: advapi32.dll not found
runtime: panic before malloc heap initialized
go: error obtaining buildID for go tool compile: exit status 0xc0000005

go tool dist: FAILED: go list -f={{if .Stale}}	STALE {{.ImportPath}}: {{.StaleReason}}{{end}} std: exit status 1

— watchflakes

@gopherbot gopherbot reopened this Sep 20, 2022
@rsc rsc closed this as completed Sep 20, 2022
@rsc rsc changed the title runtime: flaky failures with mayMoreStackPreempt runtime: mayMoreStackPreempt failures Sep 20, 2022
@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    post <- section == "maymorestack=mayMoreStackPreempt"
2022-09-06 15:48 linux-amd64-longtest go@07b19bf5 runtime.TestCgoPprofCallback (log) 
--- FAIL: TestCgoPprofCallback (0.58s)
    testenv.go:468: [/workdir/tmp/go-build3380638690/testprogcgo.exe CgoPprofCallback] exit status: signal: segmentation fault (core dumped)
    crash_cgo_test.go:228: expected "OK\n" got

— watchflakes

@gopherbot gopherbot reopened this Nov 4, 2022
@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    post <- section == "maymorestack=mayMoreStackPreempt"
2022-10-31 21:00 linux-386-longtest go@ec0b5402 runtime.TestCgoTracebackContextPreemption (log) 
--- FAIL: TestCgoTracebackContextPreemption (60.06s)
    testenv.go:454: context deadline exceeded: terminating command: /workdir/tmp/go-build82099082/testprogcgo.exe TracebackContextPreemption
    crash_test.go:59: /workdir/tmp/go-build82099082/testprogcgo.exe TracebackContextPreemption: exit status 2
    crash_cgo_test.go:284: expected "OK\n" got SIGQUIT: quit
        PC=0x80b7eff m=0 sigcode=0

        eax    0x0
        ebx    0x8296d10
        ecx    0x80
        edx    0x0
        edi    0x0
        esi    0x0
        ebp    0x0
        esp    0xffb85348
        eip    0x80b7eff
        eflags 0x286
        cs     0x23
        fs     0x0
        gs     0x63
2022-11-02 18:19 linux-386-longtest go@07a70bca runtime.TestCgoTracebackContextPreemption (log) 
--- FAIL: TestCgoTracebackContextPreemption (60.06s)
    exec.go:152: context deadline exceeded: terminating command: /workdir/tmp/go-build3697616094/testprogcgo.exe TracebackContextPreemption
    crash_test.go:59: /workdir/tmp/go-build3697616094/testprogcgo.exe TracebackContextPreemption: exit status 2
    crash_cgo_test.go:284: expected "OK\n" got SIGQUIT: quit
        PC=0x80b7eff m=0 sigcode=0

        eax    0xfffffff5
        ebx    0x8296d10
        ecx    0x80
        edx    0x0
        edi    0x0
        esi    0x0
        ebp    0x0
        esp    0xffb80458
        eip    0x80b7eff
        eflags 0x286
        cs     0x23
        fs     0x0
        gs     0x63
2022-11-03 15:17 linux-386-longtest go@1bfb51f8 runtime.TestCgoTracebackContextPreemption (log) 
--- FAIL: TestCgoTracebackContextPreemption (60.06s)
    exec.go:152: context deadline exceeded: terminating command: /workdir/tmp/go-build368093199/testprogcgo.exe TracebackContextPreemption
    crash_test.go:59: /workdir/tmp/go-build368093199/testprogcgo.exe TracebackContextPreemption: exit status 2
    crash_cgo_test.go:284: expected "OK\n" got SIGQUIT: quit
        PC=0x80b7eff m=0 sigcode=0

        eax    0x0
        ebx    0x8296d10
        ecx    0x80
        edx    0x0
        edi    0x0
        esi    0x0
        ebp    0x0
        esp    0xffbb95b4
        eip    0x80b7eff
        eflags 0x286
        cs     0x23
        fs     0x0
        gs     0x63
2022-11-03 15:30 linux-386-longtest go@e81263c7 runtime.TestCgoTracebackContextPreemption (log) 
--- FAIL: TestCgoTracebackContextPreemption (60.06s)
    exec.go:152: context deadline exceeded: terminating command: /workdir/tmp/go-build1088517119/testprogcgo.exe TracebackContextPreemption
    crash_test.go:59: /workdir/tmp/go-build1088517119/testprogcgo.exe TracebackContextPreemption: exit status 2
    crash_cgo_test.go:284: expected "OK\n" got SIGQUIT: quit
        PC=0x80b7eff m=0 sigcode=0

        eax    0x1
        ebx    0x9c80310
        ecx    0x81
        edx    0x1
        edi    0x0
        esi    0x0
        ebp    0x0
        esp    0xffdec718
        eip    0x80b7eff
        eflags 0x292
        cs     0x23
        fs     0x0
        gs     0x63
2022-11-03 17:01 linux-386-longtest go@667c53e1 runtime.TestCgoTracebackContextPreemption (log) 
--- FAIL: TestCgoTracebackContextPreemption (60.06s)
    exec.go:152: context deadline exceeded: terminating command: /workdir/tmp/go-build1853768809/testprogcgo.exe TracebackContextPreemption
    crash_test.go:59: /workdir/tmp/go-build1853768809/testprogcgo.exe TracebackContextPreemption: exit status 2
    crash_cgo_test.go:284: expected "OK\n" got SIGQUIT: quit
        PC=0x80b7eff m=0 sigcode=0

        eax    0x0
        ebx    0x8296d10
        ecx    0x80
        edx    0x0
        edi    0x0
        esi    0x0
        ebp    0x0
        esp    0xffcd9648
        eip    0x80b7eff
        eflags 0x286
        cs     0x23
        fs     0x0
        gs     0x63
2022-11-03 17:40 linux-386-longtest go@7abc8a2e runtime.TestCgoTracebackContextPreemption (log) 
--- FAIL: TestCgoTracebackContextPreemption (60.06s)
    exec.go:152: context deadline exceeded: terminating command: /workdir/tmp/go-build3148955378/testprogcgo.exe TracebackContextPreemption
    crash_test.go:59: /workdir/tmp/go-build3148955378/testprogcgo.exe TracebackContextPreemption: exit status 2
    crash_cgo_test.go:284: expected "OK\n" got SIGQUIT: quit
        PC=0x80b7eff m=0 sigcode=0

        eax    0x0
        ebx    0x8296d10
        ecx    0x80
        edx    0x0
        edi    0x0
        esi    0x0
        ebp    0x0
        esp    0xffa0a878
        eip    0x80b7eff
        eflags 0x286
        cs     0x23
        fs     0x0
        gs     0x63
2022-11-03 18:33 linux-386-longtest go@44cabb80 runtime.TestCgoTracebackContextPreemption (log) 
--- FAIL: TestCgoTracebackContextPreemption (60.06s)
    exec.go:152: context deadline exceeded: terminating command: /workdir/tmp/go-build2865322188/testprogcgo.exe TracebackContextPreemption
    crash_test.go:59: /workdir/tmp/go-build2865322188/testprogcgo.exe TracebackContextPreemption: exit status 2
    crash_cgo_test.go:284: expected "OK\n" got SIGQUIT: quit
        PC=0x80b7efd m=0 sigcode=0

        eax    0xf0
        ebx    0x8296d10
        ecx    0x80
        edx    0x0
        edi    0x0
        esi    0x0
        ebp    0x0
        esp    0xfff0a0e8
        eip    0x80b7efd
        eflags 0x286
        cs     0x23
        fs     0x0
        gs     0x63
2022-11-03 19:34 linux-386-longtest go@3511c822 runtime.TestCgoTracebackContextPreemption (log) 
--- FAIL: TestCgoTracebackContextPreemption (60.06s)
    exec.go:152: context deadline exceeded: terminating command: /workdir/tmp/go-build1678369203/testprogcgo.exe TracebackContextPreemption
    crash_test.go:59: /workdir/tmp/go-build1678369203/testprogcgo.exe TracebackContextPreemption: exit status 2
    crash_cgo_test.go:284: expected "OK\n" got SIGQUIT: quit
        PC=0x80b7eff m=0 sigcode=0

        eax    0x0
        ebx    0x8296d10
        ecx    0x80
        edx    0x0
        edi    0x0
        esi    0x0
        ebp    0x0
        esp    0xffac9090
        eip    0x80b7eff
        eflags 0x286
        cs     0x23
        fs     0x0
        gs     0x63
2022-11-03 19:59 linux-386-longtest go@d031e9e0 runtime.TestCgoTracebackContextPreemption (log) 
--- FAIL: TestCgoTracebackContextPreemption (60.06s)
    exec.go:152: context deadline exceeded: terminating command: /workdir/tmp/go-build3827993796/testprogcgo.exe TracebackContextPreemption
    crash_test.go:59: /workdir/tmp/go-build3827993796/testprogcgo.exe TracebackContextPreemption: exit status 2
    crash_cgo_test.go:284: expected "OK\n" got SIGQUIT: quit
        PC=0x80b7d6f m=0 sigcode=0

        eax    0x1
        ebx    0x9846e50
        ecx    0x81
        edx    0x1
        edi    0x0
        esi    0x0
        ebp    0x0
        esp    0xff9e7c18
        eip    0x80b7d6f
        eflags 0x292
        cs     0x23
        fs     0x0
        gs     0x63

— watchflakes

@mknyszek mknyszek added this to the Go1.20 milestone Nov 9, 2022
@mknyszek mknyszek self-assigned this Nov 9, 2022
@mknyszek mknyszek removed their assignment Nov 23, 2022
@cherrymui
Copy link
Member

No more failure for a while. Probably fixed by CL https://golang.org/cl/447495 , which is submitted at Nov. 4, so the time seems to match.

@gopherbot gopherbot reopened this Feb 2, 2023
@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    post <- section == "maymorestack=mayMoreStackPreempt"
2023-01-25 16:38 linux-arm64-longtest go@1d3088ef runtime.TestCrashDumpsAllThreads (log) 
panic: test timed out after 50m0s
running tests:
	TestCrashDumpsAllThreads (49m39s)

runtime.gopark(0x4362a0?, 0xffff64c08d00?, 0x2?, 0x1b?, 0x5?)
	/tmp/workdir/go/src/runtime/proc.go:381 +0x124 fp=0x4000bbfcb0 sp=0x4000bbfc90 pc=0x53e84
runtime.netpollblock(0xffff64c08ce8?, 0x72?, 0x0?)
	/tmp/workdir/go/src/runtime/netpoll.go:527 +0x190 fp=0x4000bbfcf0 sp=0x4000bbfcb0 pc=0x4b9b0
internal/poll.runtime_pollWait(0xffff64c08ce8, 0x72)
	/tmp/workdir/go/src/runtime/netpoll.go:306 +0xd0 fp=0x4000bbfd20 sp=0x4000bbfcf0 pc=0x8da60
internal/poll.(*pollDesc).wait(0x4a1470?, 0x6a05c0?, 0x1)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:84 +0x28 fp=0x4000bbfd50 sp=0x4000bbfd20 pc=0xc0108
internal/poll.(*pollDesc).waitRead(...)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0x4000981f80, {0x4000bbfea7, 0x1, 0x1})
	/tmp/workdir/go/src/internal/poll/fd_unix.go:167 +0x200 fp=0x4000bbfdf0 sp=0x4000bbfd50 pc=0xc0df0
os.(*File).read(...)
	/tmp/workdir/go/src/os/file_posix.go:31
os.(*File).Read(0x40026ae180, {0x4000bbfea7?, 0x4000bbff30?, 0x1?})
	/tmp/workdir/go/src/os/file.go:118 +0x58 fp=0x4000bbfe50 sp=0x4000bbfdf0 pc=0xc55c8
runtime_test.TestCrashDumpsAllThreads(0x4000e0fba0)
	/tmp/workdir/go/src/runtime/crash_unix_test.go:117 +0x4ac fp=0x4000bbff60 sp=0x4000bbfe50 pc=0x2c235c
testing.tRunner(0x4000e0fba0, 0x437308)
2023-02-01 21:30 linux-amd64-longtest go@cda461bb runtime.TestCrashDumpsAllThreads (log) 
panic: test timed out after 50m0s
running tests:
	TestCrashDumpsAllThreads (49m41s)

runtime.gopark(0x83f3d8?, 0x7f22a44dab20?, 0x2?, 0x1b?, 0x5?)
	/workdir/go/src/runtime/proc.go:381 +0x110 fp=0xc000a17cf8 sp=0xc000a17cd8 pc=0x440f30
runtime.netpollblock(0x7f22a44dab08?, 0x72?, 0x0?)
	/workdir/go/src/runtime/netpoll.go:527 +0x117 fp=0xc000a17d30 sp=0xc000a17cf8 pc=0x4391d7
internal/poll.runtime_pollWait(0x7f22a44dab08, 0x72)
	/workdir/go/src/runtime/netpoll.go:306 +0xa5 fp=0xc000a17d50 sp=0xc000a17d30 pc=0x4778a5
internal/poll.(*pollDesc).wait(0x8a7c60?, 0xaa75c8?, 0x1)
	/workdir/go/src/internal/poll/fd_poll_runtime.go:84 +0x27 fp=0xc000a17d78 sp=0xc000a17d50 pc=0x4a8c67
internal/poll.(*pollDesc).waitRead(...)
	/workdir/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc0007b96e0, {0xc000a17eaf, 0x1, 0x1})
	/workdir/go/src/internal/poll/fd_unix.go:167 +0x27a fp=0xc000a17e10 sp=0xc000a17d78 pc=0x4a997a
os.(*File).read(...)
	/workdir/go/src/os/file_posix.go:31
os.(*File).Read(0xc00238e190, {0xc000a17eaf?, 0xc000985f38?, 0x1?})
	/workdir/go/src/os/file.go:118 +0x4c fp=0xc000a17e68 sp=0xc000a17e10 pc=0x4ae5cc
runtime_test.TestCrashDumpsAllThreads(0xc000b17a00)
	/workdir/go/src/runtime/crash_unix_test.go:117 +0x579 fp=0xc000a17f70 sp=0xc000a17e68 pc=0x6d0ef9
testing.tRunner(0xc000b17a00, 0x8404c8)

— watchflakes

@dmitshur dmitshur modified the milestones: Go1.20, Backlog Feb 2, 2023
@prattmic
Copy link
Member

cc @aclements

These timeouts blocked release branch CLs as flakes; we should get them fixed or skipped.

@aclements
Copy link
Member

aclements commented Feb 15, 2023 •
edited

This reproduces pretty quickly on my linux/amd64 laptop with:

cd runtime
go test -c
GOFLAGS="-gcflags=runtime=-d=maymorestack=runtime.mayMoreStackPreempt -gcflags=runtime/testdata/...=" stress2 ./runtime.test -test.run=CrashDumpsAllThreads -test.timeout=30m

Of course, my usual first step would be to send it a SIGQUIT and see what's happening, but that's exactly what fails in this test. 😛 I haven't debugged yet. gdb may hold answers.

For reference, I initially tried running the testprog directly with the below script before I realized there are various pipes and signals involved in running this test. We might still need to reproduce those, but I'm hoping we can debug this through the test driver.

cd runtime/testdata/testprog
GOFLAGS="-gcflags=runtime=-d=maymorestack=runtime.mayMoreStackPreempt -gcflags=runtime/testdata/...=" go build
# Expects to write to FD 3 and then get a SIGQUIT
GOTRACEBACK=crash GOGC=off GODEBUG=asyncpreemptoff=1 ./testprog CrashDumpsAllThreads

@aclements
Copy link
Member

All of the Ms are just parked in mPark in normal places in the scheduler, except one thread that's in the infinite loop in crashDumpsAllThreadsLoop. /proc/PID/status and /proc/PID/task/*/status says there are no signals pending, blocked, or ignored by the process or any of its threads. It's a little suspicious that the blocked mask is 0, and in another Go process I have running it's fffffffc3bfa3a00.

@aclements
Copy link
Member

Ah hah, it's getting stuck before the SIGQUIT is involved. It's actually getting stuck in this loop, before the subprocess even indicates to the parent that it's ready for the SIGQUIT.

@aclements
Copy link
Member

Amusingly, this means you can send the subprocess a SIGQUIT. I've pasted the interesting part of the traceback below. All other goroutines and threads are uninteresting (this is running with GOTRACEBACK=crash so we see all threads). The test sets GOMAXPROCS to 5 and starts 4 infinite loops with async preemption disabled, and this looks to me like we're failing to steal goroutine 1 onto another P.

SIGQUIT: quit
PC=0x4b615d m=0 sigcode=0

goroutine 33 [running]:
main.crashDumpsAllThreadsLoop(0x0?, 0x0?)
	/home/austin/go.dev/src/runtime/testdata/testprog/crashdump.go:56 +0x1d fp=0xc0001127c0 sp=0xc0001127a8 pc=0x4b615d
main.CrashDumpsAllThreads.func1()
	/home/austin/go.dev/src/runtime/testdata/testprog/crashdump.go:29 +0x25 fp=0xc0001127e0 sp=0xc0001127c0 pc=0x4b6105
runtime.goexit()
	/home/austin/go.dev/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0001127e8 sp=0xc0001127e0 pc=0x467441
created by main.CrashDumpsAllThreads
	/home/austin/go.dev/src/runtime/testdata/testprog/crashdump.go:29 +0x70

goroutine 1 [runnable]:
runtime.makechan(0x4ca180?, 0x0?)
	/home/austin/go.dev/src/runtime/chan.go:72 +0x1df fp=0xc0000bce58 sp=0xc0000bce50 pc=0x4050bf
main.CrashDumpsAllThreads()
	/home/austin/go.dev/src/runtime/testdata/testprog/crashdump.go:28 +0xe9 fp=0xc0000bcee8 sp=0xc0000bce58 pc=0x4b5f49
main.main()
	/home/austin/go.dev/src/runtime/testdata/testprog/main.go:34 +0x133 fp=0xc0000bcf80 sp=0xc0000bcee8 pc=0x4baeb3
runtime.main()
	/home/austin/go.dev/src/runtime/proc.go:250 +0x207 fp=0xc0000bcfe0 sp=0xc0000bcf80 pc=0x439487
runtime.goexit()
	/home/austin/go.dev/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0000bcfe8 sp=0xc0000bcfe0 pc=0x467441

@aclements
Copy link
Member

Faster repro. Apply the following diff

--- a/src/runtime/testdata/testprog/crashdump.go
+++ b/src/runtime/testdata/testprog/crashdump.go
@@ -29,6 +29,8 @@ func CrashDumpsAllThreads() {
                <-c
        }
 
+       return
+
        // Tell our parent that all the goroutines are executing.
        if _, err := os.NewFile(3, "pipe").WriteString("x"); err != nil {
                fmt.Fprintf(os.Stderr, "write to pipe failed: %v\n", err)

Then

cd runtime/testdata/testprog
GOFLAGS="-gcflags=runtime=-d=maymorestack=runtime.mayMoreStackPreempt -gcflags=runtime/testdata/...=" go build
GOTRACEBACK=crash GOGC=off GODEBUG=asyncpreemptoff=1 stress2 ./testprog CrashDumpsAllThreads

@aclements
Copy link
Member

Here's a version that works without a patch:

cd runtime/testdata/testprog
GOFLAGS="-gcflags=runtime=-d=maymorestack=runtime.mayMoreStackPreempt -gcflags=runtime/testdata/...=" go build
GOTRACEBACK=crash GOGC=off GODEBUG=asyncpreemptoff=1 stress2 -timeouts-fail -max-fails=1 -timeout=10s -pass="write to pipe" -max-runs=50000 ./testprog CrashDumpsAllThreads

@aclements
Copy link
Member

This isn't new, either. I reproduced in Go 1.18, which was the first release to have mayMoreStack.

@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    post <- section == "maymorestack=mayMoreStackPreempt"
2023-02-23 06:07 linux-arm64-longtest go@71c02bed runtime.TestCrashDumpsAllThreads (log) 
panic: test timed out after 50m0s
running tests:
	TestCrashDumpsAllThreads (49m40s)

runtime.gopark(0x819328?, 0xffff943a0f20?, 0x2?, 0x1b?, 0x5?)
	/tmp/workdir/go/src/runtime/proc.go:381 +0x120 fp=0x40002a0cb0 sp=0x40002a0c90 pc=0x442f50
runtime.netpollblock(0xffff943a0f08?, 0x72?, 0x0?)
	/tmp/workdir/go/src/runtime/netpoll.go:527 +0x190 fp=0x40002a0cf0 sp=0x40002a0cb0 pc=0x43a960
internal/poll.runtime_pollWait(0xffff943a0f08, 0x72)
	/tmp/workdir/go/src/runtime/netpoll.go:306 +0xd0 fp=0x40002a0d20 sp=0x40002a0cf0 pc=0x47c900
internal/poll.(*pollDesc).wait(0x8830a0?, 0xa997b8?, 0x1)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:84 +0x28 fp=0x40002a0d50 sp=0x40002a0d20 pc=0x4af8a8
internal/poll.(*pollDesc).waitRead(...)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0x40007ab320, {0x40002a0ea7, 0x1, 0x1})
	/tmp/workdir/go/src/internal/poll/fd_unix.go:167 +0x200 fp=0x40002a0df0 sp=0x40002a0d50 pc=0x4b0590
os.(*File).read(...)
	/tmp/workdir/go/src/os/file_posix.go:31
os.(*File).Read(0x400141e238, {0x40002a0ea7?, 0x40002a0f30?, 0x1?})
	/tmp/workdir/go/src/os/file.go:118 +0x58 fp=0x40002a0e50 sp=0x40002a0df0 pc=0x4b4f28
runtime_test.TestCrashDumpsAllThreads(0x400016e340)
	/tmp/workdir/go/src/runtime/crash_unix_test.go:117 +0x4ac fp=0x40002a0f60 sp=0x40002a0e50 pc=0x6afbbc
testing.tRunner(0x400016e340, 0x81a410)

— watchflakes

@rhysh rhysh mentioned this issue Dec 1, 2023
Open
@gopherbot gopherbot reopened this Mar 8, 2024
@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    post <- section == "maymorestack=mayMoreStackPreempt"
2024-03-08 22:14 linux-arm64-longtest go@c220fbab runtime.TestNetpollDeadlock (log) 
--- FAIL: TestNetpollDeadlock (2640.70s)
    exec.go:193: test timed out while running command: /tmp/workdir/tmp/go-build229666404/testprognet.exe NetpollDeadlock
    crash_test.go:506: /tmp/workdir/tmp/go-build229666404/testprognet.exe NetpollDeadlock: exit status 2
    crash_test.go:509: output does not start with "done\n":
        dialing
        SIGQUIT: quit
        PC=0x8d2fc m=0 sigcode=0

        goroutine 0 gp=0x23de40 m=0 mp=0x23e6c0 [idle]:
        runtime.futex(0x23e800, 0x80, 0x0, 0x0, 0x0, 0x0)
...
        r24     0x0
        r25     0x0
        r26     0x151bf0
        r27     0x237000
        r28     0x23de40
        r29     0xfffff9abfd58
        lr      0x4a40c
        sp      0xfffff9abfd60
        pc      0x8d2fc
        fault   0x0

— watchflakes

@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    post <- section == "maymorestack=mayMoreStackPreempt"
2024-03-09 14:19 windows-amd64-longtest go@74726def runtime.TestNetpollDeadlock (log) 
--- FAIL: TestNetpollDeadlock (2587.85s)
    exec.go:193: test timed out while running command: C:\Users\gopher\AppData\Local\Temp\1\go-build3501004536\testprognet.exe NetpollDeadlock
    crash_test.go:506: C:\Users\gopher\AppData\Local\Temp\1\go-build3501004536\testprognet.exe NetpollDeadlock: exit status 1
    crash_test.go:509: output does not start with "done\n":
        dialing

— watchflakes

@gopherbot
Copy link

Sorry, but there were parse errors in the watch flakes script.
The script I found was:

    #!watchflakes
    post <- section == "maymorestack=mayMoreStackPreempt" || package == "runtime:mayMoreStackPreempt"

And the problems were:

script:2.62: unknown field package

See https://go.dev/wiki/Watchflakes for details.

— watchflakes

@mknyszek
Copy link
Contributor

The TestNetpollDeadlock failures seem like #66275, so I'm inclined to say it's not specific to mayMoreStack and close this for now.

@mknyszek mknyszek closed this as not planned Won't fix, can't repro, duplicate, stale Mar 13, 2024
@golang golang deleted a comment from gopherbot Mar 14, 2024
@golang golang deleted a comment from gopherbot Mar 14, 2024
@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    default <- section == "maymorestack=mayMoreStackPreempt" || pkg == "runtime:mayMoreStackPreempt"
2024-02-16 20:25 gotip-windows-amd64-longtest go@cdd0ddaf runtime:mayMoreStackPreempt.TestReadMetricsCumulative (log) 
=== RUN   TestReadMetricsCumulative
    metrics_test.go:543: /cpu/classes/user:cpu-seconds decreased: 43.052189 < 43.056638
--- FAIL: TestReadMetricsCumulative (0.01s)

— watchflakes

@gopherbot gopherbot reopened this Apr 5, 2024
@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    default <- section == "maymorestack=mayMoreStackPreempt" || pkg == "runtime:mayMoreStackPreempt"
2024-04-05 20:51 linux-amd64-longtest go@5ec7395a runtime.TestCrashWhileTracing (log) 
--- FAIL: TestCrashWhileTracing (0.14s)
    crash_test.go:919: error at event 1038: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx

        goroutine 1 [running]:
        runtime_test.init.1()
        	/workdir/go/src/runtime/crash_test.go:888 +0x85
2024-04-05 20:51 windows-amd64-longtest go@5ec7395a runtime.TestCrashWhileTracing (log) 
--- FAIL: TestCrashWhileTracing (0.13s)
    crash_test.go:919: error at event 1358: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx

        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/workdir/go/src/runtime/crash_test.go:888 +0x85
2024-04-05 22:09 linux-amd64-longtest go@d186dde8 runtime.TestCrashWhileTracing (log) 
--- FAIL: TestCrashWhileTracing (0.10s)
    crash_test.go:919: error at event 795: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx

        goroutine 1 [running]:
        runtime_test.init.1()
        	/workdir/go/src/runtime/crash_test.go:888 +0x85
2024-04-05 22:09 windows-amd64-longtest go@d186dde8 runtime.TestCrashWhileTracing (log) 
--- FAIL: TestCrashWhileTracing (0.15s)
    crash_test.go:919: error at event 1080: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx

        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/workdir/go/src/runtime/crash_test.go:888 +0x85
2024-04-05 22:18 windows-amd64-longtest go@5d18f889 runtime.TestCrashWhileTracing (log) 
--- FAIL: TestCrashWhileTracing (0.14s)
    crash_test.go:919: error at event 1216: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx

        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/workdir/go/src/runtime/crash_test.go:888 +0x85

— watchflakes

@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    default <- section == "maymorestack=mayMoreStackPreempt" || pkg == "runtime:mayMoreStackPreempt"
2024-04-07 03:32 windows-amd64-longtest go@20f052c8 runtime.TestCrashWhileTracing (log) 
--- FAIL: TestCrashWhileTracing (0.14s)
    crash_test.go:919: error at event 1: failed to read full batch: read 2693 but wanted 65461
    crash_test.go:938: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:940: stderr output:
        panic: yzzyx

        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/workdir/go/src/runtime/crash_test.go:888 +0x85
2024-04-08 15:39 linux-amd64-longtest go@ae0a08de runtime.TestCrashWhileTracing (log) 
--- FAIL: TestCrashWhileTracing (0.09s)
    crash_test.go:919: error at event 844: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx

        goroutine 1 [running]:
        runtime_test.init.1()
        	/workdir/go/src/runtime/crash_test.go:888 +0x85

— watchflakes

@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    default <- section == "maymorestack=mayMoreStackPreempt" || pkg == "runtime:mayMoreStackPreempt"
2024-04-08 15:39 windows-amd64-longtest go@ae0a08de runtime.TestCrashWhileTracing (log) 
--- FAIL: TestCrashWhileTracing (0.14s)
    crash_test.go:919: error at event 1305: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx

        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/workdir/go/src/runtime/crash_test.go:888 +0x85
2024-04-08 15:53 windows-amd64-longtest go@da732dd1 runtime.TestCrashWhileTracing (log) 
--- FAIL: TestCrashWhileTracing (0.14s)
    crash_test.go:919: error at event 1066: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx

        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/workdir/go/src/runtime/crash_test.go:888 +0x85
2024-04-08 16:36 windows-amd64-longtest go@e8f5c04c runtime.TestCrashWhileTracing (log) 
--- FAIL: TestCrashWhileTracing (0.14s)
    crash_test.go:919: error at event 1314: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx

        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/workdir/go/src/runtime/crash_test.go:888 +0x85

— watchflakes

@mknyszek
Copy link
Contributor

mknyszek commented Apr 8, 2024

I have a revert CL out to fix this.

@mknyszek
Copy link
Contributor

mknyszek commented Apr 8, 2024

I think I understand what went wrong here. Looks like the fact that this CL made the tracer more preemptible also made it much more likely that the trace would have a broken tail. The test seems to succeed overall though, because other invariants it checks are completely fine. I think I know how to fix this to re-land it.

@mknyszek
Copy link
Contributor

mknyszek commented Apr 8, 2024

Revert landed.

@mknyszek mknyszek closed this as completed Apr 8, 2024
@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    default <- section == "maymorestack=mayMoreStackPreempt" || pkg == "runtime:mayMoreStackPreempt"
2024-04-08 20:51 windows-amd64-longtest go@8008998b runtime.TestCrashWhileTracing (log) 
--- FAIL: TestCrashWhileTracing (0.15s)
    crash_test.go:919: error at event 1189: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx

        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/workdir/go/src/runtime/crash_test.go:888 +0x85

— watchflakes

@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    default <- section == "maymorestack=mayMoreStackPreempt" || pkg == "runtime:mayMoreStackPreempt"
2024-04-08 21:03 linux-amd64-longtest go@017478a9 runtime.TestCrashWhileTracing (log) 
--- FAIL: TestCrashWhileTracing (0.09s)
    crash_test.go:919: error at event 1067: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx

        goroutine 1 [running]:
        runtime_test.init.1()
        	/workdir/go/src/runtime/crash_test.go:888 +0x85
2024-04-08 21:43 linux-amd64-longtest go@e995aa95 runtime.TestCrashWhileTracing (log) 
--- FAIL: TestCrashWhileTracing (0.09s)
    crash_test.go:919: error at event 774: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx

        goroutine 1 [running]:
        runtime_test.init.1()
        	/workdir/go/src/runtime/crash_test.go:888 +0x85

— watchflakes

@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    default <- section == "maymorestack=mayMoreStackPreempt" || pkg == "runtime:mayMoreStackPreempt"
2024-04-08 21:43 windows-amd64-longtest go@d4395ebc runtime.TestCrashWhileTracing (log) 
--- FAIL: TestCrashWhileTracing (0.14s)
    crash_test.go:919: error at event 1128: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx

        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/workdir/go/src/runtime/crash_test.go:888 +0x85

— watchflakes

@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    default <- section == "maymorestack=mayMoreStackPreempt" || pkg == "runtime:mayMoreStackPreempt"
2024-04-08 21:43 darwin-amd64-longtest go@e995aa95 runtime.TestCrashWhileTracing (log) 
--- FAIL: TestCrashWhileTracing (3.13s)
    crash_test.go:919: error at event 816: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx

        goroutine 1 [running]:
        runtime_test.init.1()
        	/tmp/buildlet/go/src/runtime/crash_test.go:888 +0x85

— watchflakes

@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    default <- section == "maymorestack=mayMoreStackPreempt" || pkg == "runtime:mayMoreStackPreempt"
2024-04-08 15:39 gotip-windows-amd64-longtest go@ae0a08de runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:919: error at event 836: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:888 +0x85
--- FAIL: TestCrashWhileTracing (0.16s)
2024-04-08 15:53 gotip-windows-amd64-longtest go@da732dd1 runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:919: error at event 1103: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:888 +0x85
--- FAIL: TestCrashWhileTracing (0.16s)
2024-04-08 20:33 gotip-windows-amd64-longtest go@50a50590 runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:919: error at event 1125: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:888 +0x85
--- FAIL: TestCrashWhileTracing (0.16s)
2024-04-08 21:03 gotip-windows-amd64-longtest go@017478a9 runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:919: error at event 1128: no frequency event found
    crash_test.go:940: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:888 +0x85
--- FAIL: TestCrashWhileTracing (0.17s)
2024-04-10 17:23 gotip-windows-amd64-longtest go@73981695 runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:921: error at event 1: failed to read full batch: read 3233 but wanted 65458
    crash_test.go:942: expected at least one full generation to have been emitted before the trace was considered broken
    crash_test.go:945: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:947: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:888 +0x85
--- FAIL: TestCrashWhileTracing (0.15s)
2024-04-10 19:41 gotip-windows-amd64-longtest go@5b5d6f87 runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:921: error at event 1: failed to read full batch: read 2703 but wanted 65455
    crash_test.go:942: expected at least one full generation to have been emitted before the trace was considered broken
    crash_test.go:945: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:947: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:888 +0x85
--- FAIL: TestCrashWhileTracing (0.17s)
2024-04-11 16:15 gotip-windows-amd64-longtest go@48e00ab7 runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:921: error at event 1: failed to read full batch: read 2532 but wanted 65456
    crash_test.go:942: expected at least one full generation to have been emitted before the trace was considered broken
    crash_test.go:945: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:947: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:888 +0x85
--- FAIL: TestCrashWhileTracing (0.17s)
2024-04-11 20:22 gotip-windows-amd64-longtest go@1843464f runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:921: error at event 1: failed to read full batch: read 2244 but wanted 65457
    crash_test.go:942: expected at least one full generation to have been emitted before the trace was considered broken
    crash_test.go:945: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:947: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:888 +0x85
--- FAIL: TestCrashWhileTracing (0.17s)
2024-04-11 21:23 gotip-windows-amd64-longtest go@bfb1f563 runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:921: error at event 1: failed to read full batch: read 920 but wanted 65456
    crash_test.go:942: expected at least one full generation to have been emitted before the trace was considered broken
    crash_test.go:945: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:947: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:888 +0x85
--- FAIL: TestCrashWhileTracing (0.16s)
2024-04-12 14:07 gotip-windows-amd64-longtest go@5c20d5fa runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:921: error at event 1: failed to read full batch: read 3541 but wanted 65458
    crash_test.go:942: expected at least one full generation to have been emitted before the trace was considered broken
    crash_test.go:945: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:947: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:888 +0x85
--- FAIL: TestCrashWhileTracing (0.15s)
2024-04-12 19:15 gotip-windows-amd64-longtest go@2f3ff1fc runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:921: error at event 1: failed to read full batch: read 2907 but wanted 65458
    crash_test.go:942: expected at least one full generation to have been emitted before the trace was considered broken
    crash_test.go:945: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:947: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:888 +0x85
--- FAIL: TestCrashWhileTracing (0.15s)
2024-04-14 18:17 gotip-windows-amd64-longtest go@37f48222 runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:921: error at event 1: failed to read full batch: read 2748 but wanted 65456
    crash_test.go:942: expected at least one full generation to have been emitted before the trace was considered broken
    crash_test.go:945: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:947: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:888 +0x85
--- FAIL: TestCrashWhileTracing (0.16s)
2024-04-15 17:03 gotip-windows-amd64-longtest go@7b10c49e runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:916: error at event 1: failed to read full batch: read 1644 but wanted 65457
    crash_test.go:937: expected at least one full generation to have been emitted before the trace was considered broken
    crash_test.go:940: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:942: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:887 +0x85
--- FAIL: TestCrashWhileTracing (0.15s)
2024-04-15 17:38 gotip-windows-amd64-longtest go@59209c4b runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:916: error at event 1: failed to read full batch: read 3279 but wanted 65457
    crash_test.go:937: expected at least one full generation to have been emitted before the trace was considered broken
    crash_test.go:940: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:942: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:887 +0x85
--- FAIL: TestCrashWhileTracing (0.15s)
2024-04-17 19:54 gotip-windows-amd64-longtest go@2073b35e runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:916: error at event 1: failed to read full batch: read 2364 but wanted 65458
    crash_test.go:937: expected at least one full generation to have been emitted before the trace was considered broken
    crash_test.go:940: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:942: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:887 +0x85
--- FAIL: TestCrashWhileTracing (0.15s)

— watchflakes

@gopherbot gopherbot reopened this Apr 18, 2024
@mknyszek
Copy link
Contributor

The non-Windows failures are likely just stragglers from the fix. The Windows failures are likely because something is failing to flush (a pipe, in this case...?).

@mknyszek mknyszek self-assigned this Apr 18, 2024
@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    default <- section == "maymorestack=mayMoreStackPreempt" || pkg == "runtime:mayMoreStackPreempt"
2024-04-19 17:15 gotip-windows-amd64-longtest go@2ff89341 runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:916: error at event 1: failed to read full batch: read 3021 but wanted 65458
    crash_test.go:937: expected at least one full generation to have been emitted before the trace was considered broken
    crash_test.go:940: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:942: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:887 +0x85
--- FAIL: TestCrashWhileTracing (0.17s)

— watchflakes

@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    default <- section == "maymorestack=mayMoreStackPreempt" || pkg == "runtime:mayMoreStackPreempt"
2024-04-24 18:15 gotip-windows-amd64-longtest go@e6891188 runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:916: error at event 1: failed to read full batch: read 2427 but wanted 65455
    crash_test.go:937: expected at least one full generation to have been emitted before the trace was considered broken
    crash_test.go:940: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:942: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:887 +0x85
--- FAIL: TestCrashWhileTracing (0.17s)
2024-04-25 00:43 gotip-windows-amd64-longtest go@799968df runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:916: error at event 1: failed to read full batch: read 2469 but wanted 65459
    crash_test.go:937: expected at least one full generation to have been emitted before the trace was considered broken
    crash_test.go:940: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:942: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:887 +0x85
--- FAIL: TestCrashWhileTracing (0.16s)

— watchflakes

@gopherbot
Copy link

Found new dashboard test flakes for:

    #!watchflakes
    default <- section == "maymorestack=mayMoreStackPreempt" || pkg == "runtime:mayMoreStackPreempt"
2024-04-25 01:05 gotip-windows-amd64-longtest go@db5f2b41 runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:916: error at event 1: failed to read full batch: read 3000 but wanted 65459
    crash_test.go:937: expected at least one full generation to have been emitted before the trace was considered broken
    crash_test.go:940: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:942: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:887 +0x85
--- FAIL: TestCrashWhileTracing (0.16s)
2024-04-25 11:28 gotip-windows-amd64-longtest go@8960925a runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:916: error at event 1: failed to read full batch: read 3018 but wanted 65457
    crash_test.go:937: expected at least one full generation to have been emitted before the trace was considered broken
    crash_test.go:940: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:942: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:887 +0x85
--- FAIL: TestCrashWhileTracing (0.15s)
2024-04-25 17:07 gotip-windows-amd64-longtest go@06478e4b runtime:mayMoreStackPreempt.TestCrashWhileTracing (log) 
=== RUN   TestCrashWhileTracing
    crash_test.go:916: error at event 1: failed to read full batch: read 2241 but wanted 65457
    crash_test.go:937: expected at least one full generation to have been emitted before the trace was considered broken
    crash_test.go:940: expected one matching log event matching, but none of the 1 received trace events match
    crash_test.go:942: stderr output:
        panic: yzzyx
        
        goroutine 1 [running]:
        runtime_test.init.1()
        	C:/b/s/w/ir/x/w/goroot/src/runtime/crash_test.go:887 +0x85
--- FAIL: TestCrashWhileTracing (0.16s)

— watchflakes

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@mknyszek mknyszek

Labels
compiler/runtime Issues related to the Go compiler and/or runtime. early-in-cycle A change that should be done early in the 3 month dev cycle. NeedsFix The path to resolution is known, but the work has not been done.
Projects
Go Compiler / Runtime
Status: In Progress
Test Flakes
Status: Done
Milestone
Go1.22
Development

No branches or pull requests
9 participants
@rsc @mknyszek @prattmic @dmitshur @dr2chase @aclements @bcmills @gopherbot @cherrymui