Separate hardware device changes from our own IO state (v0.4.1)

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-<pid>-<n>` 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

mac/Resources/Info.plist

@@ -16,9 +16,9 @@
     <key>CFBundlePackageType</key>
     <string>APPL</string>
     <key>CFBundleShortVersionString</key>
-    <string>0.4.0</string>
+    <string>0.4.1</string>
     <key>CFBundleVersion</key>
-    <string>8</string>
+    <string>9</string>
     <key>LSMinimumSystemVersion</key>
     <string>13.0</string>
     <!-- Menu-bar-only agent: no Dock icon, no main window. -->

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