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.
This commit is contained in:
Cheviiot
2026-07-25 15:58:22 +10:00
parent bdea270d71
commit f6b9a0811a
7 changed files with 313 additions and 39 deletions
+33
View File
@@ -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":
+22
View File
@@ -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)
}
}
}
+13 -8
View File
@@ -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()
}
+45 -31
View File
@@ -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()
}
+97
View File
@@ -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)
}
+82
View File
@@ -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")
}
}