diff --git a/.github/actions/setup-deps/action.yml b/.github/actions/setup-deps/action.yml index 22300a0c1c..ff4e478d80 100644 --- a/.github/actions/setup-deps/action.yml +++ b/.github/actions/setup-deps/action.yml @@ -535,6 +535,9 @@ runs: # the ARM64 runner. The x64 runner keeps CLANG64 as the LLGo host even # when R11 activates a separate llvm-mingw 386 target afterwards. msystem: ${{ inputs.windows-arch == 'arm64' && 'CLANGARM64' || 'CLANG64' }} + # ARM64 images initialize MSYS2 before the job starts. Reuse that + # installation instead of bootstrapping an x64 base under emulation. + release: ${{ runner.arch != 'ARM64' }} path-type: inherit update: true install: pacman-contrib diff --git a/.github/scripts/test_ci_workflows.py b/.github/scripts/test_ci_workflows.py index 558b44677e..35297a5db7 100644 --- a/.github/scripts/test_ci_workflows.py +++ b/.github/scripts/test_ci_workflows.py @@ -3,11 +3,13 @@ import json import os from pathlib import Path +import runpy import shutil import subprocess import sys import tempfile import unittest +from unittest import mock import yaml @@ -79,7 +81,12 @@ def test_intel_macos_runs_both_native_debuggers(self): self.assertIn("test/debug/runtime/runtest.sh -v", commands) self.assertIn("^TestGDBIntegration$", commands) self.assertNotIn("^TestGDBCompleteWorkerUnwind$", commands) - self.assertIn("exec sudo -n", commands) + self.assertIn("test/debug/runtime/gdb_darwin.py", commands) + self.assertNotIn("sudo", commands) + helper = runpy.run_path(str(WORKFLOWS.parents[1] / "test/debug/runtime/gdb_darwin.py")) + with mock.patch("os.execvp", side_effect=SystemExit) as execute, self.assertRaises(SystemExit): + helper["main"]("/native/gdb", ["--version"]) + execute.assert_called_once_with("sudo", ["sudo", "-n", "/native/gdb", "--version"]) self.assertNotIn("continue-on-error", job) self.assertTrue(all("continue-on-error" not in step for step in job["steps"])) diff --git a/.github/workflows/llgo.yml b/.github/workflows/llgo.yml index 44dc968f81..4d2e8a2074 100644 --- a/.github/workflows/llgo.yml +++ b/.github/workflows/llgo.yml @@ -614,12 +614,12 @@ jobs: shell: bash run: | set -euo pipefail - # Unsigned Homebrew GDB cannot obtain the inferior's task port as - # the runner user. Elevate only the debugger, not builds or Go tests. - # This does not change host trust settings or pretend Apple Silicon - # has the native Darwin process backend. + # GDB's Darwin fork/exec can block in wait4 at _dyld_start. Spawn + # suspended, then use native attach with the same test assertions. + # Elevate only GDB to obtain task ports on the ephemeral runner. wrapper="$RUNNER_TEMP/llgo-gdb-native" - printf '#!/bin/bash\nexec sudo -n %q "$@"\n' "$LLGO_GDB" > "$wrapper" + printf '#!/bin/bash\nexec python3 %q %q "$@"\n' \ + "$GITHUB_WORKSPACE/test/debug/runtime/gdb_darwin.py" "$LLGO_GDB" > "$wrapper" chmod +x "$wrapper" "$wrapper" --batch --nx -ex 'python import gdb; print(gdb.VERSION)' echo "LLGO_GDB=$wrapper" >> "$GITHUB_ENV" diff --git a/.github/workflows/test_windows_runtime.ps1 b/.github/workflows/test_windows_runtime.ps1 index b0e354ecf7..24f5e0aef7 100644 --- a/.github/workflows/test_windows_runtime.ps1 +++ b/.github/workflows/test_windows_runtime.ps1 @@ -91,9 +91,22 @@ foreach ($artifact in @($runtime, $stdlib, $ffi, $empty, $coreFault, $network)) } Write-Host "==> windows-runtime-smoke.exe" -& $runtime -if ($LASTEXITCODE -ne 0) { - throw "windows-runtime-smoke.exe exited with code $LASTEXITCODE" +$runtimeStdout = Join-Path $out "runtime.stdout" +$runtimeStderr = Join-Path $out "runtime.stderr" +$runtimeProcess = Start-Process -FilePath $runtime -NoNewWindow -PassThru ` + -RedirectStandardOutput $runtimeStdout -RedirectStandardError $runtimeStderr +if (-not $runtimeProcess.WaitForExit(60000)) { + $runtimeProcess.Kill() + throw "windows-runtime-smoke.exe did not terminate after main returned" +} +$runtimeProcess.WaitForExit() +Get-Content $runtimeStdout +Get-Content $runtimeStderr +if ($runtimeProcess.ExitCode -ne 0) { + throw "windows-runtime-smoke.exe exited with code $($runtimeProcess.ExitCode)" +} +if (-not (Get-Content -Raw $runtimeStdout).Contains("windows C stdio smoke: ok")) { + throw "normal Windows main return lost buffered C stdio output" } Write-Host "==> windows-runtime-smoke.exe (unrecovered fault)" diff --git a/internal/build/main_module.go b/internal/build/main_module.go index 0527d3d5fa..1d3f2af441 100644 --- a/internal/build/main_module.go +++ b/internal/build/main_module.go @@ -137,9 +137,13 @@ func genMainModule(ctx *context, rtPkgPath string, pkg *packages.Package, cfg *g if cfg.rtInit || wasmRuntimeScheduler { rtInit = declareNoArgFunc(mainPkg, rtPkgPath+".init") } - var processExit llssa.Function + var processExit, stdioFlush llssa.Function if ctx.buildConf.Goos == "windows" { processExit = declareRuntimeExit(mainPkg, "runtime.exit") + stdioFlush = mainPkg.NewFunc("fflush", newSignature( + []types.Type{types.Typ[types.UnsafePointer]}, + []types.Type{types.Typ[types.Int32]}, + ), llssa.InC) } var abiInit llssa.Function @@ -223,6 +227,7 @@ func genMainModule(ctx *context, rtPkgPath string, pkg *packages.Package, cfg *g pyFinalize: pyFinalize, rtInit: rtInit, processExit: processExit, + stdioFlush: stdioFlush, coverageExit: coverageExit, abiInit: abiInit, packageInits: packageInits, @@ -449,6 +454,7 @@ type entryFunctions struct { pyFinalize llssa.Function rtInit llssa.Function processExit llssa.Function + stdioFlush llssa.Function coverageExit llssa.Function abiInit llssa.Function packageInits []llssa.Function @@ -549,10 +555,10 @@ func emitRuntimeMainBody(b llssa.Builder, fns entryFunctions) { b.Call(fns.coverageExit.Expr, b.Prog.IntVal(0, b.Prog.Int())) } if fns.processExit != nil { - // Go terminates the process as soon as main returns, regardless of - // other goroutines. On Windows, call runtime.exit (ExitProcess) rather - // than returning through CRT teardown, which may wait on runtime-owned - // threads and violates that guarantee. + // Preserve normal C-main stdio flushing before immediate Go termination. + // Flush while the other threads can still release their stream locks; + // DLL_PROCESS_DETACH after killing them cannot safely do that cleanup. + b.Call(fns.stdioFlush.Expr, b.Prog.Nil(b.Prog.VoidPtr())) b.Call(fns.processExit.Expr, b.Prog.IntVal(0, b.Prog.Int32())) } } diff --git a/internal/build/main_module_test.go b/internal/build/main_module_test.go index 10d0788b1e..7df2e73f64 100644 --- a/internal/build/main_module_test.go +++ b/internal/build/main_module_test.go @@ -96,6 +96,7 @@ func TestGenMainModuleWindowsExitsAfterMain(t *testing.T) { ir := mod.LPkg.String() assertInOrder(t, ir, `call void @"example.com/foo.main"()`, + `call i32 @fflush(ptr null)`, `call void @runtime.exit(i32 0)`, ) } @@ -131,7 +132,7 @@ func TestGenMainModuleCoverageExit(t *testing.T) { `call void @runtime.runCoverageExitHook(i64 0)`, } if goos == "windows" { - order = append(order, `call void @runtime.exit(i32 0)`) + order = append(order, `call i32 @fflush(ptr null)`, `call void @runtime.exit(i32 0)`) } assertInOrder(t, ir, order...) } diff --git a/runtime/_test/windowsruntime/main.go b/runtime/_test/windowsruntime/main.go index 226dbae139..b90004fa6f 100644 --- a/runtime/_test/windowsruntime/main.go +++ b/runtime/_test/windowsruntime/main.go @@ -6,6 +6,7 @@ import ( "time" "unsafe" + c "github.com/xgo-dev/llgo/runtime/internal/clite" nativesync "github.com/xgo-dev/llgo/runtime/internal/sync" // The smoke package lives below the LLGo runtime root, whose packages are // excluded from the ordinary need-runtime signal. Import the core runtime @@ -366,4 +367,6 @@ func main() { }() <-lingeringStarted println("windows runtime smoke: ok") + // The parent redirects stdout, so this remains buffered until main returns. + c.Printf(c.Str("windows C stdio smoke: ok\n")) } diff --git a/runtime/internal/runtime/os_windows.go b/runtime/internal/runtime/os_windows.go index c09b8851b8..35522e002c 100644 --- a/runtime/internal/runtime/os_windows.go +++ b/runtime/internal/runtime/os_windows.go @@ -22,7 +22,6 @@ import ( "unsafe" c "github.com/xgo-dev/llgo/runtime/internal/clite" - cliteos "github.com/xgo-dev/llgo/runtime/internal/clite/os" psync "github.com/xgo-dev/llgo/runtime/internal/sync" "github.com/xgo-dev/llgo/runtime/internal/sync/atomic" "github.com/xgo-dev/llgo/runtime/internal/thread" @@ -40,22 +39,21 @@ type mOS struct { // processExiting is non-zero after runtime.exit or syscall.Exit starts // terminating the process. It serves the same purpose as exiting in the Go // runtime. The thread backend separately records the same transition before -// Windows starts running FLS process-shutdown callbacks. +// native process shutdown. var processExiting uint32 // processExitLock is used only to freeze a thread until ExitProcess terminates // it. Its zero value is a ready-to-use Windows SRW lock. var processExitLock psync.Mutex -// ExitProcess marks the runtime as exiting before asking Windows to terminate -// all process threads. Keep every Go-facing process exit path behind this +// ExitProcess marks the runtime as exiting before immediate native process +// termination. Keep every Go-facing process exit path behind this // helper so newosproc can distinguish shutdown from a real resource failure. // //go:nosplit func ExitProcess(code uint32) { atomic.Store(&processExiting, 1) - thread.BeginProcessExit() - cliteos.ExitProcess(code) + thread.ExitProcess(code) } //go:linkname runtime_exit runtime.exit diff --git a/runtime/internal/thread/_wrap/thread_windows.c b/runtime/internal/thread/_wrap/thread_windows.c index d28d253b4d..f785a19370 100644 --- a/runtime/internal/thread/_wrap/thread_windows.c +++ b/runtime/internal/thread/_wrap/thread_windows.c @@ -25,6 +25,10 @@ __declspec(dllimport) llgo_handle LLGO_WINAPI CreateThread( void *attributes, llgo_size_t stack_size, llgo_win_thread_start start, void *arg, llgo_dword flags, llgo_dword *thread_id); __declspec(dllimport) void LLGO_WINAPI ExitThread(llgo_dword exit_code); +__declspec(dllimport) void LLGO_WINAPI ExitProcess(llgo_dword exit_code); +__declspec(dllimport) llgo_handle LLGO_WINAPI GetCurrentProcess(void); +__declspec(dllimport) llgo_bool LLGO_WINAPI +TerminateProcess(llgo_handle process, llgo_uint exit_code); __declspec(dllimport) llgo_bool LLGO_WINAPI CloseHandle(llgo_handle handle); __declspec(dllimport) llgo_dword LLGO_WINAPI GetLastError(void); __declspec(dllimport) llgo_handle LLGO_WINAPI GetProcessHeap(void); @@ -59,9 +63,20 @@ enum { * deliberately retained sidecar allocation. */ static llgo_dword llgo_process_exiting; -void llgo_win_thread_begin_process_exit(void) +void llgo_win_thread_exit_process(llgo_dword exit_code) { __atomic_store_n(&llgo_process_exiting, 1, __ATOMIC_RELEASE); + /* Go process exit must not wait for other goroutines or DLL callbacks. + * ExitProcess kills the other threads before DLL_PROCESS_DETACH; a DLL + * cleanup callback can then wait on a lock held by a killed thread. Native + * gcgort stress gets stuck inside LdrShutdownProcess. Self-termination + * skips that unsafe teardown and does not return. + * See Microsoft's ExitProcess documentation on shutdown with unknown + * thread state. Go exit hooks run before this call. */ + TerminateProcess(GetCurrentProcess(), (llgo_uint)exit_code); + /* The current-process pseudo-handle has termination rights. Retain the + * normal exit path only if self-termination unexpectedly fails. */ + ExitProcess(exit_code); } typedef void *(*llgo_thread_routine)(void *arg); diff --git a/runtime/internal/thread/thread_windows.go b/runtime/internal/thread/thread_windows.go index 3f367fe529..54df36f5dd 100644 --- a/runtime/internal/thread/thread_windows.go +++ b/runtime/internal/thread/thread_windows.go @@ -44,8 +44,8 @@ func createDetached(stackSize uintptr, routine RoutineFunc, arg c.Pointer) c.Int //go:linkname exit C.llgo_win_thread_exit func exit() -//go:linkname beginProcessExit C.llgo_win_thread_begin_process_exit -func beginProcessExit() +//go:linkname exitProcess C.llgo_win_thread_exit_process +func exitProcess(code c.Uint) //go:linkname keyCreate C.llgo_win_fls_create func keyCreate(index *c.Uint) c.Int @@ -71,10 +71,10 @@ func Exit() { exit() } -// BeginProcessExit prevents Windows process shutdown from invoking Go or -// BDWGC through the FLS lifecycle callback. -func BeginProcessExit() { - beginProcessExit() +// ExitProcess terminates the current process without DLL or FLS teardown. +// Such callbacks can deadlock after Windows has killed their lock owners. +func ExitProcess(code uint32) { + exitProcess(c.Uint(code)) } func (key *Key) Create(destructor KeyDestructor) c.Int { diff --git a/test/debug/README.md b/test/debug/README.md index 989edbf1a8..e3a8ffa12f 100644 --- a/test/debug/README.md +++ b/test/debug/README.md @@ -59,8 +59,10 @@ modules exclude these programs from root-module `go test ./test/...` and `llgo test ./test/...` enumeration. The LLGo workflow invokes the LLDB suite in its native platform jobs and the GDB suite in its Linux and all six Windows ABI/architecture jobs. A separate -Intel macOS job exercises both debuggers; its GDB wrapper uses the ephemeral -runner's passwordless sudo permission to obtain native task ports. +Intel macOS job exercises both debuggers; its GDB wrapper starts the executable +suspended with `posix_spawn`, then attaches natively using the ephemeral runner's +passwordless sudo permission to obtain task ports. This avoids GDB's Darwin +fork/exec startup hang while preserving the complete values/registry gate. The Windows debugger is installed separately from the pinned compiler and LLDB dependencies. Apple Silicon has no native GDB process target: use LLDB there; GDB remote debugging remains available. Unit tests and package-specific `testdata` remain diff --git a/test/debug/runtime/gdb.md b/test/debug/runtime/gdb.md index 4263402b6d..a59098858f 100644 --- a/test/debug/runtime/gdb.md +++ b/test/debug/runtime/gdb.md @@ -48,9 +48,13 @@ Darwin GDB uses debugger-local Mach ports in its native thread identifiers. The adapter asks the host kernel for each port's system thread ID so that it can match the runtime registry. Remote target identifiers are not passed to host Mach APIs. Intel macOS native launch additionally needs a debugger with -permission to obtain task ports. The dedicated Intel CI job runs only GDB -through an explicit `sudo -n` wrapper on its ephemeral runner; compilation and -Go test orchestration remain unprivileged. It also runs the full native LLDB +permission to obtain task ports. The dedicated Intel CI job launches the executable +suspended with Darwin's `posix_spawn`, then uses GDB's native attach path. This +avoids GDB 17's fork/exec hang in `decode_message`/`wait4` before `_dyld_start` +executes. The helper preserves GDB's normal disabled-ASLR layout and all +acceptance assertions, and reaps the inferior after GDB finishes. Only GDB runs +through `sudo -n` on the ephemeral runner; compilation and Go test orchestration +remain unprivileged. It also runs the full native LLDB suite using Apple's signed `/usr/bin/lldb`. Apple Silicon GDB native process debugging is not supported; the native acceptance command reports that limitation directly. `llgo gdb` still supports cross-target/remote sessions on Apple Silicon. diff --git a/test/debug/runtime/gdb_darwin.py b/test/debug/runtime/gdb_darwin.py new file mode 100644 index 0000000000..58c3df96f1 --- /dev/null +++ b/test/debug/runtime/gdb_darwin.py @@ -0,0 +1,80 @@ +# Copyright (c) 2026 The XGo Authors (xgo.dev). All rights reserved. +# Licensed under the Apache License, Version 2.0. + +"""Launch native Darwin GDB acceptance through a suspended posix_spawn. + +GDB 17's own fork/exec path can block in decode_message's wait4 while the +inferior is stopped at _dyld_start. Its attach path avoids that handshake. +The inferior, native GDB transport, breakpoints and assertions stay the same. +""" + +import ctypes +import os +import signal +import subprocess +import sys + + +def spawn_suspended(executable): + system = ctypes.CDLL("/usr/lib/libSystem.B.dylib") + attr_pointer = ctypes.POINTER(ctypes.c_void_p) + strings = ctypes.POINTER(ctypes.c_char_p) + for name in ("posix_spawnattr_init", "posix_spawnattr_destroy"): + getattr(system, name).argtypes = [attr_pointer] + system.posix_spawnattr_setflags.argtypes = [attr_pointer, ctypes.c_short] + system.posix_spawn.argtypes = [ctypes.POINTER(ctypes.c_int), ctypes.c_char_p, + ctypes.c_void_p, attr_pointer, strings, strings] + + def check(error): + if error: + raise OSError(error, os.strerror(error)) + + attributes = ctypes.c_void_p() + check(system.posix_spawnattr_init(ctypes.byref(attributes))) + try: + # START_SUSPENDED (sys/spawn.h) plus DISABLE_ASLR, matching GDB's + # normal Darwin launch. GDB 17 cannot relocate dyld 17 images. + check(system.posix_spawnattr_setflags(ctypes.byref(attributes), 0x0180)) + argv = (ctypes.c_char_p * 2)(os.fsencode(executable), None) + values = [os.fsencode(key + "=" + value) + for key, value in os.environ.items()] + environ = (ctypes.c_char_p * (len(values) + 1))(*values, None) + pid = ctypes.c_int() + check(system.posix_spawn(ctypes.byref(pid), argv[0], None, + ctypes.byref(attributes), argv, environ)) + return pid.value + finally: + check(system.posix_spawnattr_destroy(ctypes.byref(attributes))) + + +def main(gdb, args): + launches = [i for i in range(1, len(args)) + if args[i - 1] == "-ex" and args[i] == "run"] + command = ["sudo", "-n", gdb] + if not launches: + # Version/Python probes and the non-running C fallback fixtures. + os.execvp(command[0], command + args) + if len(launches) != 1 or "--batch" not in args: + raise ValueError("expected one batch acceptance launch") + index = args.index("--batch") + 1 + executable = args[index] + pid = spawn_suspended(executable) + try: + args[launches[0]] = "continue" + # Clear the BSD stop after GDB has installed its Mach suspension. + # The program remains stopped until the original first run command. + args[index + 1:index + 1] = [ + "-ex", "attach " + str(pid), + "-ex", "python import os, signal; os.kill(" + str(pid) + ", signal.SIGCONT)", + ] + return subprocess.call(command + args) + finally: + try: + os.kill(pid, signal.SIGKILL) + except ProcessLookupError: + pass + os.waitpid(pid, 0) + + +if __name__ == "__main__": + sys.exit(main(sys.argv[1], sys.argv[2:])) diff --git a/test/go/windows_exit_gc_test.go b/test/go/windows_exit_gc_test.go new file mode 100644 index 0000000000..e606bab856 --- /dev/null +++ b/test/go/windows_exit_gc_test.go @@ -0,0 +1,71 @@ +//go:build windows && !nogc + +package gotest + +import ( + "context" + "os" + "os/exec" + "runtime" + "strconv" + "sync/atomic" + "testing" + "time" +) + +var windowsExitGCObjects [8][]byte + +func TestWindowsExitDuringGC(t *testing.T) { + const helperEnv = "LLGO_TEST_WINDOWS_EXIT_GC" + if value := os.Getenv(helperEnv); value != "" { + iteration, err := strconv.Atoi(value) + if err != nil { + t.Fatal(err) + } + ready := make(chan struct{}, len(windowsExitGCObjects)+1) + start := make(chan struct{}) + for i := range windowsExitGCObjects { + go func(i int) { + ready <- struct{}{} + <-start + for range 256 { + windowsExitGCObjects[i] = make([]byte, 4096) + } + }(i) + } + var collecting uint32 + go func() { + ready <- struct{}{} + <-start + atomic.StoreUint32(&collecting, 1) + runtime.GC() + }() + for range len(windowsExitGCObjects) + 1 { + <-ready + } + close(start) + for atomic.LoadUint32(&collecting) == 0 { + } + // Vary exit timing without allocating or starting the timer scheduler. + // Bound background work so the test isolates shutdown, not starvation + // under a collector loop that never lets other threads acquire its lock. + for range iteration % 4 * 10000 { + atomic.LoadUint32(&collecting) + } + os.Exit(iteration % 2 * 23) + } + + for iteration := range 32 { + ctx, cancel := context.WithTimeout(context.Background(), 20*time.Second) + cmd := exec.CommandContext(ctx, os.Args[0], "-test.run=^TestWindowsExitDuringGC$") + cmd.Env = append(os.Environ(), helperEnv+"="+strconv.Itoa(iteration)) + output, err := cmd.CombinedOutput() + timedOut := ctx.Err() != nil + cancel() + want := iteration % 2 * 23 + if timedOut || cmd.ProcessState == nil || cmd.ProcessState.ExitCode() != want { + t.Fatalf("iteration %d: child err=%v, state=%v, timeout=%v, want exit %d\n%s", + iteration, err, cmd.ProcessState, timedOut, want, output) + } + } +} diff --git a/test/goroot/env_windows_test.go b/test/goroot/env_windows_test.go new file mode 100644 index 0000000000..e72388934c --- /dev/null +++ b/test/goroot/env_windows_test.go @@ -0,0 +1,57 @@ +//go:build windows + +package goroot + +import ( + "os" + "os/exec" + "path/filepath" + "strings" + "testing" + "time" +) + +func TestRunnerEnvPreservesWindowsPath(t *testing.T) { + if os.Getenv("LLGO_GOROOT_PATH_HELPER") == "1" { + if _, err := exec.LookPath("cmd.exe"); err != nil { + os.Exit(1) + } + return + } + executable, err := os.Executable() + if err != nil { + t.Fatal(err) + } + inherited := os.Getenv("PATH") + for _, item := range os.Environ() { + key, _, _ := strings.Cut(item, "=") + if strings.EqualFold(key, "PATH") { + t.Cleanup(func() { + _ = os.Unsetenv("PATH") + _ = os.Setenv(key, inherited) + }) + break + } + } + for _, key := range []string{"PATH", "Path", "pAtH"} { + t.Run(key, func(t *testing.T) { + t.Setenv("PATH", inherited) + // Windows retains an environment variable's original spelling + // when updating it, so remove the old entry before renaming it. + if err := os.Unsetenv("PATH"); err != nil { + t.Fatal(err) + } + if err := os.Setenv(key, inherited); err != nil { + t.Fatal(err) + } + root := t.TempDir() + env := runnerEnv(root, root, filepath.Join(root, "gopath"), + []string{"LLGO_GOROOT_PATH_HELPER=1"}) + _, stderr, code, _, err := runProgram(root, executable, env, 5*time.Second, + "-test.run=^TestRunnerEnvPreservesWindowsPath$", "-test.count=1") + if err != nil || code != 0 { + t.Fatalf("child lost the inherited %s: exit=%d err=%v stderr=%s", key, code, err, strings.TrimSpace(string(stderr))) + } + }) + } +} diff --git a/test/goroot/proc_identity_windows_test.go b/test/goroot/proc_identity_windows_test.go new file mode 100644 index 0000000000..a068ba17c7 --- /dev/null +++ b/test/goroot/proc_identity_windows_test.go @@ -0,0 +1,83 @@ +//go:build windows + +package goroot + +import ( + "os" + "os/exec" + "testing" + "time" + + "golang.org/x/sys/windows" +) + +func TestWindowsProcessIdentityHelper(t *testing.T) { + switch os.Getenv("LLGO_GOROOT_WINDOWS_PROCESS_HELPER") { + case "exit": + os.Exit(0) + case "sleep": + time.Sleep(time.Minute) + os.Exit(0) + } +} + +func startWindowsIdentityHelper(t *testing.T, mode string) (*exec.Cmd, *processTree) { + t.Helper() + cmd := exec.Command(os.Args[0], "-test.run=^TestWindowsProcessIdentityHelper$") + cmd.Env = append(os.Environ(), "LLGO_GOROOT_WINDOWS_PROCESS_HELPER="+mode) + if err := cmd.Start(); err != nil { + t.Fatal(err) + } + tree, err := newProcessTree(cmd) + if err != nil { + _ = cmd.Process.Kill() + _ = cmd.Wait() + t.Fatal(err) + } + t.Cleanup(func() { + tree.kill() + _ = cmd.Wait() + tree.close() + }) + return cmd, tree +} + +func TestWindowsProcessIdentitySurvivesWait(t *testing.T) { + guardTestTimeout(t) + cmd, tree := startWindowsIdentityHelper(t, "exit") + if err := cmd.Wait(); err != nil { + t.Fatal(err) + } + created, err := windowsProcessCreationTime(tree.handle) + if err != nil || created != tree.creationTime { + t.Fatalf("identity after Wait = %d, %v; want %d", created, err, tree.creationTime) + } + if _, err := tree.rss(); err != nil { + t.Fatalf("snapshot after Wait: %v", err) + } + tree.close() + if _, err := tree.rss(); err == nil { + t.Fatal("closed process tree still accepts snapshots") + } +} + +func TestWindowsProcessTerminationRejectsReusedPID(t *testing.T) { + guardTestTimeout(t) + cmd, tree := startWindowsIdentityHelper(t, "sleep") + if rss, err := tree.rss(); err != nil || rss == 0 { + t.Fatalf("live process RSS = %d, %v; want a valid matching snapshot", rss, err) + } + terminateWindowsProcess(tree.rootPID, tree.creationTime-1) + var code uint32 + if err := windows.GetExitCodeProcess(tree.handle, &code); err != nil { + t.Fatal(err) + } + const stillActive = 259 // STILL_ACTIVE from GetExitCodeProcess. + if code != stillActive { + t.Fatalf("process with a different identity was terminated: exit code %d", code) + } + terminateWindowsProcess(tree.rootPID, tree.creationTime) + if err := cmd.Wait(); err == nil { + t.Fatal("matching process identity was not terminated") + } +} diff --git a/test/goroot/proc_other_test.go b/test/goroot/proc_other_test.go index a889231aad..2d86e612ff 100644 --- a/test/goroot/proc_other_test.go +++ b/test/goroot/proc_other_test.go @@ -6,7 +6,20 @@ import "os/exec" func configureProcessGroup(cmd *exec.Cmd) {} -func killProcessTree(cmd *exec.Cmd) { +type processTree struct { + cmd *exec.Cmd +} + +func newProcessTree(cmd *exec.Cmd) (*processTree, error) { + return &processTree{cmd: cmd}, nil +} + +func (tree *processTree) close() {} + +func (tree *processTree) rss() (uint64, error) { return 0, nil } + +func (tree *processTree) kill() { + cmd := tree.cmd if cmd.Process == nil { return } @@ -14,5 +27,3 @@ func killProcessTree(cmd *exec.Cmd) { } func resourceMonitoringSupported() bool { return false } - -func processGroupRSS(int) (uint64, error) { return 0, nil } diff --git a/test/goroot/proc_unix_test.go b/test/goroot/proc_unix_test.go index 95f94c4fdd..4ac698782d 100644 --- a/test/goroot/proc_unix_test.go +++ b/test/goroot/proc_unix_test.go @@ -23,7 +23,22 @@ func configureProcessGroup(cmd *exec.Cmd) { cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true} } -func killProcessTree(cmd *exec.Cmd) { +type processTree struct { + cmd *exec.Cmd +} + +func newProcessTree(cmd *exec.Cmd) (*processTree, error) { + return &processTree{cmd: cmd}, nil +} + +func (tree *processTree) close() {} + +func (tree *processTree) rss() (uint64, error) { + return processGroupRSS(tree.cmd.Process.Pid) +} + +func (tree *processTree) kill() { + cmd := tree.cmd if cmd.Process == nil { return } @@ -45,7 +60,13 @@ func processGroupRSS(processGroupID int) (uint64, error) { } result := make(chan queryResult, 1) go func() { - output, err := exec.CommandContext(ctx, "ps", "-axo", "pgid=,rss=").Output() + args := []string{"-axo", "pgid=,rss="} + if runtime.GOOS == "darwin" { + // Reading RSS for every process can stall on unrelated Mach tasks. + // BSD ps -g selects the entire process group, including descendants. + args = []string{"-g", strconv.Itoa(processGroupID), "-o", "pgid=,rss="} + } + output, err := exec.CommandContext(ctx, "ps", args...).Output() result <- queryResult{output, err} }() var output []byte @@ -106,25 +127,27 @@ func TestProcessGroupRSSQueryIsBounded(t *testing.T) { func TestRunProgramDeadlineAfterSlowRSSQuery(t *testing.T) { disableSystemMemoryLimits(t) dir := t.TempDir() - if err := os.WriteFile(filepath.Join(dir, "ps"), []byte("#!/bin/sh\nexec /bin/sleep 2\n"), 0o755); err != nil { + if err := os.WriteFile(filepath.Join(dir, "ps"), []byte("#!/bin/sh\nexec /bin/sleep 6\n"), 0o755); err != nil { t.Fatal(err) } t.Setenv("PATH", dir+string(os.PathListSeparator)+os.Getenv("PATH")) previousTimeout, previousPoll := processRSSQueryTimeout, *flagRSSPoll - processRSSQueryTimeout, *flagRSSPoll = 400*time.Millisecond, 5*time.Millisecond + processRSSQueryTimeout, *flagRSSPoll = 5*time.Second, 5*time.Millisecond t.Cleanup(func() { processRSSQueryTimeout, *flagRSSPoll = previousTimeout, previousPoll }) // Both children exit while sampling is still running. Their actual wait // completion time decides the deadline, rather than select's random pick. + // Leave seconds of scheduling headroom for the before-deadline child: + // a 150ms deadline can expire under concurrent CI coverage workloads. for _, tc := range []struct { name, sleep string wantTimeout bool }{ {"before-deadline", "0.05", false}, - {"after-deadline", "0.25", true}, + {"after-deadline", "4", true}, } { t.Run(tc.name, func(t *testing.T) { _, _, exitCode, _, err := runProgram(t.TempDir(), "/bin/sh", os.Environ(), - 150*time.Millisecond, "-c", "sleep "+tc.sleep) + 3*time.Second, "-c", "sleep "+tc.sleep) if tc.wantTimeout { if err == nil || !strings.Contains(err.Error(), "timed out after") { t.Fatalf("late child error = %v, want timeout", err) diff --git a/test/goroot/proc_windows_test.go b/test/goroot/proc_windows_test.go index b48e60cac7..625522277b 100644 --- a/test/goroot/proc_windows_test.go +++ b/test/goroot/proc_windows_test.go @@ -4,58 +4,104 @@ package goroot import ( "fmt" + "os" "os/exec" - "reflect" - "sort" "syscall" - "testing" "unsafe" "golang.org/x/sys/windows" ) -type windowsProcessInfo struct { - parentPID uint32 - rss uint64 -} - func configureProcessGroup(cmd *exec.Cmd) { cmd.SysProcAttr = &syscall.SysProcAttr{CreationFlags: windows.CREATE_NEW_PROCESS_GROUP} } -func killProcessTree(cmd *exec.Cmd) { - if cmd.Process == nil { +type processTree struct { + rootPID uint32 + handle windows.Handle + creationTime int64 +} + +func newProcessTree(cmd *exec.Cmd) (*processTree, error) { + rootPID := uint32(cmd.Process.Pid) + handle, err := windows.OpenProcess(windows.PROCESS_QUERY_LIMITED_INFORMATION|windows.PROCESS_TERMINATE, false, rootPID) + if err != nil { + return nil, err + } + creationTime, err := windowsProcessCreationTime(handle) + if err != nil { + windows.CloseHandle(handle) + return nil, err + } + // Keep the process object, and therefore its PID, alive until cleanup. + // Cmd.Wait closes its own handle before we inspect remaining descendants. + return &processTree{rootPID: rootPID, handle: handle, creationTime: creationTime}, nil +} + +func (tree *processTree) close() { + if tree.handle != 0 { + _ = windows.CloseHandle(tree.handle) + tree.handle = 0 + } +} + +func (tree *processTree) snapshot(includeNames bool) (map[uint32]windowsProcessInfo, error) { + if tree.handle == 0 { + return nil, fmt.Errorf("process tree is closed") + } + processes, err := snapshotWindowsProcesses(includeNames) + if err != nil { + return nil, err + } + if root, ok := processes[tree.rootPID]; ok { + if root.creationTime != tree.creationTime { + return nil, fmt.Errorf("process %d identity changed", tree.rootPID) + } + } else { + // Terminated roots are absent from the process table. The retained + // handle still owns their PID, so real orphaned children can be found. + processes[tree.rootPID] = windowsProcessInfo{creationTime: tree.creationTime} + } + return processes, nil +} + +func (tree *processTree) kill() { + if tree.handle == 0 { return } - rootPID := uint32(cmd.Process.Pid) - if processes, err := snapshotWindowsProcesses(); err == nil { - processTree := windowsProcessTree(rootPID, processes) - for i := len(processTree) - 1; i > 0; i-- { - terminateWindowsProcess(processTree[i]) + if processes, err := tree.snapshot(true); err == nil { + pids := windowsProcessTree(tree.rootPID, processes) + parents := make(map[uint32]bool, len(pids)) + for _, pid := range pids { + parents[pid] = true + } + for pid, process := range processes { + if parents[process.parentPID] && !parents[pid] { + fmt.Fprintf(os.Stderr, "goroot cleanup ignored stale parent link: pid=%d name=%q parent=%d\n", pid, process.name, process.parentPID) + } + } + for i := len(pids) - 1; i > 0; i-- { + terminateWindowsProcess(pids[i], processes[pids[i]].creationTime) } } - _ = cmd.Process.Kill() + _ = windows.TerminateProcess(tree.handle, 1) } func resourceMonitoringSupported() bool { return true } -func processGroupRSS(processGroupID int) (uint64, error) { - processes, err := snapshotWindowsProcesses() +func (tree *processTree) rss() (uint64, error) { + processes, err := tree.snapshot(false) if err != nil { return 0, err } - rootPID := uint32(processGroupID) - if _, ok := processes[rootPID]; !ok { - return 0, fmt.Errorf("process %d is no longer present", processGroupID) - } var total uint64 - for _, pid := range windowsProcessTree(rootPID, processes) { + for _, pid := range windowsProcessTree(tree.rootPID, processes) { total += processes[pid].rss } return total, nil } -func snapshotWindowsProcesses() (map[uint32]windowsProcessInfo, error) { +func snapshotWindowsProcesses(includeNames bool) (map[uint32]windowsProcessInfo, error) { bufferSize := uint32(1 << 20) for { buffer := make([]byte, bufferSize) @@ -77,11 +123,11 @@ func snapshotWindowsProcesses() (map[uint32]windowsProcessInfo, error) { if err != nil { return nil, err } - return parseWindowsProcessSnapshot(buffer) + return parseWindowsProcessSnapshot(buffer, includeNames) } } -func parseWindowsProcessSnapshot(buffer []byte) (map[uint32]windowsProcessInfo, error) { +func parseWindowsProcessSnapshot(buffer []byte, includeNames bool) (map[uint32]windowsProcessInfo, error) { processes := make(map[uint32]windowsProcessInfo) entrySize := uint32(unsafe.Sizeof(windows.SYSTEM_PROCESS_INFORMATION{})) for offset := uint32(0); ; { @@ -90,10 +136,15 @@ func parseWindowsProcessSnapshot(buffer []byte) (map[uint32]windowsProcessInfo, } entry := (*windows.SYSTEM_PROCESS_INFORMATION)(unsafe.Pointer(&buffer[offset])) pid := uint32(entry.UniqueProcessID) - processes[pid] = windowsProcessInfo{ - parentPID: uint32(entry.InheritedFromUniqueProcessID), - rss: uint64(entry.WorkingSetSize), + process := windowsProcessInfo{ + parentPID: uint32(entry.InheritedFromUniqueProcessID), + rss: uint64(entry.WorkingSetSize), + creationTime: entry.CreateTime, + } + if includeNames { + process.name = entry.ImageName.String() } + processes[pid] = process if entry.NextEntryOffset == 0 { return processes, nil } @@ -104,53 +155,26 @@ func parseWindowsProcessSnapshot(buffer []byte) (map[uint32]windowsProcessInfo, } } -func windowsProcessTree(rootPID uint32, processes map[uint32]windowsProcessInfo) []uint32 { - children := make(map[uint32][]uint32) - for pid, process := range processes { - if pid != rootPID { - children[process.parentPID] = append(children[process.parentPID], pid) - } - } - for parentPID := range children { - sort.Slice(children[parentPID], func(i, j int) bool { - return children[parentPID][i] < children[parentPID][j] - }) - } - tree := []uint32{rootPID} - seen := map[uint32]bool{rootPID: true} - for i := 0; i < len(tree); i++ { - for _, childPID := range children[tree[i]] { - if !seen[childPID] { - seen[childPID] = true - tree = append(tree, childPID) - } - } +func windowsProcessCreationTime(handle windows.Handle) (int64, error) { + // GetProcessTimes and SYSTEM_PROCESS_INFORMATION.CreateTime both use + // FILETIME: 100-nanosecond intervals since January 1, 1601 (UTC). + var created, exited, kernel, user windows.Filetime + if err := windows.GetProcessTimes(handle, &created, &exited, &kernel, &user); err != nil { + return 0, err } - return tree + return int64(created.HighDateTime)<<32 | int64(created.LowDateTime), nil } -func terminateWindowsProcess(pid uint32) { - handle, err := windows.OpenProcess(windows.PROCESS_TERMINATE, false, pid) +func terminateWindowsProcess(pid uint32, creationTime int64) { + handle, err := windows.OpenProcess(windows.PROCESS_QUERY_LIMITED_INFORMATION|windows.PROCESS_TERMINATE, false, pid) if err != nil { return } defer windows.CloseHandle(handle) - _ = windows.TerminateProcess(handle, 1) -} - -func TestWindowsProcessTree(t *testing.T) { - guardTestTimeout(t) - processes := map[uint32]windowsProcessInfo{ - 10: {parentPID: 1}, - 11: {parentPID: 10}, - 12: {parentPID: 10}, - 13: {parentPID: 11}, - 14: {parentPID: 99}, - 15: {parentPID: 15}, - } - got := windowsProcessTree(10, processes) - want := []uint32{10, 11, 12, 13} - if !reflect.DeepEqual(got, want) { - t.Fatalf("windowsProcessTree() = %v, want %v", got, want) + // A descendant can exit and have its PID reused between the snapshot + // and OpenProcess. Only terminate the exact process from the snapshot. + if current, err := windowsProcessCreationTime(handle); err != nil || current != creationTime { + return } + _ = windows.TerminateProcess(handle, 1) } diff --git a/test/goroot/process_tree_test.go b/test/goroot/process_tree_test.go new file mode 100644 index 0000000000..784c651163 --- /dev/null +++ b/test/goroot/process_tree_test.go @@ -0,0 +1,96 @@ +package goroot + +import ( + "reflect" + "sort" + "testing" +) + +type windowsProcessInfo struct { + parentPID uint32 + rss uint64 + creationTime int64 + name string +} + +func windowsProcessTree(rootPID uint32, processes map[uint32]windowsProcessInfo) []uint32 { + if _, ok := processes[rootPID]; !ok { + return nil + } + children := make(map[uint32][]uint32) + for pid, process := range processes { + if pid != rootPID { + children[process.parentPID] = append(children[process.parentPID], pid) + } + } + for parentPID := range children { + sort.Slice(children[parentPID], func(i, j int) bool { + return children[parentPID][i] < children[parentPID][j] + }) + } + tree := []uint32{rootPID} + seen := map[uint32]bool{rootPID: true} + for i := 0; i < len(tree); i++ { + for _, childPID := range children[tree[i]] { + // Parent PIDs are historical identifiers. An older process cannot + // be a child of the process that now owns its saved parent PID. + if processes[childPID].creationTime < processes[tree[i]].creationTime { + continue + } + if !seen[childPID] { + seen[childPID] = true + tree = append(tree, childPID) + } + } + } + return tree +} + +func TestWindowsProcessTree(t *testing.T) { + guardTestTimeout(t) + processes := map[uint32]windowsProcessInfo{ + 10: {parentPID: 1}, + 11: {parentPID: 10}, + 12: {parentPID: 10}, + 13: {parentPID: 11}, + 14: {parentPID: 99}, + 15: {parentPID: 15}, + } + got := windowsProcessTree(10, processes) + want := []uint32{10, 11, 12, 13} + if !reflect.DeepEqual(got, want) { + t.Fatalf("windowsProcessTree() = %v, want %v", got, want) + } +} + +func TestWindowsProcessTreeRejectsReusedParentPID(t *testing.T) { + processes := map[uint32]windowsProcessInfo{ + 10: {parentPID: 1, creationTime: 100}, + 11: {parentPID: 10, creationTime: 50, name: "Runner.Listener.exe"}, + 12: {parentPID: 10, creationTime: 110}, + 13: {parentPID: 11, creationTime: 120}, + 14: {parentPID: 12, creationTime: 90}, + 15: {parentPID: 12, creationTime: 130}, + } + got := windowsProcessTree(10, processes) + want := []uint32{10, 12, 15} + if !reflect.DeepEqual(got, want) { + t.Fatalf("windowsProcessTree() = %v, want %v; older processes are unrelated", got, want) + } +} + +func TestWindowsProcessTreeRequiresRootIdentity(t *testing.T) { + processes := map[uint32]windowsProcessInfo{ + 11: {parentPID: 10, creationTime: 50}, + } + if got := windowsProcessTree(10, processes); len(got) != 0 { + t.Fatalf("windowsProcessTree() = %v without a root identity, want empty", got) + } + // A retained root identity also distinguishes real orphaned descendants + // from older processes after the root disappears from the snapshot. + processes[10] = windowsProcessInfo{creationTime: 100} + processes[12] = windowsProcessInfo{parentPID: 10, creationTime: 110} + if got, want := windowsProcessTree(10, processes), []uint32{10, 12}; !reflect.DeepEqual(got, want) { + t.Fatalf("retained-root tree = %v, want %v", got, want) + } +} diff --git a/test/goroot/runner_test.go b/test/goroot/runner_test.go index 913eb43a58..9334faff53 100644 --- a/test/goroot/runner_test.go +++ b/test/goroot/runner_test.go @@ -914,24 +914,28 @@ func runnerEnv(repoRoot, goroot, gopath string, extra []string) []string { env := append([]string{}, os.Environ()...) pathFound := false for i, item := range env { - switch { - case strings.HasPrefix(item, "GOROOT="): + key, value, _ := strings.Cut(item, "=") + if runtime.GOOS == "windows" { + key = strings.ToUpper(key) + } + switch key { + case "GOROOT": env[i] = "GOROOT=" + goroot - case strings.HasPrefix(item, "GOENV="): + case "GOENV": env[i] = "GOENV=off" - case strings.HasPrefix(item, "GOFLAGS="): + case "GOFLAGS": env[i] = "GOFLAGS=" - case strings.HasPrefix(item, "GOTOOLCHAIN="): + case "GOTOOLCHAIN": env[i] = "GOTOOLCHAIN=local" - case strings.HasPrefix(item, "LLGO_ROOT="): + case "LLGO_ROOT": env[i] = "LLGO_ROOT=" + repoRoot - case strings.HasPrefix(item, "GOPATH="): + case "GOPATH": env[i] = "GOPATH=" + gopath - case strings.HasPrefix(item, "GO111MODULE="): + case "GO111MODULE": env[i] = "GO111MODULE=off" - case strings.HasPrefix(item, "PATH="): + case "PATH": pathFound = true - env[i] = "PATH=" + filepath.Join(goroot, "bin") + string(os.PathListSeparator) + strings.TrimPrefix(item, "PATH=") + env[i] = "PATH=" + filepath.Join(goroot, "bin") + string(os.PathListSeparator) + value } } if !pathFound { @@ -1013,6 +1017,13 @@ func runProgram(dir, app string, env []string, timeout time.Duration, args ...st if err := cmd.Start(); err != nil { return nil, nil, 0, time.Since(start), err } + tree, treeErr := newProcessTree(cmd) + if treeErr != nil { + _ = cmd.Process.Kill() + _ = cmd.Wait() + return nil, nil, 0, time.Since(start), fmt.Errorf("track process tree: %w", treeErr) + } + defer tree.close() waitCh := make(chan error, 1) var waitFinished time.Time @@ -1075,7 +1086,7 @@ func runProgram(dir, app string, env []string, timeout time.Duration, args ...st case <-timeoutCh: goto timedOut case <-rssCh: - rssBytes, rssErr := processGroupRSS(cmd.Process.Pid) + rssBytes, rssErr := tree.rss() if rssErr != nil { continue } @@ -1085,14 +1096,14 @@ func runProgram(dir, app string, env []string, timeout time.Duration, args ...st limitBytes := uint64(*flagMaxRSSMiB) << 20 if *flagMaxRSSMiB > 0 && rssBytes > limitBytes { terminationErr = &resourceLimitError{message: fmt.Sprintf("process-group RSS %s exceeded limit %s", formatBytes(rssBytes), formatBytes(limitBytes))} - killProcessTree(cmd) + tree.kill() err = waitTerminatedProgram(cmd, waitCh, 10*time.Second) goto finished } case <-memoryCh: if memoryErr := checkSystemMemoryPressure(); memoryErr != nil { terminationErr = memoryErr - killProcessTree(cmd) + tree.kill() err = waitTerminatedProgram(cmd, waitCh, 10*time.Second) goto finished } @@ -1106,7 +1117,7 @@ timedOut: default: } terminationErr = fmt.Errorf("timed out after %s", timeout) - killProcessTree(cmd) + tree.kill() err = waitTerminatedProgram(cmd, waitCh, 10*time.Second) goto finished waited: @@ -1120,7 +1131,7 @@ waited: // child, but an ExitError masks it after a non-zero exit. Either error // can therefore leave descendants alive. if err != nil || terminationErr != nil { - killProcessTree(cmd) + tree.kill() } finished: if *flagRSSWarnMiB > 0 && peakRSS >= uint64(*flagRSSWarnMiB)<<20 { diff --git a/test/goroot/runner_unit_test.go b/test/goroot/runner_unit_test.go index acc530823a..83a0d9a952 100644 --- a/test/goroot/runner_unit_test.go +++ b/test/goroot/runner_unit_test.go @@ -828,6 +828,14 @@ func TestRunProgramRSSLimit(t *testing.T) { runtime.KeepAlive(memory) return } + if os.Getenv("LLGO_GOROOT_HELPER") == "allocate-descendant" { + cmd := exec.Command(os.Args[0], "-test.run=^TestRunProgramRSSLimit$") + cmd.Env = upsertEnv(os.Environ(), "LLGO_GOROOT_HELPER=allocate") + if err := cmd.Run(); err != nil { + t.Fatal(err) + } + return + } disableSystemMemoryLimits(t) oldLimit := *flagMaxRSSMiB @@ -839,18 +847,22 @@ func TestRunProgramRSSLimit(t *testing.T) { *flagRSSPoll = oldPoll }() - _, _, _, elapsed, err := runProgram( - t.TempDir(), - os.Args[0], - append(os.Environ(), "LLGO_GOROOT_HELPER=allocate"), - 5*time.Second, - "-test.run=^TestRunProgramRSSLimit$", - ) - if err == nil || !strings.Contains(err.Error(), "RSS") { - t.Fatalf("err=%v, want RSS limit error", err) - } - if elapsed >= 5*time.Second { - t.Fatalf("elapsed=%s, memory limit did not terminate before timeout", elapsed) + for _, helper := range []string{"allocate", "allocate-descendant"} { + t.Run(helper, func(t *testing.T) { + _, _, _, elapsed, err := runProgram( + t.TempDir(), + os.Args[0], + upsertEnv(os.Environ(), "LLGO_GOROOT_HELPER="+helper), + 5*time.Second, + "-test.run=^TestRunProgramRSSLimit$", + ) + if err == nil || !strings.Contains(err.Error(), "RSS") { + t.Fatalf("err=%v, want RSS limit error", err) + } + if elapsed >= 5*time.Second { + t.Fatalf("elapsed=%s, memory limit did not terminate before timeout", elapsed) + } + }) } }