From f6b9a0811a5095341c0365e0039b544377b6f979 Mon Sep 17 00:00:00 2001 From: Cheviiot <153805936+Cheviiot@users.noreply.github.com> Date: Sat, 25 Jul 2026 15:58:22 +1000 Subject: [PATCH] Prevent and recover from wedged Wine-hosted processes Prompted by a real incident: an MSBuild node-reuse worker (its own /nodeReuse:true default) survived a build getting interrupted, came back deadlocked, and got reused by the next `msbuild` invocation - which then failed with a confusing, unrelated-looking `System.TypeLoadException` on Microsoft.VisualStudio.Telemetry on every call for hours, until the stale process was killed by hand. That's exactly the "unrelated blocker" noted in this repo's own earlier session notes (CLAUDE.md) while debugging a real project's build - it wasn't a missing dependency, it was a corrupted reused process. Two changes: - vintner now forces /nodeReuse:false on every msbuild invocation (unless the caller already passed their own /nodeReuse or /nr switch), so a wedged worker can never poison a later, unrelated build in the first place. Costs each invocation the couple-hundred- ms/node startup time node reuse exists to save. - VINTNER_TIMEOUT (a duration string, e.g. "30m") bounds how long any single tool invocation is allowed to run, for the case something wedges that isn't MSBuild-specific. Every exec.Command site in internal/wrapper now goes through a shared newToolCommand constructor that, when the timeout is set, kills the *whole* process group (not just the immediate `wine` process - a wedged child surviving under it is exactly the scenario this needs to reach) via a context deadline, and reports a clear "timed out after Xm" message (exit 124, matching the timeout(1) convention) instead of a bare "signal: killed". Unset by default - every real build observed stays unbounded, matching Windows' own behavior. Verified end-to-end, not just at the unit level: a real `sleep 30` through the `cmd` native wrapper with VINTNER_TIMEOUT=1s was killed within the deadline and reported the timeout clearly (exit 124); a real `cl` invocation with the same 1s timeout finished normally (0.26s) without being mistaken for a hang. --- README.md | 21 +++++++ internal/wrapper/msbuildenv.go | 33 ++++++++++ internal/wrapper/msbuildenv_test.go | 22 +++++++ internal/wrapper/native.go | 21 ++++--- internal/wrapper/run.go | 76 +++++++++++++--------- internal/wrapper/timeout.go | 97 +++++++++++++++++++++++++++++ internal/wrapper/timeout_test.go | 82 ++++++++++++++++++++++++ 7 files changed, 313 insertions(+), 39 deletions(-) create mode 100644 internal/wrapper/timeout.go create mode 100644 internal/wrapper/timeout_test.go diff --git a/README.md b/README.md index b93ba3b..35f83d9 100644 --- a/README.md +++ b/README.md @@ -23,6 +23,7 @@ approach: download the real MSVC/WinSDK, wrap the compiler under Wine. - [Commands](#commands) - [Building drivers (WDK)](#building-drivers-wdk) - [Building against D3DX9 (DirectX SDK)](#building-against-d3dx9-directx-sdk) +- [Automated/scripted builds](#automatedscripted-builds) - [Language](#language) - [Shell completion](#shell-completion) - [Using clang-cl/lld-link instead of Wine](#using-clang-cllld-link-instead-of-wine) @@ -164,6 +165,26 @@ Point your project's `IncludePath`/`LibraryPath` at Requires `cabextract` on `PATH` (the installer is a self-extracting CAB archive). +## Automated/scripted builds + +Every tool invocation runs unbounded by default, same as the real thing on +Windows. Set `VINTNER_TIMEOUT` (a `time.ParseDuration` string, e.g. `30m`, +`2h`) to have vintner kill and fail a build that runs longer than that +instead of hanging forever - meant for CI and other unattended callers, not +interactive use. This guards against one confirmed failure mode: an +MSBuild node-reuse worker (`/nodeReuse:true` is MSBuild's own default) can +survive its parent process under Wine and, if a prior build was +interrupted mid-compile, come back wedged - reused by the next `msbuild` +call and failing every subsequent build with a confusing, unrelated-looking +error, indefinitely, until it's killed by hand. vintner already forces +`/nodeReuse:false` on every `msbuild` invocation to prevent this in the +first place; `VINTNER_TIMEOUT` is the backstop for whatever else might +wedge under Wine that isn't MSBuild-specific. + +```bash +VINTNER_TIMEOUT=30m msbuild MyProject.sln +``` + ## Language CLI text (usage, progress lines, prompts) defaults to English. Set diff --git a/internal/wrapper/msbuildenv.go b/internal/wrapper/msbuildenv.go index be0f764..49a935b 100644 --- a/internal/wrapper/msbuildenv.go +++ b/internal/wrapper/msbuildenv.go @@ -218,6 +218,39 @@ func msbuildGlobalArgs(cfg *wineenv.Config, args []string) []string { return out } +var reNodeReuse = regexp.MustCompile(`(?i)^[-/](nodereuse|nr):`) + +// msbuildNodeReuseArgs returns ["/nodeReuse:false"] unless args already pins +// node reuse one way or the other. +// +// MSBuild's node-reuse worker processes (its own /nodeReuse:true default) +// don't behave like a normal child process here: they're meant to outlive +// the parent msbuild.exe invocation that spawned them, waiting around under +// Wine for the *next* msbuild call to reuse them - so nothing about +// vintner's own process-lifetime handling (see signals.go) touches them, +// and there's no parent process left to notice if one wedges. If a build is +// interrupted (Ctrl-C, a killed session, a crashed Wine transport) mid- +// compile, the worker can be left holding a half-open pipe/mutex, +// permanently deadlocked rather than exited - confirmed in practice: a +// stale reused node kept throwing an unrelated-looking +// `System.TypeLoadException` on Microsoft.VisualStudio.Telemetry on every +// subsequent build, for hours, until it was killed by hand and the next +// build got a fresh node. Forcing node reuse off means every invocation +// gets a clean process, so a wedged one can never poison a later, +// unrelated build - at the cost of the couple-hundred-ms/node startup time +// node reuse exists to save. Callers who deliberately want reuse (e.g. +// running many builds back to back and are prepared to clean up wedged +// nodes themselves) can still pass their own /nodeReuse or /nr switch to +// override this. +func msbuildNodeReuseArgs(args []string) []string { + for _, a := range args { + if reNodeReuse.MatchString(a) { + return nil + } + } + return []string{"/nodeReuse:false"} +} + func msbuildPlatform(arch string) string { switch arch { case "x86": diff --git a/internal/wrapper/msbuildenv_test.go b/internal/wrapper/msbuildenv_test.go index 13d36a5..c381465 100644 --- a/internal/wrapper/msbuildenv_test.go +++ b/internal/wrapper/msbuildenv_test.go @@ -198,3 +198,25 @@ func TestMsbuildEnvPreferredToolArchitecture(t *testing.T) { t.Errorf(`with DotnetHost=arm64, PreferredToolArchitecture = %q, want unset`, env["PreferredToolArchitecture"]) } } + +func TestMsbuildNodeReuseArgsForcesOffByDefault(t *testing.T) { + got := msbuildNodeReuseArgs([]string{"Foo.sln", "/p:Configuration=Release"}) + want := []string{"/nodeReuse:false"} + if len(got) != 1 || got[0] != want[0] { + t.Errorf("msbuildNodeReuseArgs(...) = %v, want %v", got, want) + } +} + +func TestMsbuildNodeReuseArgsRespectsExplicitOverride(t *testing.T) { + for _, explicit := range []string{ + "/nodeReuse:true", + "-nodeReuse:true", + "/nr:true", + "/NODEREUSE:FALSE", // caller explicitly wanting it off too - still shouldn't double up + } { + got := msbuildNodeReuseArgs([]string{"Foo.sln", explicit}) + if got != nil { + t.Errorf("msbuildNodeReuseArgs with explicit %q = %v, want nil (left alone)", explicit, got) + } + } +} diff --git a/internal/wrapper/native.go b/internal/wrapper/native.go index e9140ef..936cc1f 100644 --- a/internal/wrapper/native.go +++ b/internal/wrapper/native.go @@ -1,6 +1,7 @@ package wrapper import ( + "fmt" "os" "os/exec" ) @@ -25,17 +26,21 @@ func execInherit(args []string) int { if len(args) == 0 { return 0 } - cmd := exec.Command(args[0], args[1:]...) - cmd.Stdin = os.Stdin - cmd.Stdout = os.Stdout - cmd.Stderr = os.Stderr - setNewProcessGroup(cmd) - if err := cmd.Start(); err != nil { + tc, cleanup := newToolCommand(args[0], args[1:]...) + defer cleanup() + tc.Stdin = os.Stdin + tc.Stdout = os.Stdout + tc.Stderr = os.Stderr + if err := tc.Start(); err != nil { return 127 } - stopSignals := forwardSignals(cmd.Process) + stopSignals := forwardSignals(tc.Process) defer stopSignals() - if err := cmd.Wait(); err != nil { + if err := tc.Wait(); err != nil { + if tc.timedOut() { + fmt.Fprintln(os.Stderr, tc.timeoutMessage()) + return 124 + } if exitErr, ok := err.(*exec.ExitError); ok { return exitErr.ExitCode() } diff --git a/internal/wrapper/run.go b/internal/wrapper/run.go index 8c79ef5..e639cca 100644 --- a/internal/wrapper/run.go +++ b/internal/wrapper/run.go @@ -84,27 +84,29 @@ func Run(tool string, args []string) int { // read as-is), and add the extra environment MSBuild's own // toolset/SDK-detection props need on top of the generic // INCLUDE/LIB/WINEPATH, plus any global properties a project file - // itself could otherwise override (see msbuildGlobalArgs). + // itself could otherwise override (see msbuildGlobalArgs) and a + // forced /nodeReuse:false (see msbuildNodeReuseArgs). msArgs := append(msbuildGlobalArgs(cfg, rewritten), rewritten...) - cmd := exec.Command(wineBin, append([]string{toolExePath}, msArgs...)...) + msArgs = append(msbuildNodeReuseArgs(rewritten), msArgs...) + tc, cleanup := newToolCommand(wineBin, append([]string{toolExePath}, msArgs...)...) + defer cleanup() env := buildEnv(paths) for k, v := range msbuildEnv(cfg, paths) { env = append(env, k+"="+v) } - cmd.Env = env - cmd.Stdin = os.Stdin - setNewProcessGroup(cmd) - exitCode = runRawStdout(cmd) + tc.Env = env + tc.Stdin = os.Stdin + exitCode = runRawStdout(tc) default: relay := filepath.Join(paths.BaseUnix, "bin", toolRelayName) if fi, err := os.Stat(relay); err == nil && !fi.IsDir() { exitCode = runViaToolRelay(wineBin, relay, toolExePath, rewritten, paths, s.stdoutFilter, s.stderrFilter) } else { - cmd := exec.Command(wineBin, append([]string{toolExePath}, rewritten...)...) - cmd.Env = buildEnv(paths) - cmd.Stdin = os.Stdin - setNewProcessGroup(cmd) - exitCode = runFiltered(cmd, s.stdoutFilter, s.stderrFilter) + tc, cleanup := newToolCommand(wineBin, append([]string{toolExePath}, rewritten...)...) + defer cleanup() + tc.Env = buildEnv(paths) + tc.Stdin = os.Stdin + exitCode = runFiltered(tc, s.stdoutFilter, s.stderrFilter) } } @@ -139,20 +141,20 @@ func runViaToolRelay(wineBin, relayExe, exePath string, args []string, paths *wi defer os.Remove(stderrFifo) cmdArgs := append([]string{relayExe, exePath}, args...) - cmd := exec.Command(wineBin, cmdArgs...) - cmd.Env = append(buildEnv(paths), "MSVCGOWINE_STDOUT="+stdoutFifo, "MSVCGOWINE_STDERR="+stderrFifo) - setNewProcessGroup(cmd) + tc, cleanup := newToolCommand(wineBin, cmdArgs...) + defer cleanup() + tc.Env = append(buildEnv(paths), "MSVCGOWINE_STDOUT="+stdoutFifo, "MSVCGOWINE_STDERR="+stderrFifo) if devNull, err := os.OpenFile(os.DevNull, os.O_WRONLY, 0); err == nil { defer devNull.Close() - cmd.Stdout = devNull - cmd.Stderr = devNull + tc.Stdout = devNull + tc.Stderr = devNull } - if err := cmd.Start(); err != nil { + if err := tc.Start(); err != nil { fmt.Fprintln(os.Stderr, "vintner:", err) return 1 } - stopSignals := forwardSignals(cmd.Process) + stopSignals := forwardSignals(tc.Process) defer stopSignals() var wg sync.WaitGroup @@ -176,10 +178,14 @@ func runViaToolRelay(wineBin, relayExe, exePath string, args []string, paths *wi pumpLines(f, os.Stderr, stderrF) }() - err := cmd.Wait() + err := tc.Wait() wg.Wait() if err != nil { + if tc.timedOut() { + fmt.Fprintln(os.Stderr, tc.timeoutMessage()) + return 124 + } if exitErr, ok := err.(*exec.ExitError); ok { return exitErr.ExitCode() } @@ -195,23 +201,23 @@ func runViaToolRelay(wineBin, relayExe, exePath string, args []string, paths *wi // own copy goroutines - not the caller's terminal or pipe - are exposed to // Wine's background processes holding those descriptors open; see // pipeDrainGrace. -func runRawStdout(cmd *exec.Cmd) int { - stdout, err := cmd.StdoutPipe() +func runRawStdout(tc *toolCommand) int { + stdout, err := tc.StdoutPipe() if err != nil { fmt.Fprintln(os.Stderr, "vintner:", err) return 1 } - stderr, err := cmd.StderrPipe() + stderr, err := tc.StderrPipe() if err != nil { fmt.Fprintln(os.Stderr, "vintner:", err) return 1 } - if err := cmd.Start(); err != nil { + if err := tc.Start(); err != nil { fmt.Fprintln(os.Stderr, "vintner:", err) return 1 } - stopSignals := forwardSignals(cmd.Process) + stopSignals := forwardSignals(tc.Process) defer stopSignals() doneOut := make(chan struct{}) @@ -219,11 +225,15 @@ func runRawStdout(cmd *exec.Cmd) int { go func() { io.Copy(os.Stdout, stdout); close(doneOut) }() go func() { io.Copy(os.Stderr, stderr); close(doneErr) }() - err = cmd.Wait() + err = tc.Wait() drain(doneOut) drain(doneErr) if err != nil { + if tc.timedOut() { + fmt.Fprintln(os.Stderr, tc.timeoutMessage()) + return 124 + } if exitErr, ok := err.(*exec.ExitError); ok { return exitErr.ExitCode() } @@ -271,23 +281,23 @@ func buildEnv(p *wineenv.Paths) []string { // runFiltered streams stdout/stderr line by line through the tool's // filters (CR-stripping always applied first), then waits for completion. -func runFiltered(cmd *exec.Cmd, stdoutF, stderrF lineFilter) int { - stdout, err := cmd.StdoutPipe() +func runFiltered(tc *toolCommand, stdoutF, stderrF lineFilter) int { + stdout, err := tc.StdoutPipe() if err != nil { fmt.Fprintln(os.Stderr, "vintner:", err) return 1 } - stderr, err := cmd.StderrPipe() + stderr, err := tc.StderrPipe() if err != nil { fmt.Fprintln(os.Stderr, "vintner:", err) return 1 } - if err := cmd.Start(); err != nil { + if err := tc.Start(); err != nil { fmt.Fprintln(os.Stderr, "vintner:", err) return 1 } - stopSignals := forwardSignals(cmd.Process) + stopSignals := forwardSignals(tc.Process) defer stopSignals() doneOut := make(chan struct{}) @@ -295,11 +305,15 @@ func runFiltered(cmd *exec.Cmd, stdoutF, stderrF lineFilter) int { go func() { pumpLines(stdout, os.Stdout, stdoutF); close(doneOut) }() go func() { pumpLines(stderr, os.Stderr, stderrF); close(doneErr) }() - err = cmd.Wait() + err = tc.Wait() drain(doneOut) drain(doneErr) if err != nil { + if tc.timedOut() { + fmt.Fprintln(os.Stderr, tc.timeoutMessage()) + return 124 + } if exitErr, ok := err.(*exec.ExitError); ok { return exitErr.ExitCode() } diff --git a/internal/wrapper/timeout.go b/internal/wrapper/timeout.go new file mode 100644 index 0000000..671c21b --- /dev/null +++ b/internal/wrapper/timeout.go @@ -0,0 +1,97 @@ +package wrapper + +import ( + "context" + "fmt" + "os" + "os/exec" + "syscall" + "time" +) + +// waitDelay bounds how long cmd.Wait() itself may block after the process +// group has already been told to die (by a timeout or a forwarded signal) - +// usually resolved immediately, but a wedged Wine transport is exactly the +// case that isn't guaranteed to notice a plain SIGKILL right away. +const waitDelay = 5 * time.Second + +// commandTimeout returns how long a single tool invocation may run before +// vintner kills it and reports a timeout, from VINTNER_TIMEOUT (a +// time.ParseDuration string, e.g. "30m", "2h"). Unset, empty, or invalid +// all mean "no timeout" (0) - the default stays a plain, unbounded build, +// matching every real build observed so far (Ogre3D's from-scratch build +// alone ran several minutes). This exists for exactly one failure mode: a +// wedged Wine-hosted process (a corrupted MSBuild node-reuse worker in the +// one confirmed case so far, but nothing about the mechanism is +// MSBuild-specific) that will otherwise never exit on its own, hanging +// vintner - and whatever's waiting on vintner - forever with no feedback. +// Automated/scripted callers that would rather fail loudly after N minutes +// than risk hanging indefinitely can set this; interactive use is +// unaffected unless it's set. +func commandTimeout() time.Duration { + v := os.Getenv("VINTNER_TIMEOUT") + if v == "" { + return 0 + } + d, err := time.ParseDuration(v) + if err != nil || d <= 0 { + return 0 + } + return d +} + +// toolCommand wraps the exec.Cmd every wine-hosted tool invocation is built +// from, plus enough state to tell a VINTNER_TIMEOUT kill apart from every +// other failure once Wait() returns. +type toolCommand struct { + *exec.Cmd + ctx context.Context + cancel context.CancelFunc + timeout time.Duration // 0 if VINTNER_TIMEOUT wasn't set +} + +// newToolCommand builds a toolCommand: its own process group +// (setNewProcessGroup) and, when VINTNER_TIMEOUT is set, a deadline that +// kills the *whole group* - not just the immediate `wine` process, since a +// wedged Wine-hosted child surviving past its parent is exactly the +// scenario this needs to reach - if the tool hasn't finished in time. +// +// Callers must defer the returned cleanup func, and should call +// timedOut() after Wait() returns to tell a timeout-triggered kill apart +// from every other failure. +func newToolCommand(name string, args ...string) (tc *toolCommand, cleanup func()) { + timeout := commandTimeout() + if timeout <= 0 { + cmd := exec.Command(name, args...) + setNewProcessGroup(cmd) + return &toolCommand{Cmd: cmd, ctx: context.Background()}, func() {} + } + + ctx, cancel := context.WithTimeout(context.Background(), timeout) + cmd := exec.CommandContext(ctx, name, args...) + setNewProcessGroup(cmd) + // cmd.Cancel's default (Go 1.20+) only signals the immediate child; + // override it to reach the whole process group, same as + // forwardSignals - the wedged process a timeout exists to clean up is + // typically under wine, not wine itself. + cmd.Cancel = func() error { + if cmd.Process == nil { + return nil + } + return syscall.Kill(-cmd.Process.Pid, syscall.SIGKILL) + } + cmd.WaitDelay = waitDelay + tc = &toolCommand{Cmd: cmd, ctx: ctx, cancel: cancel, timeout: timeout} + return tc, cancel +} + +// timedOut reports whether this command was killed by its own +// VINTNER_TIMEOUT deadline rather than exiting (however it exited) on its +// own - call after Wait() returns a non-nil error. +func (tc *toolCommand) timedOut() bool { + return tc.ctx.Err() == context.DeadlineExceeded +} + +func (tc *toolCommand) timeoutMessage() string { + return fmt.Sprintf("vintner: %s: timed out after %s (VINTNER_TIMEOUT), killed", tc.Path, tc.timeout) +} diff --git a/internal/wrapper/timeout_test.go b/internal/wrapper/timeout_test.go new file mode 100644 index 0000000..709f887 --- /dev/null +++ b/internal/wrapper/timeout_test.go @@ -0,0 +1,82 @@ +package wrapper + +import ( + "syscall" + "testing" + "time" +) + +func TestCommandTimeout(t *testing.T) { + for _, tc := range []struct { + name string + env string + want time.Duration + }{ + {"unset", "", 0}, + {"valid", "30m", 30 * time.Minute}, + {"invalid unit-less number", "30", 0}, + {"zero", "0s", 0}, + {"negative", "-5m", 0}, + } { + t.Run(tc.name, func(t *testing.T) { + t.Setenv("VINTNER_TIMEOUT", tc.env) + if got := commandTimeout(); got != tc.want { + t.Errorf("commandTimeout() with VINTNER_TIMEOUT=%q = %v, want %v", tc.env, got, tc.want) + } + }) + } +} + +// TestNewToolCommandKillsOnTimeout is the real end-to-end check: start a +// process that would otherwise run far longer than the timeout (mimicking +// a wedged Wine-hosted tool), and confirm newToolCommand's deadline +// actually kills it - not just that timedOut() would report true in +// principle, but that Wait() actually returns, promptly, with the process +// gone. +func TestNewToolCommandKillsOnTimeout(t *testing.T) { + t.Setenv("VINTNER_TIMEOUT", "300ms") + + tc, cleanup := newToolCommand("sleep", "30") + defer cleanup() + + if err := tc.Start(); err != nil { + t.Fatalf("starting sleep: %v", err) + } + pid := tc.Process.Pid + + done := make(chan error, 1) + go func() { done <- tc.Wait() }() + + select { + case err := <-done: + if err == nil { + t.Fatal("expected sleep 30 to be killed by the timeout, but it exited successfully") + } + if !tc.timedOut() { + t.Errorf("Wait() returned an error (%v) but timedOut() = false", err) + } + case <-time.After(5 * time.Second): + t.Fatal("newToolCommand's timeout did not kill the process within 5s of a 300ms deadline") + } + + // Belt-and-suspenders: the process should genuinely be gone, not just + // reported as such. Signal 0 sends nothing but still fails with ESRCH + // once the pid is gone - the standard Unix way to probe existence. + if err := syscall.Kill(pid, 0); err == nil { + t.Errorf("pid %d still exists after the timeout killed it", pid) + } +} + +func TestNewToolCommandNoTimeoutByDefault(t *testing.T) { + t.Setenv("VINTNER_TIMEOUT", "") + + tc, cleanup := newToolCommand("true") + defer cleanup() + + if err := tc.Run(); err != nil { + t.Fatalf("running `true` with no VINTNER_TIMEOUT set: %v", err) + } + if tc.timedOut() { + t.Error("timedOut() = true for a command that finished well within any reasonable time, with no timeout configured") + } +}