Integrate with wine-access logging.

internal/wine/diagnostics.go

@@ -0,0 +1,160 @@
+package wine
+
+import (
+	"encoding/json"
+	"log/slog"
+	"strings"
+	"sync/atomic"
+	"time"
+)
+
+const diagnosticLineLimit = 4096
+
+// helperDiagnostics is written only by os/exec's stderr copier. It drains
+// arbitrary Wine output without waiting for the log sink. Each helper gets a
+// bounded line buffer, queue and rate window. After cmd.Wait, its logging
+// worker drains the remaining records independently of process shutdown.
+type helperDiagnostics struct {
+	lines      chan string
+	done       chan struct{}
+	partial    []byte
+	overlong   bool
+	window     time.Time
+	seen       map[string]bool
+	suppressed atomic.Uint64
+}
+
+func newHelperDiagnostics() *helperDiagnostics {
+	return &helperDiagnostics{
+		lines: make(chan string, 64), done: make(chan struct{}),
+		seen: make(map[string]bool),
+	}
+}
+
+func (output *helperDiagnostics) Write(data []byte) (int, error) {
+	for _, char := range data {
+		if char == '\n' {
+			if output.overlong {
+				output.suppressed.Add(1)
+			} else {
+				output.queueLine(string(output.partial))
+			}
+			output.partial = output.partial[:0]
+			output.overlong = false
+		} else if !output.overlong {
+			if len(output.partial) == diagnosticLineLimit {
+				output.overlong = true
+				output.partial = output.partial[:0]
+			} else {
+				output.partial = append(output.partial, char)
+			}
+		}
+	}
+	return len(data), nil
+}
+
+func (output *helperDiagnostics) queueLine(line string) {
+	line = strings.TrimSuffix(line, "\r")
+	// Do not mix arbitrary Wine/application stderr into reader diagnostics.
+	if !strings.HasPrefix(line, "wine-access: ") {
+		return
+	}
+	now := time.Now()
+	if now.Sub(output.window) >= 10*time.Second {
+		output.window = now
+		clear(output.seen)
+	}
+	if output.seen[line] || len(output.seen) >= 32 {
+		output.suppressed.Add(1)
+		return
+	}
+	output.seen[line] = true
+	select {
+	case output.lines <- strings.TrimPrefix(line, "wine-access: "):
+	default:
+		output.suppressed.Add(1)
+	}
+}
+
+// finish is called after Wait has stopped the stderr copier, including its
+// WaitDelay deadline. It never waits for a slow log sink during helper shutdown.
+func (output *helperDiagnostics) finish() {
+	if output.overlong {
+		output.suppressed.Add(1)
+	} else if len(output.partial) != 0 {
+		output.queueLine(string(output.partial))
+	}
+	close(output.lines)
+}
+
+func (output *helperDiagnostics) logRecords(logger *slog.Logger) {
+	defer close(output.done)
+	ticker := time.NewTicker(10 * time.Second)
+	defer ticker.Stop()
+	reportSuppressed := func() {
+		if count := output.suppressed.Swap(0); count != 0 {
+			logger.Warn("Wine helper diagnostics suppressed", "count", count)
+		}
+	}
+	for {
+		select {
+		case line, open := <-output.lines:
+			if !open {
+				reportSuppressed()
+				return
+			}
+			logHelperRecord(logger, line)
+		case <-ticker.C:
+			reportSuppressed()
+		}
+	}
+}
+
+func logHelperRecord(logger *slog.Logger, line string) {
+	if body, found := strings.CutPrefix(line, "identity "); found {
+		var identity struct {
+			Version  string `json:"version"`
+			Revision string `json:"revision"`
+			Modified bool   `json:"modified"`
+		}
+		if err := json.Unmarshal([]byte(body), &identity); err != nil || identity.Version == "" || identity.Revision == "" {
+			logger.Warn("Invalid Wine helper identity record")
+			return
+		}
+		logger.Info("Wine accessibility helper identity", "version", identity.Version,
+			"revision", identity.Revision, "modified", identity.Modified)
+		return
+	}
+	if body, found := strings.CutPrefix(line, "ready "); found {
+		var status struct {
+			Reader          string `json:"reader"`
+			ControlsEnabled bool   `json:"controls_enabled"`
+			Controller      bool   `json:"controller"`
+			Review          bool   `json:"review"`
+			MSAAWorker      bool   `json:"msaa_worker"`
+			WinEvents       bool   `json:"win_events"`
+			MenuHook        bool   `json:"menu_hook"`
+			InputHook       bool   `json:"input_hook"`
+			Host32Started   bool   `json:"host32_started"`
+			ControlPoll     bool   `json:"control_poll"`
+		}
+		if err := json.Unmarshal([]byte(body), &status); err != nil || status.Reader == "" {
+			logger.Warn("Invalid Wine helper initialization record")
+			return
+		}
+		logger.Info("Wine accessibility helper initialized", "reader", status.Reader,
+			"controls_enabled", status.ControlsEnabled, "controller", status.Controller,
+			"review", status.Review, "msaa_worker", status.MSAAWorker,
+			"win_events", status.WinEvents, "menu_hook", status.MenuHook,
+			"input_hook", status.InputHook, "host32_started", status.Host32Started,
+			"control_poll", status.ControlPoll)
+		return
+	}
+	if strings.HasPrefix(line, "reader event replies resumed after ") ||
+		line == "another helper already owns this Wine desktop" ||
+		line == "disabled by command-line options" {
+		logger.Info("Wine accessibility helper diagnostic", "diagnostic", line)
+	} else {
+		logger.Warn("Wine accessibility helper diagnostic", "diagnostic", line)
+	}
+}

