cthulhu/internal/wine/diagnostics.go

package wine

import (
	"encoding/json"
	"log/slog"
	"strconv"
	"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
	// onReady is installed before the first Write and receives valid ready
	// records before diagnostic throttling. It runs on the stderr copier
	// (or finish for a final partial line) and must only publish bounded
	// state, never log, block, or supervise processes.
	onReady func(helperReady)
}

// helperReady is the helper's startup status record. Older helpers omit
// hook_exclusions and therefore report zero, which is accurate for them.
type helperReady 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"`
	HookExclusions  int    `json:"hook_exclusions"`
}

func parseHelperReady(line string) (helperReady, bool) {
	body, found := strings.CutPrefix(line, "ready ")
	if !found {
		return helperReady{}, false
	}
	var status helperReady
	if err := json.Unmarshal([]byte(body), &status); err != nil || status.Reader == "" {
		return helperReady{}, false
	}
	return status, true
}

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
	}
	// Readiness controls exclusion fallback and must survive a full queue,
	// diagnostic throttling, and a slow log sink. The line buffer above
	// bounds parsing independently of how many diagnostics are retained.
	record := strings.TrimPrefix(line, "wine-access: ")
	if output.onReady != nil {
		if ready, valid := parseHelperReady(record); valid {
			output.onReady(ready)
		}
	}
	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 <- record:
	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 strings.HasPrefix(line, "ready ") {
		status, valid := parseHelperReady(line)
		if !valid {
			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, "hook_exclusions", status.HookExclusions)
		return
	}
	// The plain exclusion-count line is expected startup evidence (it is
	// emitted even when the helper then exits early), while a rejected
	// exclusion value stays a warning through the default branch.
	if hookExclusionCountLine(line) ||
		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)
	}
}

func hookExclusionCountLine(line string) bool {
	rest, found := strings.CutPrefix(line, "hook exclusions for ")
	if !found {
		return false
	}
	number, found := strings.CutSuffix(rest, " program(s)")
	if !found || number == "" {
		return false
	}
	count, err := strconv.Atoi(number)
	return err == nil && count >= 0 && strconv.Itoa(count) == number
}