openbsd-386-72 at 3009566a46f19e9c94df4cf51cc374763698cba0 :: Running /tmp/workdir/go/src/make.bash with args ["/tmp/workdir/go/src/make.bash" "-force"] and env ["HOME=/" "INRC=1" "_=/bin/sh" "WORKDIR=/tmp/workdir" "GO_BUILDER_NAME=openbsd-386-72" "GOBIN=" "GOROOT_BOOTSTRAP=" "TMPDIR=/tmp/workdir/tmp" "GOCACHE=/tmp/workdir/gocache" "GOPLSCACHE=/tmp/workdir/goplscache" "PATH=/tmp/workdir/go1.4/go/bin:/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/bin" "PWD=/tmp/workdir/go/src"] in dir /tmp/workdir/go/src WARNING: //go1.4/bin/go does not exist, found /tmp/workdir/go1.4/go/bin/go from env WARNING: set /tmp/workdir/go1.4/go as GOROOT_BOOTSTRAP Building Go cmd/dist using /tmp/workdir/go1.4/go. (go1.22.6 openbsd/386) Building Go toolchain1 using /tmp/workdir/go1.4/go. Building Go bootstrap cmd/go (go_bootstrap) using Go toolchain1. Building Go toolchain2 using go_bootstrap and Go toolchain1. Building Go toolchain3 using go_bootstrap and Go toolchain2. Building packages and commands for openbsd/386. --- Installed Go for openbsd/386 in /tmp/workdir/go Installed commands in /tmp/workdir/go/bin *** You need to add /tmp/workdir/go/bin to your PATH. ##### Test execution environment. # GOARCH: 386 # CPU: Intel(R) Xeon(R) CPU @ 2.80GHz # GOOS: openbsd # OS Version: OpenBSD 7.2 OpenBSD 7.2 (GENERIC) #5: Tue Jul 25 16:20:24 CEST 2023 root@syspatch-72-i386.openbsd.org:/usr/src/sys/arch/i386/compile/GENERIC i386 ##### Testing packages. ok archive/tar 0.211s ok archive/zip 0.479s ok bufio 0.087s ok bytes 0.431s ok cmp 0.016s ok compress/bzip2 0.091s ok compress/flate 0.828s ok compress/gzip 1.899s ok compress/lzw 0.106s ok compress/zlib 0.582s ok container/heap 0.018s ok container/list 0.016s ok container/ring 0.017s ok context 0.302s ok crypto 1.291s ok crypto/aes 0.021s ok crypto/cipher 8.301s ok crypto/des 0.032s ok crypto/dsa 0.018s ok crypto/ecdh 0.328s ok crypto/ecdsa 0.190s ok crypto/ed25519 0.335s ok crypto/elliptic 0.047s ? crypto/fips140 [no test files] ok crypto/hkdf 0.017s ok crypto/hmac 0.032s ok crypto/internal/boring 0.015s ? crypto/internal/boring/bbig [no test files] ok crypto/internal/boring/bcache 0.191s ? crypto/internal/boring/sig [no test files] ? crypto/internal/cryptotest [no test files] ? crypto/internal/entropy [no test files] ? crypto/internal/fips140 [no test files] ok crypto/internal/fips140/aes 0.036s ok crypto/internal/fips140/aes/gcm 0.015s [no tests to run] ? crypto/internal/fips140/alias [no test files] ok crypto/internal/fips140/bigmod 0.080s ? crypto/internal/fips140/check [no test files] ? crypto/internal/fips140/check/checktest [no test files] ok crypto/internal/fips140/drbg 0.015s [no tests to run] ok crypto/internal/fips140/ecdh 0.015s ok crypto/internal/fips140/ecdsa 0.169s ? crypto/internal/fips140/ed25519 [no test files] ok crypto/internal/fips140/edwards25519 0.524s ok crypto/internal/fips140/edwards25519/field 0.081s ? crypto/internal/fips140/hkdf [no test files] ? crypto/internal/fips140/hmac [no test files] ok crypto/internal/fips140/mlkem 0.238s ok crypto/internal/fips140/nistec 0.162s ok crypto/internal/fips140/nistec/fiat 0.015s [no tests to run] ? crypto/internal/fips140/pbkdf2 [no test files] ok crypto/internal/fips140/rsa 0.342s ? crypto/internal/fips140/sha256 [no test files] ? crypto/internal/fips140/sha3 [no test files] ? crypto/internal/fips140/sha512 [no test files] ? crypto/internal/fips140/ssh [no test files] ok crypto/internal/fips140/subtle 0.015s ? crypto/internal/fips140/tls12 [no test files] ? crypto/internal/fips140/tls13 [no test files] ok crypto/internal/fips140deps 0.191s ? crypto/internal/fips140deps/byteorder [no test files] ? crypto/internal/fips140deps/cpu [no test files] ? crypto/internal/fips140deps/godebug [no test files] ? crypto/internal/fips140hash [no test files] ? crypto/internal/fips140only [no test files] ok crypto/internal/fips140test 3.036s ok crypto/internal/hpke 0.024s ? crypto/internal/impl [no test files] ? crypto/internal/randutil [no test files] ok crypto/internal/sysrand 0.393s ? crypto/internal/sysrand/internal/seccomp [no test files] ok crypto/md5 0.022s ok crypto/mlkem 0.111s ok crypto/pbkdf2 0.036s ok crypto/rand 0.790s ok crypto/rc4 0.055s ok crypto/rsa 1.283s ok crypto/sha1 0.021s ok crypto/sha256 0.022s ok crypto/sha3 4.350s ok crypto/sha512 0.026s ok crypto/subtle 0.200s ok crypto/tls 16.262s ? crypto/tls/internal/fips140tls [no test files] ok crypto/x509 2.682s ? crypto/x509/pkix [no test files] ok database/sql 0.788s ok database/sql/driver 0.015s ok debug/buildinfo 0.162s ok debug/dwarf 0.060s ok debug/elf 0.205s ok debug/gosym 0.060s ok debug/macho 0.027s ok debug/pe 0.070s ok debug/plan9obj 0.017s ok embed 0.017s [no tests to run] ok embed/internal/embedtest 0.017s ? encoding [no test files] ok encoding/ascii85 0.017s ok encoding/asn1 0.019s ok encoding/base32 0.040s ok encoding/base64 0.019s ok encoding/binary 0.025s ok encoding/csv 0.028s ok encoding/gob 4.491s ok encoding/hex 0.019s ok encoding/json 0.462s ok encoding/pem 1.094s ok encoding/xml 0.095s ok errors 0.026s ok expvar 0.022s ok flag 0.071s ok fmt 0.114s ok go/ast 0.022s ok go/build 6.651s ok go/build/constraint 0.080s ok go/constant 0.020s ok go/doc 0.101s ok go/doc/comment 1.591s ok go/format 0.022s ok go/importer 0.658s ok go/internal/gccgoimporter 0.036s ok go/internal/gcimporter 4.718s ok go/internal/srcimporter 17.861s ok go/parser 0.513s ok go/printer 0.200s ok go/scanner 0.018s ok go/token 0.038s ok go/types 27.346s ok go/version 0.020s ok hash 0.018s ok hash/adler32 0.022s ok hash/crc32 0.021s ok hash/crc64 0.022s ok hash/fnv 0.016s ok hash/maphash 2.283s ok html 0.018s ok html/template 0.098s ok image 0.090s ok image/color 0.029s ? image/color/palette [no test files] ok image/draw 0.099s ok image/gif 0.224s ? image/internal/imageutil [no test files] ok image/jpeg 0.226s ok image/png 0.337s ok index/suffixarray 0.219s ok internal/abi 0.167s ? internal/asan [no test files] ? internal/bisect [no test files] ok internal/buildcfg 0.016s ? internal/bytealg [no test files] ? internal/byteorder [no test files] ? internal/cfg [no test files] ok internal/chacha8rand 0.016s ok internal/copyright 0.362s ? internal/coverage [no test files] ? internal/coverage/calloc [no test files] ok internal/coverage/cfile 1.808s ok internal/coverage/cformat 0.016s ok internal/coverage/cmerge 0.021s ? internal/coverage/decodecounter [no test files] ? internal/coverage/decodemeta [no test files] ? internal/coverage/encodecounter [no test files] ? internal/coverage/encodemeta [no test files] ok internal/coverage/pods 0.019s ? internal/coverage/rtcov [no test files] ok internal/coverage/slicereader 0.015s ok internal/coverage/slicewriter 0.020s ? internal/coverage/stringtab [no test files] ok internal/coverage/test 0.024s ? internal/coverage/uleb128 [no test files] ok internal/cpu 0.037s ok internal/dag 0.016s ok internal/diff 0.022s ? internal/exportdata [no test files] ? internal/filepathlite [no test files] ok internal/fmtsort 0.016s ok internal/fuzz 0.024s ? internal/goarch [no test files] ok internal/godebug 1.204s ok internal/godebugs 9.053s ? internal/goexperiment [no test files] ? internal/goos [no test files] ? internal/goroot [no test files] ok internal/gover 0.015s ? internal/goversion [no test files] ok internal/itoa 0.015s ? internal/lazyregexp [no test files] ? internal/lazytemplate [no test files] ? internal/msan [no test files] ? internal/nettrace [no test files] ? internal/obscuretestdata [no test files] ? internal/oserror [no test files] ok internal/pkgbits 0.016s ok internal/platform 1.911s ok internal/poll 0.073s ok internal/profile 0.015s ? internal/profilerecord [no test files] ? internal/race [no test files] ok internal/reflectlite 0.018s ok internal/routebsd 0.017s ok internal/runtime/atomic 0.054s ? internal/runtime/exithook [no test files] ? internal/runtime/gc [no test files] ok internal/runtime/maps 0.720s ok internal/runtime/math 0.015s ok internal/runtime/sys 0.015s ok internal/runtime/wasitest 0.017s ok internal/saferio 0.109s ok internal/singleflight 0.132s ? internal/stringslite [no test files] ok internal/sync 1.399s ok internal/synctest 1.369s ? internal/syscall/execenv [no test files] ? internal/syscall/unix [no test files] ok internal/sysinfo 0.016s ? internal/syslist [no test files] ok internal/testenv 0.472s ? internal/testlog [no test files] ? internal/testpty [no test files] --- FAIL: TestTraceStress (128.35s) --- FAIL: TestTraceStress/Default (128.35s) exec.go:213: test timed out while running command: /tmp/workdir/go/bin/go run testdata/testprog/stress.go trace_test.go:615: signal: killed --- FAIL: TestTraceStressStartStop (6.42s) --- FAIL: TestTraceStressStartStop/Default (6.42s) exec.go:213: test timed out while running command: /tmp/workdir/go/bin/go run testdata/testprog/stress-start-stop.go trace_test.go:615: signal: killed --- FAIL: TestTraceManyStartStop (0.20s) --- FAIL: TestTraceManyStartStop/Default (0.20s) exec.go:213: test timed out while running command: /tmp/workdir/go/bin/go run testdata/testprog/many-start-stop.go trace_test.go:613: stderr: SIGQUIT: quit PC=0x45ae1b9f m=3 sigcode=0 goroutine 0 gp=0x65c08b48 m=3 mp=0x65c43008 [idle]: runtime.thrsleep(0x65c4330c, 0x3, 0x0, 0x0, 0x65c4330c) runtime/sys_openbsd1.go:17 +0x21 fp=0x323a66a0 sp=0x323a6690 pc=0x80a8a71 runtime.semasleep(0xffffffffffffffff) runtime/os_openbsd.go:118 +0xe0 fp=0x323a66dc sp=0x323a66a0 pc=0x8086660 runtime.notesleep(0x65c430c4) runtime/lock_sema.go:62 +0x7e fp=0x323a66f8 sp=0x323a66dc pc=0x805ef5e runtime.mPark(...) runtime/proc.go:1910 runtime.stopm() runtime/proc.go:2933 +0x96 fp=0x323a670c sp=0x323a66f8 pc=0x808ff16 runtime.findRunnable() runtime/proc.go:3682 +0xcb9 fp=0x323a6804 sp=0x323a670c pc=0x80917a9 runtime.schedule() runtime/proc.go:4050 +0xb1 fp=0x323a6820 sp=0x323a6804 pc=0x8092e41 runtime.park_m(0x65c08fc8) runtime/proc.go:4173 +0x227 fp=0x323a684c sp=0x323a6820 pc=0x80932b7 runtime.mcall(0x40000) runtime/asm_386.s:327 +0x40 fp=0x323a6854 sp=0x323a684c pc=0x80c5250 goroutine 1 gp=0x65c08128 m=nil [sync.WaitGroup.Wait]: runtime.gopark(0x87c4c88, 0x8c49720, 0x18, 0x5, 0x4) runtime/proc.go:458 +0xfa fp=0x65c2dac8 sp=0x65c2dab4 pc=0x80bff9a runtime.goparkunlock(...) runtime/proc.go:464 runtime.semacquire1(0x65e3aae8, 0x0, 0x1, 0x0, 0x18) runtime/sema.go:188 +0x27b fp=0x65c2daf8 sp=0x65c2dac8 pc=0x809ed9b sync.runtime_SemacquireWaitGroup(0x65e3aae8) runtime/sema.go:110 +0x35 fp=0x65c2db10 sp=0x65c2daf8 pc=0x80c15d5 sync.(*WaitGroup).Wait(0x65e3aae0) sync/waitgroup.go:141 +0x5f fp=0x65c2db2c sp=0x65c2db10 pc=0x80d0a1f cmd/go/internal/work.(*Builder).Do(0x65c03ab0, {0x888c9b0, 0x8c50420}, 0x65f0b388) cmd/go/internal/work/exec.go:234 +0x415 fp=0x65c2dbc4 sp=0x65c2db2c pc=0x853d9a5 cmd/go/internal/run.runRun({0x888c9b0, 0x8c50420}, 0x8c3a8a0, {0x65c1c0e8, 0x1, 0x1}) cmd/go/internal/run/run.go:172 +0x840 fp=0x65c2dc90 sp=0x65c2dbc4 pc=0x8592ef0 main.invoke(0x8c3a8a0, {0x65c1c0e0, 0x2, 0x2}) cmd/go/main.go:341 +0x8ba fp=0x65c2de64 sp=0x65c2dc90 pc=0x85e159a main.main() cmd/go/main.go:220 +0x1031 fp=0x65c2dfac sp=0x65c2de64 pc=0x85e0601 runtime.main() runtime/proc.go:283 +0x288 fp=0x65c2dff0 sp=0x65c2dfac pc=0x808b648 runtime.goexit({}) runtime/asm_386.s:1386 +0x1 fp=0x65c2dff4 sp=0x65c2dff0 pc=0x80c65d1 goroutine 2 gp=0x65c08488 m=nil [force gc (idle)]: runtime.gopark(0x87c4c88, 0x8c41ab8, 0x11, 0xa, 0x1) runtime/proc.go:458 +0xfa fp=0x65c3e7dc sp=0x65c3e7c8 pc=0x80bff9a runtime.goparkunlock(...) runtime/proc.go:464 runtime.forcegchelper() runtime/proc.go:371 +0xc7 fp=0x65c3e7f0 sp=0x65c3e7dc pc=0x808b9a7 runtime.goexit({}) runtime/asm_386.s:1386 +0x1 fp=0x65c3e7f4 sp=0x65c3e7f0 pc=0x80c65d1 created by runtime.init.6 in goroutine 1 runtime/proc.go:359 +0x1d goroutine 3 gp=0x65c085a8 m=nil [GC sweep wait]: runtime.gopark(0x87c4c88, 0x8c41ea0, 0xc, 0x9, 0x1) runtime/proc.go:458 +0xfa fp=0x65c3efcc sp=0x65c3efb8 pc=0x80bff9a runtime.goparkunlock(...) runtime/proc.go:464 runtime.bgsweep(0x65c24040) runtime/mgcsweep.go:276 +0x8f fp=0x65c3efe8 sp=0x65c3efcc pc=0x807720f runtime.gcenable.gowrap1() runtime/mgc.go:203 +0x21 fp=0x65c3eff0 sp=0x65c3efe8 pc=0x80689c1 runtime.goexit({}) runtime/asm_386.s:1386 +0x1 fp=0x65c3eff4 sp=0x65c3eff0 pc=0x80c65d1 created by runtime.gcenable in goroutine 1 runtime/mgc.go:203 +0x71 goroutine 4 gp=0x65c086c8 m=nil [GC scavenge wait]: runtime.gopark(0x87c4c88, 0x8c42c00, 0xd, 0xa, 0x2) runtime/proc.go:458 +0xfa fp=0x65c3f7b8 sp=0x65c3f7a4 pc=0x80bff9a runtime.goparkunlock(...) runtime/proc.go:464 runtime.(*scavengerState).park(0x8c42c00) runtime/mgcscavenge.go:425 +0x54 fp=0x65c3f7cc sp=0x65c3f7b8 pc=0x80748c4 runtime.bgscavenge(0x65c24040) runtime/mgcscavenge.go:653 +0x45 fp=0x65c3f7e8 sp=0x65c3f7cc pc=0x8074f05 runtime.gcenable.gowrap2() runtime/mgc.go:204 +0x21 fp=0x65c3f7f0 sp=0x65c3f7e8 pc=0x8068981 runtime.goexit({}) runtime/asm_386.s:1386 +0x1 fp=0x65c3f7f4 sp=0x65c3f7f0 pc=0x80c65d1 created by runtime.gcenable in goroutine 1 runtime/mgc.go:204 +0xb1 goroutine 5 gp=0x65c08c68 m=nil [finalizer wait]: runtime.gopark(0x87c4b38, 0x8c50510, 0x10, 0xa, 0x1) runtime/proc.go:458 +0xfa fp=0x65c3ff98 sp=0x65c3ff84 pc=0x80bff9a runtime.runFinalizersAndCleanups() runtime/mfinal.go:198 +0xed fp=0x65c3fff0 sp=0x65c3ff98 pc=0x8067a6d runtime.goexit({}) runtime/asm_386.s:1386 +0x1 fp=0x65c3fff4 sp=0x65c3fff0 pc=0x80c65d1 created by runtime.createfing in goroutine 1 runtime/mfinal.go:168 +0x5a goroutine 6 gp=0x65c08fc8 m=nil [chan receive]: runtime.gopark(0x87c4b18, 0x65c24234, 0xe, 0x7, 0x2) runtime/proc.go:458 +0xfa fp=0x65c4078c sp=0x65c40778 pc=0x80bff9a runtime.chanrecv(0x65c24200, 0x0, 0x1) runtime/chan.go:664 +0x41a fp=0x65c407cc sp=0x65c4078c pc=0x805a2fa runtime.chanrecv1(0x65c24200, 0x0) runtime/chan.go:506 +0x1c fp=0x65c407e0 sp=0x65c407cc pc=0x8059eac runtime.unique_runtime_registerUniqueMapCleanup.func2(...) runtime/mgc.go:1810 runtime.unique_runtime_registerUniqueMapCleanup.gowrap1() runtime/mgc.go:1813 +0x34 fp=0x65c407f0 sp=0x65c407e0 pc=0x806c2c4 runtime.goexit({}) runtime/asm_386.s:1386 +0x1 fp=0x65c407f4 sp=0x65c407f0 pc=0x80c65d1 created by unique.runtime_registerUniqueMapCleanup in goroutine 1 runtime/mgc.go:1808 +0x66 goroutine 8 gp=0x65c09208 m=nil [runnable]: syscall.syscall6(0x80e0ce0, 0x11d72, 0x65ccd4c4, 0x0, 0x65e0f4f0, 0x0, 0x0) runtime/sys_openbsd3.go:54 +0x20 fp=0x65ccd470 sp=0x65ccd460 pc=0x80c3bb0 syscall.wait4(0x11d72, 0x65ccd4c4, 0x0, 0x65e0f4f0) syscall/zsyscall_openbsd_386.go:43 +0x5d fp=0x65ccd4a8 sp=0x65ccd470 pc=0x80dd9ed syscall.Wait4(0x11d72, 0x65ccd4e8, 0x0, 0x65e0f4f0) syscall/syscall_bsd.go:144 +0x3b fp=0x65ccd4cc sp=0x65ccd4a8 pc=0x80db06b os.(*Process).pidWait.func1(...) os/exec_unix.go:64 os.ignoringEINTR2[...](...) os/file_posix.go:266 os.(*Process).pidWait(0x65efb8c0) os/exec_unix.go:63 +0x9e fp=0x65ccd500 sp=0x65ccd4cc pc=0x8143fae os.(*Process).wait(0x65efb8c0) os/exec_unix.go:28 +0x22 fp=0x65ccd514 sp=0x65ccd500 pc=0x8143ed2 os.(*Process).Wait(...) os/exec.go:340 os/exec.(*Cmd).Wait(0x65f0b458) os/exec/exec.go:922 +0x36 fp=0x65ccd54c sp=0x65ccd514 pc=0x817e136 os/exec.(*Cmd).Run(0x65f0b458) os/exec/exec.go:626 +0x3f fp=0x65ccd55c sp=0x65ccd54c pc=0x817cf2f cmd/go/internal/work.(*Builder).toolID.func1() cmd/go/internal/work/buildid.go:163 +0x236 fp=0x65ccd5e8 sp=0x65ccd55c pc=0x8537f76 cmd/internal/par.(*Cache[...]).Do(0x888e660, {0x8767c87, 0x7}, 0x65ccd640) cmd/internal/par/work.go:160 +0x11f fp=0x65ccd624 sp=0x65ccd5e8 pc=0x84de63f cmd/go/internal/work.(*Builder).toolID(0x65c03ab0, {0x8767c87, 0x7}) cmd/go/internal/work/buildid.go:147 +0x54 fp=0x65ccd650 sp=0x65ccd624 pc=0x8537d24 cmd/go/internal/work.(*Builder).buildActionID(0x65c03ab0, 0x65f06418) cmd/go/internal/work/exec.go:344 +0x12f0 fp=0x65ccd854 sp=0x65ccd650 pc=0x853fc00 cmd/go/internal/work.(*Builder).build(0x65c03ab0, {0x888c9b0, 0x8c50420}, 0x65f06418) cmd/go/internal/work/exec.go:484 +0x2a2 fp=0x65ccde7c sp=0x65ccd854 pc=0x85413a2 cmd/go/internal/work.(*buildActor).Act(0x65edcec8, 0x65c03ab0, {0x888c9b0, 0x8c50420}, 0x65f06418) cmd/go/internal/work/action.go:468 +0x33 fp=0x65ccde98 sp=0x65ccde7c pc=0x852f363 cmd/go/internal/work.(*Builder).Do.func3({0x888c9b0, 0x8c50420}, 0x65f06418) cmd/go/internal/work/exec.go:153 +0x912 fp=0x65ccdf84 sp=0x65ccde98 pc=0x853e5f2 cmd/go/internal/work.(*Builder).Do.func4() cmd/go/internal/work/exec.go:225 +0xaf fp=0x65ccdff0 sp=0x65ccdf84 pc=0x853db7f runtime.goexit({}) runtime/asm_386.s:1386 +0x1 fp=0x65ccdff4 sp=0x65ccdff0 pc=0x80c65d1 created by cmd/go/internal/work.(*Builder).Do in goroutine 1 cmd/go/internal/work/exec.go:211 +0x376 goroutine 9 gp=0x65ee57a8 m=nil [runnable]: os/exec.(*Cmd).Start.gowrap1() os/exec/exec.go:748 fp=0x65c40ff0 sp=0x65c40fec pc=0x817d960 runtime.goexit({}) runtime/asm_386.s:1386 +0x1 fp=0x65c40ff4 sp=0x65c40ff0 pc=0x80c65d1 created by os/exec.(*Cmd).Start in goroutine 8 os/exec/exec.go:748 +0x8b6 goroutine 10 gp=0x65ee58c8 m=nil [runnable]: os/exec.(*Cmd).Start.gowrap1() os/exec/exec.go:748 fp=0x65c417f0 sp=0x65c417ec pc=0x817d960 runtime.goexit({}) runtime/asm_386.s:1386 +0x1 fp=0x65c417f4 sp=0x65c417f0 pc=0x80c65d1 created by os/exec.(*Cmd).Start in goroutine 8 os/exec/exec.go:748 +0x8b6 eax 0x58 ebx 0x65c4330c ecx 0x0 edx 0x323a66a0 edi 0x1dc esi 0x65c08b48 ebp 0x323a6648 esp 0x323a6630 eip 0x45ae1b9f eflags 0x202 cs 0x2b fs 0x5b gs 0x63 trace_test.go:615: exit status 2 --- FAIL: TestTraceWaitOnPipe (0.00s) --- FAIL: TestTraceWaitOnPipe/Default (0.00s) trace_test.go:615: context deadline exceeded --- FAIL: TestTraceIterPull (0.00s) --- FAIL: TestTraceIterPull/Default (0.00s) trace_test.go:615: context deadline exceeded panic: test timed out after 3m0s running tests: TestTraceV1 (0s) TestTraceV1/stress_1_11_good (0s) goroutine 136 gp=0x66aae7e8 m=0 mp=0x8432940 [running]: panic({0x8255ec0, 0x668221b8}) /tmp/workdir/go/src/runtime/panic.go:802 +0x135 fp=0x66990f84 sp=0x66990f30 pc=0x80bccd5 testing.(*M).startAlarm.func1() /tmp/workdir/go/src/testing/testing.go:2494 +0x36a fp=0x66990ff0 sp=0x66990f84 pc=0x814b82a runtime.goexit({}) /tmp/workdir/go/src/runtime/asm_386.s:1386 +0x1 fp=0x66990ff4 sp=0x66990ff0 pc=0x80c3211 created by time.goFunc /tmp/workdir/go/src/time/sleep.go:215 +0x29 goroutine 1 gp=0x66806128 m=nil [chan receive]: runtime.gopark(0x82a4208, 0x6681f134, 0xe, 0x7, 0x2) /tmp/workdir/go/src/runtime/proc.go:458 +0xfa fp=0x6684ac34 sp=0x6684ac20 pc=0x80bd11a runtime.chanrecv(0x6681f100, 0x6684acaf, 0x1) /tmp/workdir/go/src/runtime/chan.go:664 +0x41a fp=0x6684ac74 sp=0x6684ac34 pc=0x8055e8a runtime.chanrecv1(0x6681f100, 0x6684acaf) /tmp/workdir/go/src/runtime/chan.go:506 +0x1c fp=0x6684ac88 sp=0x6684ac74 pc=0x8055a3c testing.(*T).Run(0x66806d88, {0x828f012, 0xb}, 0x82a406c) /tmp/workdir/go/src/testing/testing.go:1866 +0x481 fp=0x6684ad10 sp=0x6684ac88 pc=0x8148281 testing.runTests.func1(0x66806d88) /tmp/workdir/go/src/testing/testing.go:2289 +0x3f fp=0x6684ad30 sp=0x6684ad10 pc=0x814a44f testing.tRunner(0x66806d88, 0x6684adf4) /tmp/workdir/go/src/testing/testing.go:1799 +0x10e fp=0x6684ad90 sp=0x6684ad30 pc=0x81472ce testing.runTests(0x668100e0, {0x842a1a0, 0x1a, 0x1a}, {0xc1fabbfaadb8445e, 0x29e8f2af74, 0x8432140}) /tmp/workdir/go/src/testing/testing.go:2287 +0x3e4 fp=0x6684ae08 sp=0x6684ad90 pc=0x814a364 testing.(*M).Run(0x66864140) /tmp/workdir/go/src/testing/testing.go:2152 +0x634 fp=0x6684af54 sp=0x6684ae08 pc=0x8148d04 main.main() _testmain.go:99 +0xdf fp=0x6684afac sp=0x6684af54 pc=0x82286af runtime.main() /tmp/workdir/go/src/runtime/proc.go:283 +0x288 fp=0x6684aff0 sp=0x6684afac pc=0x8089158 runtime.goexit({}) /tmp/workdir/go/src/runtime/asm_386.s:1386 +0x1 fp=0x6684aff4 sp=0x6684aff0 pc=0x80c3211 goroutine 2 gp=0x66806488 m=nil [force gc (idle), 3 minutes]: runtime.gopark(0x82a4374, 0x8431dc0, 0x11, 0xa, 0x1) /tmp/workdir/go/src/runtime/proc.go:458 +0xfa fp=0x668387dc sp=0x668387c8 pc=0x80bd11a runtime.goparkunlock(...) /tmp/workdir/go/src/runtime/proc.go:464 runtime.forcegchelper() /tmp/workdir/go/src/runtime/proc.go:371 +0xc7 fp=0x668387f0 sp=0x668387dc pc=0x80894b7 runtime.goexit({}) /tmp/workdir/go/src/runtime/asm_386.s:1386 +0x1 fp=0x668387f4 sp=0x668387f0 pc=0x80c3211 created by runtime.init.6 in goroutine 1 /tmp/workdir/go/src/runtime/proc.go:359 +0x1d goroutine 3 gp=0x668065a8 m=nil [runnable]: runtime.goschedIfBusy() /tmp/workdir/go/src/runtime/proc.go:410 +0x36 fp=0x66995fcc sp=0x66995fc0 pc=0x8089566 runtime.bgsweep(0x6681e040) /tmp/workdir/go/src/runtime/mgcsweep.go:300 +0x141 fp=0x66995fe8 sp=0x66995fcc pc=0x8072bc1 runtime.gcenable.gowrap1() /tmp/workdir/go/src/runtime/mgc.go:203 +0x21 fp=0x66995ff0 sp=0x66995fe8 pc=0x8064321 runtime.goexit({}) /tmp/workdir/go/src/runtime/asm_386.s:1386 +0x1 fp=0x66995ff4 sp=0x66995ff0 pc=0x80c3211 created by runtime.gcenable in goroutine 1 /tmp/workdir/go/src/runtime/mgc.go:203 +0x71 goroutine 4 gp=0x668066c8 m=nil [runnable]: runtime.gopark(0x82a4374, 0x8432260, 0x13, 0xe, 0x2) /tmp/workdir/go/src/runtime/proc.go:458 +0xfa fp=0x66847f68 sp=0x66847f54 pc=0x80bd11a runtime.goparkunlock(...) /tmp/workdir/go/src/runtime/proc.go:464 runtime.(*scavengerState).sleep(0x8432260, 0x412ea2c400000000) /tmp/workdir/go/src/runtime/mgcscavenge.go:504 +0x149 fp=0x66847fcc sp=0x66847f68 pc=0x80703d9 runtime.bgscavenge(0x6681e040) /tmp/workdir/go/src/runtime/mgcscavenge.go:662 +0xa0 fp=0x66847fe8 sp=0x66847fcc pc=0x8070860 runtime.gcenable.gowrap2() /tmp/workdir/go/src/runtime/mgc.go:204 +0x21 fp=0x66847ff0 sp=0x66847fe8 pc=0x80642e1 runtime.goexit({}) /tmp/workdir/go/src/runtime/asm_386.s:1386 +0x1 fp=0x66847ff4 sp=0x66847ff0 pc=0x80c3211 created by runtime.gcenable in goroutine 1 /tmp/workdir/go/src/runtime/mgc.go:204 +0xb1 goroutine 5 gp=0x66806c68 m=nil [finalizer wait, 3 minutes]: runtime.gopark(0x82a4228, 0x843e470, 0x10, 0xa, 0x1) /tmp/workdir/go/src/runtime/proc.go:458 +0xfa fp=0x66839f98 sp=0x66839f84 pc=0x80bd11a runtime.runFinalizersAndCleanups() /tmp/workdir/go/src/runtime/mfinal.go:198 +0xed fp=0x66839ff0 sp=0x66839f98 pc=0x80633cd runtime.goexit({}) /tmp/workdir/go/src/runtime/asm_386.s:1386 +0x1 fp=0x66839ff4 sp=0x66839ff0 pc=0x80c3211 created by runtime.createfing in goroutine 1 /tmp/workdir/go/src/runtime/mfinal.go:168 +0x5a goroutine 12 gp=0x66806fc8 m=nil [chan receive, 3 minutes]: runtime.gopark(0x82a4208, 0x6681e1f4, 0xe, 0x7, 0x2) /tmp/workdir/go/src/runtime/proc.go:458 +0xfa fp=0x66848d34 sp=0x66848d20 pc=0x80bd11a runtime.chanrecv(0x6681e1c0, 0x0, 0x1) /tmp/workdir/go/src/runtime/chan.go:664 +0x41a fp=0x66848d74 sp=0x66848d34 pc=0x8055e8a runtime.chanrecv1(0x6681e1c0, 0x0) /tmp/workdir/go/src/runtime/chan.go:506 +0x1c fp=0x66848d88 sp=0x66848d74 pc=0x8055a3c testing.(*T).Parallel(0x668070e8) /tmp/workdir/go/src/testing/testing.go:1580 +0x267 fp=0x66848e08 sp=0x66848d88 pc=0x8146f87 internal/trace_test.TestMMU(0x668070e8) /tmp/workdir/go/src/internal/trace/gc_test.go:28 +0x2c fp=0x66848f84 sp=0x66848e08 pc=0x821aadc testing.tRunner(0x668070e8, 0x82a4020) /tmp/workdir/go/src/testing/testing.go:1799 +0x10e fp=0x66848fe4 sp=0x66848f84 pc=0x81472ce testing.(*T).Run.gowrap1() /tmp/workdir/go/src/testing/testing.go:1858 +0x28 fp=0x66848ff0 sp=0x66848fe4 pc=0x81483c8 runtime.goexit({}) /tmp/workdir/go/src/runtime/asm_386.s:1386 +0x1 fp=0x66848ff4 sp=0x66848ff0 pc=0x80c3211 created by testing.(*T).Run in goroutine 1 /tmp/workdir/go/src/testing/testing.go:1858 +0x462 goroutine 10 gp=0x66807688 m=nil [GC worker (idle)]: runtime.gopark(0x82a4238, 0x66bfc000, 0x1b, 0xa, 0x0) /tmp/workdir/go/src/runtime/proc.go:458 +0xfa fp=0x66849f8c sp=0x66849f78 pc=0x80bd11a runtime.gcBgMarkWorker(0x6681fd00) /tmp/workdir/go/src/runtime/mgc.go:1437 +0xeb fp=0x66849fe8 sp=0x66849f8c pc=0x8066dab runtime.gcBgMarkStartWorkers.gowrap1() /tmp/workdir/go/src/runtime/mgc.go:1347 +0x21 fp=0x66849ff0 sp=0x66849fe8 pc=0x8066ca1 runtime.goexit({}) /tmp/workdir/go/src/runtime/asm_386.s:1386 +0x1 fp=0x66849ff4 sp=0x66849ff0 pc=0x80c3211 created by runtime.gcBgMarkStartWorkers in goroutine 9 /tmp/workdir/go/src/runtime/mgc.go:1347 +0x114 goroutine 131 gp=0x66807328 m=nil [chan receive]: runtime.gopark(0x82a4208, 0x6681e4b4, 0xe, 0x7, 0x2) /tmp/workdir/go/src/runtime/proc.go:458 +0xfa fp=0x66846e5c sp=0x66846e48 pc=0x80bd11a runtime.chanrecv(0x6681e480, 0x66846ed7, 0x1) /tmp/workdir/go/src/runtime/chan.go:664 +0x41a fp=0x66846e9c sp=0x66846e5c pc=0x8055e8a runtime.chanrecv1(0x6681e480, 0x66846ed7) /tmp/workdir/go/src/runtime/chan.go:506 +0x1c fp=0x66846eb0 sp=0x66846e9c pc=0x8055a3c testing.(*T).Run(0x670c1448, {0x6681aa3a, 0x10}, 0x6696c288) /tmp/workdir/go/src/testing/testing.go:1866 +0x481 fp=0x66846f38 sp=0x66846eb0 pc=0x8148281 internal/trace_test.TestTraceV1(0x670c1448) /tmp/workdir/go/src/internal/trace/tracev1_test.go:28 +0xe5 fp=0x66846f84 sp=0x66846f38 pc=0x8222ba5 testing.tRunner(0x670c1448, 0x82a406c) /tmp/workdir/go/src/testing/testing.go:1799 +0x10e fp=0x66846fe4 sp=0x66846f84 pc=0x81472ce testing.(*T).Run.gowrap1() /tmp/workdir/go/src/testing/testing.go:1858 +0x28 fp=0x66846ff0 sp=0x66846fe4 pc=0x81483c8 runtime.goexit({}) /tmp/workdir/go/src/runtime/asm_386.s:1386 +0x1 fp=0x66846ff4 sp=0x66846ff0 pc=0x80c3211 created by testing.(*T).Run in goroutine 1 /tmp/workdir/go/src/testing/testing.go:1858 +0x462 goroutine 135 gp=0x66aae488 m=nil [runnable]: internal/trace/internal/tracev1.(*orderEventList).Pop(0x66893700) /tmp/workdir/go/src/internal/trace/internal/tracev1/order.go:134 +0x155 fp=0x668934d4 sp=0x668934d0 pc=0x81d8db5 internal/trace/internal/tracev1.(*parser).parseEventBatches(0x668f9c80) /tmp/workdir/go/src/internal/trace/internal/tracev1/parser.go:466 +0x48b fp=0x66893868 sp=0x668934d4 pc=0x81d9f7b internal/trace/internal/tracev1.(*parser).parse(0x668f9c80) /tmp/workdir/go/src/internal/trace/internal/tracev1/parser.go:211 +0x1d0 fp=0x6689390c sp=0x66893868 pc=0x81d9540 internal/trace/internal/tracev1.Parse({0x82e4ff0, 0x669a0030}, 0xb) /tmp/workdir/go/src/internal/trace/internal/tracev1/parser.go:175 +0x96 fp=0x66893988 sp=0x6689390c pc=0x81d9316 internal/trace.NewReader({0x82e4fa0, 0x668223e0}) /tmp/workdir/go/src/internal/trace/reader.go:50 +0x19e fp=0x66893a60 sp=0x66893988 pc=0x81fadfe internal/trace_test.TestTraceV1.func1(0x669bc008) /tmp/workdir/go/src/internal/trace/tracev1_test.go:35 +0x193 fp=0x66893f84 sp=0x66893a60 pc=0x8222ea3 testing.tRunner(0x669bc008, 0x6696c288) /tmp/workdir/go/src/testing/testing.go:1799 +0x10e fp=0x66893fe4 sp=0x66893f84 pc=0x81472ce testing.(*T).Run.gowrap1() /tmp/workdir/go/src/testing/testing.go:1858 +0x28 fp=0x66893ff0 sp=0x66893fe4 pc=0x81483c8 runtime.goexit({}) /tmp/workdir/go/src/runtime/asm_386.s:1386 +0x1 fp=0x66893ff4 sp=0x66893ff0 pc=0x80c3211 created by testing.(*T).Run in goroutine 131 /tmp/workdir/go/src/testing/testing.go:1858 +0x462 FAIL internal/trace 180.181s FAIL go tool dist: Failed: exit status 1