327 lines
11 KiB
Go
327 lines
11 KiB
Go
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 }
|