package wine import ( "bytes" "context" "encoding/json" "fmt" "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 TestHelperReadinessBypassesDiagnosticBackpressure(t *testing.T) { for _, test := range []struct { name string windows int }{ {name: "rate limit", windows: 1}, {name: "full queue", windows: 2}, } { t.Run(test.name, func(t *testing.T) { output := newHelperDiagnostics() child := &process{launchedHelper: "helper", exclusions: map[string]bool{"game.exe": true}} readyCount := 0 output.onReady = func(ready helperReady) { readyCount++ child.readyExclusions.Store(int64(ready.HookExclusions)) child.readySeen.Store(true) } // Do not start a log consumer: readiness must arrive even if a // sink cannot make progress. Fill successive rate windows to // exercise both diagnostic throttling and a completely full queue. for window := 0; window < test.windows; window++ { output.window = time.Now().Add(-11 * time.Second) for index := 0; index < 32; index++ { fmt.Fprintf(output, "wine-access: startup warning %d/%d\n", window, index) } } if test.windows == 2 { if len(output.lines) != cap(output.lines) { t.Fatal("diagnostic queue was not filled") } output.window = time.Now().Add(-11 * time.Second) } for _, line := range []string{ "wine-access: ready {broken}\n", "unrelated: ready {\"reader\":\"org.example.Reader\"}\n", } { output.Write([]byte(line)) } if readyCount != 0 { t.Fatal("invalid or unrelated output published readiness") } // Older helpers omit hook_exclusions and therefore report zero. output.Write([]byte("wine-access: rea")) output.Write([]byte("dy {\"reader\":\"org.example.Reader\"}\r\n")) if readyCount != 1 { t.Fatalf("readiness publications before logging = %d, want 1", readyCount) } manager := New(nil) if !manager.restart_running_helper(child, prefix{}, Settings{}) || !manager.helper_unconfirmed("helper") { t.Fatal("lost exclusion mismatch fallback under diagnostic backpressure") } output.finish() output.logRecords(slog.New(slog.DiscardHandler)) if readyCount != 1 { t.Fatalf("logging published readiness again: count = %d", readyCount) } }) } } 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, Settings{}); 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(), Settings{}); 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") } } } func TestHelperDiagnosticsHookExclusionEvidence(t *testing.T) { var log bytes.Buffer output := newHelperDiagnostics() readyRecords := make(chan helperReady, 4) output.onReady = func(ready helperReady) { readyRecords <- ready } go output.logRecords(slog.New(slog.NewJSONHandler(&log, nil))) for _, line := range []string{ "wine-access: hook exclusions for 2 program(s)\n", "wine-access: ignoring invalid --exclude-hook-program value\n", "wine-access: ready {\"reader\":\"org.example.Reader\",\"controls_enabled\":true,\"hook_exclusions\":2}\n", // Older helpers have no count field; they report zero. "wine-access: ready {\"reader\":\"org.example.Reader\",\"controls_enabled\":true}\n", } { if _, err := output.Write([]byte(line)); err != nil { t.Fatal(err) } } output.finish() <-output.done levels := map[string]string{} var exclusionCounts []float64 for _, line := range strings.Split(strings.TrimSpace(log.String()), "\n") { var record map[string]any if err := json.Unmarshal([]byte(line), &record); err != nil { t.Fatalf("invalid log record %q: %v", line, err) } if diagnostic, ok := record["diagnostic"].(string); ok { levels[diagnostic] = record["level"].(string) } if record["msg"] == "Wine accessibility helper initialized" { count, ok := record["hook_exclusions"].(float64) if !ok { t.Fatalf("initialized record lacks hook_exclusions: %s", line) } exclusionCounts = append(exclusionCounts, count) } } if levels["hook exclusions for 2 program(s)"] != "INFO" { t.Fatalf("plain exclusion-count line levels = %v", levels) } if levels["ignoring invalid --exclude-hook-program value"] != "WARN" { t.Fatalf("invalid exclusion line levels = %v", levels) } if len(exclusionCounts) != 2 || exclusionCounts[0] != 2 || exclusionCounts[1] != 0 { t.Fatalf("logged hook_exclusions = %v, want [2 0]", exclusionCounts) } close(readyRecords) var consumed []int for ready := range readyRecords { consumed = append(consumed, ready.HookExclusions) } if len(consumed) != 2 || consumed[0] != 2 || consumed[1] != 0 { t.Fatalf("consumed ready counts = %v, want [2 0]", consumed) } } func TestHelperStartRecordMirrorsProgramsAndExtra(t *testing.T) { t.Setenv("WINE_ACCESS_NO_DIALOG_READER", "") root := t.TempDir() helper := filepath.Join(root, "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{} source := prefix{path: root, programs: map[string]bool{"launcher.exe": true, "game.exe": true}} settings := Settings{ExcludedPrograms: []string{"Game.EXE", "game.exe", "Another.exe"}} if err := manager.launch(child, source, time.Now(), settings); err != nil { t.Fatal(err) } defer stop(child) deadline := time.After(2 * time.Second) for { select { case record := <-handler.records: if record.Message != "Wine accessibility helper started" { continue } attrs := map[string]string{} record.Attrs(func(attr slog.Attr) bool { attrs[attr.Key] = attr.Value.String() return true }) if attrs["programs"] != "['game.exe', 'launcher.exe']" { t.Fatalf("programs = %q", attrs["programs"]) } want := "['--exclude-hook-program', 'another.exe', '--exclude-hook-program', 'game.exe']" if attrs["extra"] != want { t.Fatalf("extra = %q, want %q", attrs["extra"], want) } return case <-deadline: t.Fatal("helper-start record missing") } } } 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 }