audiopolicy: Modify logging in setOutputDevices
Modify logging in setOutputDevices to log ioHandles, mixport
names for better debugging.
Also, modify the method signature to include caller, as
setOutputDevices can be modified from multiple places,
having a caller context is helpful during multiple
device connection scenarios.
Test: Build and check logs while running usecases
Bug: 293535290
Change-Id: I461bf184bfab1c45ebe0170008fc59aa5a6a29a4
diff --git a/services/audiopolicy/common/managerdefinitions/include/AudioOutputDescriptor.h b/services/audiopolicy/common/managerdefinitions/include/AudioOutputDescriptor.h
index febccac..a03ed06 100644
--- a/services/audiopolicy/common/managerdefinitions/include/AudioOutputDescriptor.h
+++ b/services/audiopolicy/common/managerdefinitions/include/AudioOutputDescriptor.h
@@ -315,6 +315,13 @@
wp<AudioPolicyMix> mPolicyMix; // non NULL when used by a dynamic policy
virtual uint32_t getRecommendedMuteDurationMs() const { return 0; }
+ virtual std::string info() const {
+ std::string result;
+ result.append("[portId:" );
+ result.append(android::internal::ToString(getId()));
+ result.append("]");
+ return result;
+ }
protected:
const sp<PolicyAudioPort> mPolicyAudioPort;
@@ -457,6 +464,8 @@
PortHandleVector getClientsForStream(audio_stream_type_t streamType) const;
+ virtual std::string info() const override;
+
const sp<IOProfile> mProfile; // I/O profile this output derives from
audio_io_handle_t mIoHandle; // output handle
uint32_t mLatency; //
diff --git a/services/audiopolicy/common/managerdefinitions/src/AudioOutputDescriptor.cpp b/services/audiopolicy/common/managerdefinitions/src/AudioOutputDescriptor.cpp
index 8b23311..c29ad9c 100644
--- a/services/audiopolicy/common/managerdefinitions/src/AudioOutputDescriptor.cpp
+++ b/services/audiopolicy/common/managerdefinitions/src/AudioOutputDescriptor.cpp
@@ -980,6 +980,18 @@
return clientsForStream;
}
+std::string SwAudioOutputDescriptor::info() const {
+ std::string result;
+ result.append("[" );
+ result.append(AudioOutputDescriptor::info());
+ result.append("[io:" );
+ result.append(android::internal::ToString(mIoHandle));
+ result.append(", " );
+ result.append(mProfile->getTagName());
+ result.append("]]");
+ return result;
+}
+
void SwAudioOutputCollection::dump(String8 *dst) const
{
dst->appendFormat("\n Outputs (%zu):\n", size());
diff --git a/services/audiopolicy/managerdefault/AudioPolicyManager.cpp b/services/audiopolicy/managerdefault/AudioPolicyManager.cpp
index f1f2048..8ed0cfa 100644
--- a/services/audiopolicy/managerdefault/AudioPolicyManager.cpp
+++ b/services/audiopolicy/managerdefault/AudioPolicyManager.cpp
@@ -337,7 +337,7 @@
outputsToReopenWithDevices.emplace(mOutputs.keyAt(i), newDevices);
continue;
}
- setOutputDevices(desc, newDevices, force, 0);
+ setOutputDevices(__func__, desc, newDevices, force, 0);
}
if (!desc->isDuplicated() && desc->mProfile->hasDynamicAudioProfile() &&
!activeMediaDevices.empty() && desc->devices() != activeMediaDevices &&
@@ -728,7 +728,7 @@
// Use legacy routing method for voice calls via setOutputDevice() on primary output.
// Otherwise, create two audio patches for TX and RX path.
if (!createRxPatch) {
- muteWaitMs = setOutputDevices(mPrimaryOutput, rxDevices, true, delayMs);
+ muteWaitMs = setOutputDevices(__func__, mPrimaryOutput, rxDevices, true, delayMs);
} else { // create RX path audio patch
connectTelephonyRxAudioSource();
// If the TX device is on the primary HW module but RX device is
@@ -888,7 +888,7 @@
disconnectTelephonyAudioSource(mCallRxSourceClient);
disconnectTelephonyAudioSource(mCallTxSourceClient);
}
- setOutputDevices(mPrimaryOutput, rxDevices, force, 0);
+ setOutputDevices(__func__, mPrimaryOutput, rxDevices, force, 0);
}
}
@@ -906,7 +906,7 @@
outputsToReopen.emplace(mOutputs.keyAt(i), newDevices);
continue;
}
- setOutputDevices(desc, newDevices, forceRouting, 0 /*delayMs*/, nullptr,
+ setOutputDevices(__func__, desc, newDevices, forceRouting, 0 /*delayMs*/, nullptr,
true /*requiresMuteCheck*/, !forceRouting /*requiresVolumeCheck*/);
}
}
@@ -2339,7 +2339,8 @@
return DEAD_OBJECT;
}
const uint32_t muteWaitMs =
- setOutputDevices(outputDesc, devices, force, 0, nullptr, requiresMuteCheck);
+ setOutputDevices(__func__, outputDesc, devices, force, 0, nullptr,
+ requiresMuteCheck);
// apply volume rules for current stream and device if necessary
auto &curves = getVolumeCurves(client->attributes());
@@ -2422,7 +2423,7 @@
outputsToReopen.emplace(mOutputs.keyAt(i), newDevices);
continue;
}
- setOutputDevices(desc, newDevices, force, delayMs);
+ setOutputDevices(__func__, desc, newDevices, force, delayMs);
// re-apply device specific volume if not done by setOutputDevice()
if (!force) {
applyStreamVolumes(desc, newDevices.types(), delayMs);
@@ -2524,7 +2525,7 @@
// still contain data that needs to be drained. The latency only covers the audio HAL
// and kernel buffers. Also the latency does not always include additional delay in the
// audio path (audio DSP, CODEC ...)
- setOutputDevices(outputDesc, newDevices, false, outputDesc->latency()*2,
+ setOutputDevices(__func__, outputDesc, newDevices, false, outputDesc->latency()*2,
nullptr, true /*requiresMuteCheck*/, requiresVolumeCheck);
// force restoring the device selection on other active outputs if it differs from the
@@ -2547,7 +2548,7 @@
outputsToReopen.emplace(mOutputs.keyAt(i), newDevices2);
continue;
}
- setOutputDevices(desc, newDevices2, force, delayMs);
+ setOutputDevices(__func__, desc, newDevices2, force, delayMs);
// re-apply device specific volume if not done by setOutputDevice()
if (!force) {
@@ -3951,8 +3952,9 @@
outputsToReopen.emplace(mOutputs.keyAt(i), newDevices);
continue;
}
- waitMs = setOutputDevices(outputDesc, newDevices, forceRouting, delayMs, nullptr,
- !skipDelays /*requiresMuteCheck*/,
+
+ waitMs = setOutputDevices(__func__, outputDesc, newDevices, forceRouting, delayMs,
+ nullptr, !skipDelays /*requiresMuteCheck*/,
!forceRouting /*requiresVolumeCheck*/, skipDelays);
// Only apply special touch sound delay once
delayMs = 0;
@@ -4939,7 +4941,7 @@
// TODO: reconfigure output format and channels here
ALOGV("%s setting device %s on output %d",
__func__, dumpDeviceTypes(devices.types()).c_str(), outputDesc->mIoHandle);
- setOutputDevices(outputDesc, devices, true, 0, handle);
+ setOutputDevices(__func__, outputDesc, devices, true, 0, handle);
index = mAudioPatches.indexOfKey(*handle);
if (index >= 0) {
if (patchDesc != 0 && patchDesc != mAudioPatches.valueAt(index)) {
@@ -5198,7 +5200,7 @@
return BAD_VALUE;
}
- setOutputDevices(outputDesc,
+ setOutputDevices(__func__, outputDesc,
getNewOutputDevices(outputDesc, true /*fromCache*/),
true,
0,
@@ -5252,7 +5254,7 @@
// 3 / Inactive Output previously hosting SwBridge that can be closed.
bool updateDevice = outputDesc->isActive() || !sourceDesc->useSwBridge() ||
sourceDesc->canCloseOutput();
- setOutputDevices(outputDesc,
+ setOutputDevices(__func__, outputDesc,
updateDevice ? getNewOutputDevices(outputDesc, true /*fromCache*/) :
outputDesc->devices(),
force,
@@ -5389,7 +5391,7 @@
outputsToReopen.emplace(mOutputs.keyAt(j), newDevices);
continue;
}
- setOutputDevices(outputDesc, newDevices, false);
+ setOutputDevices(__func__, outputDesc, newDevices, false);
}
}
reopenOutputsWithDevices(outputsToReopen);
@@ -6267,7 +6269,7 @@
outputDesc->close();
} else {
addOutput(output, outputDesc);
- setOutputDevices(outputDesc,
+ setOutputDevices(__func__, outputDesc,
DeviceVector(supportedDevice),
true,
0,
@@ -6467,8 +6469,8 @@
if (device_distinguishes_on_address(deviceType)) {
ALOGV("checkOutputsForDevice(): setOutputDevices %s",
device->toString().c_str());
- setOutputDevices(desc, DeviceVector(device), true/*force*/, 0/*delay*/,
- NULL/*patch handle*/);
+ setOutputDevices(__func__, desc, DeviceVector(device), true/*force*/,
+ 0/*delay*/, NULL/*patch handle*/);
}
ALOGV("checkOutputsForDevice(): adding output %d", output);
}
@@ -7351,7 +7353,7 @@
if (!desc->supportedDevices().containsAtLeastOne(outputDesc->supportedDevices())) {
continue;
}
- ALOGVV("%s() %s (curDevice %s)", __func__,
+ ALOGVV("%s() output %s %s (curDevice %s)", __func__, desc->info().c_str(),
mute ? "muting" : "unmuting", curDevices.toString().c_str());
setStrategyMute(productStrategy, mute, desc, mute ? 0 : delayMs);
if (desc->isStrategyActive(productStrategy)) {
@@ -7404,7 +7406,8 @@
return 0;
}
-uint32_t AudioPolicyManager::setOutputDevices(const sp<SwAudioOutputDescriptor>& outputDesc,
+uint32_t AudioPolicyManager::setOutputDevices(const char *caller,
+ const sp<SwAudioOutputDescriptor>& outputDesc,
const DeviceVector &devices,
bool force,
int delayMs,
@@ -7413,13 +7416,15 @@
bool skipMuteDelay)
{
// TODO(b/262404095): Consider if the output need to be reopened.
- ALOGV("%s device %s delayMs %d", __func__, devices.toString().c_str(), delayMs);
+ std::string logPrefix = std::string("caller ") + caller + outputDesc->info();
+ ALOGV("%s %s device %s delayMs %d", __func__, logPrefix.c_str(),
+ devices.toString().c_str(), delayMs);
uint32_t muteWaitMs;
if (outputDesc->isDuplicated()) {
- muteWaitMs = setOutputDevices(outputDesc->subOutput1(), devices, force, delayMs,
+ muteWaitMs = setOutputDevices(__func__, outputDesc->subOutput1(), devices, force, delayMs,
nullptr /* patchHandle */, requiresMuteCheck, skipMuteDelay);
- muteWaitMs += setOutputDevices(outputDesc->subOutput2(), devices, force, delayMs,
+ muteWaitMs += setOutputDevices(__func__, outputDesc->subOutput2(), devices, force, delayMs,
nullptr /* patchHandle */, requiresMuteCheck, skipMuteDelay);
return muteWaitMs;
}
@@ -7429,7 +7434,8 @@
DeviceVector prevDevices = outputDesc->devices();
DeviceVector availPrevDevices = mAvailableOutputDevices.filter(prevDevices);
- ALOGV("setOutputDevices() prevDevice %s", prevDevices.toString().c_str());
+ ALOGV("%s %s prevDevice %s", __func__, logPrefix.c_str(),
+ prevDevices.toString().c_str());
if (!filteredDevices.isEmpty()) {
outputDesc->setDevices(filteredDevices);
@@ -7439,7 +7445,8 @@
if (requiresMuteCheck) {
muteWaitMs = checkDeviceMuteStrategies(outputDesc, prevDevices, delayMs);
} else {
- ALOGV("%s: suppressing checkDeviceMuteStrategies", __func__);
+ ALOGV("%s: %s suppressing checkDeviceMuteStrategies", __func__,
+ logPrefix.c_str());
muteWaitMs = 0;
}
@@ -7449,7 +7456,8 @@
// output profile or if new device is not supported AND previous device(s) is(are) still
// available (otherwise reset device must be done on the output)
if (!devices.isEmpty() && filteredDevices.isEmpty() && !availPrevDevices.empty()) {
- ALOGV("%s: unsupported device %s for output", __func__, devices.toString().c_str());
+ ALOGV("%s: %s unsupported device %s for output", __func__, logPrefix.c_str(),
+ devices.toString().c_str());
// restore previous device after evaluating strategy mute state
outputDesc->setDevices(prevDevices);
return muteWaitMs;
@@ -7462,16 +7470,19 @@
// AND the output is connected by a valid audio patch.
// Doing this check here allows the caller to call setOutputDevices() without conditions
if ((filteredDevices.isEmpty() || filteredDevices == prevDevices) && !force && outputRouted) {
- ALOGV("%s setting same device %s or null device, force=%d, patch handle=%d", __func__,
- filteredDevices.toString().c_str(), force, outputDesc->getPatchHandle());
+ ALOGV("%s %s setting same device %s or null device, force=%d, patch handle=%d",
+ __func__, logPrefix.c_str(), filteredDevices.toString().c_str(), force,
+ outputDesc->getPatchHandle());
if (requiresVolumeCheck && !filteredDevices.isEmpty()) {
- ALOGV("%s setting same device on routed output, force apply volumes", __func__);
+ ALOGV("%s %s setting same device on routed output, force apply volumes",
+ __func__, logPrefix.c_str());
applyStreamVolumes(outputDesc, filteredDevices.types(), delayMs, true /*force*/);
}
return muteWaitMs;
}
- ALOGV("%s changing device to %s", __func__, filteredDevices.toString().c_str());
+ ALOGV("%s %s changing device to %s", __func__, logPrefix.c_str(),
+ filteredDevices.toString().c_str());
// do the routing
if (filteredDevices.isEmpty() || mAvailableOutputDevices.filter(filteredDevices).empty()) {
diff --git a/services/audiopolicy/managerdefault/AudioPolicyManager.h b/services/audiopolicy/managerdefault/AudioPolicyManager.h
index 863c785..509cc79 100644
--- a/services/audiopolicy/managerdefault/AudioPolicyManager.h
+++ b/services/audiopolicy/managerdefault/AudioPolicyManager.h
@@ -526,6 +526,7 @@
/**
* @brief setOutputDevices change the route of the specified output.
+ * @param caller of the method
* @param outputDesc to be considered
* @param device to be considered to route the output
* @param force if true, force the routing even if no change.
@@ -539,7 +540,8 @@
* @return the number of ms we have slept to allow new routing to take effect in certain
* cases.
*/
- uint32_t setOutputDevices(const sp<SwAudioOutputDescriptor>& outputDesc,
+ uint32_t setOutputDevices(const char *caller,
+ const sp<SwAudioOutputDescriptor>& outputDesc,
const DeviceVector &device,
bool force = false,
int delayMs = 0,