Skip to content
Draft
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
@@ -0,0 +1,112 @@
#pragma once

#import <AVFoundation/AVFoundation.h>
#import <Foundation/Foundation.h>

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
Original file line number Diff line number Diff line change
@@ -0,0 +1,277 @@
#import <audioapi/ios/system/AudioAPIDiagnostics.h>

#import <os/log.h>

#include <ctype.h>
#include <pthread.h>
#include <atomic>

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<bool> diagnosticsEnabled{true};
#else
static std::atomic<bool> diagnosticsEnabled{false};
#endif

static std::atomic<uint64_t> 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<NSString *> *currentThreadScopeStack(void)
{
NSMutableDictionary *threadStorage = [[NSThread currentThread] threadDictionary];
NSMutableArray<NSString *> *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<NSString *> *scopeStack = currentThreadScopeStack();

if (scopeStack.count == 0) {
return;
}

[scopeStack removeLastObject];
}

NSString *AudioAPICurrentDiagnosticsScope(void)
{
NSMutableArray<NSString *> *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<NSString *> *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];
}
Loading