AudioOutputDescriptor: improve refcount logging

Improve refcount to match exact client descriptor
Abort on invalid client descriptor refcounts
Log changes to active clients and refcounts

Test: dumpsys of media.audio_policy
Bug: 112067674
Change-Id: I5fe4d3e7135efbf9bc5bffb258374115d87c24e6
diff --git a/services/audiopolicy/Android.mk b/services/audiopolicy/Android.mk
index c577589..f23e426 100644
--- a/services/audiopolicy/Android.mk
+++ b/services/audiopolicy/Android.mk
@@ -73,6 +73,7 @@
 LOCAL_C_INCLUDES += \
     frameworks/av/services/audiopolicy/common/include \
     frameworks/av/services/audiopolicy/engine/interface \
+    $(call include-path-for, audio-utils) \
 
 LOCAL_STATIC_LIBRARIES := \
     libaudiopolicycomponents
@@ -109,7 +110,8 @@
 
 LOCAL_C_INCLUDES += \
     frameworks/av/services/audiopolicy/common/include \
-    frameworks/av/services/audiopolicy/engine/interface
+    frameworks/av/services/audiopolicy/engine/interface \
+    $(call include-path-for, audio-utils) \
 
 LOCAL_CFLAGS := -Wall -Werror
 
diff --git a/services/audiopolicy/common/managerdefinitions/include/AudioOutputDescriptor.h b/services/audiopolicy/common/managerdefinitions/include/AudioOutputDescriptor.h
index 27b1c93..cb4206a 100644
--- a/services/audiopolicy/common/managerdefinitions/include/AudioOutputDescriptor.h
+++ b/services/audiopolicy/common/managerdefinitions/include/AudioOutputDescriptor.h
@@ -17,6 +17,8 @@
 #pragma once
 
 #include <sys/types.h>
+
+#include <audio_utils/SimpleLog.h>
 #include <utils/Errors.h>
 #include <utils/Timers.h>
 #include <utils/KeyedVector.h>
@@ -59,7 +61,7 @@
                            audio_devices_t device,
                            uint32_t delayMs,
                            bool force);
-    virtual void changeStreamActiveCount(audio_stream_type_t stream, int delta);
+    virtual void changeStreamActiveCount(const sp<TrackClientDescriptor>& client, int delta);
             uint32_t streamActiveCount(audio_stream_type_t stream) const
                             { return mActiveCount[stream]; }
             void setClientActive(const sp<TrackClientDescriptor>& client, bool active);
@@ -74,6 +76,12 @@
     virtual sp<AudioPort> getAudioPort() const { return mPort; }
     virtual void toAudioPort(struct audio_port *port) const;
 
+    using ActiveClientMap = std::map<sp<TrackClientDescriptor>, size_t /* count */>;
+
+    const ActiveClientMap& getActiveClients() const {
+        return mActiveClients;
+    }
+
     audio_module_handle_t getModuleHandle() const;
 
     // implementation of AudioIODescriptorInterface
@@ -101,6 +109,8 @@
     audio_patch_handle_t mPatchHandle;
     audio_port_handle_t mId;
     TrackClientMap mClients;
+    ActiveClientMap mActiveClients;
+    SimpleLog mLocalLog;
 };
 
 // Audio output driven by a software mixer in audio flinger.
@@ -121,7 +131,8 @@
     virtual bool isFixedVolume(audio_devices_t device);
     virtual sp<AudioOutputDescriptor> subOutput1() { return mOutput1; }
     virtual sp<AudioOutputDescriptor> subOutput2() { return mOutput2; }
-    virtual void changeStreamActiveCount(audio_stream_type_t stream, int delta);
+            void changeStreamActiveCount(
+                    const sp<TrackClientDescriptor>& client, int delta) override;
     virtual bool setVolume(float volume,
                            audio_stream_type_t stream,
                            audio_devices_t device,
diff --git a/services/audiopolicy/common/managerdefinitions/include/ClientDescriptor.h b/services/audiopolicy/common/managerdefinitions/include/ClientDescriptor.h
index 1a3300d..ee231b6 100644
--- a/services/audiopolicy/common/managerdefinitions/include/ClientDescriptor.h
+++ b/services/audiopolicy/common/managerdefinitions/include/ClientDescriptor.h
@@ -47,6 +47,7 @@
 
     status_t dump(int fd, int spaces, int index);
     virtual status_t dump(String8& dst, int spaces, int index);
+    virtual std::string toShortString() const;
 
     audio_port_handle_t portId() const { return mPortId; }
     uid_t uid() const { return mUid; }
@@ -90,6 +91,7 @@
 
     using ClientDescriptor::dump;
     status_t dump(String8& dst, int spaces, int index) override;
+    std::string toShortString() const override;
 
     audio_output_flags_t flags() const { return mFlags; }
     audio_stream_type_t stream() const { return mStream; }
diff --git a/services/audiopolicy/common/managerdefinitions/src/AudioOutputDescriptor.cpp b/services/audiopolicy/common/managerdefinitions/src/AudioOutputDescriptor.cpp
index 9327e7e..ba56b96 100644
--- a/services/audiopolicy/common/managerdefinitions/src/AudioOutputDescriptor.cpp
+++ b/services/audiopolicy/common/managerdefinitions/src/AudioOutputDescriptor.cpp
@@ -103,16 +103,37 @@
     }
 }
 
