AudioTrack: Add error event logging
Test: atest AudioTrackTest#testAudioTrackErrors
Test: adb shell dumpsys media.metrics
Bug: 199763036
Merged-In: Idaf5d28b43670fdf745a5e16d0a5737fbb2f68c6
Change-Id: Idaf5d28b43670fdf745a5e16d0a5737fbb2f68c6
diff --git a/media/libaudioclient/AudioTrack.cpp b/media/libaudioclient/AudioTrack.cpp
index 3bc666b..822df2e 100644
--- a/media/libaudioclient/AudioTrack.cpp
+++ b/media/libaudioclient/AudioTrack.cpp
@@ -25,6 +25,7 @@
#include <android/media/IAudioPolicyService.h>
#include <android-base/macros.h>
+#include <android-base/stringprintf.h>
#include <audio_utils/clock.h>
#include <audio_utils/primitives.h>
#include <binder/IPCThreadState.h>
@@ -44,6 +45,7 @@
static const int kMaxLoopCountNotifications = 32;
using ::android::aidl_utils::statusTFromBinderStatus;
+using ::android::base::StringPrintf;
namespace android {
// ---------------------------------------------------------------------------
@@ -394,6 +396,7 @@
pid_t myPid;
uid_t uid = VALUE_OR_FATAL(aidl2legacy_int32_t_uid_t(attributionSource.uid));
pid_t pid = VALUE_OR_FATAL(aidl2legacy_int32_t_pid_t(attributionSource.pid));
+ std::string errorMessage;
// Note mPortId is not valid until the track is created, so omit mPortId in ALOG for set.
ALOGV("%s(): streamType %d, sampleRate %u, format %#x, channelMask %#x, frameCount %zu, "
@@ -419,32 +422,34 @@
case TRANSFER_CALLBACK:
case TRANSFER_SYNC_NOTIF_CALLBACK:
if (cbf == NULL || sharedBuffer != 0) {
- ALOGE("%s(): Transfer type %s but cbf == NULL || sharedBuffer != 0",
+ errorMessage = StringPrintf(
+ "%s: Transfer type %s but cbf == NULL || sharedBuffer != 0",
convertTransferToText(transferType), __func__);
status = BAD_VALUE;
- goto exit;
+ goto error;
}
break;
case TRANSFER_OBTAIN:
case TRANSFER_SYNC:
if (sharedBuffer != 0) {
- ALOGE("%s(): Transfer type TRANSFER_OBTAIN but sharedBuffer != 0", __func__);
+ errorMessage = StringPrintf(
+ "%s: Transfer type TRANSFER_OBTAIN but sharedBuffer != 0", __func__);
status = BAD_VALUE;
- goto exit;
+ goto error;
}
break;
case TRANSFER_SHARED:
if (sharedBuffer == 0) {
- ALOGE("%s(): Transfer type TRANSFER_SHARED but sharedBuffer == 0", __func__);
+ errorMessage = StringPrintf(
+ "%s: Transfer type TRANSFER_SHARED but sharedBuffer == 0", __func__);
status = BAD_VALUE;
- goto exit;
+ goto error;
}
break;
default:
- ALOGE("%s(): Invalid transfer type %d",
- __func__, transferType);
+ errorMessage = StringPrintf("%s: Invalid transfer type %d", __func__, transferType);
status = BAD_VALUE;
- goto exit;
+ goto error;
}
mSharedBuffer = sharedBuffer;
mTransfer = transferType;
@@ -458,9 +463,9 @@
// invariant that mAudioTrack != 0 is true only after set() returns successfully
if (mAudioTrack != 0) {
- ALOGE("%s(): Track already in use", __func__);
+ errorMessage = StringPrintf("%s: Track already in use", __func__);
status = INVALID_OPERATION;
- goto exit;
+ goto error;
}
// handle default values first.
@@ -469,9 +474,9 @@
}
if (pAttributes == NULL) {
if (uint32_t(streamType) >= AUDIO_STREAM_PUBLIC_CNT) {
- ALOGE("%s(): Invalid stream type %d", __func__, streamType);
+ errorMessage = StringPrintf("%s: Invalid stream type %d", __func__, streamType);
status = BAD_VALUE;
- goto exit;
+ goto error;
}
mOriginalStreamType = streamType;
@@ -495,16 +500,16 @@
// validate parameters
if (!audio_is_valid_format(format)) {
- ALOGE("%s(): Invalid format %#x", __func__, format);
+ errorMessage = StringPrintf("%s: Invalid format %#x", __func__, format);
status = BAD_VALUE;
- goto exit;
+ goto error;
}
mFormat = format;
if (!audio_is_output_channel(channelMask)) {
- ALOGE("%s(): Invalid channel mask %#x", __func__, channelMask);
+ errorMessage = StringPrintf("%s: Invalid channel mask %#x", __func__, channelMask);
status = BAD_VALUE;
- goto exit;
+ goto error;
}
mChannelMask = channelMask;
channelCount = audio_channel_count_from_out_mask(channelMask);
@@ -543,8 +548,10 @@
// sampling rate must be specified for direct outputs
if (sampleRate == 0 && (flags & AUDIO_OUTPUT_FLAG_DIRECT) != 0) {
+ errorMessage = StringPrintf(
+ "%s: sample rate must be specified for direct outputs", __func__);
status = BAD_VALUE;
- goto exit;
+ goto error;
}
mSampleRate = sampleRate;
mOriginalSampleRate = sampleRate;
@@ -574,16 +581,17 @@
mNotificationsPerBufferReq = 0;
} else {
if (!(flags & AUDIO_OUTPUT_FLAG_FAST)) {
- ALOGE("%s(): notificationFrames=%d not permitted for non-fast track",
+ errorMessage = StringPrintf(
+ "%s: notificationFrames=%d not permitted for non-fast track",
__func__, notificationFrames);
status = BAD_VALUE;
- goto exit;
+ goto error;
}
if (frameCount > 0) {
ALOGE("%s(): notificationFrames=%d not permitted with non-zero frameCount=%zu",
__func__, notificationFrames, frameCount);
status = BAD_VALUE;
- goto exit;
+ goto error;
}
mNotificationFramesReq = 0;
const uint32_t minNotificationsPerBuffer = 1;
@@ -628,6 +636,7 @@
mAudioTrackThread->requestExitAndWait();
mAudioTrackThread.clear();
}
+ // We do not goto error to prevent double-logging errors.
goto exit;
}
@@ -662,6 +671,12 @@
mFramesWrittenAtRestore = -1; // -1 is a unique initializer.
mVolumeHandler = new media::VolumeHandler();
+error:
+ if (status != NO_ERROR) {
+ ALOGE_IF(!errorMessage.empty(), "%s", errorMessage.c_str());
+ reportError(status, AMEDIAMETRICS_PROP_EVENT_VALUE_CREATE, errorMessage.c_str());
+ }
+ // fall through
exit:
mStatus = status;
return status;
@@ -1687,12 +1702,13 @@
{
status_t status;
bool callbackAdded = false;
+ std::string errorMessage;
const sp<IAudioFlinger>& audioFlinger = AudioSystem::get_audio_flinger();
if (audioFlinger == 0) {
- ALOGE("%s(%d): Could not get audioflinger",
+ errorMessage = StringPrintf("%s(%d): Could not get audioflinger",
__func__, mPortId);
- status = NO_INIT;
+ status = DEAD_OBJECT;
goto exit;
}
@@ -1769,10 +1785,11 @@
}
if (status != NO_ERROR || output.outputId == AUDIO_IO_HANDLE_NONE) {
- ALOGE("%s(%d): AudioFlinger could not create track, status: %d output %d",
+ errorMessage = StringPrintf(
+ "%s(%d): AudioFlinger could not create track, status: %d output %d",
__func__, mPortId, status, output.outputId);
if (status == NO_ERROR) {
- status = NO_INIT;
+ status = INVALID_OPERATION; // device not ready
}
goto exit;
}
@@ -1803,8 +1820,8 @@
output.audioTrack->getCblk(&sfr);
sp<IMemory> iMem = VALUE_OR_FATAL(aidl2legacy_NullableSharedFileRegion_IMemory(sfr));
if (iMem == 0) {
- ALOGE("%s(%d): Could not get control block", __func__, mPortId);
- status = NO_INIT;
+ errorMessage = StringPrintf("%s(%d): Could not get control block", __func__, mPortId);
+ status = FAILED_TRANSACTION;
goto exit;
}
// TODO: Using unsecurePointer() has some associated security pitfalls
@@ -1813,8 +1830,9 @@
// issue (e.g. by copying).
void *iMemPointer = iMem->unsecurePointer();
if (iMemPointer == NULL) {
- ALOGE("%s(%d): Could not get control block pointer", __func__, mPortId);
- status = NO_INIT;
+ errorMessage = StringPrintf(
+ "%s(%d): Could not get control block pointer", __func__, mPortId);
+ status = FAILED_TRANSACTION;
goto exit;
}
// invariant that mAudioTrack != 0 is true only after set() returns successfully
@@ -1872,8 +1890,10 @@
// issue (e.g. by copying).
buffers = mSharedBuffer->unsecurePointer();
if (buffers == NULL) {
- ALOGE("%s(%d): Could not get buffer pointer", __func__, mPortId);
- status = NO_INIT;
+ errorMessage = StringPrintf(
+ "%s(%d): Could not get buffer pointer", __func__, mPortId);
+ ALOGE("%s", errorMessage.c_str());
+ status = FAILED_TRANSACTION;
goto exit;
}
}
@@ -1971,17 +1991,44 @@
}
exit:
- if (status != NO_ERROR && callbackAdded) {
- // note: mOutput is always valid is callbackAdded is true
- AudioSystem::removeAudioDeviceCallback(this, mOutput, mPortId);
+ if (status != NO_ERROR) {
+ if (callbackAdded) {
+ // note: mOutput is always valid is callbackAdded is true
+ AudioSystem::removeAudioDeviceCallback(this, mOutput, mPortId);
+ }
+ ALOGE_IF(!errorMessage.empty(), "%s", errorMessage.c_str());
+ reportError(status, AMEDIAMETRICS_PROP_EVENT_VALUE_CREATE, errorMessage.c_str());
}
-
mStatus = status;
// sp<IAudioTrack> track destructor will cause releaseOutput() to be called by AudioFlinger
return status;
}
+void AudioTrack::reportError(status_t status, const char *event, const char *message) const
+{
+ if (status == NO_ERROR) return;
+ // We report error on the native side because some callers do not come
+ // from Java.
+ mediametrics::LogItem(std::string(AMEDIAMETRICS_KEY_PREFIX_AUDIO_TRACK) + "error")
+ .set(AMEDIAMETRICS_PROP_EVENT, event)
+ .set(AMEDIAMETRICS_PROP_ERROR, mediametrics::statusToErrorString(status))
+ .set(AMEDIAMETRICS_PROP_ERRORMESSAGE, message)
+ .set(AMEDIAMETRICS_PROP_ORIGINALFLAGS, toString(mOrigFlags).c_str())
+ .set(AMEDIAMETRICS_PROP_SESSIONID, (int32_t)mSessionId)
+ .set(AMEDIAMETRICS_PROP_CONTENTTYPE, toString(mAttributes.content_type).c_str())
+ .set(AMEDIAMETRICS_PROP_USAGE, toString(mAttributes.usage).c_str())
+ .set(AMEDIAMETRICS_PROP_SELECTEDDEVICEID, (int32_t)mSelectedDeviceId)
+ .set(AMEDIAMETRICS_PROP_ENCODING, toString(mFormat).c_str())
+ .set(AMEDIAMETRICS_PROP_CHANNELMASK, (int32_t)mChannelMask)
+ .set(AMEDIAMETRICS_PROP_FRAMECOUNT, (int32_t)mReqFrameCount) // requested frame count
+ // the following are NOT immutable
+ .set(AMEDIAMETRICS_PROP_SAMPLERATE, (int32_t)mSampleRate)
+ .set(AMEDIAMETRICS_PROP_PLAYBACK_SPEED, (double)mPlaybackRate.mSpeed)
+ .set(AMEDIAMETRICS_PROP_PLAYBACK_PITCH, (double)mPlaybackRate.mPitch)
+ .record();
+}
+
status_t AudioTrack::obtainBuffer(Buffer* audioBuffer, int32_t waitCount, size_t *nonContig)
{
if (audioBuffer == NULL) {