diff --git a/.claude/CLAUDE.md b/.claude/CLAUDE.md index 1cf6ddb..d0d9e97 100644 --- a/.claude/CLAUDE.md +++ b/.claude/CLAUDE.md @@ -197,6 +197,42 @@ to be fixed: list with a chip. A ~173px column has no room to both truncate and stay readable, so dual-column names wrap as they did before the chips existed. +### Capture-card health and the log file + +The wall is Windows 11 with two PCIe **Elgato 4K60 Pro MK.2** cards. Its startup +script (Mosaic, then Warp, then the cards, then the app) lives in +`LAB271/labs-videowall-config`, not here: this repo is the application only. +A card sometimes comes up showing black with a live source plugged in. The +**split-flap never shows for this**: the wall has no no-signal references on +purpose, and the stream opened fine. + +`src/renderer/stream-health.js` is the policy (pure, unit tested) and +`renderer.js` samples it every 2s: + +| Status | Evidence | Reopen schedule | +|---|---|---| +| `open-failed` / `ended` / `no-frames` / `stalled` | getUserMedia, track state, frame counter | 2s, 5s, 15s, 30s, then every 60s | +| `dark` | 32x18 luma thumbnail is one flat colour for 6s | 5s ... then every 10 min | + +Three things worth not re-learning: + +- **It counts frames and never measures motion.** A held slide still arrives at + 60fps, so this does not reopen the #159 question. A stop only counts as a stall + if the feed was *flowing* first, which keeps a static virtual camera (which + really does send only one frame) from being reopened in a loop. +- **A reopen releases every side on the device first.** Chromium shares one + capture session per device, so reopening one side while the other still holds a + track never closes the device. On the wall both panels usually show the same card. +- **The driver exposes no signal-lock state** (registry and services checked). + The picture is the only evidence. Reopening a flat feed is safe because its + blank moment cannot be seen. + +Everything either process prints goes to +`/logs/input-viewer-YYYY-MM-DD.log` (`src/main/file-log.js`): 7 days +kept, 20 MB/day cap, 600 lines/min. Renderer lines arrive through +`console-message`, so an object argument logs as `[object Object]`. Log a flat +string when the line matters. `__health()` in DevTools prints the current state. + ### The test-mode launch flags (#248) | Flag | Effect | diff --git a/input_viewer_electron/src/main/file-log.js b/input_viewer_electron/src/main/file-log.js new file mode 100644 index 0000000..b1d9cc5 --- /dev/null +++ b/input_viewer_electron/src/main/file-log.js @@ -0,0 +1,168 @@ +// SPDX-License-Identifier: Apache-2.0 +// SPDX-FileCopyrightText: 2025-2026 Schuberg Philis / Lab271 +/** + * Persistent app log: one file per day, kept for a week. + * + * Before this, nothing the app printed survived it. The wall came up with a dark + * capture card, someone restarted the app ten minutes later, and there was no way + * to tell afterwards what the renderer had seen. This is the record. + * + * Bounded three ways, because the wall runs for months: + * - files older than `retentionDays` are deleted (on start and at each day change) + * - a day's file stops growing at `maxBytesPerDay`, with one line saying so + * - more than `maxLinesPerMinute` lines in a minute are dropped and counted, + * so a log loop cannot fill the disk before the day cap even matters + * Worst case on disk is retentionDays x maxBytesPerDay; the default is ~140 MB and + * a normal day is a few hundred KB. + * + * Synchronous appends on purpose: a crash or a hard power-off is exactly when + * the last lines matter, and at the rate limit the cost is nothing. + */ +const fs = require('fs') +const path = require('path') + +const FILE_RE = /^input-viewer-(\d{4})-(\d{2})-(\d{2})\.log$/ + +function pad(n) { + return String(n).padStart(2, '0') +} + +/** Local-date stamp, so a file is one wall-clock day where the wall is. */ +function dayStamp(d) { + return `${d.getFullYear()}-${pad(d.getMonth() + 1)}-${pad(d.getDate())}` +} + +function timeStamp(d) { + return `${pad(d.getHours())}:${pad(d.getMinutes())}:${pad(d.getSeconds())}.` + + String(d.getMilliseconds()).padStart(3, '0') +} + +/** + * @param {{dir: string, retentionDays?: number, maxBytesPerDay?: number, + * maxLinesPerMinute?: number, maxLineLength?: number, now?: () => Date}} opts + */ +function createFileLog({ + dir, + retentionDays = 7, + maxBytesPerDay = 20 * 1024 * 1024, + maxLinesPerMinute = 600, + maxLineLength = 2000, + now = () => new Date(), +}) { + let day = null + let file = null + let bytes = 0 + let capped = false + let minute = null + let linesThisMinute = 0 + let dropped = 0 + let broken = false + + function prune(today) { + let names + try { + names = fs.readdirSync(dir) + } catch { + return [] + } + // Compare calendar days, not mtimes: a file touched late is still that day. + const cutoff = new Date(today.getFullYear(), today.getMonth(), today.getDate() - (retentionDays - 1)) + const removed = [] + for (const name of names) { + const m = FILE_RE.exec(name) + if (!m) continue + const fileDay = new Date(Number(m[1]), Number(m[2]) - 1, Number(m[3])) + if (fileDay < cutoff) { + try { + fs.unlinkSync(path.join(dir, name)) + removed.push(name) + } catch { /* in use or gone; try again tomorrow */ } + } + } + return removed + } + + function rollIfNeeded(d) { + const stamp = dayStamp(d) + if (stamp === day) return + day = stamp + file = path.join(dir, `input-viewer-${stamp}.log`) + capped = false + try { + fs.mkdirSync(dir, { recursive: true }) + bytes = fs.existsSync(file) ? fs.statSync(file).size : 0 + } catch { + bytes = 0 + } + prune(d) + } + + function append(text) { + if (broken) return + try { + fs.appendFileSync(file, text) + bytes += Buffer.byteLength(text) + } catch { + // A log that cannot be written must never take the app down with it. + // Stop trying rather than throw on every console.log. + broken = true + } + } + + return { + /** + * @param {string} level info | warn | error | debug + * @param {string} source main | renderer | ... + * @param {string} message + */ + write(level, source, message) { + const d = now() + rollIfNeeded(d) + + const m = Math.floor(d.getTime() / 60_000) + if (m !== minute) { + if (dropped > 0 && !capped) { + append(`${timeStamp(d)} WARN [log] dropped ${dropped} line(s) over ` + + `${maxLinesPerMinute}/min in the previous minute\n`) + } + minute = m + linesThisMinute = 0 + dropped = 0 + } + if (linesThisMinute >= maxLinesPerMinute) { + dropped += 1 + return + } + linesThisMinute += 1 + + if (capped) return + if (bytes >= maxBytesPerDay) { + capped = true + append(`${timeStamp(d)} WARN [log] ${maxBytesPerDay} byte daily cap reached; ` + + 'nothing more is written until tomorrow\n') + return + } + + let text = String(message) + if (text.length > maxLineLength) text = text.slice(0, maxLineLength) + '...(truncated)' + // One record per line, so a multi-line stack does not interleave with others. + text = text.replace(/\r?\n/g, '\n ') + append(`${timeStamp(d)} ${level.toUpperCase().padEnd(5)} [${source}] ${text}\n`) + }, + + /** Delete files past retention. Returns the names removed. */ + prune() { + return prune(now()) + }, + + /** Today's file. */ + path() { + rollIfNeeded(now()) + return file + }, + + dir, + } +} + +module.exports = { createFileLog, dayStamp } diff --git a/input_viewer_electron/src/main/index.js b/input_viewer_electron/src/main/index.js index 020d17f..8773ff8 100644 --- a/input_viewer_electron/src/main/index.js +++ b/input_viewer_electron/src/main/index.js @@ -3,7 +3,9 @@ const { app, BrowserWindow, ipcMain, systemPreferences, dialog, shell, screen } = require('electron') const path = require('path') const fs = require('fs') +const os = require('os') const { exec } = require('child_process') +const { createFileLog } = require('./file-log.js') // Hardware acceleration for video decode/rendering app.commandLine.appendSwitch('ignore-gpu-blocklist') @@ -77,6 +79,40 @@ function getAppVersion() { // Settings file path const settingsPath = path.join(app.getPath('userData'), 'settings.json') +// Persistent log (see file-log.js): /logs/input-viewer-YYYY-MM-DD.log, +// seven days kept. Main's own console is teed into it here; the renderer's +// console arrives through 'console-message' in createWindow(). +const fileLog = createFileLog({ dir: path.join(app.getPath('userData'), 'logs') }) + +for (const [method, level] of [['log', 'info'], ['info', 'info'], ['warn', 'warn'], ['error', 'error']]) { + const original = console[method].bind(console) + console[method] = (...args) => { + original(...args) + fileLog.write(level, 'main', args.map(formatLogArg).join(' ')) + } +} + +function formatLogArg(arg) { + if (typeof arg === 'string') return arg + if (arg instanceof Error) return arg.stack || `${arg.name}: ${arg.message}` + try { + return JSON.stringify(arg) + } catch { + return String(arg) + } +} + +// Renderer console levels: Electron 43 passes a string on the event object; +// older versions passed a number as the second argument. +const RENDERER_LEVELS = { 0: 'debug', 1: 'info', 2: 'warn', 3: 'error', + verbose: 'debug', info: 'info', warning: 'warn', error: 'error', debug: 'debug' } + +// Startup banner. OS uptime is here because the question after a bad boot is +// usually "how long after the machine came up did the app open the cards". +console.log(`[App] Input Viewer ${app.getVersion()} starting; ` + + `${process.platform} ${os.release()} ${process.arch}, electron ${process.versions.electron}, ` + + `OS up ${Math.round(os.uptime())}s, pid ${process.pid}, log ${fileLog.dir}`) + // Default settings const defaultSettings = { leftDeviceId: null, @@ -226,6 +262,22 @@ function createWindow() { callback(allowed) }) + // Everything the renderer prints goes to the log file too. Debug level is left + // out: it is DevTools-only chatter and would only eat the rate limit. + mainWindow.webContents.on('console-message', (event, legacyLevel, legacyMessage) => { + const level = RENDERER_LEVELS[event?.level ?? legacyLevel] ?? 'info' + if (level === 'debug') return + fileLog.write(level, 'renderer', event?.message ?? legacyMessage ?? '') + }) + + // The failures that leave a black wall with nothing in the renderer's own log, + // because the renderer is the thing that died. + mainWindow.webContents.on('render-process-gone', (_event, details) => { + console.error(`[App] renderer process gone: ${details.reason} (exit ${details.exitCode})`) + }) + mainWindow.on('unresponsive', () => console.warn('[App] window unresponsive')) + mainWindow.on('responsive', () => console.log('[App] window responsive again')) + // Handle window closed mainWindow.on('closed', () => { mainWindow = null @@ -271,6 +323,14 @@ app.whenReady().then(async () => { }) }) +// GPU and utility processes: the video decode and capture paths run in these. +app.on('child-process-gone', (_event, details) => { + console.error(`[App] ${details.type} process gone: ${details.reason} ` + + `(exit ${details.exitCode}${details.name ? `, ${details.name}` : ''})`) +}) + +app.on('before-quit', () => console.log('[App] quitting')) + // Quit when all windows are closed (except on macOS) app.on('window-all-closed', () => { if (process.platform !== 'darwin') { diff --git a/input_viewer_electron/src/renderer/renderer.js b/input_viewer_electron/src/renderer/renderer.js index ccd5c0b..3f16022 100644 --- a/input_viewer_electron/src/renderer/renderer.js +++ b/input_viewer_electron/src/renderer/renderer.js @@ -76,6 +76,10 @@ import { isMockDeviceId } from './mock-capture.js' +// Capture-card health: notices a card that opened but is not delivering, and +// reopens it. +import { createStreamHealth, lumaStats } from './stream-health.js' + // ============================================================================= // State Management // ============================================================================= @@ -114,6 +118,11 @@ const state = { testFlags: { ...DEFAULT_TEST_FLAGS }, // Live mock streams, so they can be stopped on input switch. Keyed by side. mockStreams: { left: null, right: null }, + // Capture-card health, per side. See stream-health.js. + health: { left: createStreamHealth(), right: createStreamHealth() }, + // Bumped on every startVideoStream call for a side, so a reopen that was + // scheduled before an operator switched inputs can tell it has been overtaken. + streamGen: { left: 0, right: 0 }, // DVD screensaver timer dvdScreensaverTimeout: null, // dvdScreensaverDelay: 10 * 1000, // 10 seconds in milliseconds @@ -545,6 +554,10 @@ async function getVideoDevices() { state.devices = devices.filter(device => device.kind === 'videoinput') console.log('Available video devices:', state.devices) + // One flat line as well: the object above reaches the log file as + // "[object Object]", and this is the line that says which cards were seen. + console.log(`[Video] ${state.devices.length} video input(s): ` + + state.devices.map(d => `"${d.label}" ${d.deviceId.slice(0, 8)}`).join(', ')) // Initialize settings for new devices state.devices.forEach((device) => { @@ -591,7 +604,7 @@ async function getVideoDevices() { renderDropdownInputLists() return state.devices } catch (error) { - console.error('Error getting video devices:', error) + console.error(`[Video] device enumeration failed: ${error?.name}: ${error?.message}`) showNoSignal('left') showNoSignal('right') return [] @@ -599,6 +612,7 @@ async function getVideoDevices() { } async function startVideoStream(deviceId, videoElement, side) { + state.streamGen[side] += 1 try { // Stop existing stream if (side === 'left' && state.leftStream) { @@ -615,12 +629,14 @@ async function startVideoStream(deviceId, videoElement, side) { } if (!deviceId) { + state.health[side].clear() showNoSignal(side) return null } // Check if device is enabled if (!isInputEnabled(deviceId)) { + state.health[side].clear() showNoSignal(side) return null } @@ -656,6 +672,7 @@ async function startVideoStream(deviceId, videoElement, side) { if (label && device) { label.textContent = getInputName(deviceId, device.label || 'Mock Input') } + state.health[side].opened(performance.now()) return mock.stream } @@ -791,14 +808,247 @@ async function startVideoStream(deviceId, videoElement, side) { label.textContent = name } + attachStreamHealth(side, deviceId, stream) return stream } catch (error) { - console.error(`Error starting ${side} stream:`, error) + // name + message explicitly: a DOMException logs as "{}" once it has been + // through the console-message bridge into the log file, and the name + // (NotReadableError, NotFoundError, AbortError...) is the useful part. + console.error(`[Video] ${side} stream failed to open: ${error?.name}: ${error?.message}`) + state.health[side].openFailed(performance.now(), error) showNoSignal(side) return null } } +// ============================================================================= +// Capture-card health +// ============================================================================= +// +// The policy lives in stream-health.js and is unit tested there. This part owns +// the sampling (frame counter + a 32x18 luma thumbnail every HEALTH_SAMPLE_MS) +// and the reopen itself. + +const HEALTH_SAMPLE_MS = 2000 +// One summary line per side at this interval, whatever the status. A baseline +// of what a healthy card looks like is what makes the bad line readable. +const HEALTH_SUMMARY_MS = 10 * 60 * 1000 +// Delay between releasing a card and opening it again. Short, but long enough +// that the driver sees the device closed rather than a handover. +const REOPEN_RELEASE_MS = 500 + +let healthTimer = null +let healthCanvas = null +let lastHealthSummary = 0 +const healthLastStatus = { left: null, right: null } +const reopenInFlight = new Set() + +function sideVideo(side) { + return side === 'left' ? elements.leftVideo : elements.rightVideo +} + +function sideDeviceId(side) { + return side === 'left' ? state.leftDeviceId : state.rightDeviceId +} + +function sideStream(side) { + return side === 'left' ? state.leftStream : state.rightStream +} + +function sideLabel(side) { + const id = sideDeviceId(side) + const device = state.devices.find(d => d.deviceId === id) + return getInputName(id, device?.label || 'unknown') +} + +/** Record a freshly opened stream and log what the card agreed to. */ +function attachStreamHealth(side, deviceId, stream) { + state.health[side].opened(performance.now()) + const track = stream.getVideoTracks()[0] + if (!track) return + const s = track.getSettings() + console.log(`[Health] ${side} opened "${track.label}" ` + + `${s.width}x${s.height}@${s.frameRate}fps id=${deviceId.slice(0, 8)}`) + // Logged the moment it happens rather than at the next sample: an ended track + // is the one event with an exact timestamp, and the log is where it is read. + track.addEventListener('ended', () => console.warn(`[Health] ${side} track ended`)) + track.addEventListener('mute', () => console.warn(`[Health] ${side} track muted`)) + track.addEventListener('unmute', () => console.log(`[Health] ${side} track unmuted`)) +} + +/** + * Frames the source has delivered so far, or null if the platform cannot say. + * + * track.stats counts at the source, so it keeps counting for a hidden feed (the + * right panel in single view is display:none). The video element's playback + * counter is the fallback. + */ +function readFrameCount(track, video) { + const stats = track?.stats + if (stats && typeof stats.totalFrames === 'number') return stats.totalFrames + const q = video?.getVideoPlaybackQuality?.() + if (q && typeof q.totalVideoFrames === 'number') return q.totalVideoFrames + return null +} + +function sampleLuma(video) { + if (!video || video.readyState < 2 || !video.videoWidth) return null + try { + if (!healthCanvas) { + healthCanvas = document.createElement('canvas') + healthCanvas.width = 32 + healthCanvas.height = 18 + } + const ctx = healthCanvas.getContext('2d', { willReadFrequently: true }) + if (!ctx) return null + ctx.drawImage(video, 0, 0, 32, 18) + return lumaStats(ctx.getImageData(0, 0, 32, 18).data) + } catch { + return null + } +} + +function describeHealth(side) { + const i = state.health[side].info() + const video = sideVideo(side) + const size = video?.videoWidth ? `${video.videoWidth}x${video.videoHeight}` : '-' + return `${i.status} ${i.fps}fps luma=${i.luma ?? '-'}±${i.lumaStd ?? '-'} ` + + `${size} reopens=${i.attempts}${i.error ? ` error=${i.error}` : ''}` +} + +// Retry schedule for "no capture devices at all", which the per-side +// trackers cannot see. Last step repeats. +const NO_DEVICES_RETRY_MS = [5000, 10_000, 30_000] +let noDevicesAttempts = 0 +let noDevicesLastTry = 0 +let noDevicesRetrying = false + +async function retryDeviceEnumeration(now) { + const wait = NO_DEVICES_RETRY_MS[Math.min(noDevicesAttempts, NO_DEVICES_RETRY_MS.length - 1)] + if (noDevicesRetrying || now - noDevicesLastTry < wait) return + noDevicesRetrying = true + noDevicesLastTry = now + noDevicesAttempts += 1 + try { + console.warn(`[Health] no capture devices, re-enumerating (attempt ${noDevicesAttempts})`) + if (await openInitialStreams(state.layoutMode)) { + console.log('[Health] capture devices found on retry') + noDevicesAttempts = 0 + } + } finally { + noDevicesRetrying = false + } +} + +function checkStreamHealth() { + const now = performance.now() + + if (state.devices.length === 0 && !state.testFlags.mock) { + retryDeviceEnumeration(now) + return + } + const summary = now - lastHealthSummary >= HEALTH_SUMMARY_MS + + for (const side of ['left', 'right']) { + const health = state.health[side] + const stream = sideStream(side) + const track = stream?.getVideoTracks?.()[0] ?? null + const video = sideVideo(side) + + if (track) { + health.sample({ + frames: readFrameCount(track, video), + ended: track.readyState === 'ended', + stats: sampleLuma(video), + }, now) + } + + const { status } = health.info() + if (status !== healthLastStatus[side]) { + const log = status === 'ok' || status === 'opening' || status === 'idle' + ? console.log : console.warn + log(`[Health] ${side} (${sideLabel(side)}): ${healthLastStatus[side] ?? 'start'} -> ` + + describeHealth(side)) + healthLastStatus[side] = status + } else if (summary && status !== 'idle') { + console.log(`[Health] ${side} (${sideLabel(side)}): ${describeHealth(side)}`) + } + + const decision = health.decide(now) + const deviceId = sideDeviceId(side) + if (decision.reopen && deviceId) { + reopenDevice(deviceId, `${side} ${decision.reason}`) + } + } + + if (summary) lastHealthSummary = now +} + +/** + * Close every stream on a device, then open them again. + * + * Every side showing this device is released FIRST. Chromium shares one + * capture session between tracks on the same device, so reopening one side + * while the other still holds a track never actually closes the device -- the + * driver would see nothing happen. On the wall both panels usually show the + * same card, so this is the normal case, not an edge case. + */ +async function reopenDevice(deviceId, reason) { + if (reopenInFlight.has(deviceId)) return + reopenInFlight.add(deviceId) + try { + const sides = ['left', 'right'].filter(side => sideDeviceId(side) === deviceId && + (sideStream(side) || state.health[side].info().status === 'open-failed')) + if (sides.length === 0) return + + const now = performance.now() + const gens = {} + for (const side of sides) { + gens[side] = state.streamGen[side] + state.health[side].reopening(now) + } + console.warn(`[Health] reopening ${deviceId.slice(0, 8)} (${sideLabel(sides[0])}) ` + + `for ${sides.join('+')}: ${reason}, attempt ${state.health[sides[0]].info().attempts}`) + + for (const side of sides) sideStream(side)?.getTracks().forEach(t => t.stop()) + closeAllFrameSources() + await new Promise(resolve => setTimeout(resolve, REOPEN_RELEASE_MS)) + + for (const side of sides) { + // An operator switch while we waited owns this side now. + if (state.streamGen[side] !== gens[side] || sideDeviceId(side) !== deviceId) continue + await startVideoStream(deviceId, sideVideo(side), side) + } + } catch (err) { + console.error(`[Health] reopen of ${deviceId.slice(0, 8)} failed: ${err?.message ?? err}`) + } finally { + reopenInFlight.delete(deviceId) + } +} + +function startStreamHealthMonitor() { + if (healthTimer !== null) return + // --no-signal pins every side dark on purpose, and a still mock card + // delivers no frames; the monitor would "fix" the state the flag exists to hold. + if (state.testFlags.noSignal) { + console.log('[Health] Not started: --no-signal pins the state') + return + } + lastHealthSummary = performance.now() + healthTimer = setInterval(checkStreamHealth, HEALTH_SAMPLE_MS) + console.log(`[Health] monitoring every ${HEALTH_SAMPLE_MS}ms`) +} + +// Console helper, same spirit as __detectState(). +globalThis.__health = () => { + const out = {} + for (const side of ['left', 'right']) { + out[side] = { device: sideLabel(side), ...state.health[side].info() } + } + console.log('[Health]', JSON.stringify(out)) + return out +} + // ============================================================================= // Audio Management // ============================================================================= @@ -3309,6 +3559,15 @@ function setupEventListeners() { // and the old ones would otherwise be read until the loop noticed. closeAllFrameSources() await getVideoDevices() + // A card coming back is the best moment to retry a side that failed; do not + // make it wait out the backoff. + for (const side of ['left', 'right']) { + const { status } = state.health[side].info() + const id = sideDeviceId(side) + if (id && (status === 'open-failed' || status === 'ended' || status === 'no-frames')) { + reopenDevice(id, `${side} ${status}, device change`) + } + } }) // Auto-updater download progress @@ -3914,6 +4173,39 @@ function getUniqueActiveDevices() { // Initialization // ============================================================================= +/** + * Enumerate the capture devices and open the startup inputs. + * + * A function rather than inline in init() so the health monitor can run it + * again: if enumeration fails at boot -- the card driver not up yet, or the + * device briefly held -- there are no device ids at all, so there is nothing + * for a per-side reopen to retry. + */ +async function openInitialStreams(layoutMode) { + await getVideoDevices() + if (state.devices.length === 0) return false + + // Use default input if set and device exists + if (state.defaultInputId) { + const defaultDevice = state.devices.find(d => d.deviceId === state.defaultInputId) + if (defaultDevice && isInputEnabled(state.defaultInputId)) { + state.leftDeviceId = state.defaultInputId + if (layoutMode === 'dual') { + state.rightDeviceId = state.defaultInputId + } + } + } + + // Always start left stream + await startVideoStream(state.leftDeviceId, elements.leftVideo, 'left') + + // Start right stream in dual mode + if (layoutMode === 'dual' && state.rightDeviceId) { + await startVideoStream(state.rightDeviceId, elements.rightVideo, 'right') + } + return true +} + async function init() { console.log('Input Viewer initializing...') @@ -3990,33 +4282,14 @@ async function init() { // first time the dropdown is opened; after that it polls only while open. // Get video devices and start streams - await getVideoDevices() - - // Start video streams - if (state.devices.length > 0) { - // Use default input if set and device exists - if (state.defaultInputId) { - const defaultDevice = state.devices.find(d => d.deviceId === state.defaultInputId) - if (defaultDevice && isInputEnabled(state.defaultInputId)) { - state.leftDeviceId = state.defaultInputId - if (layoutMode === 'dual') { - state.rightDeviceId = state.defaultInputId - } - } - } - - // Always start left stream - await startVideoStream(state.leftDeviceId, elements.leftVideo, 'left') - - // Start right stream in dual mode - if (layoutMode === 'dual' && state.rightDeviceId) { - await startVideoStream(state.rightDeviceId, elements.rightVideo, 'right') - } - } + await openInitialStreams(layoutMode) // --no-signal (#248): override whatever the streams above did to the overlays. applyForcedNoSignal() + // After the first open, so a card that failed it is retried from here on. + startStreamHealthMonitor() + // Initialize screensaver registry (random screensaver chosen on activation) initScreensavers(elements.screensaverCanvas) diff --git a/input_viewer_electron/src/renderer/stream-health.js b/input_viewer_electron/src/renderer/stream-health.js new file mode 100644 index 0000000..db9636b --- /dev/null +++ b/input_viewer_electron/src/renderer/stream-health.js @@ -0,0 +1,277 @@ +// SPDX-License-Identifier: Apache-2.0 +// SPDX-FileCopyrightText: 2025-2026 Schuberg Philis / Lab271 +/** + * Capture-card health: is this input actually working, and should it be reopened? + * + * The wall runs two Elgato 4K60 Pro MK.2 cards, and sometimes one comes up after + * boot showing black (or the card's own no-signal picture) with a live source + * plugged in -- until someone restarts the app. The split-flap board never shows + * for it, because the stream opened fine; nothing downstream knew it was bad. + * + * The driver exposes no signal-lock state outside Elgato's own SDK (checked on + * the wall: nothing in the registry, no service), so the only evidence is what + * arrives on the stream. This module turns that evidence into a status and a + * reopen decision. It is pure -- no DOM, no timers, the clock is passed in -- so + * the policy is unit tested; renderer.js owns the sampling and the reopen. + * + * Statuses: + * opening stream open, no frame yet + * ok frames arriving and the picture is not uniform + * no-frames open for FIRST_FRAME_TIMEOUT_MS and not a single frame + * stalled frames WERE flowing and have stopped for STALL_MS + * ended the track ended (driver dropped it, device went away) + * open-failed getUserMedia rejected + * dark frames arriving, but the picture is one flat colour + * + * Why a frame COUNT and not motion: #159 rejected motion detection because a + * held slide is pixel-identical for minutes. A capture card still delivers that + * held slide at 60fps, so "frames stopped arriving" is a different and safe + * question. The "was flowing" condition keeps a virtual camera showing a static + * image -- which genuinely sends only a frame or two (see the rVFC watchdog note + * in renderer.js) -- from being reported as stalled. + * + * Why reopening a dark feed is safe: a reopen blanks the picture for a moment. + * On a feed that is already one flat colour, that blank is invisible. The worst + * case is a presenter deliberately blanking to black (PowerPoint `B`), where a + * reopen is equally invisible. The dark cadence is slow for exactly this reason: + * with no source plugged in all night, it is the steady state. + */ + +export const HEALTH = { + /** Open but no frame at all after this long: the card is not delivering. */ + FIRST_FRAME_TIMEOUT_MS: 8000, + /** Frames stopped for this long after flowing: stalled. */ + STALL_MS: 6000, + /** A feed must deliver at least this rate once before a stop counts as a stall. */ + FLOWING_MIN_FPS: 5, + /** Uniform picture for this long before it counts as dark. */ + DARK_MS: 6000, + /** Healthy this long and the reopen backoff starts over. */ + RECOVERED_RESET_MS: 60_000, + /** Delays before each reopen of a faulted feed; the last one repeats. */ + FAULT_BACKOFF_MS: [2000, 5000, 15_000, 30_000, 60_000], + /** Delays before each reopen of a dark feed; the last one repeats. */ + DARK_BACKOFF_MS: [5000, 15_000, 30_000, 60_000, 5 * 60_000, 10 * 60_000], + /** Standard deviation of luma (0-255) below which a picture is one flat colour. */ + UNIFORM_STD_MAX: 3, +} + +const FAULTS = new Set(['no-frames', 'stalled', 'ended', 'open-failed']) + +/** + * Mean and standard deviation of luma over an RGBA pixel buffer. + * + * Meant for a tiny downscale (32x18 is 576 pixels), not a full frame. + * + * @param {Uint8ClampedArray|Uint8Array} data RGBA + * @returns {{mean: number, std: number}} + */ +export function lumaStats(data) { + const n = Math.floor(data.length / 4) + if (n === 0) return { mean: 0, std: 0 } + let sum = 0 + let sumSq = 0 + for (let i = 0; i < n; i++) { + const o = i * 4 + // Rec. 601 weights; exactness is irrelevant, flatness is the question. + const y = 0.299 * data[o] + 0.587 * data[o + 1] + 0.114 * data[o + 2] + sum += y + sumSq += y * y + } + const mean = sum / n + const variance = Math.max(0, sumSq / n - mean * mean) + return { mean, std: Math.sqrt(variance) } +} + +/** Is this picture one flat colour -- black, or a solid no-signal screen? */ +export function isUniform(stats) { + return !!stats && stats.std <= HEALTH.UNIFORM_STD_MAX +} + +/** Delay before reopen number `attempt` (0-based) under a backoff schedule. */ +export function backoffDelay(schedule, attempt) { + return schedule[Math.min(Math.max(0, attempt), schedule.length - 1)] +} + +/** + * Health state for one side's stream. + * + * Feed it events and samples; ask it what to do. `now` is a millisecond clock + * (performance.now() in the app, a plain number in tests). + */ +export function createStreamHealth() { + let status = 'idle' + let openedAt = 0 + let lastFrames = null // last frame counter reading + let lastFrameAt = 0 // when the counter last moved + let lastSampleAt = 0 + let firstFrameAt = null + let flowing = false // has this stream ever delivered at FLOWING_MIN_FPS + let uniformSince = null + let lastStats = null + let fps = 0 + let error = null + + // Survives reopens, so the backoff actually backs off. + let attempts = 0 + let lastReopenAt = null + let healthySince = null + + function setStatus(next, now) { + status = next + if (next === 'ok') { + if (healthySince === null) healthySince = now + } else { + healthySince = null + } + } + + return { + /** A stream was just attached. */ + opened(now) { + openedAt = now + lastFrames = null + lastFrameAt = now + lastSampleAt = now + firstFrameAt = null + flowing = false + uniformSince = null + lastStats = null + fps = 0 + error = null + setStatus('opening', now) + }, + + /** getUserMedia rejected. */ + openFailed(now, err) { + openedAt = now + error = err ? String(err.name || err.message || err) : 'unknown' + setStatus('open-failed', now) + }, + + /** Nothing to monitor on this side (no device, disabled, torn down). */ + clear() { + status = 'idle' + attempts = 0 + lastReopenAt = null + healthySince = null + error = null + }, + + /** + * One observation. + * + * @param {{frames: number|null, ended: boolean, stats: {mean:number,std:number}|null}} s + * frames: a monotonically increasing count of frames delivered, or null if + * the platform cannot say. stats: luma of a small downscale, or null. + * @param {number} now + * @returns {string} the status after this sample + */ + sample({ frames, ended, stats }, now) { + if (status === 'idle' || status === 'open-failed') return status + + if (ended) { + setStatus('ended', now) + return status + } + + if (typeof frames === 'number') { + if (lastFrames === null) { + lastFrames = frames + // A counter that already reads > 0 on the first look has delivered. + if (frames > 0) { lastFrameAt = now; firstFrameAt = now } + } else if (frames > lastFrames) { + const dt = now - lastSampleAt + fps = dt > 0 ? ((frames - lastFrames) * 1000) / dt : fps + if (fps >= HEALTH.FLOWING_MIN_FPS) flowing = true + if (firstFrameAt === null) firstFrameAt = now + lastFrames = frames + lastFrameAt = now + } else if (frames < lastFrames) { + // The counter went backwards: the element's playback counter restarts + // when its source is replaced. A new baseline, not evidence of a stall. + lastFrames = frames + lastFrameAt = now + } else { + fps = 0 + } + } + lastSampleAt = now + + if (stats) { + lastStats = stats + if (isUniform(stats)) { + if (uniformSince === null) uniformSince = now + } else { + uniformSince = null + } + } + + if (typeof frames === 'number') { + if (firstFrameAt === null) { + if (now - openedAt >= HEALTH.FIRST_FRAME_TIMEOUT_MS) { + setStatus('no-frames', now) + return status + } + setStatus('opening', now) + return status + } + if (flowing && now - lastFrameAt >= HEALTH.STALL_MS) { + setStatus('stalled', now) + return status + } + } + + if (uniformSince !== null && now - uniformSince >= HEALTH.DARK_MS) { + setStatus('dark', now) + return status + } + + setStatus('ok', now) + if (attempts > 0 && now - healthySince >= HEALTH.RECOVERED_RESET_MS) { + attempts = 0 + lastReopenAt = null + } + return status + }, + + /** + * Should this side be reopened now? + * + * @returns {{reopen: boolean, reason: string|null, waitMs: number}} + */ + decide(now) { + const schedule = FAULTS.has(status) ? HEALTH.FAULT_BACKOFF_MS + : status === 'dark' ? HEALTH.DARK_BACKOFF_MS + : null + if (!schedule) return { reopen: false, reason: null, waitMs: 0 } + + // Measured from the last reopen, or from when the stream opened for the + // first attempt -- so a stream that goes bad an hour in is reopened after + // the first delay, not immediately. + const since = lastReopenAt ?? openedAt + const wait = backoffDelay(schedule, attempts) + const waitMs = Math.max(0, since + wait - now) + return { reopen: waitMs === 0, reason: status, waitMs } + }, + + /** A reopen was started. */ + reopening(now) { + attempts += 1 + lastReopenAt = now + }, + + /** Snapshot for logging. */ + info() { + return { + status, + fps: Math.round(fps * 10) / 10, + flowing, + attempts, + luma: lastStats ? Math.round(lastStats.mean) : null, + lumaStd: lastStats ? Math.round(lastStats.std * 10) / 10 : null, + error, + } + }, + } +} diff --git a/input_viewer_electron/test/file-log.test.js b/input_viewer_electron/test/file-log.test.js new file mode 100644 index 0000000..edf964d --- /dev/null +++ b/input_viewer_electron/test/file-log.test.js @@ -0,0 +1,110 @@ +// SPDX-License-Identifier: Apache-2.0 +// SPDX-FileCopyrightText: 2025-2026 Schuberg Philis / Lab271 +import { describe, it, expect, beforeEach, afterEach } from 'vitest' +import { createRequire } from 'node:module' +import fs from 'node:fs' +import os from 'node:os' +import path from 'node:path' + +const require = createRequire(import.meta.url) +const { createFileLog, dayStamp } = require('../src/main/file-log.js') + +let dir +beforeEach(() => { dir = fs.mkdtempSync(path.join(os.tmpdir(), 'iv-log-')) }) +afterEach(() => { fs.rmSync(dir, { recursive: true, force: true }) }) + +function clock(start) { + let t = new Date(start) + return { now: () => t, set: (d) => { t = new Date(d) }, advance: (ms) => { t = new Date(t.getTime() + ms) } } +} + +function readToday(log) { + return fs.readFileSync(log.path(), 'utf8') +} + +describe('createFileLog', () => { + it('writes one timestamped line per record into a file named for the day', () => { + const c = clock('2026-09-23T08:40:00') + const log = createFileLog({ dir, now: c.now }) + log.write('info', 'renderer', '[Health] left ok') + log.write('warn', 'main', 'two\nlines') + expect(path.basename(log.path())).toBe('input-viewer-2026-09-23.log') + const text = readToday(log) + expect(text).toMatch(/^08:40:00\.000 INFO {2}\[renderer\] \[Health\] left ok\n/) + expect(text).toContain('WARN [main] two\n lines\n') + }) + + it('rolls to a new file at midnight', () => { + const c = clock('2026-09-23T23:59:59') + const log = createFileLog({ dir, now: c.now }) + log.write('info', 'main', 'before') + c.advance(2000) + log.write('info', 'main', 'after') + expect(fs.readdirSync(dir).sort()).toEqual([ + 'input-viewer-2026-09-23.log', 'input-viewer-2026-09-24.log', + ]) + }) + + it('deletes files older than a week, and leaves other files alone', () => { + for (const d of ['2026-09-10', '2026-09-16', '2026-09-17', '2026-09-22']) { + fs.writeFileSync(path.join(dir, `input-viewer-${d}.log`), 'x') + } + fs.writeFileSync(path.join(dir, 'settings.json'), '{}') + const c = clock('2026-09-23T09:00:00') + const log = createFileLog({ dir, retentionDays: 7, now: c.now }) + log.write('info', 'main', 'start') + // Seven calendar days kept: 17th..23rd. + expect(fs.readdirSync(dir).sort()).toEqual([ + 'input-viewer-2026-09-17.log', 'input-viewer-2026-09-22.log', + 'input-viewer-2026-09-23.log', 'settings.json', + ]) + }) + + it('prunes again when the day changes, not only at startup', () => { + const c = clock('2026-09-23T12:00:00') + const log = createFileLog({ dir, retentionDays: 7, now: c.now }) + log.write('info', 'main', 'day 0') + c.set('2026-10-01T00:00:01') + log.write('info', 'main', 'day 8') + expect(fs.readdirSync(dir)).toEqual(['input-viewer-2026-10-01.log']) + }) + + it('stops growing at the daily cap and says so once', () => { + const c = clock('2026-09-23T09:00:00') + const log = createFileLog({ dir, maxBytesPerDay: 200, now: c.now }) + for (let i = 0; i < 50; i++) log.write('info', 'main', `line ${i}`) + const text = readToday(log) + expect(text.length).toBeLessThan(400) + expect(text.match(/daily cap reached/g)).toHaveLength(1) + }) + + it('rate-limits a flood and reports how much was dropped', () => { + const c = clock('2026-09-23T09:00:00') + const log = createFileLog({ dir, maxLinesPerMinute: 5, now: c.now }) + for (let i = 0; i < 20; i++) log.write('info', 'renderer', `spam ${i}`) + c.advance(60_000) + log.write('info', 'renderer', 'next minute') + const text = readToday(log) + expect(text.match(/spam/g)).toHaveLength(5) + expect(text).toContain('dropped 15 line(s)') + expect(text).toContain('next minute') + }) + + it('truncates a runaway line', () => { + const c = clock('2026-09-23T09:00:00') + const log = createFileLog({ dir, maxLineLength: 10, now: c.now }) + log.write('info', 'main', 'x'.repeat(100)) + expect(readToday(log)).toContain('xxxxxxxxxx...(truncated)') + }) + + it('never throws when the directory cannot be written', () => { + const blocker = path.join(dir, 'not-a-dir') + fs.writeFileSync(blocker, '') + const log = createFileLog({ dir: blocker, now: () => new Date('2026-09-23T09:00:00') }) + expect(() => log.write('error', 'main', 'still fine')).not.toThrow() + }) + + it('stamps days in local time', () => { + expect(dayStamp(new Date(2026, 0, 5, 23, 30))).toBe('2026-01-05') + }) +}) diff --git a/input_viewer_electron/test/stream-health.test.js b/input_viewer_electron/test/stream-health.test.js new file mode 100644 index 0000000..3dad838 --- /dev/null +++ b/input_viewer_electron/test/stream-health.test.js @@ -0,0 +1,191 @@ +// SPDX-License-Identifier: Apache-2.0 +// SPDX-FileCopyrightText: 2025-2026 Schuberg Philis / Lab271 +import { describe, it, expect } from 'vitest' +import { + HEALTH, createStreamHealth, lumaStats, isUniform, backoffDelay, +} from '../src/renderer/stream-health.js' + +const BUSY = { mean: 90, std: 40 } // a real picture +const FLAT = { mean: 1, std: 0.2 } // black, or a solid no-signal screen + +/** Drive a tracker at a fixed fps for `ms`, sampling every `step` ms. */ +function run(h, { from, ms, fps, stats = BUSY, step = 2000, frames }) { + let t = from + let count = frames.value + let status + while (t < from + ms) { + t += step + count += (fps * step) / 1000 + status = h.sample({ frames: count, ended: false, stats }, t) + } + frames.value = count + return { t, status } +} + +describe('lumaStats', () => { + it('reports a flat picture as uniform and a varied one as not', () => { + const flat = new Uint8ClampedArray(32 * 18 * 4).fill(10) + expect(isUniform(lumaStats(flat))).toBe(true) + + const bars = new Uint8ClampedArray(32 * 18 * 4) + for (let i = 0; i < bars.length; i += 4) { + const v = (i / 4) % 2 ? 250 : 5 + bars[i] = bars[i + 1] = bars[i + 2] = v + } + expect(isUniform(lumaStats(bars))).toBe(false) + }) + + it('treats a solid colour that is not black as uniform too', () => { + // An Elgato-style solid blue no-signal screen is as dead as black. + const blue = new Uint8ClampedArray(64 * 4) + for (let i = 0; i < blue.length; i += 4) { blue[i + 2] = 200; blue[i + 3] = 255 } + const s = lumaStats(blue) + expect(s.mean).toBeGreaterThan(20) + expect(isUniform(s)).toBe(true) + }) + + it('does not divide by zero on an empty buffer', () => { + expect(lumaStats(new Uint8ClampedArray(0))).toEqual({ mean: 0, std: 0 }) + }) +}) + +describe('backoffDelay', () => { + it('repeats the last step forever', () => { + const s = [1, 2, 3] + expect([0, 1, 2, 3, 99].map(a => backoffDelay(s, a))).toEqual([1, 2, 3, 3, 3]) + }) +}) + +describe('createStreamHealth', () => { + it('is ok while a card delivers a real picture', () => { + const h = createStreamHealth() + h.opened(0) + const { status } = run(h, { from: 0, ms: 30_000, fps: 60, frames: { value: 0 } }) + expect(status).toBe('ok') + expect(h.decide(30_000).reopen).toBe(false) + }) + + it('is ok on a held slide: pixels frozen, frames still arriving', () => { + // The #159 trap. A still picture at 60fps is a working card. + const h = createStreamHealth() + h.opened(0) + const { status } = run(h, { from: 0, ms: 60_000, fps: 60, frames: { value: 0 } }) + expect(status).toBe('ok') + }) + + it('reports no-frames when a card opens and never delivers', () => { + const h = createStreamHealth() + h.opened(0) + expect(h.sample({ frames: 0, ended: false, stats: null }, 4000)).toBe('opening') + expect(h.sample({ frames: 0, ended: false, stats: null }, HEALTH.FIRST_FRAME_TIMEOUT_MS)) + .toBe('no-frames') + }) + + it('reports stalled when frames stop after flowing', () => { + const h = createStreamHealth() + h.opened(0) + const frames = { value: 0 } + const { t } = run(h, { from: 0, ms: 10_000, fps: 60, frames }) + // Counter stops moving. + h.sample({ frames: frames.value, ended: false, stats: BUSY }, t + 2000) + expect(h.sample({ frames: frames.value, ended: false, stats: BUSY }, t + HEALTH.STALL_MS)) + .toBe('stalled') + }) + + it('treats a counter that goes backwards as a new baseline, not a stall', () => { + const h = createStreamHealth() + h.opened(0) + const frames = { value: 0 } + const { t } = run(h, { from: 0, ms: 10_000, fps: 60, frames }) + frames.value = 0 + const after = run(h, { from: t, ms: 10_000, fps: 60, frames }) + expect(after.status).toBe('ok') + }) + + it('does not call a static virtual camera stalled', () => { + // One frame, then nothing: never reached FLOWING_MIN_FPS, so a stop is not + // a stall. (OBS Virtual Camera behaves exactly like this on a still scene.) + const h = createStreamHealth() + h.opened(0) + h.sample({ frames: 1, ended: false, stats: BUSY }, 500) + for (let t = 2500; t < 60_000; t += 2000) { + expect(h.sample({ frames: 1, ended: false, stats: BUSY }, t)).toBe('ok') + } + }) + + it('reports ended as soon as the track ends', () => { + const h = createStreamHealth() + h.opened(0) + expect(h.sample({ frames: 10, ended: true, stats: BUSY }, 1000)).toBe('ended') + }) + + it('reports dark after a flat picture persists, not on the first flat sample', () => { + const h = createStreamHealth() + h.opened(0) + const frames = { value: 0 } + const first = run(h, { from: 0, ms: 2000, fps: 60, stats: FLAT, frames }) + expect(first.status).toBe('ok') + const later = run(h, { from: first.t, ms: HEALTH.DARK_MS, fps: 60, stats: FLAT, frames }) + expect(later.status).toBe('dark') + }) + + it('works without a frame counter, on the picture alone', () => { + const h = createStreamHealth() + h.opened(0) + expect(h.sample({ frames: null, ended: false, stats: BUSY }, 2000)).toBe('ok') + h.sample({ frames: null, ended: false, stats: FLAT }, 4000) + expect(h.sample({ frames: null, ended: false, stats: FLAT }, 4000 + HEALTH.DARK_MS)) + .toBe('dark') + }) + + it('backs off between reopens of a faulted feed', () => { + const h = createStreamHealth() + h.openFailed(0, new Error('NotReadableError')) + expect(h.info().error).toBe('Error') + + const delays = [] + let t = 0 + for (let i = 0; i < HEALTH.FAULT_BACKOFF_MS.length + 2; i++) { + const d = h.decide(t) + expect(d.reopen).toBe(false) + t += d.waitMs + expect(h.decide(t)).toMatchObject({ reopen: true, reason: 'open-failed' }) + delays.push(d.waitMs) + h.reopening(t) + h.openFailed(t, 'again') + } + const last = HEALTH.FAULT_BACKOFF_MS.at(-1) + expect(delays).toEqual([...HEALTH.FAULT_BACKOFF_MS, last, last]) + }) + + it('uses the slower schedule for a dark feed', () => { + const h = createStreamHealth() + h.opened(0) + const frames = { value: 0 } + const { t } = run(h, { from: 0, ms: HEALTH.DARK_MS + 2000, fps: 60, stats: FLAT, frames }) + expect(h.info().status).toBe('dark') + const d = h.decide(t) + expect(d.reason).toBe('dark') + // First wait is counted from when the stream opened. + expect(d.waitMs).toBe(Math.max(0, HEALTH.DARK_BACKOFF_MS[0] - t)) + }) + + it('starts the backoff over once a reopened feed has stayed healthy', () => { + const h = createStreamHealth() + h.openFailed(0, 'x') + h.reopening(2000); h.openFailed(2000, 'x') + h.reopening(7000) + h.opened(7000) + expect(h.info().attempts).toBe(2) + + const frames = { value: 0 } + run(h, { from: 7000, ms: HEALTH.RECOVERED_RESET_MS + 4000, fps: 60, frames }) + expect(h.info().attempts).toBe(0) + }) + + it('does nothing for a side with no stream', () => { + const h = createStreamHealth() + expect(h.sample({ frames: 0, ended: true, stats: FLAT }, 99_999)).toBe('idle') + expect(h.decide(99_999).reopen).toBe(false) + }) +})