-void AudioOutputDescriptor::changeStreamActiveCount(audio_stream_type_t stream,
-                                                                   int delta)
+void AudioOutputDescriptor::changeStreamActiveCount(const sp<TrackClientDescriptor>& client,
+                                                    int delta)
 {
+    if (delta == 0) return;
+    const audio_stream_type_t stream = client->stream();
     if ((delta + (int)mActiveCount[stream]) < 0) {
-        ALOGW("%s invalid delta %d for stream %d, active count %d",
-              __FUNCTION__, delta, stream, mActiveCount[stream]);
-        mActiveCount[stream] = 0;
-        return;
+        // any mismatched active count will abort.
+        LOG_ALWAYS_FATAL("%s(%s) invalid delta %d, active stream count %d",
+              __func__, client->toShortString().c_str(), delta, mActiveCount[stream]);
+        // mActiveCount[stream] = 0;
+        // return;
     }
     mActiveCount[stream] += delta;
+
+    if (delta > 0) {
+        mActiveClients[client] += delta;
+    } else {
+        auto it = mActiveClients.find(client);
+        if (it == mActiveClients.end()) { // client not found!
+            LOG_ALWAYS_FATAL("%s(%s) invalid delta %d, inactive client",
+                    __func__, client->toShortString().c_str(), delta);
+        } else if (it->second < -delta) { // invalid delta!
+            LOG_ALWAYS_FATAL("%s(%s) invalid delta %d, active client count %zu",
+                    __func__, client->toShortString().c_str(), delta, it->second);
+        }
+        it->second += delta;
+        if (it->second == 0) {
+            (void)mActiveClients.erase(it);
+        }
+    }
+
     ALOGV("%s stream %d, count %d", __FUNCTION__, stream, mActiveCount[stream]);
 }
 
@@ -120,15 +141,24 @@
 {
     if (mClients.find(client->portId()) == mClients.end()
         || active == client->active()) {
+
+        mLocalLog.log("%s(%s): ignored active: %d, current stream count %d",
+                __func__, client->toShortString().c_str(),
+                active, mActiveCount[client->stream()]);
         return;
     }
 
-    changeStreamActiveCount(client->stream(), active ? 1 : -1);
+    changeStreamActiveCount(client, active ? 1 : -1);
+
+    mLocalLog.log("%s(%s): active: %d, current stream count %d",
+            __func__, client->toShortString().c_str(),
+             active, mActiveCount[client->stream()]);
 
     // Handle non-client-specific activity ref count
     int32_t oldGlobalActiveCount = mGlobalActiveCount;
     if (!active && mGlobalActiveCount < 1) {
-        ALOGW("%s invalid deactivation with globalRefCount %d", __FUNCTION__, mGlobalActiveCount);
+        ALOGW("%s(%s): invalid deactivation with globalRefCount %d",
+                __func__, client->toShortString().c_str(), mGlobalActiveCount);
         mGlobalActiveCount = 1;
     }
     mGlobalActiveCount += active ? 1 : -1;
@@ -279,8 +309,21 @@
         client.second->dump(result, 2, index++);
     }
     result.append(" \n");
+
+    if (mActiveClients.size() > 0) {
+        result.append(" AudioTrack active clients:\n");
+        index = 0;
+        for (const auto& clientPair : mActiveClients) {
+            result.appendFormat(" Refcount: %zu", clientPair.second);
+            clientPair.first->dump(result, 2, index++);
+        }
+        result.append(" \n");
+    }
+
     write(fd, result.string(), result.size());
 
+    // write local log
+    mLocalLog.dump(fd, "   " /* prefix */, 40 /* lines */);
     return NO_ERROR;
 }
 
