From 895401de51f645c1033b51365d82a61a936058b6 Mon Sep 17 00:00:00 2001 From: sudacode Date: Fri, 27 Feb 2026 21:02:21 -0800 Subject: [PATCH] fix(startup): replace fixed overlay sleeps with readiness retries --- ...es-and-optimize-startup-command-runtime.md | 72 ++++ launcher/mpv.test.ts | 82 +++- launcher/mpv.ts | 63 ++- plugin/subminer/process.lua | 388 ++++++++++++++++++ scripts/test-plugin-process-start-retries.lua | 128 ++++++ 5 files changed, 728 insertions(+), 5 deletions(-) create mode 100644 backlog/tasks/task-73 - MPV-plugin-split-into-modules-and-optimize-startup-command-runtime.md create mode 100644 plugin/subminer/process.lua create mode 100644 scripts/test-plugin-process-start-retries.lua diff --git a/backlog/tasks/task-73 - MPV-plugin-split-into-modules-and-optimize-startup-command-runtime.md b/backlog/tasks/task-73 - MPV-plugin-split-into-modules-and-optimize-startup-command-runtime.md new file mode 100644 index 0000000..53477eb --- /dev/null +++ b/backlog/tasks/task-73 - MPV-plugin-split-into-modules-and-optimize-startup-command-runtime.md @@ -0,0 +1,72 @@ +--- +id: TASK-73 +title: 'MPV plugin: split into modules and optimize startup/command runtime' +status: In Progress +assignee: [] +created_date: '2026-02-28 20:50' +labels: [] +dependencies: [] +references: + - plugin/subminer/main.lua + - plugin/subminer/bootstrap.lua + - plugin/subminer/process.lua + - plugin/subminer/lifecycle.lua + - plugin/subminer/messages.lua + - plugin/subminer/ui.lua + - plugin/subminer/hover.lua + - plugin/subminer/options.lua + - plugin/subminer/state.lua + - plugin/subminer.conf + - scripts/test-plugin-start-gate.lua + - scripts/test-plugin-process-start-retries.lua + - launcher/commands/playback-command.ts + - launcher/mpv.ts + - launcher/mpv.test.ts + - launcher/smoke.e2e.test.ts + - Makefile + - package.json + - docs/mpv-plugin.md + - docs/installation.md + - docs/architecture.md + - README.md +priority: medium +--- + +## Description + + +Scope: Replace monolithic `plugin/subminer.lua` with modular plugin runtime; optimize command execution paths; align install/docs/tests; fix launcher smoke instability. + +Delivered behavior: +- Full plugin cutover to `plugin/subminer/main.lua` + module directory (no runtime compatibility shim with old monolith file). +- Process/control command path moved toward async subprocess usage for non-start actions (`stop`, `toggle`, `settings`, restart stop leg), reducing synchronous blocking in mpv script runtime. +- Startup/runtime loading updated with lazy module initialization via bootstrap proxies. +- Plugin install flow updated to copy `plugin/subminer/` directory and remove legacy `~/.config/mpv/scripts/subminer.lua` file. +- Added plugin gate script wiring to package scripts (`test:plugin:src`) and launcher test flow. +- Smoke tests stabilized across sandbox environments where UNIX socket bind can return `EPERM` while preserving normal-path assertions. +- Playback command cleanup race fixed when mpv exits before exit-listener registration. + +Risk/impact context: +- mpv plugin loading path changed from single-file to module directory; packaging/install paths must stay consistent with release assets. +- Async control path changes reduce blocking but can surface timing differences; regression checks added for cold start and launcher smoke behavior. + + +## Final Summary + + +Startup fixed-sleep removal delivered in launcher + plugin start paths: +- `launcher/mpv.ts:startOverlay` no longer blocks on hard `2000ms`; now uses bounded readiness/event checks: + - bounded wait for mpv IPC socket readiness + - bounded wait for spawned overlay command settle (`exit`/`error`) +- `plugin/subminer/process.lua` removed fixed `0.35s` texthooker delay and fixed `0.6s` startup visibility delay. +- Overlay start now uses short bounded retries on non-ready start failures, then applies startup overlay visibility once start succeeds. + +Regression coverage added: +- `launcher/mpv.test.ts` adds guard that `startOverlay` resolves quickly when readiness arrives. +- `scripts/test-plugin-process-start-retries.lua` asserts retry behavior and guards against reintroducing fixed `0.35/0.6` timers. + +Validation run: +- `bun test launcher/mpv.test.ts` pass. +- `lua scripts/test-plugin-process-start-retries.lua` pass. +- Existing broader plugin gate suite still has unrelated failure in current tree (`scripts/test-plugin-start-gate.lua` AniSkip async curl assertion). + diff --git a/launcher/mpv.test.ts b/launcher/mpv.test.ts index 425a3ff..a2743d5 100644 --- a/launcher/mpv.test.ts +++ b/launcher/mpv.test.ts @@ -4,7 +4,8 @@ import fs from 'node:fs'; import path from 'node:path'; import net from 'node:net'; import { EventEmitter } from 'node:events'; -import { waitForUnixSocketReady } from './mpv'; +import type { Args } from './types'; +import { startOverlay, state, waitForUnixSocketReady } from './mpv'; import * as mpvModule from './mpv'; function createTempSocketPath(): { dir: string; socketPath: string } { @@ -59,3 +60,82 @@ test('waitForUnixSocketReady returns true when socket becomes connectable before fs.rmSync(dir, { recursive: true, force: true }); } }); + +function makeArgs(overrides: Partial = {}): Args { + return { + backend: 'x11', + directory: '.', + recursive: false, + profile: '', + startOverlay: false, + youtubeSubgenMode: 'off', + whisperBin: '', + whisperModel: '', + youtubeSubgenOutDir: '', + youtubeSubgenAudioFormat: 'wav', + youtubeSubgenKeepTemp: false, + youtubePrimarySubLangs: [], + youtubeSecondarySubLangs: [], + youtubeAudioLangs: [], + youtubeWhisperSourceLanguage: 'ja', + useTexthooker: false, + autoStartOverlay: false, + texthookerOnly: false, + useRofi: false, + logLevel: 'error', + passwordStore: '', + target: '', + targetKind: '', + jimakuApiKey: '', + jimakuApiKeyCommand: '', + jimakuApiBaseUrl: '', + jimakuLanguagePreference: 'none', + jimakuMaxEntryResults: 10, + jellyfin: false, + jellyfinLogin: false, + jellyfinLogout: false, + jellyfinPlay: false, + jellyfinDiscovery: false, + doctor: false, + configPath: false, + configShow: false, + mpvIdle: false, + mpvSocket: false, + mpvStatus: false, + appPassthrough: false, + appArgs: [], + jellyfinServer: '', + jellyfinUsername: '', + jellyfinPassword: '', + ...overrides, + }; +} + +test('startOverlay resolves without fixed 2s sleep when readiness signals arrive quickly', async () => { + const { dir, socketPath } = createTempSocketPath(); + const appPath = path.join(dir, 'fake-subminer.sh'); + fs.writeFileSync(appPath, '#!/bin/sh\nexit 0\n'); + fs.chmodSync(appPath, 0o755); + fs.writeFileSync(socketPath, ''); + const originalCreateConnection = net.createConnection; + try { + net.createConnection = (() => { + const socket = new EventEmitter() as net.Socket; + socket.destroy = (() => socket) as net.Socket['destroy']; + socket.setTimeout = (() => socket) as net.Socket['setTimeout']; + setTimeout(() => socket.emit('connect'), 10); + return socket; + }) as typeof net.createConnection; + + const startedAt = Date.now(); + await startOverlay(appPath, makeArgs(), socketPath); + const elapsedMs = Date.now() - startedAt; + + assert.ok(elapsedMs < 1200, `expected startOverlay <1200ms, got ${elapsedMs}ms`); + } finally { + net.createConnection = originalCreateConnection; + state.overlayProc = null; + state.overlayManagedByLauncher = false; + fs.rmSync(dir, { recursive: true, force: true }); + } +}); diff --git a/launcher/mpv.ts b/launcher/mpv.ts index 5e06471..7848202 100644 --- a/launcher/mpv.ts +++ b/launcher/mpv.ts @@ -28,6 +28,8 @@ export const state = { }; const DETACHED_IDLE_MPV_PID_FILE = path.join(os.tmpdir(), 'subminer-idle-mpv.pid'); +const OVERLAY_START_SOCKET_READY_TIMEOUT_MS = 900; +const OVERLAY_START_COMMAND_SETTLE_TIMEOUT_MS = 700; function readTrackedDetachedMpvPid(): number | null { try { @@ -498,7 +500,47 @@ export function startMpv( state.mpvProc = spawn('mpv', mpvArgs, { stdio: 'inherit' }); } -export function startOverlay(appPath: string, args: Args, socketPath: string): Promise { +async function waitForOverlayStartCommandSettled( + proc: ReturnType, + logLevel: LogLevel, + timeoutMs: number, +): Promise { + await new Promise((resolve) => { + let settled = false; + let timer: ReturnType | null = null; + + const finish = () => { + if (settled) return; + settled = true; + if (timer) clearTimeout(timer); + proc.off('exit', onExit); + proc.off('error', onError); + resolve(); + }; + + const onExit = (code: number | null) => { + if (typeof code === 'number' && code !== 0) { + log('warn', logLevel, `Overlay start command exited with status ${code}`); + } + finish(); + }; + + const onError = (error: Error) => { + log('warn', logLevel, `Overlay start command failed: ${error.message}`); + finish(); + }; + + proc.once('exit', onExit); + proc.once('error', onError); + timer = setTimeout(finish, timeoutMs); + + if (proc.exitCode !== null && proc.exitCode !== undefined) { + onExit(proc.exitCode); + } + }); +} + +export async function startOverlay(appPath: string, args: Args, socketPath: string): Promise { const backend = detectBackend(args.backend); log('info', args.logLevel, `Starting SubMiner overlay (backend: ${backend})...`); @@ -512,9 +554,22 @@ export function startOverlay(appPath: string, args: Args, socketPath: string): P }); state.overlayManagedByLauncher = true; - return new Promise((resolve) => { - setTimeout(resolve, 2000); - }); + const [socketReady] = await Promise.all([ + waitForUnixSocketReady(socketPath, OVERLAY_START_SOCKET_READY_TIMEOUT_MS), + waitForOverlayStartCommandSettled( + state.overlayProc, + args.logLevel, + OVERLAY_START_COMMAND_SETTLE_TIMEOUT_MS, + ), + ]); + + if (!socketReady) { + log( + 'debug', + args.logLevel, + 'Overlay start continuing before mpv socket readiness was confirmed', + ); + } } export function launchTexthookerOnly(appPath: string, args: Args): never { diff --git a/plugin/subminer/process.lua b/plugin/subminer/process.lua new file mode 100644 index 0000000..2386591 --- /dev/null +++ b/plugin/subminer/process.lua @@ -0,0 +1,388 @@ +local M = {} + +local OVERLAY_START_RETRY_DELAY_SECONDS = 0.2 +local OVERLAY_START_MAX_ATTEMPTS = 6 +local STARTUP_OVERLAY_ACTION_RETRY_DELAY_SECONDS = 0.2 +local STARTUP_OVERLAY_ACTION_MAX_ATTEMPTS = 6 + +function M.create(ctx) + local mp = ctx.mp + local opts = ctx.opts + local state = ctx.state + local binary = ctx.binary + local environment = ctx.environment + local options_helper = ctx.options_helper + local subminer_log = ctx.log.subminer_log + local show_osd = ctx.log.show_osd + local normalize_log_level = ctx.log.normalize_log_level + + local function resolve_backend(override_backend) + local selected = override_backend + if selected == nil or selected == "" then + selected = opts.backend + end + if selected == "auto" then + return environment.detect_backend() + end + return selected + end + + local function build_command_args(action, overrides) + overrides = overrides or {} + local args = { state.binary_path } + + table.insert(args, "--" .. action) + local log_level = normalize_log_level(overrides.log_level or opts.log_level) + if log_level ~= "info" then + table.insert(args, "--log-level") + table.insert(args, log_level) + end + + if action == "start" then + local backend = resolve_backend(overrides.backend) + if backend and backend ~= "" then + table.insert(args, "--backend") + table.insert(args, backend) + end + + local socket_path = overrides.socket_path or opts.socket_path + table.insert(args, "--socket") + table.insert(args, socket_path) + end + + return args + end + + local function run_control_command_async(action, overrides, callback) + local args = build_command_args(action, overrides) + subminer_log("debug", "process", "Control command: " .. table.concat(args, " ")) + mp.command_native_async({ + name = "subprocess", + args = args, + playback_only = false, + capture_stdout = true, + capture_stderr = true, + }, function(success, result, error) + local ok = success and (result == nil or result.status == 0) + if callback then + callback(ok, result, error) + end + end) + end + + local function parse_start_script_message_overrides(...) + local overrides = {} + for i = 1, select("#", ...) do + local token = select(i, ...) + if type(token) == "string" and token ~= "" then + local key, value = token:match("^([%w_%-]+)=(.+)$") + if key and value then + local normalized_key = key:lower() + if normalized_key == "backend" then + local backend = value:lower() + if backend == "auto" or backend == "hyprland" or backend == "sway" or backend == "x11" or backend == "macos" then + overrides.backend = backend + end + elseif normalized_key == "socket" or normalized_key == "socket_path" then + overrides.socket_path = value + elseif normalized_key == "texthooker" or normalized_key == "texthooker_enabled" then + local parsed = options_helper.coerce_bool(value, nil) + if parsed ~= nil then + overrides.texthooker_enabled = parsed + end + elseif normalized_key == "log-level" or normalized_key == "log_level" then + overrides.log_level = normalize_log_level(value) + end + end + end + end + return overrides + end + + local function resolve_visible_overlay_startup() + return options_helper.coerce_bool(opts.auto_start_visible_overlay, false) + end + + local function apply_startup_overlay_preferences() + local should_show_visible = resolve_visible_overlay_startup() + local visible_action = should_show_visible and "show-visible-overlay" or "hide-visible-overlay" + + local function try_apply(attempt) + run_control_command_async(visible_action, nil, function(ok) + if ok then + subminer_log( + "debug", + "process", + "Applied visible startup action: " .. visible_action .. " (attempt " .. tostring(attempt) .. ")" + ) + return + end + + if attempt >= STARTUP_OVERLAY_ACTION_MAX_ATTEMPTS then + subminer_log("warn", "process", "Failed to apply visible startup action: " .. visible_action) + return + end + + mp.add_timeout(STARTUP_OVERLAY_ACTION_RETRY_DELAY_SECONDS, function() + try_apply(attempt + 1) + end) + end) + end + + try_apply(1) + end + + local function build_texthooker_args() + local args = { state.binary_path, "--texthooker", "--port", tostring(opts.texthooker_port) } + local log_level = normalize_log_level(opts.log_level) + if log_level ~= "info" then + table.insert(args, "--log-level") + table.insert(args, log_level) + end + return args + end + + local function ensure_texthooker_running(callback) + if not opts.texthooker_enabled then + callback() + return + end + + if state.texthooker_running then + callback() + return + end + + local args = build_texthooker_args() + subminer_log("info", "texthooker", "Starting texthooker process: " .. table.concat(args, " ")) + state.texthooker_running = true + + mp.command_native_async({ + name = "subprocess", + args = args, + playback_only = false, + capture_stdout = true, + capture_stderr = true, + }, function(success, result, error) + if not success or (result and result.status ~= 0) then + state.texthooker_running = false + subminer_log( + "warn", + "texthooker", + "Texthooker process exited unexpectedly: " .. (error or (result and result.stderr) or "unknown error") + ) + end + end) + + -- Start overlay immediately; overlay start path retries on readiness failures. + callback() + end + + local function start_overlay(overrides) + if not binary.ensure_binary_available() then + subminer_log("error", "binary", "SubMiner binary not found") + show_osd("Error: binary not found") + return + end + + if state.overlay_running then + subminer_log("info", "process", "Overlay already running") + show_osd("Already running") + return + end + + overrides = overrides or {} + local texthooker_enabled = overrides.texthooker_enabled + if texthooker_enabled == nil then + texthooker_enabled = opts.texthooker_enabled + end + + local function launch_overlay_with_retry(attempt) + local args = build_command_args("start", overrides) + if attempt == 1 then + subminer_log("info", "process", "Starting overlay: " .. table.concat(args, " ")) + else + subminer_log( + "warn", + "process", + "Retrying overlay start (attempt " .. tostring(attempt) .. "): " .. table.concat(args, " ") + ) + end + + if attempt == 1 then + show_osd("Starting...") + end + state.overlay_running = true + + mp.command_native_async({ + name = "subprocess", + args = args, + playback_only = false, + capture_stdout = true, + capture_stderr = true, + }, function(success, result, error) + if not success or (result and result.status ~= 0) then + local reason = error or (result and result.stderr) or "unknown error" + if attempt < OVERLAY_START_MAX_ATTEMPTS then + mp.add_timeout(OVERLAY_START_RETRY_DELAY_SECONDS, function() + launch_overlay_with_retry(attempt + 1) + end) + return + end + + state.overlay_running = false + subminer_log("error", "process", "Overlay start failed after retries: " .. reason) + show_osd("Overlay start failed") + return + end + + apply_startup_overlay_preferences() + end) + end + + if texthooker_enabled then + ensure_texthooker_running(function() + launch_overlay_with_retry(1) + end) + else + launch_overlay_with_retry(1) + end + end + + local function start_overlay_from_script_message(...) + local overrides = parse_start_script_message_overrides(...) + start_overlay(overrides) + end + + local function stop_overlay() + if not binary.ensure_binary_available() then + subminer_log("error", "binary", "SubMiner binary not found") + show_osd("Error: binary not found") + return + end + + run_control_command_async("stop", nil, function(ok, result) + if ok then + subminer_log("info", "process", "Overlay stopped") + else + subminer_log( + "warn", + "process", + "Stop command returned non-zero status: " .. tostring(result and result.status or "unknown") + ) + end + end) + + state.overlay_running = false + state.texthooker_running = false + show_osd("Stopped") + end + + local function toggle_overlay() + if not binary.ensure_binary_available() then + subminer_log("error", "binary", "SubMiner binary not found") + show_osd("Error: binary not found") + return + end + + run_control_command_async("toggle", nil, function(ok) + if not ok then + subminer_log("warn", "process", "Toggle command failed") + show_osd("Toggle failed") + end + end) + end + + local function open_options() + if not binary.ensure_binary_available() then + subminer_log("error", "binary", "SubMiner binary not found") + show_osd("Error: binary not found") + return + end + + run_control_command_async("settings", nil, function(ok) + if ok then + subminer_log("info", "process", "Options window opened") + show_osd("Options opened") + else + subminer_log("warn", "process", "Failed to open options") + show_osd("Failed to open options") + end + end) + end + + local function restart_overlay() + if not binary.ensure_binary_available() then + subminer_log("error", "binary", "SubMiner binary not found") + show_osd("Error: binary not found") + return + end + + subminer_log("info", "process", "Restarting overlay...") + show_osd("Restarting...") + + run_control_command_async("stop", nil, function() + state.overlay_running = false + state.texthooker_running = false + + ensure_texthooker_running(function() + local start_args = build_command_args("start") + subminer_log("info", "process", "Starting overlay: " .. table.concat(start_args, " ")) + + state.overlay_running = true + mp.command_native_async({ + name = "subprocess", + args = start_args, + playback_only = false, + capture_stdout = true, + capture_stderr = true, + }, function(success, result, error) + if not success or (result and result.status ~= 0) then + state.overlay_running = false + subminer_log( + "error", + "process", + "Overlay start failed: " .. (error or (result and result.stderr) or "unknown error") + ) + show_osd("Restart failed") + else + show_osd("Restarted successfully") + end + end) + end) + end) + end + + local function check_status() + if not binary.ensure_binary_available() then + show_osd("Status: binary not found") + return + end + + local status = state.overlay_running and "running" or "stopped" + show_osd("Status: overlay is " .. status) + subminer_log("info", "process", "Status check: overlay is " .. status) + end + + local function check_binary_available() + return binary.ensure_binary_available() + end + + return { + build_command_args = build_command_args, + run_control_command_async = run_control_command_async, + parse_start_script_message_overrides = parse_start_script_message_overrides, + apply_startup_overlay_preferences = apply_startup_overlay_preferences, + ensure_texthooker_running = ensure_texthooker_running, + start_overlay = start_overlay, + start_overlay_from_script_message = start_overlay_from_script_message, + stop_overlay = stop_overlay, + toggle_overlay = toggle_overlay, + open_options = open_options, + restart_overlay = restart_overlay, + check_status = check_status, + check_binary_available = check_binary_available, + } +end + +return M diff --git a/scripts/test-plugin-process-start-retries.lua b/scripts/test-plugin-process-start-retries.lua new file mode 100644 index 0000000..cf5fca1 --- /dev/null +++ b/scripts/test-plugin-process-start-retries.lua @@ -0,0 +1,128 @@ +local function assert_true(condition, message) + if condition then + return + end + error(message) +end + +local function has_flag(call, flag) + local args = call.args or {} + for _, arg in ipairs(args) do + if arg == flag then + return true + end + end + return false +end + +local function has_timeout(timeouts, target) + for _, value in ipairs(timeouts) do + if math.abs(value - target) < 0.0001 then + return true + end + end + return false +end + +local recorded = { + async_calls = {}, + timeouts = {}, + logs = {}, +} + +local start_attempts = 0 + +local mp = {} + +function mp.command_native_async(command, callback) + recorded.async_calls[#recorded.async_calls + 1] = command + + local success = true + local result = { status = 0, stdout = "", stderr = "" } + local err = nil + + if has_flag(command, "--start") then + start_attempts = start_attempts + 1 + if start_attempts == 1 then + success = false + result = { status = 1, stdout = "", stderr = "startup-not-ready" } + err = "startup-not-ready" + end + end + + if callback then + callback(success, result, err) + end +end + +function mp.add_timeout(seconds, callback) + recorded.timeouts[#recorded.timeouts + 1] = seconds + if callback then + callback() + end +end + +local process_module = dofile("plugin/subminer/process.lua") +local process = process_module.create({ + mp = mp, + opts = { + backend = "x11", + socket_path = "/tmp/subminer.sock", + log_level = "debug", + texthooker_enabled = true, + texthooker_port = 5174, + auto_start_visible_overlay = false, + }, + state = { + binary_path = "/tmp/subminer", + overlay_running = false, + texthooker_running = false, + }, + binary = { + ensure_binary_available = function() + return true + end, + }, + environment = { + detect_backend = function() + return "x11" + end, + }, + options_helper = { + coerce_bool = function(value, default_value) + if value == true or value == "yes" or value == "true" then + return true + end + if value == false or value == "no" or value == "false" then + return false + end + return default_value + end, + }, + log = { + subminer_log = function(_level, _scope, line) + recorded.logs[#recorded.logs + 1] = line + end, + show_osd = function(_) end, + normalize_log_level = function(value) + return value or "info" + end, + }, +}) + +process.start_overlay() + +assert_true(start_attempts == 2, "expected start overlay command retry after readiness failure") +assert_true(not has_timeout(recorded.timeouts, 0.35), "fixed texthooker wait (0.35s) should be removed") +assert_true(not has_timeout(recorded.timeouts, 0.6), "fixed startup visibility delay (0.6s) should be removed") + +local retry_timeout_seen = false +for _, timeout_seconds in ipairs(recorded.timeouts) do + if timeout_seconds > 0 and timeout_seconds <= 0.25 then + retry_timeout_seen = true + break + end +end +assert_true(retry_timeout_seen, "expected shorter bounded retry timeout") + +print("plugin process retry regression tests: OK")