Temporary additional logging to investigate bug

The bug appears related to continuing to use an invalid buffer provider
in fast mixer after track destruction, so focus the added logs in that area.

Also includes a bug fix: was calling log in an unsafe place
near Threads.cpp AudioFlinger::PlaybackThread::createTrack_l line 1250.

Details:
 - include caller pid or client pid where appropriate
 - increase log buffer size
 - log mFastIndex when AudioMixer sees an invalid bufferProvider.
 - log both potentially modified and actually modified tracks in FastMixer.
 - fix benign bug where sq->end() was called more than once.
 - log StateQueue push() call and return.
 - increase StateQueue size from 4 to 8 entries
 - log mixer->enable(), bufferProvider, and currentTrackMask
 - log buffer provider addresses
 - increase fast mixer log buffer again
 - check logf format vs. argument list compatibility
 - add logging to AudioMixer
 - add checking of magic field in AudioMixer to detect overwrites
 - add bool AudioMixer::enabled()
 - increase log buffer sizes yet again
 - enable assertion checking without ALOGV
 - improve a few log messages
 - check for corruption in more places
 - log in all the process hooks
 - add new mixer APIs so we can check for corruption of mixer state
 - fix a build warning

Bug: 6490974
Change-Id: Ib0c4a73dcf606ef9bd898313b3b40ef61ab42f51

1 files changed, 89 insertions, 4 deletions

diff --git a/services/audioflinger/FastMixer.cpp b/services/audioflinger/FastMixer.cpp
index 80e37ca..75c3c41 100644
--- a/services/audioflinger/FastMixer.cpp
+++ b/services/audioflinger/FastMixer.cpp
@@ -21,13 +21,15 @@
 // </IMPORTANT_WARNING>
 
 #define LOG_TAG "FastMixer"
-//#define LOG_NDEBUG 0
+#define LOG_NDEBUG 0
 
 #define ATRACE_TAG ATRACE_TAG_AUDIO
 
 #include <sys/atomics.h>
 #include <time.h>
 #include <utils/Log.h>
+#undef ALOGV
+#define ALOGV(a...) do { } while (0)
 #include <utils/Trace.h>
 #include <system/audio.h>
 #ifdef FAST_MIXER_STATISTICS
@@ -93,6 +95,8 @@ bool FastMixer::threadLoop()
     uint32_t warmupCycles = 0;  // counter of number of loop cycles required to warmup
     NBAIO_Sink* teeSink = NULL; // if non-NULL, then duplicate write() to this non-blocking sink
     NBLog::Writer dummyLogWriter, *logWriter = &dummyLogWriter;
+    bool myEnabled[FastMixerState::kMaxFastTracks];
+    memset(myEnabled, 0, sizeof(myEnabled));
 
     for (;;) {
 
@@ -120,12 +124,16 @@ bool FastMixer::threadLoop()
         FastMixerState::Command command = next->mCommand;
         if (next != current) {
 
+            logWriter->logTimestamp();
             logWriter->log("next != current");
 
             // As soon as possible of learning of a new dump area, start using it
             dumpState = next->mDumpState != NULL ? next->mDumpState : &dummyDumpState;
             teeSink = next->mTeeSink;
             logWriter = next->mNBLogWriter != NULL ? next->mNBLogWriter : &dummyLogWriter;
+            if (mixer != NULL) {
+                mixer->setLog(logWriter);
+            }
 
             // We want to always have a valid reference to the previous (non-idle) state.
             // However, the state queue only guarantees access to current and previous states.
@@ -300,13 +308,21 @@ bool FastMixer::threadLoop()
                     addedTracks &= ~(1 << i);
                     const FastTrack* fastTrack = &current->mFastTracks[i];
                     AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
+                    logWriter->logf("bp %d i=%d %p", __LINE__, i, bufferProvider);
                     ALOG_ASSERT(bufferProvider != NULL && fastTrackNames[i] == -1);
+                    if (bufferProvider == NULL ||
+                            bufferProvider->getValid() != AudioBufferProvider::kValid) {
+                        logWriter->logTimestamp();
+                        logWriter->logf("added invalid %#x", i);
+                    }
                     if (mixer != NULL) {
                         // calling getTrackName with default channel mask and a random invalid
                         //   sessionId (no effects here)
                         name = mixer->getTrackName(AUDIO_CHANNEL_OUT_STEREO, -555);
                         ALOG_ASSERT(name >= 0);
                         fastTrackNames[i] = name;
+                        mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::FAST_INDEX,
+                                (void *) i);
                         mixer->setBufferProvider(name, bufferProvider);
                         mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::MAIN_BUFFER,
                                 (void *) mixBuffer);
@@ -317,27 +333,41 @@ bool FastMixer::threadLoop()
                         }
                         mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,
                                 (void *) fastTrack->mChannelMask);
+                        if (!mixer->enabled(name)) {
+                            logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);
+                        }
                         mixer->enable(name);
+                        myEnabled[i] = true;
                     }
                     generations[i] = fastTrack->mGeneration;
                 }
 
-                // finally process modified tracks; these use the same slot
+                // finally process (potentially) modified tracks; these use the same slot
                 // but may have a different buffer provider or volume provider
                 unsigned modifiedTracks = currentTrackMask & previousTrackMask;
                 if (modifiedTracks) {
-                    logWriter->logf("modified %#x", modifiedTracks);
+                    logWriter->logf("pot. mod. %#x", modifiedTracks);
                 }