@@ -361,15 +404,15 @@
     }
 }
 
-void SwAudioOutputDescriptor::changeStreamActiveCount(audio_stream_type_t stream,
-                                                                   int delta)
+void SwAudioOutputDescriptor::changeStreamActiveCount(const sp<TrackClientDescriptor>& client,
+                                                       int delta)
 {
     // forward usage count change to attached outputs
     if (isDuplicated()) {
-        mOutput1->changeStreamActiveCount(stream, delta);
-        mOutput2->changeStreamActiveCount(stream, delta);
+        mOutput1->changeStreamActiveCount(client, delta);
+        mOutput2->changeStreamActiveCount(client, delta);
     }
-    AudioOutputDescriptor::changeStreamActiveCount(stream, delta);
+    AudioOutputDescriptor::changeStreamActiveCount(client, delta);
 }
 
 bool SwAudioOutputDescriptor::isFixedVolume(audio_devices_t device)
diff --git a/services/audiopolicy/common/managerdefinitions/src/ClientDescriptor.cpp b/services/audiopolicy/common/managerdefinitions/src/ClientDescriptor.cpp
index 0d65a31..6e6f507 100644
--- a/services/audiopolicy/common/managerdefinitions/src/ClientDescriptor.cpp
+++ b/services/audiopolicy/common/managerdefinitions/src/ClientDescriptor.cpp
@@ -44,10 +44,18 @@
     return status;
 }
 
+std::string ClientDescriptor::toShortString() const
+{
+    std::stringstream ss;
+
+    ss << "PortId: " << mPortId << " SessionId: " << mSessionId << " Uid: " << mUid;
+    return ss.str();
+}
+
 status_t ClientDescriptor::dump(String8& out, int spaces, int index)
 {
     out.appendFormat("%*sClient %d:\n", spaces, "", index+1);
-    out.appendFormat("%*s- Port ID: %d Session Id: %d UID: %d\n", spaces, "",
+    out.appendFormat("%*s- Port Id: %d Session Id: %d UID: %d\n", spaces, "",
              mPortId, mSessionId, mUid);
     out.appendFormat("%*s- Format: %08x Sampling rate: %d Channels: %08x\n", spaces, "",
              mConfig.format, mConfig.sample_rate, mConfig.channel_mask);
@@ -65,6 +73,14 @@
     return NO_ERROR;
 }
 
+std::string TrackClientDescriptor::toShortString() const
+{
+    std::stringstream ss;
+
+    ss << ClientDescriptor::toShortString() << " Stream: " << mStream;
+    return ss.str();
+}
+
 status_t RecordClientDescriptor::dump(String8& out, int spaces, int index)
 {
     ClientDescriptor::dump(out, spaces, index);
diff --git a/services/audiopolicy/managerdefault/AudioPolicyManager.cpp b/services/audiopolicy/managerdefault/AudioPolicyManager.cpp
index 380f0fb..4543dd0 100644
--- a/services/audiopolicy/managerdefault/AudioPolicyManager.cpp
+++ b/services/audiopolicy/managerdefault/AudioPolicyManager.cpp
@@ -4529,10 +4529,9 @@
             // and as they were also referenced on the other output, the reference
             // count for their stream type must be adjusted accordingly on
             // the other output.
-            bool wasActive = outputDesc2->isActive();
-            for (int j = 0; j < AUDIO_STREAM_CNT; j++) {
-                int activeCount = dupOutputDesc->streamActiveCount((audio_stream_type_t)j);
-                outputDesc2->changeStreamActiveCount((audio_stream_type_t)j,-activeCount);
+            const bool wasActive = outputDesc2->isActive();
+            for (const auto &clientPair : dupOutputDesc->getActiveClients()) {
+                outputDesc2->changeStreamActiveCount(clientPair.first, -clientPair.second);
             }
             // stop() will be a no op if the output is still active but is needed in case all
             // active streams refcounts where cleared above
diff --git a/services/audiopolicy/tests/Android.mk b/services/audiopolicy/tests/Android.mk
index b739b88..513312e 100644
--- a/services/audiopolicy/tests/Android.mk
+++ b/services/audiopolicy/tests/Android.mk
@@ -6,6 +6,7 @@
   frameworks/av/services/audiopolicy \
   frameworks/av/services/audiopolicy/common/include \
   frameworks/av/services/audiopolicy/engine/interface \
+  $(call include-path-for, audio-utils) \
 
 LOCAL_SHARED_LIBRARIES := \
   libaudiopolicymanagerdefault \