diff --git a/dev/procedures/mac-audio-lifecycle.md b/dev/procedures/mac-audio-lifecycle.md index 1a0b2ce..ea5f4c4 100644 --- a/dev/procedures/mac-audio-lifecycle.md +++ b/dev/procedures/mac-audio-lifecycle.md @@ -121,6 +121,79 @@ immediate line when a stall starts or ends or the device set changes. (Same reason `scheduleStartRetry` announces its slow mode once — a line a minute for half an hour buries everything else.) +## Opening the default input creates an aggregate device — so a restart churns two + +The first field output from `AudioDiagnostics` showed the input device set is not +just the microphone: + +``` +inputs=[*"Logitech BRIO"/usb/48000Hz/2ch/alive=y/running=n + "CADefaultDeviceAggregate-70999-0"/grup/48000Hz/2ch/alive=y/running=n] +``` + +That second entry is a **private aggregate device** (`grup` = +`kAudioDeviceTransportTypeAggregate`) that coreaudiod creates *per client* when +an app captures from the default input, so the client can survive the default +changing under it. It was already present in the first sample, before capture +started — i.e. **merely constructing `AudioHub` creates it**, because +`makeEngine()` materializes `inputNode`, and touching that property opens the +default input device. + +The consequence is that the retry ladder's cost was under-estimated twice over. +`prepareFormat()` → `renewEngine()` does not merely open and close the +microphone; it tears down and recreates an aggregate device inside coreaudiod on +every attempt — a much heavier operation than a device open, and one that has to +re-resolve the default input each time. That is what runs once a minute, for as +long as the mic is missing. + +It also means the *device set itself* changes on every one of those cycles, as +the aggregate comes and goes. So a diagnostic that alarms on "the device list +changed" alarms on our own restarts. Separate the two: an appearing/vanishing +device (or a changed rate, channel count or alive flag) is a hardware event; +`isRunningSomewhere` flipping is usually just us. `AudioDiagnostics.identities()` +is that split. + +## What the first day of field data settled — and what it did **not** (#79) + +Written down because the sections above read as a case against the retry ladder, +and a future session could mistake that case for a verdict. It is not one. + +**Confirmed by measurement:** + +- *The instrument is sound.* Buffer accounting is exact — 8192.0 frames per + buffer against `installTap`'s `bufferSize`, 5.859 buffers/sec against a + theoretical 5.859 — and it reconciles against events it shares no code with: a + 605s heartbeat window was missing 14.2s of audio, and the log independently + recorded a 14s outage inside it. +- *The aggregate really is destroyed and rebuilt per restart.* The suffix in + `CADefaultDeviceAggregate--` is a per-client counter; it went `-0` → + `-2` across a single unplug/replug. **Use that suffix to count churn** — it is + the cheapest available measure of how many times coreaudiod has rebuilt the + aggregate for us. +- *The ladder does run at its ceiling in the wild.* One outage produced five + failed starts at 63, 63, 63 and 56 seconds apart — the once-a-minute + open/close cycle, observed rather than argued. +- *The mic leaves on its own, often.* Two spontaneous drop-outs in ~70 minutes + with nobody touching the hardware. Restart cycles are frequent even when + nothing sleeps, so any per-restart cost is paid far more often than a + sleep/wake-shaped mental model suggests. + +**Not confirmed, and it is the whole question:** every observed episode +recovered cleanly — the four-minute one, the nine-second one, and the deliberate +replug. Churn *happens*; it has **not** been shown to cause the wedge. The wedge +state (menu claiming "listening", mic dead system-wide, process alive) has not +recurred since the diagnostics shipped. Don't write the fix until an `AUDIO +STALL` line with `running=y` says which theory is right. + +**A design constraint the data did settle**, for whatever cheap availability +probe eventually replaces the build-an-engine-to-ask approach: a device can be +present in the HAL, `alive=y`, and still useless. Mid-teardown the input listed +as `"(unnamed)"/????/0Hz/2ch/alive=y` — readable enough to enumerate, with an +unreadable name, unknown transport and a **zero sample rate**. So the probe must +require a nonzero rate (and sane channel count), not mere presence, or it will +wave through starts that cannot succeed — the same trap as `outputFormat` above, +one layer down. + ## Diagnostics must not assume a toolchain on the owner's Mac The Mac running LaughCounter installs the DMG from CI and has **no Xcode command diff --git a/mac/Resources/Info.plist b/mac/Resources/Info.plist index fc57973..ab01e36 100644 --- a/mac/Resources/Info.plist +++ b/mac/Resources/Info.plist @@ -16,9 +16,9 @@ CFBundlePackageType APPL CFBundleShortVersionString - 0.4.0 + 0.4.1 CFBundleVersion - 8 + 9 LSMinimumSystemVersion 13.0 diff --git a/mac/Sources/LaughCounter/AudioDiagnostics.swift b/mac/Sources/LaughCounter/AudioDiagnostics.swift index f34b14c..dda8107 100644 --- a/mac/Sources/LaughCounter/AudioDiagnostics.swift +++ b/mac/Sources/LaughCounter/AudioDiagnostics.swift @@ -71,6 +71,11 @@ final class AudioDiagnostics { /// counters are reset every tick. private var totalBuffers = 0 private var totalFrames = 0 + /// Loudest sample seen since the last heartbeat, and how many buffers that + /// heartbeat covers. Both span the heartbeat interval so every number on + /// that line describes the same window. + private var intervalPeak: Float = 0 + private var buffersThisInterval = 0 /// "The app believes it is capturing." Supplied by `AppDelegate`; without it /// a stall is meaningless, since no buffers is correct when paused. @@ -162,6 +167,12 @@ final class AudioDiagnostics { lock.unlock() totalBuffers += buffers totalFrames += frames + // Peak must span the whole heartbeat interval, not the last five-second + // sample. Reported beside cumulative buffers/frames, a five-second peak + // reads as if it covered the same span — so a laugh mid-interval could + // be followed by a quiet moment and the line would report near-silence. + intervalPeak = max(intervalPeak, localPeak) + buffersThisInterval += buffers let silence = last.map { now - $0 } let listening = isListening?() ?? false @@ -171,8 +182,19 @@ final class AudioDiagnostics { // and CoreAudio's own notification is suppressed around our restarts. let devices = Self.inputDevices() if devices != lastDevices { - AppLog.shared.log("input devices changed — \(Self.describe(devices))", - level: "WARN") + // Two very different events wear the same diff, and conflating them + // would bury the one that matters. A device appearing or vanishing + // (or changing rate/channels/alive) is a hardware event worth a + // WARN. `isRunningSomewhere` flipping is usually just us starting or + // stopping capture — informative, but not an alarm. Observed + // immediately in the field: the first restart after launch logged + // "input devices changed" as a WARN when nothing had changed but our + // own IO state. + let changed = Self.identities(devices) != Self.identities(lastDevices) + AppLog.shared.log( + (changed ? "input devices changed — " : "input IO state changed — ") + + Self.describe(devices), + level: changed ? "WARN" : "INFO") lastDevices = devices } @@ -194,8 +216,21 @@ final class AudioDiagnostics { let state = listening ? (stalled ? "listening-but-STALLED" : "listening") : "not listening" AppLog.shared.log("audio health: \(state) " + "buffers=\(totalBuffers) frames=\(totalFrames) " - + "peak=\(String(format: "%.4f", localPeak)) " + + "peak=\(String(format: "%.4f", intervalPeak)) " + "\(healthSuffix(devices: devices))") + // Buffers arriving with every sample exactly zero is a third failure + // mode, distinct from a stall (no buffers) and from a dead device + // (nothing to open): the stream is alive and carrying digital + // silence. A real microphone always has a noise floor, so an exact + // zero across ten minutes is never the room being quiet — it is a + // muted input or a stream that is no longer connected to hardware. + if listening, buffersThisInterval > 0, intervalPeak == 0 { + AppLog.shared.log("no signal: \(buffersThisInterval) buffers arrived over the " + + "last \(Int(heartbeatInterval))s and every sample was zero — the input is " + + "muted or the stream is not carrying audio", level: "ERROR") + } + intervalPeak = 0 + buffersThisInterval = 0 } } @@ -356,6 +391,16 @@ final class AudioDiagnostics { } } + /// Everything about the input device set *except* whether IO is running on + /// it — i.e. the part that changing means the hardware changed under us, + /// rather than us having started or stopped capturing. + private static func identities(_ devices: [InputDevice]) -> [String] { + devices.map { + "\($0.uid)|\($0.name)|\($0.transport)|\($0.sampleRate)|\($0.channels)" + + "|\($0.isAlive)|\($0.isDefault)" + } + } + private static func describe(_ devices: [InputDevice]) -> String { guard !devices.isEmpty else { return "inputs=NONE" } let rendered = devices.map { device in