diag(ios,audio): log AVAudioSession state + route changes around picker overrides

Add structured NSLog instrumentation to AppDelegate.swift and debugPrint
chains in voice_compact.dart::_AudioOutputPickerSheetState so we can
correlate user picker taps with what iOS actually does to the route.

Three diagnostic streams:

* 'chanora.session[<tag>]' from Swift — full session snapshot (category,
  mode, sampleRate, ioBufferDuration, current route inputs+outputs,
  preferredInput) emitted on every setActive and every
  AVAudioSession.routeChangeNotification with the reason decoded
  (override / routeConfigurationChange / newDeviceAvailable / etc).
* 'chanora.route[<tag>]' from Dart — current route's inputs+outputs
  emitted before/after every overrideOutputAudioPort or
  setPreferredInput call, plus a delayed re-check at +250 ms to detect
  silent reverts.
* Existing 'chanora: ...' debugPrint lines from the picker now include
  the OK case (override returned, setPreferredInput returned) so we see
  a positive signal in the log when the API didn't throw.

Used to root-cause the 'speaker selector not working' issue: the
hypothesis is that cpal's RemoteIO AudioUnit reacts to its own format
configuration notifications by triggering routeConfigurationChange
that reverts our Dart-side override. The logs will confirm or deny
this — if we see 'chanora.session[routeChange.override] out=Speaker'
followed by 'chanora.session[routeChange.routeConfigurationChange]
out=Receiver' within a few hundred ms, that's the smoking gun.