internal/wine/diagnostics_test.go

@@ -0,0 +1,167 @@
+package wine
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"log/slog"
+	"os"
+	"path/filepath"
+	"strings"
+	"testing"
+	"time"
+)
+
+func TestHelperDiagnosticsHandlesSplitOversizedAndUnrelatedOutput(t *testing.T) {
+	var log bytes.Buffer
+	output := newHelperDiagnostics()
+	go output.logRecords(slog.New(slog.NewJSONHandler(&log, nil)))
+	for _, chunk := range []string{
+		"unrelated application text\nwine-acc", "ess: identity {\"version\":\"2026.10.15\",",
+		"\"revision\":\"abc123\",\"modified\":true}\r\n",
+		"wine-access: " + strings.Repeat("private", diagnosticLineLimit) + "\n",
+		"wine-access: ready {broken}\n",
+		"wine-access: ready {\"reader\":\"org.example.Reader\",\"controls_enabled\":true,\"control_poll\":true}\n",
+		"wine-access: native input hook unavailable",
+	} {
+		if count, err := output.Write([]byte(chunk)); err != nil || count != len(chunk) {
+			t.Fatalf("stderr write = (%d, %v)", count, err)
+		}
+	}
+	output.finish()
+	<-output.done
+	text := log.String()
+	for _, want := range []string{
+		`"version":"2026.10.15"`, `"revision":"abc123"`, `"modified":true`,
+		`"msg":"Wine accessibility helper initialized"`, `"control_poll":true`,
+		"Invalid Wine helper initialization record", "native input hook unavailable",
+		"Wine helper diagnostics suppressed",
+	} {
+		if !strings.Contains(text, want) {
+			t.Errorf("missing %q in %s", want, text)
+		}
+	}
+	for _, unwanted := range []string{"unrelated application text", "private", "{broken}"} {
+		if strings.Contains(text, unwanted) {
+			t.Errorf("unexpected output %q in log", unwanted)
+		}
+	}
+	for _, line := range strings.Split(strings.TrimSpace(text), "\n") {
+		if !json.Valid([]byte(line)) {
+			t.Errorf("invalid log record: %s", line)
+		}
+	}
+}
+
+func TestHelperDiagnosticsBoundsFloodAndRecoversNextWindow(t *testing.T) {
+	var log bytes.Buffer
+	output := newHelperDiagnostics()
+	// With no consumer, writes must still finish after filling the queue.
+	for i := 0; i < 1000; i++ {
+		output.Write([]byte("wine-access: repeated failure\n"))
+		output.Write([]byte("wine-access: failure " + strings.Repeat("x", i) + "\n"))
+	}
+	if len(output.lines) > 32 {
+		t.Fatalf("diagnostic burst queued %d records", len(output.lines))
+	}
+	output.window = time.Now().Add(-11 * time.Second)
+	output.Write([]byte("wine-access: reader event replies resumed after 2 failed calls\n"))
+	output.finish()
+	go output.logRecords(slog.New(slog.NewJSONHandler(&log, nil)))
+	<-output.done
+	if strings.Count(log.String(), `"diagnostic":"repeated failure"`) != 1 {
+		t.Fatalf("repeated failure was not coalesced: %s", log.String())
+	}
+	if !strings.Contains(log.String(), "reader event replies resumed") || !strings.Contains(log.String(), `"count":1968`) {
+		t.Fatalf("missing recovery or suppression count: %s", log.String())
+	}
+}
+
+func TestManagerCapturesActualHelperDiagnosticsAndBoundsInheritedStderr(t *testing.T) {
+	root := t.TempDir()
+	helper := filepath.Join(root, "helper")
+	// Leave a descendant holding stderr after the helper exits. WaitDelay must
+	// retire the copier without waiting for the descendant.
+	script := "#!/bin/sh\necho 'wine-access: identity {\"version\":\"2026.10.15\",\"revision\":\"abc123\",\"modified\":false}' >&2\n" +
+		"echo 'wine-access: native menu hook unavailable (error 126)' >&2\n" +
+		"sleep 2 &\nexit 0\n"
+	if err := os.WriteFile(helper, []byte(script), 0700); err != nil {
+		t.Fatal(err)
+	}
+	handler := &channelLogHandler{records: make(chan slog.Record, 32)}
+	manager := &Manager{helper: helper, logger: slog.New(handler)}
+	child := &process{}
+	started := time.Now()
+	if err := manager.launch(child, prefix{path: root}, started); err != nil {
+		t.Fatal(err)
+	}
+	select {
+	case <-child.done:
+	case <-time.After(time.Second):
+		t.Fatal("inherited stderr kept helper shutdown waiting")
+	}
+	identity, diagnostic := false, false
+	deadline := time.After(time.Second)
+	for !identity || !diagnostic {
+		select {
+		case record := <-handler.records:
+			record.Attrs(func(attr slog.Attr) bool {
+				identity = identity || attr.Key == "revision" && attr.Value.String() == "abc123"
+				diagnostic = diagnostic || attr.Key == "diagnostic" && strings.Contains(attr.Value.String(), "native menu hook unavailable")
+				return true
+			})
+		case <-deadline:
+			t.Fatal("helper diagnostics missing")
+		}
+	}
+}
+
+func TestManagerExpectedStopIsNotAHelperFailure(t *testing.T) {
+	helper := filepath.Join(t.TempDir(), "helper")
+	if err := os.WriteFile(helper, []byte("#!/bin/sh\nexec sleep 30\n"), 0700); err != nil {
+		t.Fatal(err)
+	}
+	handler := &channelLogHandler{records: make(chan slog.Record, 32)}
+	manager := &Manager{helper: helper, logger: slog.New(handler)}
+	child := &process{}
+	if err := manager.launch(child, prefix{path: t.TempDir()}, time.Now()); err != nil {
+		t.Fatal(err)
+	}
+	stop(child)
+	for {
+		select {
+		case record := <-handler.records:
+			if record.Message != "Wine accessibility helper exited" {
+				continue
+			}
+			if record.Level != slog.LevelInfo {
+				t.Fatalf("expected stop logged as failure: %v", record)
+			}
+			return
+		default:
+			t.Fatal("missing helper exit record")
+		}
+	}
+}
+
+type channelLogHandler struct {
+	records chan slog.Record
+	attrs   []slog.Attr
+}
+
+func (handler *channelLogHandler) Enabled(_ context.Context, level slog.Level) bool {
+	return level >= slog.LevelInfo
+}
+
+func (handler *channelLogHandler) Handle(_ context.Context, record slog.Record) error {
+	record = record.Clone()
+	record.AddAttrs(handler.attrs...)
+	handler.records <- record
+	return nil
+}
+
+func (handler *channelLogHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
+	return &channelLogHandler{records: handler.records, attrs: append(append([]slog.Attr{}, handler.attrs...), attrs...)}
+}
+
+func (handler *channelLogHandler) WithGroup(string) slog.Handler { return handler }