+                unsigned actuallyModifiedTracks = 0;
                 while (modifiedTracks != 0) {
                     i = __builtin_ctz(modifiedTracks);
                     modifiedTracks &= ~(1 << i);
                     const FastTrack* fastTrack = &current->mFastTracks[i];
                     if (fastTrack->mGeneration != generations[i]) {
+                        actuallyModifiedTracks |= 1 << i;
                         AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
+                        logWriter->logf("bp %d i=%d %p", __LINE__, i, bufferProvider);
                         ALOG_ASSERT(bufferProvider != NULL);
+                        if (bufferProvider == NULL ||
+                                bufferProvider->getValid() != AudioBufferProvider::kValid) {
+                            logWriter->logTimestamp();
+                            logWriter->logf("modified invalid %#x", i);
+                        }
                         if (mixer != NULL) {
                             name = fastTrackNames[i];
                             ALOG_ASSERT(name >= 0);
+                            mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::FAST_INDEX,
+                                    (void *) i);
                             mixer->setBufferProvider(name, bufferProvider);
                             if (fastTrack->mVolumeProvider == NULL) {
                                 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,
@@ -360,6 +390,9 @@ bool FastMixer::threadLoop()
                         generations[i] = fastTrack->mGeneration;
                     }
                 }
+                if (actuallyModifiedTracks) {
+                    logWriter->logf("act. mod. %#x", actuallyModifiedTracks);
+                }
 
                 fastTracksGen = current->mFastTracksGen;
 
@@ -377,6 +410,7 @@ bool FastMixer::threadLoop()
             ALOG_ASSERT(mixBuffer != NULL);
             // for each track, update volume and check for underrun
             unsigned currentTrackMask = current->mTrackMask;
+            logWriter->logf("ctm %#x", currentTrackMask);
             while (currentTrackMask != 0) {
                 i = __builtin_ctz(currentTrackMask);
                 currentTrackMask &= ~(1 << i);
@@ -410,25 +444,76 @@ bool FastMixer::threadLoop()
                         underruns.mBitFields.mEmpty++;
                         underruns.mBitFields.mMostRecent = UNDERRUN_EMPTY;
                         mixer->disable(name);
+                        myEnabled[i] = false;
                     } else {
                         // allow mixing partial buffer
                         underruns.mBitFields.mPartial++;
                         underruns.mBitFields.mMostRecent = UNDERRUN_PARTIAL;
+                        if (!mixer->enabled(name)) {
+                            logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);
+                        }
                         mixer->enable(name);
+                        myEnabled[i] = true;
                     }
                 } else {
                     underruns.mBitFields.mFull++;
                     underruns.mBitFields.mMostRecent = UNDERRUN_FULL;
+                    if (!mixer->enabled(name)) {
+                        logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);
+                    }
                     mixer->enable(name);
+                    myEnabled[i] = true;
                 }
                 ftDump->mUnderruns = underruns;
                 ftDump->mFramesReady = framesReady;
+                AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
+                if (bufferProvider == NULL ||
+                        bufferProvider->getValid() != AudioBufferProvider::kValid) {
+                    logWriter->logTimestamp();
+                    logWriter->logf("mixing invalid %#x", i);
+                }
             }
 
             int64_t pts;
             if (outputSink == NULL || (OK != outputSink->getNextWriteTimestamp(&pts)))
                 pts = AudioBufferProvider::kInvalidPTS;
 
+            // validate that mixer state is correct
+            currentTrackMask = current->mTrackMask;
+            unsigned expectedMixerEnabled = 0;
+            while (currentTrackMask != 0) {
+                i = __builtin_ctz(currentTrackMask);
+                currentTrackMask &= ~(1 << i);
+                const FastTrack* fastTrack = &current->mFastTracks[i];
+                int name = fastTrackNames[i];
+                ALOG_ASSERT(name >= 0);
+                bool isEnabled = mixer->enabled(name);
+                if (isEnabled != myEnabled[i]) {
+                    logWriter->logTimestamp();
+                    logWriter->logf("? i=%d name=%d mixena=%d ftena=%d", i, name, isEnabled,
+                            myEnabled[i]);
+                }
+                if (myEnabled[i]) {
+                    expectedMixerEnabled |= 1 << name;
+                }
+                AudioBufferProvider *abp = mixer->getBufferProvider(name);
+                if (abp != fastTrack->mBufferProvider) {
+                    logWriter->logTimestamp();
+                    logWriter->logf("? i=%d name=%d mixbp=%p ftbp=%p", i, name, abp,
+                            fastTrack->mBufferProvider);
+                }
+                int fastIndex = mixer->getFastIndex(name);
+                if (fastIndex != (int) i) {
+                    logWriter->logTimestamp();
+                    logWriter->logf("? i=%d name=%d fastIndex=%d", i, name, fastIndex);
+                }
+            }
+            unsigned mixerEnabled = mixer->enabledTrackNames();
+            if (mixerEnabled != expectedMixerEnabled) {
+                logWriter->logTimestamp();
+                logWriter->logf("? mixena=%#x expected=%#x", mixerEnabled, expectedMixerEnabled);
+            }
+
             // process() is CPU-bound
             mixer->process(pts);
             mixBufferState = MIXED;
@@ -453,7 +538,7 @@ bool FastMixer::threadLoop()
             ATRACE_END();
             dumpState->mWriteSequence++;
             if (framesWritten >= 0) {
-                ALOG_ASSERT(framesWritten <= frameCount);
+                ALOG_ASSERT((size_t) framesWritten <= frameCount);
                 dumpState->mFramesWritten += framesWritten;
                 //if ((size_t) framesWritten == frameCount) {
                 //    didFullWrite = true;