Pure diagnostic commit. No behavioural change. Logs are NSLog +
debugPrint so they appear in Xcode console / 'flutter logs' / the
device log via Console.app or 'devicectl device log'.
This commit is contained in:
EdisonJwa
2026-05-16 23:57:50 +08:00
parent b1d117033e
commit da631a2bef
2 changed files with 113 additions and 28 deletions
@@ -85,6 +85,20 @@ import AVFoundation
object: nil object: nil
) )
// Diagnostic: subscribe to every AVAudioSession route change so
// we can correlate user picker actions with what iOS actually
// does to the route. The reason printed here ("override",
// "newDeviceAvailable", "categoryChange", etc.) tells us
// whether our Dart-side override was honoured or silently
// reverted by another component (e.g. cpal's RemoteIO unit
// reacting to its own configuration change).
NotificationCenter.default.addObserver(
self,
selector: #selector(handleRouteChange(_:)),
name: AVAudioSession.routeChangeNotification,
object: nil
)
// Request microphone access on first launch rather than waiting // Request microphone access on first launch rather than waiting
// for the user's first voice-channel join. The latter is // for the user's first voice-channel join. The latter is
// surprising: the user has only tapped "connect to server" and // surprising: the user has only tapped "connect to server" and
@@ -123,11 +137,69 @@ import AVFoundation
do { do {
try AVAudioSession.sharedInstance().setActive(true, options: []) try AVAudioSession.sharedInstance().setActive(true, options: [])
NSLog("chanora_flutter: AVAudioSession activated on foreground") NSLog("chanora_flutter: AVAudioSession activated on foreground")
logSessionState(tag: "didBecomeActive")
} catch { } catch {
NSLog("chanora_flutter: AVAudioSession setActive failed: \(error)") NSLog("chanora_flutter: AVAudioSession setActive failed: \(error)")
} }
} }
/// Log the full AVAudioSession state with a diagnostic tag. Used
/// after every state transition (setActive, route change) so we
/// can correlate user-perceived audio bugs with what iOS thinks
/// the session looks like. Output is parseable by grep
/// `chanora.session\[`.
private func logSessionState(tag: String) {
let s = AVAudioSession.sharedInstance()
let route = s.currentRoute
let outs = route.outputs.map { "\($0.portType.rawValue)/\($0.portName)" }.joined(separator: ",")
let ins = route.inputs.map { "\($0.portType.rawValue)/\($0.portName)" }.joined(separator: ",")
let preferredInput = s.preferredInput?.portName ?? "<nil>"
NSLog("""
chanora.session[\(tag)] \
cat=\(s.category.rawValue) \
mode=\(s.mode.rawValue) \
sr=\(s.sampleRate) \
ioBuf=\(String(format: "%.4f", s.ioBufferDuration)) \
out=[\(outs)] in=[\(ins)] \
preferredInput=\(preferredInput)
""")
}
/// Called by `routeChangeNotification`. iOS posts this whenever
/// the route is reconfigured for any reason user toggles
/// Bluetooth, plugs in headphones, our `overrideOutputAudioPort`
/// call, OR (the suspected bug here) when cpal's RemoteIO
/// AudioUnit reacts to its own format change and resets the
/// route. The `reason` field tells us which case it is:
///
/// * `.override` : our Dart-side override took effect.
/// * `.routeConfigurationChange` : something else (cpal?)
/// triggered an internal reconfig.
/// * `.newDeviceAvailable` / `.oldDeviceUnavailable` :
/// user hardware change.
/// * `.categoryChange` : someone (us or another app) set a
/// new category.
@objc private func handleRouteChange(_ note: Notification) {
guard let reasonValue = note.userInfo?[AVAudioSessionRouteChangeReasonKey] as? UInt,
let reason = AVAudioSession.RouteChangeReason(rawValue: reasonValue) else {
NSLog("chanora.routeChange[unknown-reason]")
return
}
let reasonName: String
switch reason {
case .unknown: reasonName = "unknown"
case .newDeviceAvailable: reasonName = "newDeviceAvailable"
case .oldDeviceUnavailable: reasonName = "oldDeviceUnavailable"
case .categoryChange: reasonName = "categoryChange"
case .override: reasonName = "override"
case .wakeFromSleep: reasonName = "wakeFromSleep"
case .noSuitableRouteForCategory: reasonName = "noSuitableRouteForCategory"
case .routeConfigurationChange: reasonName = "routeConfigurationChange"
@unknown default: reasonName = "default(\(reasonValue))"
}
logSessionState(tag: "routeChange.\(reasonName)")
}
func didInitializeImplicitFlutterEngine(_ engineBridge: FlutterImplicitEngineBridge) { func didInitializeImplicitFlutterEngine(_ engineBridge: FlutterImplicitEngineBridge) {
GeneratedPluginRegistrant.register(with: engineBridge.pluginRegistry) GeneratedPluginRegistrant.register(with: engineBridge.pluginRegistry)
} }
@@ -766,65 +766,78 @@ class _AudioOutputPickerSheetState extends State<_AudioOutputPickerSheet> {
} }
} }
/// Diagnostic helper: log the current route's first input and
/// output ports with a tag so we can correlate user actions with
/// what iOS thinks the route is. Called immediately before an
/// override, immediately after, and again 250 ms later to detect
/// silent revert.
Future<void> _logRoute(String tag) async {
try {
final route = await AVAudioSession().currentRoute;
final outs = route.outputs
.map((o) => '${o.portType.name}/${o.portName}')
.join(',');
final ins = route.inputs
.map((i) => '${i.portType.name}/${i.portName}')
.join(',');
debugPrint('chanora.route[$tag] out=[$outs] in=[$ins]');
} catch (e) {
debugPrint('chanora.route[$tag] FAILED: $e');
}
}
Future<void> _selectSpeaker() async { Future<void> _selectSpeaker() async {
await _logRoute('speaker.before');
try { try {
// Apple-documented quirk: in .voiceChat mode, calling
// setPreferredInput(builtInMic) AFTER overrideOutputAudioPort(.speaker)
// causes iOS to recalculate the route. Built-in mic naturally
// pairs with the receiver (not the speaker), so the system
// SILENTLY REVERTS the speaker override and routes audio
// back through the earpiece. Net: the await chain returns
// successfully ('no exception'), but the user hears no
// change.
//
// Fix: do NOT call setPreferredInput when forcing speaker.
// The speaker override is sufficient on its own \u2014 input
// remains on whatever the system was already using (built-in
// mic by default, or BT/wired if connected and selected
// elsewhere). For consistency, only switch input when the
// user explicitly picks a non-speaker input row.
await AVAudioSession() await AVAudioSession()
.overrideOutputAudioPort(AVAudioSessionPortOverride.speaker); .overrideOutputAudioPort(AVAudioSessionPortOverride.speaker);
debugPrint('chanora: audio output -> speakerphone (override applied)'); debugPrint('chanora: override(.speaker) returned OK');
} catch (e, st) { } catch (e, st) {
debugPrint('chanora: _selectSpeaker FAILED: $e\n$st'); debugPrint('chanora: _selectSpeaker FAILED: $e\n$st');
} }
await _logRoute('speaker.after');
// Schedule a delayed re-check — if cpal's RemoteIO unit reverts
// the route on routeChangeNotification, this will surface the
// revert (out=builtInReceiver instead of builtInSpeaker).
Future.delayed(const Duration(milliseconds: 250), () {
_logRoute('speaker.after+250ms');
});
if (!mounted) return; if (!mounted) return;
Navigator.of(context).pop(); Navigator.of(context).pop();
} }
Future<void> _selectReceiver() async { Future<void> _selectReceiver() async {
await _logRoute('receiver.before');
try { try {
// Same quirk in reverse: removing the speaker override
// (.none) is enough to restore the .voiceChat default route,
// which is the built-in receiver. Calling setPreferredInput
// explicitly here is redundant and risks the same recalc
// race that broke _selectSpeaker before.
await AVAudioSession() await AVAudioSession()
.overrideOutputAudioPort(AVAudioSessionPortOverride.none); .overrideOutputAudioPort(AVAudioSessionPortOverride.none);
debugPrint('chanora: audio output -> receiver (override cleared)'); debugPrint('chanora: override(.none) returned OK');
} catch (e, st) { } catch (e, st) {
debugPrint('chanora: _selectReceiver FAILED: $e\n$st'); debugPrint('chanora: _selectReceiver FAILED: $e\n$st');
} }
await _logRoute('receiver.after');
Future.delayed(const Duration(milliseconds: 250), () {
_logRoute('receiver.after+250ms');
});
if (!mounted) return; if (!mounted) return;
Navigator.of(context).pop(); Navigator.of(context).pop();
} }
Future<void> _selectInput(AVAudioSessionPortDescription port) async { Future<void> _selectInput(AVAudioSessionPortDescription port) async {
await _logRoute('input.${port.portType.name}.before');
try { try {
// Drop any speakerphone override so the route follows the
// selected input. BT / wired headset / USB inputs pair their
// OWN output (the user hears audio through the same device
// they speak into), so .none + setPreferredInput is the
// correct combo here.
await AVAudioSession() await AVAudioSession()
.overrideOutputAudioPort(AVAudioSessionPortOverride.none); .overrideOutputAudioPort(AVAudioSessionPortOverride.none);
await AVAudioSession().setPreferredInput(port); await AVAudioSession().setPreferredInput(port);
debugPrint( debugPrint(
'chanora: audio output -> ${port.portName} (${port.portType})'); 'chanora: setPreferredInput(${port.portName}/${port.portType.name}) OK');
} catch (e, st) { } catch (e, st) {
debugPrint('chanora: _selectInput FAILED: $e\n$st'); debugPrint('chanora: _selectInput FAILED: $e\n$st');
} }
await _logRoute('input.${port.portType.name}.after');
Future.delayed(const Duration(milliseconds: 250), () {
_logRoute('input.${port.portType.name}.after+250ms');
});
if (!mounted) return; if (!mounted) return;
Navigator.of(context).pop(); Navigator.of(context).pop();
} }