internal/wine/manager.go

@@ -11,6 +11,7 @@ import (
 	"path/filepath"
 	"strconv"
 	"strings"
+	"sync/atomic"
 	"syscall"
 	"time"
 )
@@ -29,6 +30,7 @@ type process struct {
 	seen     time.Time
 	failures int
 	next     time.Time
+	stopping atomic.Bool
 }
 
 type Manager struct {
@@ -178,9 +180,12 @@ func backoff(failures int) time.Duration {
 
 func (manager *Manager) launch(child *process, source prefix, now time.Time) error {
 	cmd := exec.Command(manager.helper)
+	diagnostics := newHelperDiagnostics()
 	cmd.Stdin = nil
 	cmd.Stdout = nil
-	cmd.Stderr = nil
+	cmd.Stderr = diagnostics
+	// Bound stderr draining if a Wine descendant retains the inherited pipe.
+	cmd.WaitDelay = 200 * time.Millisecond
 	cmd.SysProcAttr = &syscall.SysProcAttr{Setsid: true}
 	environment := os.Environ()
 	for _, key := range []string{"DISPLAY", "WAYLAND_DISPLAY", "XDG_RUNTIME_DIR", "DBUS_SESSION_BUS_ADDRESS"} {
@@ -197,17 +202,29 @@ func (manager *Manager) launch(child *process, source prefix, now time.Time) err
 		return err
 	}
 	child.cmd, child.done, child.started = cmd, make(chan struct{}), now
-	go manager.wait(cmd, child)
-	manager.logger.Info("Wine accessibility helper started")
+	child.stopping.Store(false)
+	logger := manager.logger.With("helper_pid", cmd.Process.Pid)
+	logger.Info("Wine accessibility helper started")
+	logger.Debug("Wine accessibility helper launch configuration", "executable", cmd.Path,
+		"wine_loader", source.loader, "wine_prefix", source.path)
+	go diagnostics.logRecords(logger)
+	go manager.wait(cmd, child, diagnostics, logger)
 	return nil
 }
 
-func (manager *Manager) wait(cmd *exec.Cmd, child *process) {
+func (manager *Manager) wait(cmd *exec.Cmd, child *process, diagnostics *helperDiagnostics, logger *slog.Logger) {
 	err := cmd.Wait()
-	if err != nil {
-		manager.logger.Warn("Wine accessibility helper exited", "error", err)
+	diagnostics.finish()
+	// Preserve record order at normal exit without letting a slow log sink
+	// hold process supervision indefinitely.
+	select {
+	case <-diagnostics.done:
+	case <-time.After(100 * time.Millisecond):
+	}
+	if err != nil && !child.stopping.Load() {
+		logger.Warn("Wine accessibility helper exited", "error", err)
 	} else {
-		manager.logger.Info("Wine accessibility helper exited")
+		logger.Info("Wine accessibility helper exited", "requested_stop", child.stopping.Load())
 	}
 	close(child.done)
 }
@@ -222,6 +239,7 @@ func stop(child *process) {
 		return
 	default:
 	}
+	child.stopping.Store(true)
 	_ = child.cmd.Process.Signal(syscall.SIGTERM)
 	select {
 	case <-child.done: