From 60083ba92073fcc071a05769fa45757ba95ede22 Mon Sep 17 00:00:00 2001 From: Marek Malek Date: Tue, 1 Sep 2026 16:07:23 +0200 Subject: [PATCH] chore(debug): add logging --- .../audioapi/ios/system/AudioAPIDiagnostics.h | 112 +++++++ .../ios/system/AudioAPIDiagnostics.mm | 277 ++++++++++++++++++ .../ios/audioapi/ios/system/AudioEngine.mm | 138 ++++++++- .../ios/system/AudioSessionManager.mm | 100 ++++++- .../ios/system/SystemNotificationManager.mm | 68 ++++- 5 files changed, 679 insertions(+), 16 deletions(-) create mode 100644 packages/react-native-audio-api/ios/audioapi/ios/system/AudioAPIDiagnostics.h create mode 100644 packages/react-native-audio-api/ios/audioapi/ios/system/AudioAPIDiagnostics.mm diff --git a/packages/react-native-audio-api/ios/audioapi/ios/system/AudioAPIDiagnostics.h b/packages/react-native-audio-api/ios/audioapi/ios/system/AudioAPIDiagnostics.h new file mode 100644 index 000000000..71e2b769e --- /dev/null +++ b/packages/react-native-audio-api/ios/audioapi/ios/system/AudioAPIDiagnostics.h @@ -0,0 +1,112 @@ +#pragma once + +#import +#import + +NS_ASSUME_NONNULL_BEGIN + +/// Lifecycle tracing for the iOS audio session and engine. +/// +/// Route changes, interruptions and media-server resets are driven by the OS and +/// cannot be reproduced from a test, so the only way to explain a restart that +/// went wrong is a trace of what the library asked for and what AVFoundation +/// answered. Every line carries a sequence number, a monotonic timestamp, the +/// calling thread and the enclosing operation path, which is what turns a +/// self-inflicted feedback loop - our own `setCategory:` posting the +/// configuration change that triggers the next restart - into something visible +/// rather than merely suspected. +/// +/// Tracing is on in debug builds and off otherwise; call +/// `AudioAPISetDiagnosticsEnabled(YES)` to force it on while chasing a report +/// from a release build. +/// +/// Lines go to the unified log under subsystem `com.swmansion.audioapi`, with +/// one category per area below. Unlike `NSLog` this survives a locked and +/// backgrounded device, which is the only state some session failures reproduce +/// in, and it can be read back after the fact: +/// +/// log stream --predicate 'subsystem == "com.swmansion.audioapi"' --style compact +/// log show --last 5m --predicate 'subsystem == "com.swmansion.audioapi"' +/// +/// Failures are logged at the error level, so `--predicate '... AND +/// messageType == error'` narrows a long trace to what actually broke. Messages +/// are declared public: an audio route is not user data, and redacted lines +/// would defeat the point. + +FOUNDATION_EXPORT NSString *const AudioAPIDiagnosticsSubsystem; + +FOUNDATION_EXPORT NSString *const AudioAPIDiagnosticsCategoryEngine; +FOUNDATION_EXPORT NSString *const AudioAPIDiagnosticsCategoryNotifications; +FOUNDATION_EXPORT NSString *const AudioAPIDiagnosticsCategoryRecorder; +FOUNDATION_EXPORT NSString *const AudioAPIDiagnosticsCategorySession; + +FOUNDATION_EXPORT BOOL AudioAPIDiagnosticsEnabled(void); +FOUNDATION_EXPORT void AudioAPISetDiagnosticsEnabled(BOOL enabled); + +FOUNDATION_EXPORT void AudioAPILogEvent(NSString *category, NSString *format, ...) + NS_FORMAT_FUNCTION(2, 3); +/// Counterpart of `AudioAPILogEvent` for things that actually went wrong. Marked +/// with `!`, logged at the error level and emitted even when tracing is +/// disabled, so a release build still reports why the engine gave up. +FOUNDATION_EXPORT void AudioAPILogFailure(NSString *category, NSString *format, ...) + NS_FORMAT_FUNCTION(2, 3); + +/// Names the operation the current thread is inside, so nested events - and +/// events the OS delivers re-entrantly from within an AVFoundation call - report +/// where they came from. Prefer the `AUDIOAPI_TRACE_SCOPE` macro over these. +FOUNDATION_EXPORT void AudioAPIPushDiagnosticsScope(NSString *name); +FOUNDATION_EXPORT void AudioAPIPopDiagnosticsScope(void); +/// The enclosing scopes joined innermost-last, e.g. `startEngine>setActive`, or +/// `-` when the current thread is not inside a traced operation. +FOUNDATION_EXPORT NSString *AudioAPICurrentDiagnosticsScope(void); + +/// These read `AVAudioSession`, and every property read is an XPC round trip to +/// mediaserverd. Keep them off paths that can repeat within one operation - a +/// trace that stalls the thread it is observing reports its own overhead. +FOUNDATION_EXPORT NSString *AudioAPIDescribeRoute(AVAudioSessionRouteDescription *_Nullable route); +FOUNDATION_EXPORT NSString *AudioAPIDescribeSession(AVAudioSession *_Nullable session); +/// Reports the raw sample rate and channel count even when they are unusable, +/// which is how a refused input shows itself: a non-nil format reading 0 Hz. +FOUNDATION_EXPORT NSString *AudioAPIDescribeFormat(AVAudioFormat *_Nullable format); +/// Renders an `NSError` as `domain/code` plus its description, and spells out +/// the four-character code AVFoundation packs into `code` - a session error +/// reads as `560557684`, which is the integer form of '!int'. +FOUNDATION_EXPORT NSString *AudioAPIDescribeError(NSError *_Nullable error); + +#define AUDIOAPI_LOG(category, format, ...) \ + do { \ + if (AudioAPIDiagnosticsEnabled()) { \ + AudioAPILogEvent((category), (format), ##__VA_ARGS__); \ + } \ + } while (0) + +#define AUDIOAPI_LOG_FAILURE(category, format, ...) \ + AudioAPILogFailure((category), (format), ##__VA_ARGS__) + +#ifdef __cplusplus + +namespace audioapi { + +/// Scope-based counterpart of `AudioAPIPushDiagnosticsScope`. +struct DiagnosticsScope { + explicit DiagnosticsScope(NSString *name) + { + AudioAPIPushDiagnosticsScope(name); + } + + ~DiagnosticsScope() + { + AudioAPIPopDiagnosticsScope(); + } + + DiagnosticsScope(const DiagnosticsScope &) = delete; + DiagnosticsScope &operator=(const DiagnosticsScope &) = delete; +}; + +} // namespace audioapi + +#define AUDIOAPI_TRACE_SCOPE(name) audioapi::DiagnosticsScope _audioAPIDiagnosticsScope(name) + +#endif // __cplusplus + +NS_ASSUME_NONNULL_END diff --git a/packages/react-native-audio-api/ios/audioapi/ios/system/AudioAPIDiagnostics.mm b/packages/react-native-audio-api/ios/audioapi/ios/system/AudioAPIDiagnostics.mm new file mode 100644 index 000000000..6ece6b724 --- /dev/null +++ b/packages/react-native-audio-api/ios/audioapi/ios/system/AudioAPIDiagnostics.mm @@ -0,0 +1,277 @@ +#import + +#import + +#include +#include +#include + +NSString *const AudioAPIDiagnosticsSubsystem = @"com.swmansion.audioapi"; + +NSString *const AudioAPIDiagnosticsCategoryEngine = @"engine"; +NSString *const AudioAPIDiagnosticsCategoryNotifications = @"notify"; +NSString *const AudioAPIDiagnosticsCategoryRecorder = @"record"; +NSString *const AudioAPIDiagnosticsCategorySession = @"session"; + +static NSString *const DiagnosticsScopeStackKey = @"AudioAPIDiagnosticsScopeStack"; + +#if DEBUG +static std::atomic diagnosticsEnabled{true}; +#else +static std::atomic diagnosticsEnabled{false}; +#endif + +static std::atomic nextSequenceNumber{0}; + +BOOL AudioAPIDiagnosticsEnabled(void) +{ + return diagnosticsEnabled.load(std::memory_order_relaxed) ? YES : NO; +} + +void AudioAPISetDiagnosticsEnabled(BOOL enabled) +{ + diagnosticsEnabled.store(enabled == YES, std::memory_order_relaxed); +} + +/// One logger per category, so a trace can be narrowed with +/// `category == "session"` instead of grepping message text. +static os_log_t logForCategory(NSString *category) +{ + static os_log_t engineLog; + static os_log_t notificationsLog; + static os_log_t recorderLog; + static os_log_t sessionLog; + static dispatch_once_t onceToken; + + dispatch_once(&onceToken, ^{ + const char *subsystem = [AudioAPIDiagnosticsSubsystem UTF8String]; + + engineLog = os_log_create(subsystem, "engine"); + notificationsLog = os_log_create(subsystem, "notify"); + recorderLog = os_log_create(subsystem, "record"); + sessionLog = os_log_create(subsystem, "session"); + }); + + if ([category isEqualToString:AudioAPIDiagnosticsCategoryNotifications]) { + return notificationsLog; + } + + if ([category isEqualToString:AudioAPIDiagnosticsCategoryRecorder]) { + return recorderLog; + } + + if ([category isEqualToString:AudioAPIDiagnosticsCategorySession]) { + return sessionLog; + } + + return engineLog; +} + +static NSTimeInterval secondsSinceFirstEvent(void) +{ + static NSTimeInterval firstEventUptime; + static dispatch_once_t onceToken; + dispatch_once(&onceToken, ^{ firstEventUptime = [[NSProcessInfo processInfo] systemUptime]; }); + + return [[NSProcessInfo processInfo] systemUptime] - firstEventUptime; +} + +static NSString *currentThreadLabel(void) +{ + if ([NSThread isMainThread]) { + return @"main"; + } + + NSString *threadName = [[NSThread currentThread] name]; + + if (threadName.length > 0) { + return threadName; + } + + uint64_t threadId = 0; + pthread_threadid_np(NULL, &threadId); + + return [NSString stringWithFormat:@"t%llu", threadId]; +} + +static NSMutableArray *currentThreadScopeStack(void) +{ + NSMutableDictionary *threadStorage = [[NSThread currentThread] threadDictionary]; + NSMutableArray *scopeStack = threadStorage[DiagnosticsScopeStackKey]; + + if (scopeStack == nil) { + scopeStack = [[NSMutableArray alloc] init]; + threadStorage[DiagnosticsScopeStackKey] = scopeStack; + } + + return scopeStack; +} + +void AudioAPIPushDiagnosticsScope(NSString *name) +{ + [currentThreadScopeStack() addObject:name]; +} + +void AudioAPIPopDiagnosticsScope(void) +{ + NSMutableArray *scopeStack = currentThreadScopeStack(); + + if (scopeStack.count == 0) { + return; + } + + [scopeStack removeLastObject]; +} + +NSString *AudioAPICurrentDiagnosticsScope(void) +{ + NSMutableArray *scopeStack = currentThreadScopeStack(); + + if (scopeStack.count == 0) { + return @"-"; + } + + return [scopeStack componentsJoinedByString:@">"]; +} + +/// The sequence number is what makes a restart storm countable: the unified log +/// reorders lines emitted from different threads within the same millisecond, so +/// wall-clock order alone cannot tell 40 dispatches from 4 retried 10 times. +static void logLine(NSString *category, NSString *marker, NSString *message, bool isFailure) +{ + NSString *line = + [NSString stringWithFormat:@"[AudioAPI]%@#%04llu %8.3fs %-6s %@ | %@", + marker, + nextSequenceNumber.fetch_add(1, std::memory_order_relaxed), + secondsSinceFirstEvent(), + [currentThreadLabel() UTF8String], + AudioAPICurrentDiagnosticsScope(), + message]; + + os_log_t log = logForCategory(category); + + if (isFailure) { + os_log_error(log, "%{public}@", line); + return; + } + + // Default rather than info: info-level lines live only in the in-memory ring + // buffer and are dropped unless someone is already streaming, which is never + // true for a failure that only reproduces on a locked device. + os_log(log, "%{public}@", line); +} + +void AudioAPILogEvent(NSString *category, NSString *format, ...) +{ + if (!AudioAPIDiagnosticsEnabled()) { + return; + } + + va_list arguments; + va_start(arguments, format); + NSString *message = [[NSString alloc] initWithFormat:format arguments:arguments]; + va_end(arguments); + + logLine(category, @" ", message, false); +} + +void AudioAPILogFailure(NSString *category, NSString *format, ...) +{ + va_list arguments; + va_start(arguments, format); + NSString *message = [[NSString alloc] initWithFormat:format arguments:arguments]; + va_end(arguments); + + logLine(category, @"!", message, true); +} + +NSString *AudioAPIDescribeRoute(AVAudioSessionRouteDescription *route) +{ + if (route == nil) { + return @"(none)"; + } + + NSMutableArray *describedPorts = [[NSMutableArray alloc] init]; + + for (AVAudioSessionPortDescription *input in route.inputs) { + [describedPorts + addObject:[NSString stringWithFormat:@"in:%@(%@)", input.portName, input.portType]]; + } + + for (AVAudioSessionPortDescription *output in route.outputs) { + [describedPorts + addObject:[NSString stringWithFormat:@"out:%@(%@)", output.portName, output.portType]]; + } + + if (describedPorts.count == 0) { + return @"(empty)"; + } + + return [describedPorts componentsJoinedByString:@", "]; +} + +NSString *AudioAPIDescribeSession(AVAudioSession *session) +{ + if (session == nil) { + return @"(none)"; + } + + return [NSString stringWithFormat: + @"category=%@, mode=%@, options=%lu, sampleRate=%.0f, inputChannels=%lu, " + @"outputChannels=%lu, ioBuffer=%.4fs", + session.category ?: @"(null)", + session.mode ?: @"(null)", + (unsigned long)session.categoryOptions, + session.sampleRate, + (unsigned long)session.inputNumberOfChannels, + (unsigned long)session.outputNumberOfChannels, + session.IOBufferDuration]; +} + +NSString *AudioAPIDescribeFormat(AVAudioFormat *format) +{ + if (format == nil) { + return @"nil"; + } + + return [NSString stringWithFormat:@"%.0fHz/%uch/%@", + format.sampleRate, + format.channelCount, + format.interleaved ? @"interleaved" : @"deinterleaved"]; +} + +/// AVFoundation reports session failures as an `OSStatus` packed from four +/// printable characters, and the decimal form is unreadable. Spelling it out is +/// what separates the failure modes: '!int' means the session was refused +/// because another app owns it, '!act' that activation itself was rejected. +static NSString *describeFourCharacterCode(NSInteger code) +{ + uint32_t rawCode = (uint32_t)code; + char characters[5] = { + (char)((rawCode >> 24) & 0xFF), + (char)((rawCode >> 16) & 0xFF), + (char)((rawCode >> 8) & 0xFF), + (char)(rawCode & 0xFF), + '\0'}; + + for (size_t index = 0; index < 4; index += 1) { + if (!isprint((unsigned char)characters[index])) { + return @""; + } + } + + return [NSString stringWithFormat:@" ('%s')", characters]; +} + +NSString *AudioAPIDescribeError(NSError *error) +{ + if (error == nil) { + return @"nil"; + } + + return [NSString stringWithFormat:@"%@/%ld%@: %@", + error.domain, + (long)error.code, + describeFourCharacterCode(error.code), + error.localizedDescription]; +} diff --git a/packages/react-native-audio-api/ios/audioapi/ios/system/AudioEngine.mm b/packages/react-native-audio-api/ios/audioapi/ios/system/AudioEngine.mm index 519edfcad..b6e5fc11b 100644 --- a/packages/react-native-audio-api/ios/audioapi/ios/system/AudioEngine.mm +++ b/packages/react-native-audio-api/ios/audioapi/ios/system/AudioEngine.mm @@ -1,3 +1,4 @@ +#import #import #import @@ -31,6 +32,11 @@ @interface AudioEngine () { /// Tracks whether voice processing is currently engaged on the system input /// node of the live engine instance. Reset whenever the engine is recreated. BOOL _voiceProcessingApplied; + /// Rebuild cadence, used only to report a restart storm. A rebuild is driven + /// by a user pulling a cable or the OS reclaiming the session, so several per + /// second means the library is answering its own notification. + NSTimeInterval _lastRebuildUptime; + NSInteger _rapidRebuildCount; } @property (nonatomic, strong) @@ -50,6 +56,8 @@ - (AVAudioFormat *)liveInputFormat; - (void)resetInputNode; - (void)rebuildAudioEngineAndResumeIfNeeded; - (void)notifyConfigurationChanges; +- (NSString *)lockedStateSnapshot; +- (void)traceRebuildCadence; @end @@ -272,14 +280,24 @@ - (void)applyVoiceProcessing NSError *error = nil; if (![systemInputNode setVoiceProcessingEnabled:wantsVoiceProcessing error:&error]) { - NSLog( - @"[AudioEngine] Error while setting voice processing to %@: %@", + AUDIOAPI_LOG_FAILURE( + AudioAPIDiagnosticsCategoryEngine, + @"could not set voice processing to %@: %@", wantsVoiceProcessing ? @"true" : @"false", - [error debugDescription]); + AudioAPIDescribeError(error)); return; } _voiceProcessingApplied = wantsVoiceProcessing; + + // Enabling voice processing rewrites the session to voiceChat and drops + // AllowBluetoothA2DP, which posts a configuration change of its own. Every + // rebuild re-toggles it, so this line repeating is the churn itself. + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategoryEngine, + @"voice processing set to %@, session is now {%@}", + wantsVoiceProcessing ? @"true" : @"false", + AudioAPIDescribeSession([AVAudioSession sharedInstance])); } - (void)materializeTrackedNodesIfNeeded @@ -490,9 +508,67 @@ - (bool)isInUse return [self hasTrackedGraph] || self.audioEngine != nil; } +/// Reports the engine's own bookkeeping. Reads no AVAudioSession property, so it +/// is safe to call from anywhere on the restart path; the caller is expected to +/// hold `_engineLock`, which every path that reaches this does. +- (NSString *)lockedStateSnapshot +{ + return [NSString stringWithFormat: + @"state=%ld, engine=%@, running=%@, inputNode=%@, " + @"graphNeedsRebuild=%@, sessionInvalidated=%@, voiceProc=%@", + (long)self.state, + self.audioEngine == nil ? @"nil" : @"live", + [self.audioEngine isRunning] ? @"true" : @"false", + self.inputNode == nil ? @"nil" : @"live", + self.graphNeedsRebuild ? @"true" : @"false", + self.sessionDeactivationInvalidatedGraph ? @"true" : @"false", + _voiceProcessingApplied ? @"true" : @"false"]; +} + +- (void)traceRebuildCadence +{ + NSTimeInterval now = [[NSProcessInfo processInfo] systemUptime]; + NSTimeInterval sinceLast = now - _lastRebuildUptime; + + if (_lastRebuildUptime > 0 && sinceLast < 1.0) { + _rapidRebuildCount += 1; + } else { + _rapidRebuildCount = 0; + } + + _lastRebuildUptime = now; + + if (_rapidRebuildCount >= 5) { + AUDIOAPI_LOG_FAILURE( + AudioAPIDiagnosticsCategoryEngine, + @"restart storm: %ld rebuilds under a second apart, last gap %.3fs - the restart path is " + @"answering a notification it emitted itself: {%@}", + (long)_rapidRebuildCount, + sinceLast, + [self lockedStateSnapshot]); + return; + } + + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategoryEngine, + @"rebuild requested, %.3fs since the previous one: {%@}", + _lastRebuildUptime > 0 ? sinceLast : 0.0, + [self lockedStateSnapshot]); +} + - (void)rebuildAudioEngineAndResumeIfNeeded { + AUDIOAPI_TRACE_SCOPE(@"rebuild"); + + [self traceRebuildCadence]; + if (_isRebuildingAudioEngine) { + // The request is dropped, not deferred: the rebuild in flight finishes with + // the configuration this one was meant to adopt, and nothing asks again. + AUDIOAPI_LOG_FAILURE( + AudioAPIDiagnosticsCategoryEngine, + @"dropping a nested rebuild request, one is already in flight: {%@}", + [self lockedStateSnapshot]); return; } @@ -512,19 +588,45 @@ - (void)rebuildAudioEngineAndResumeIfNeeded [self notifyConfigurationChanges]; _isRebuildingAudioEngine = NO; + + // The silent death: startEngine reported the engine running and it stopped + // itself again before this point, usually because voice processing changed the + // IO format underneath it. The graph looks complete, so nothing downstream + // knows a rebuild is still owed. + if (self.state == AudioEngineState::AudioEngineStateRunning && ![self.audioEngine isRunning]) { + AUDIOAPI_LOG_FAILURE( + AudioAPIDiagnosticsCategoryEngine, + @"rebuild finished with the engine stopped while the state still says Running: {%@}", + [self lockedStateSnapshot]); + } } - (void)rebuildAudioEngine { + AUDIOAPI_TRACE_SCOPE(@"rebuildGraph"); + [self destroyAudioEnginePreservingSessionDeactivationState:YES]; [self createAudioEngineIfNeeded]; [self materializeTrackedNodesIfNeeded]; + + // Clearing the flag while the registered input node is still missing is how a + // refused restart becomes permanent: nothing downstream knows a rebuild is owed. + if (self.inputRegistration != nil && self.inputNode == nil) { + AUDIOAPI_LOG_FAILURE( + AudioAPIDiagnosticsCategoryEngine, + @"clearing graphNeedsRebuild even though the registered input node did not " + @"materialize: {%@}", + [self lockedStateSnapshot]); + } + self.graphNeedsRebuild = false; } - (bool)startEngine { + AUDIOAPI_TRACE_SCOPE(@"startEngine"); + NSError *error = nil; if (self.audioEngine != nil && [self.audioEngine isRunning] && @@ -535,7 +637,11 @@ - (bool)startEngine [self createAudioEngineIfNeeded]; if (![self.sessionManager ensureActive:true error:&error]) { - NSLog(@"Error while activating audio session: %@", [error debugDescription]); + AUDIOAPI_LOG_FAILURE( + AudioAPIDiagnosticsCategoryEngine, + @"giving up on start, the session would not activate: %@; {%@}", + AudioAPIDescribeError(error), + [self lockedStateSnapshot]); return false; } @@ -547,7 +653,10 @@ - (bool)startEngine } if (self.inputRegistration != nil && self.inputNode == nil) { - NSLog(@"Error while materializing the audio input node: missing live input format"); + AUDIOAPI_LOG_FAILURE( + AudioAPIDiagnosticsCategoryEngine, + @"giving up on start, the input node has no live format: {%@}", + [self lockedStateSnapshot]); return false; } @@ -555,12 +664,25 @@ - (bool)startEngine [self.audioEngine startAndReturnError:&error]; if (error != nil) { - NSLog(@"Error while starting the audio engine: %@", [error debugDescription]); + AUDIOAPI_LOG_FAILURE( + AudioAPIDiagnosticsCategoryEngine, + @"engine refused to start: %@; {%@}", + AudioAPIDescribeError(error), + [self lockedStateSnapshot]); return false; } self.state = AudioEngineState::AudioEngineStateRunning; self.sessionDeactivationInvalidatedGraph = false; + + // Read back rather than trusted: an engine can report a successful start and + // stop itself before the caller looks again, which is what a voice-processing + // format change does. A `running=false` here is the loop's fingerprint. + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategoryEngine, + @"engine started, reading back: {%@}", + [self lockedStateSnapshot]); + return true; } @@ -630,12 +752,16 @@ - (void)stopIfPossible - (void)restartAudioEngine { + AUDIOAPI_TRACE_SCOPE(@"restart"); + std::scoped_lock lock(_engineLock); // The engine is created lazily on first node attach. Apps that only use // session management and notifications never have one, and a system-driven // restart (media services reset, configuration change) must not create it. if (![self hasTrackedGraph] && self.audioEngine == nil) { + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategoryEngine, @"restart ignored, this app has no engine of its own"); return; } diff --git a/packages/react-native-audio-api/ios/audioapi/ios/system/AudioSessionManager.mm b/packages/react-native-audio-api/ios/audioapi/ios/system/AudioSessionManager.mm index f825a06da..db525f181 100644 --- a/packages/react-native-audio-api/ios/audioapi/ios/system/AudioSessionManager.mm +++ b/packages/react-native-audio-api/ios/audioapi/ios/system/AudioSessionManager.mm @@ -1,4 +1,5 @@ #import +#import #import #import @@ -51,6 +52,8 @@ + (instancetype)sharedInstance - (void)cleanup { + AUDIOAPI_LOG(AudioAPIDiagnosticsCategorySession, @"cleanup, releasing the session object"); + self.audioSession = nil; } @@ -65,10 +68,43 @@ - (bool)areDesiredOptionsSet - (bool)configureAudioSession:(NSError **)outError { - if (!self.shouldManageSession || [self areDesiredOptionsSet]) { + AUDIOAPI_TRACE_SCOPE(@"configureSession"); + + if (!self.shouldManageSession) { + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategorySession, @"session is externally owned, leaving it alone"); + return true; + } + + // A manager that has been cleaned up keeps answering, and every call below is + // then a message to nil that reports success. This is the signature to look + // for - not a setCategory failing with a nil error. + if (self.audioSession == nil) { + AUDIOAPI_LOG_FAILURE( + AudioAPIDiagnosticsCategorySession, + @"configureAudioSession has no session object: this manager was cleaned up but is still " + @"reachable, so the configuration below is silently discarded"); + } + + // The only thing standing between a reconfiguration and the configuration + // change it provokes, so both outcomes are worth a line: it tells a restart + // storm that is being braked here apart from one waved straight through. + if ([self areDesiredOptionsSet]) { + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategorySession, + @"session already matches the desired configuration, skipping setCategory: {%@}", + AudioAPIDescribeSession(self.audioSession)); return true; } + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategorySession, + @"setCategory wants category=%@, mode=%@, options=%lu; session is {%@}", + self.desiredCategory, + self.desiredMode, + (unsigned long)self.desiredOptions, + AudioAPIDescribeSession(self.audioSession)); + NSError *categoryError = nil; [self.audioSession setCategory:self.desiredCategory mode:self.desiredMode @@ -76,17 +112,32 @@ - (bool)configureAudioSession:(NSError **)outError error:&categoryError]; if (categoryError != nil) { - NSLog(@"Error while configuring audio session: %@", [categoryError debugDescription]); + AUDIOAPI_LOG_FAILURE( + AudioAPIDiagnosticsCategorySession, + @"setCategory refused: %@; session left at {%@}", + AudioAPIDescribeError(categoryError), + AudioAPIDescribeSession(self.audioSession)); if (outError != nil) { *outError = categoryError; } return false; } - NSLog( - @"[AudioSessionManager] Configured audio session: category=%@, mode=%@, options=%lu", - self.audioSession.category, - self.audioSession.mode, - (unsigned long)self.audioSession.categoryOptions); + + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategorySession, + @"setCategory applied, session is now {%@}", + AudioAPIDescribeSession(self.audioSession)); + + // A refused setCategory can still apply part of what was asked for, and then + // this never converges: every later call retries the same rejected change and + // emits another configuration change doing so. + if (AudioAPIDiagnosticsEnabled() && ![self areDesiredOptionsSet]) { + AUDIOAPI_LOG_FAILURE( + AudioAPIDiagnosticsCategorySession, + @"setCategory reported success but the session did not converge on the desired " + @"configuration; actual={%@}", + AudioAPIDescribeSession(self.audioSession)); + } if (@available(iOS 13.0, *)) { if (self.audioSession.allowHapticsAndSystemSoundsDuringRecording != @@ -176,22 +227,47 @@ - (bool)ensureActive:(bool)force error:(NSError **)error - (bool)activateSessionIfNeeded:(bool)force error:(NSError **)error { + AUDIOAPI_TRACE_SCOPE(@"setActive"); + if (!self.shouldManageSession) { return true; } if (self.isActive && !force) { + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategorySession, @"session already active and not forced, no-op"); return true; } + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategorySession, + @"activating session, force=%@, cachedActive=%@", + force ? @"true" : @"false", + self.isActive ? @"true" : @"false"); + if (![self configureAudioSession:error]) { return false; } - bool success = [self.audioSession setActive:true withOptions:0 error:error]; + NSError *activationError = nil; + bool success = [self.audioSession setActive:true withOptions:0 error:&activationError]; + + if (error != nil && activationError != nil) { + *error = activationError; + } if (success) { self.isActive = true; + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategorySession, + @"session activated, route is {%@}", + AudioAPIDescribeRoute(self.audioSession.currentRoute)); + } else { + AUDIOAPI_LOG_FAILURE( + AudioAPIDiagnosticsCategorySession, + @"setActive refused: %@; session is {%@}", + AudioAPIDescribeError(activationError), + AudioAPIDescribeSession(self.audioSession)); } return success; @@ -199,6 +275,14 @@ - (bool)activateSessionIfNeeded:(bool)force error:(NSError **)error - (void)markInactive { + // Dropping the flag is what forces the next operation to re-assert activation, + // and re-asserting is what emits a configuration change. Whether this ran is + // the difference between a restart that settles and one that feeds itself. + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategorySession, + @"marking session inactive, was %@", + self.isActive ? @"active" : @"inactive"); + // AVAudioSession does not expose a reliable active-state query, so drop our cached flag and // force the next audio operation to re-assert activation. self.isActive = false; diff --git a/packages/react-native-audio-api/ios/audioapi/ios/system/SystemNotificationManager.mm b/packages/react-native-audio-api/ios/audioapi/ios/system/SystemNotificationManager.mm index 7e8701462..12389f777 100644 --- a/packages/react-native-audio-api/ios/audioapi/ios/system/SystemNotificationManager.mm +++ b/packages/react-native-audio-api/ios/audioapi/ios/system/SystemNotificationManager.mm @@ -1,13 +1,23 @@ #import #import +#import #import #import #import +#include + @implementation SystemNotificationManager static NSString *NotificationManagerContext = @"SystemNotificationManagerContext"; +/// Restart requests handed to the main queue against restart requests that have +/// actually run. The gap between them is the queue depth, which is the one thing +/// a per-event log line cannot show: a burst of notifications each scheduling a +/// restart looks identical to a single restart until the two counts diverge. +static std::atomic restartsScheduled{0}; +static std::atomic restartsDrained{0}; + - (instancetype)initWithAudioAPIModule:(AudioAPIModule *)audioAPIModule { if (self = [super init]) { @@ -180,6 +190,8 @@ - (void)handleSecondaryAudio:(NSNotification *)notification - (void)handleRouteChange:(NSNotification *)notification { + AUDIOAPI_TRACE_SCOPE(@"routeChange"); + NSInteger routeChangeReason = [notification.userInfo[AVAudioSessionRouteChangeReasonKey] integerValue]; NSString *reasonStr; @@ -219,13 +231,33 @@ - (void)handleRouteChange:(NSNotification *)notification payload:audioapi::StringPayload{ .name = "reason", .reason = [reasonStr UTF8String]}]; + AVAudioSession *session = [AVAudioSession sharedInstance]; + + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategoryNotifications, + @"routeChange reason=%@, route is {%@}, session is {%@}", + reasonStr, + AudioAPIDescribeRoute(session.currentRoute), + AudioAPIDescribeSession(session)); + switch (routeChangeReason) { case AVAudioSessionRouteChangeReasonNewDeviceAvailable: case AVAudioSessionRouteChangeReasonOldDeviceUnavailable: case AVAudioSessionRouteChangeReasonRouteConfigurationChange: + // Note the reason a ConfigurationChange is not taken at face value: our + // own reconfiguration reports itself here, so this is the door a restart + // walks back through after it has already run. + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategoryNotifications, + @"routeChange reason=%@ is treated as a configuration change, restarting the engine", + reasonStr); [self handleEngineConfigurationChange:nil]; break; default: + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategoryNotifications, + @"routeChange reason=%@ needs no engine restart", + reasonStr); break; } } @@ -239,10 +271,13 @@ - (void)handleMediaServicesReset:(NSNotification *)notification return; } - NSLog( - @"[NotificationManager] Media services have been reset, tearing down and rebuilding everything."); + AUDIOAPI_LOG_FAILURE( + AudioAPIDiagnosticsCategoryNotifications, + @"media services were reset, tearing down and rebuilding everything"); dispatch_async(dispatch_get_main_queue(), ^{ + AUDIOAPI_TRACE_SCOPE(@"mediaServicesReset"); + bool wasSessionActive = sessionManager.isActive; [sessionManager markInactive]; @@ -256,6 +291,8 @@ - (void)handleMediaServicesReset:(NSNotification *)notification - (void)handleEngineConfigurationChange:(NSNotification *)notification { + AUDIOAPI_TRACE_SCOPE(@"engineNotification"); + AudioEngine *audioEngine = self.audioAPIModule.audioEngine; AudioSessionManager *sessionManager = self.audioAPIModule.audioSessionManager; @@ -264,10 +301,37 @@ - (void)handleEngineConfigurationChange:(NSNotification *)notification // an engine of our own there is nothing to restart, and marking the session // inactive would corrupt bookkeeping for apps that only manage the session. if (![audioEngine isInUse]) { + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategoryNotifications, + @"configuration change ignored, no engine of ours is in use"); return; } + uint64_t scheduled = restartsScheduled.fetch_add(1, std::memory_order_relaxed) + 1; + uint64_t drained = restartsDrained.load(std::memory_order_relaxed); + + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategoryNotifications, + @"scheduling a restart on the main queue, %llu scheduled and %llu run so far (%llu in " + @"flight)", + scheduled, + drained, + scheduled - drained); + dispatch_async(dispatch_get_main_queue(), ^{ + AUDIOAPI_TRACE_SCOPE(@"restartDispatch"); + + uint64_t run = restartsDrained.fetch_add(1, std::memory_order_relaxed) + 1; + uint64_t outstanding = restartsScheduled.load(std::memory_order_relaxed) - run; + + // Reported before the work, not after: a restart that never returns because + // it re-entered the notification that scheduled it leaves no trailing line. + AUDIOAPI_LOG( + AudioAPIDiagnosticsCategoryNotifications, + @"running scheduled restart %llu, %llu still queued behind it", + run, + outstanding); + [sessionManager markInactive]; [audioEngine restartAudioEngine]; });