Fix bugs in BufferQueue automated test and related

Fix test bugs:
Clean up the player, mixer, and the engine (must be done in that order).
Re-enable 2 more tests; all 9 tests pass now.

Fix engine bugs:
IObject now has a de-init hook, which cleans up condition variable and mutex.
Run the de-initializers in reverse order so that IObject de-init hook is run last.
Replace the dedicated mEngine.mShutdownCond by the shared IObject condition variable.
Forgot to iniitalize mShtudownAck.
Unlocking the object mutex during CEngine_Destroy was bogus.

Miscellaneous logging and debugging improvements:
Track the source code location of the most recent mutex unlock.
Add more trace log options for detailed leave reasons.
Improve performance of trace log when disabled.
Turn on assert checking.
Check return value of pthread_cond_destroy and pthread_mutex_destroy.
Add comment.
Line length 100.

Change-Id: I23b7b495d439894b2fd31295a38cb73ef7b6be2e

libopensles/Android.mk

@@ -26,7 +26,7 @@ include $(BUILD_STATIC_LIBRARY)
 include $(CLEAR_VARS)
 
 LOCAL_CFLAGS += -DUSE_BASE -DUSE_GAME -DUSE_MUSIC -DUSE_PHONE -DUSE_OPTIONAL \
--DUSE_TRACE -DUSE_DEBUG
+-DUSE_TRACE -DUSE_DEBUG -UNDEBUG
 
 LOCAL_SRC_FILES:=                     \
         OpenSLES_IID.c                \

libopensles/CEngine.c

@@ -59,9 +59,9 @@ void CEngine_Destroy(void *self)
         delete [] this->mEngine.mEqPresetNames;
     }
 #endif
-    while (!this->mEngine.mShutdownAck)
-        pthread_cond_wait(&this->mEngine.mShutdownCond, &this->mObject.mMutex);
-    object_unlock_exclusive(&this->mObject);
+    while (!this->mEngine.mShutdownAck) {
+        object_cond_wait(&this->mObject);
+    }
     (void) pthread_join(this->mSyncThread, (void **) NULL);
     ThreadPool_deinit(&this->mEngine.mThreadPool);
 

libopensles/IEngine.c

@@ -662,9 +662,7 @@ void IEngine_init(void *self)
     for (i = 0; i < MAX_INSTANCE; ++i)
         this->mInstances[i] = NULL;
     this->mShutdown = SL_BOOLEAN_FALSE;
-    int ok;
-    ok = pthread_cond_init(&this->mShutdownCond, (const pthread_condattr_t *) NULL);
-    assert(0 == ok);
+    this->mShutdownAck = SL_BOOLEAN_FALSE;
 #if defined(ANDROID) && !defined(USE_BACKPORT)
     this->mEqNumPresets = 0;
     this->mEqPresetNames = NULL;

libopensles/IEqualizer.c

@@ -438,8 +438,6 @@ static SLresult IEqualizer_GetPresetName(SLEqualizerItf self, SLuint16 index, co
         if (index >= this->mThis->mEngine->mEqNumPresets) {
             result = SL_RESULT_PARAMETER_INVALID;
         } else {
-            // FIXME This gives the application access to the library memory space and is
-            //  identified as a security issue. This is being addressed by the OpenSL ES WG
             *ppName = (SLchar *) this->mThis->mEngine->mEqPresetNames[index];
             result = SL_RESULT_SUCCESS;
         }

libopensles/IObject.c

@@ -427,7 +427,6 @@ static void IObject_Destroy(SLObjectItf self)
     Abort_internal(this, SL_BOOLEAN_TRUE);
     const ClassTable *class__ = this->mClass;
     VoidHook destroy = class__->mDestroy;
-    const struct iid_vtable *x = class__->mInterfaces;
     // const, no lock needed
     IEngine *thisEngine = this->mEngine;
     unsigned i = this->mInstanceID;
@@ -455,11 +454,15 @@ static void IObject_Destroy(SLObjectItf self)
         (*destroy)(this);
     // Call the deinitializer for each currently exposed interface,
     // whether it is implicit, explicit, optional, or dynamically added.
+    // The deinitializers are called in the reverse order that the
+    // initializers were called, so that IObject_deinit is called last.
     unsigned incorrect = 0;
-    SLuint8 *interfaceStateP = this->mInterfaceStates;
-    unsigned index;
-    for (index = 0; index < class__->mInterfaceCount; ++index, ++x, ++interfaceStateP) {
-        SLuint32 state = *interfaceStateP;
+    unsigned index = class__->mInterfaceCount;
+    const struct iid_vtable *x = &class__->mInterfaces[index];
+    SLuint8 *interfaceStateP = &this->mInterfaceStates[index];
+    for ( ; index > 0; --index) {
+        --x;
+        SLuint32 state = *--interfaceStateP;
         switch (state) {
         case INTERFACE_UNINITIALIZED:
             break;
@@ -487,8 +490,7 @@ static void IObject_Destroy(SLObjectItf self)
             break;
         }
     }
-    // redundant: this->mState = SL_OBJECT_STATE_UNREALIZED;
-    object_unlock_exclusive(this);
+    // The mutex is unlocked and destroyed by IObject_deinit, which is the last deinitializer
 #ifdef USE_DEBUG
     memset(this, 0x55, class__->mSize);
 #endif
@@ -601,6 +603,9 @@ static const struct SLObjectItf_ IObject_Itf = {
     IObject_SetLossOfControlInterfaces,
 };
 
+
+/** \brief This must be the first initializer called for an object */
+
 void IObject_init(void *self)
 {
     IObject *this = (IObject *) self;
@@ -631,3 +636,23 @@ void IObject_init(void *self)
     ok = pthread_cond_init(&this->mCond, (const pthread_condattr_t *) NULL);
     assert(0 == ok);
 }
+
+
+/** \brief This must be the last deinitializer called for an object */
+
+void IObject_deinit(void *self)
+{
+    IObject *this = (IObject *) self;
+#ifdef USE_DEBUG
+    assert(pthread_equal(pthread_self(), this->mOwner));
+#endif
+    int ok;
+    ok = pthread_cond_destroy(&this->mCond);
+    assert(0 == ok);
+    // equivalent to object_unlock_exclusive, but without the rigmarole
+    ok = pthread_mutex_unlock(&this->mMutex);
+    assert(0 == ok);
+    ok = pthread_mutex_destroy(&this->mMutex);
+    assert(0 == ok);
+    // redundant: this->mState = SL_OBJECT_STATE_UNREALIZED;
+}

libopensles/MPH_to.c

@@ -26,6 +26,9 @@
 // Important note: if you add any interfaces here, be sure to also
 // update the #define for the corresponding INTERFACES_<Class>.
 
+// IObject is the first interface in a class, so the index for MPH_OBJECT must be zero.
+// Don't cross streams, otherwise bad things happen.
+
 const signed char MPH_to_3DGroup[MPH_MAX] = {
 #ifdef USE_DESIGNATED_INITIALIZERS
     [0 ... MPH_MAX-1] = -1,

libopensles/ThreadPool.c

@@ -134,10 +134,11 @@ fail:
 
 static void ThreadPool_deinit_internal(ThreadPool *tp, unsigned initialized, unsigned nThreads)
 {
+    int ok;
+
     assert(NULL != tp);
     // Destroy all threads
     if (0 < nThreads) {
-        int ok;
         assert(INITIALIZED_ALL == initialized);
         ok = pthread_mutex_lock(&tp->mMutex);
         assert(0 == ok);
@@ -179,12 +180,18 @@ static void ThreadPool_deinit_internal(ThreadPool *tp, unsigned initialized, uns
     }
 
     // destroy the mutex and condition variables
-    if (initialized & INITIALIZED_CONDNOTEMPTY)
-        (void) pthread_cond_destroy(&tp->mCondNotEmpty);
-    if (initialized & INITIALIZED_CONDNOTFULL)
-        (void) pthread_cond_destroy(&tp->mCondNotFull);
-    if (initialized & INITIALIZED_MUTEX)
-        (void) pthread_mutex_destroy(&tp->mMutex);
+    if (initialized & INITIALIZED_CONDNOTEMPTY) {
+        ok = pthread_cond_destroy(&tp->mCondNotEmpty);
+        assert(0 == ok);
+    }
+    if (initialized & INITIALIZED_CONDNOTFULL) {
+        ok = pthread_cond_destroy(&tp->mCondNotFull);
+        assert(0 == ok);
+    }
+    if (initialized & INITIALIZED_MUTEX) {
+        ok = pthread_mutex_destroy(&tp->mMutex);
+        assert(0 == ok);
+    }
     tp->mInitialized = INITIALIZED_NONE;
 
     // release the closure circular buffer

libopensles/locks.c

@@ -55,8 +55,6 @@ void object_lock_exclusive_(IObject *this, const char *file, int line)
         }
         assert(false);
     }
-    assert(NULL == this->mFile);
-    assert(0 == this->mLine);
     this->mOwner = pthread_self();
     this->mFile = file;
     this->mLine = line;
@@ -73,25 +71,37 @@ void object_lock_exclusive(IObject *this)
 
 /* Exclusively unlock an object and do not report any updates */
 
-void object_unlock_exclusive(IObject *this)
-{
 #ifdef USE_DEBUG
+void object_unlock_exclusive_(IObject *this, const char *file, int line)
+{
     assert(pthread_equal(pthread_self(), this->mOwner));
     assert(NULL != this->mFile);
     assert(0 != this->mLine);
     memset(&this->mOwner, 0, sizeof(pthread_t));
-    this->mFile = NULL;
-    this->mLine = 0;
-#endif
+    this->mFile = file;
+    this->mLine = line;
     int ok;
     ok = pthread_mutex_unlock(&this->mMutex);
     assert(0 == ok);
 }
+#else
+void object_unlock_exclusive(IObject *this)
+{
+    int ok;
+    ok = pthread_mutex_unlock(&this->mMutex);
+    assert(0 == ok);
+}
+#endif
 
 
 /* Exclusively unlock an object and report updates to the specified bit-mask of attributes */
 
+#ifdef USE_DEBUG
+void object_unlock_exclusive_attributes_(IObject *this, unsigned attributes,
+    const char *file, int line)
+#else
 void object_unlock_exclusive_attributes(IObject *this, unsigned attributes)
+#endif
 {
 
 #ifdef USE_DEBUG
@@ -188,8 +198,8 @@ void object_unlock_exclusive_attributes(IObject *this, unsigned attributes)
     }
 #ifdef USE_DEBUG
     memset(&this->mOwner, 0, sizeof(pthread_t));
-    this->mFile = NULL;
-    this->mLine = 0;
+    this->mFile = file;
+    this->mLine = line;
 #endif
     ok = pthread_mutex_unlock(&this->mMutex);
     assert(0 == ok);
@@ -212,8 +222,8 @@ void object_cond_wait_(IObject *this, const char *file, int line)
     assert(NULL != this->mFile);
     assert(0 != this->mLine);
     memset(&this->mOwner, 0, sizeof(pthread_t));
-    this->mFile = NULL;
-    this->mLine = 0;
+    this->mFile = file;
+    this->mLine = line;
     // alas we don't know the new owner's identity
     int ok;
     ok = pthread_cond_wait(&this->mCond, &this->mMutex);

libopensles/locks.h

@@ -18,18 +18,24 @@
 
 #ifdef USE_DEBUG
 extern void object_lock_exclusive_(IObject *this, const char *file, int line);
+extern void object_unlock_exclusive_(IObject *this, const char *file, int line);
+extern void object_unlock_exclusive_attributes_(IObject *this, unsigned attr,
+    const char *file, int line);
 extern void object_cond_wait_(IObject *this, const char *file, int line);
 #else
 extern void object_lock_exclusive(IObject *this);
-extern void object_cond_wait(IObject *this);
-#endif
 extern void object_unlock_exclusive(IObject *this);
 extern void object_unlock_exclusive_attributes(IObject *this, unsigned attr);
+extern void object_cond_wait(IObject *this);
+#endif
 extern void object_cond_signal(IObject *this);
 extern void object_cond_broadcast(IObject *this);
 
 #ifdef USE_DEBUG
 #define object_lock_exclusive(this) object_lock_exclusive_((this), __FILE__, __LINE__)
+#define object_unlock_exclusive(this) object_unlock_exclusive_((this), __FILE__, __LINE__)
+#define object_unlock_exclusive_attributes(this, attr) \
+    object_unlock_exclusive_attributes_((this), (attr), __FILE__, __LINE__)
 #define object_cond_wait(this) object_cond_wait_((this), __FILE__, __LINE__)
 #endif
 

libopensles/sles.c

@@ -678,6 +678,8 @@ extern void IAndroidAudioEffect_init(void *);
 extern void
     IOutputMixExt_init(void *);
 #endif
+extern void
+    IObject_deinit(void *);
 
 
 /*static*/ const struct MPH_init MPH_init_table[MPH_MAX] = {
@@ -710,7 +712,7 @@ extern void
     { /* MPH_MIDIMUTESOLO, */ IMIDIMuteSolo_init, NULL, NULL },
     { /* MPH_MUTESOLO, */ IMuteSolo_init, NULL, NULL },
     { /* MPH_NULL, */ NULL, NULL, NULL },
-    { /* MPH_OBJECT, */ IObject_init, NULL, NULL },
+    { /* MPH_OBJECT, */ IObject_init, NULL, IObject_deinit },
     { /* MPH_OUTPUTMIX, */ IOutputMix_init, NULL, NULL },
     { /* MPH_PITCH, */ IPitch_init, NULL, NULL },
     { /* MPH_PLAY, */ IPlay_init, NULL, NULL },

libopensles/sles_allinclusive.h

@@ -536,7 +536,6 @@ typedef struct Engine_interface {
     IObject *mInstances[MAX_INSTANCE];
     SLboolean mShutdown;
     SLboolean mShutdownAck;
-    pthread_cond_t mShutdownCond;
     ThreadPool mThreadPool; // for asynchronous operations
 #if defined(ANDROID) && !defined(USE_BACKPORT)
     SLuint32 mEqNumPresets;
@@ -1200,6 +1199,10 @@ extern void slTraceSetEnabled(unsigned enabled);
 #define SL_TRACE_ENTER          0x1
 #define SL_TRACE_LEAVE_FAILURE  0x2
 #define SL_TRACE_LEAVE_VOID     0x4
+#define SL_TRACE_LEAVE_SUCCESS  0x8
+#define SL_TRACE_LEAVE          (SL_TRACE_LEAVE_FAILURE | SL_TRACE_LEAVE_VOID | \
+                                    SL_TRACE_LEAVE_SUCCESS)
+#define SL_TRACE_ALL            (SL_TRACE_ENTER | SL_TRACE_LEAVE)
 #define SL_TRACE_DEFAULT        (SL_TRACE_LEAVE_FAILURE)
 
 #ifndef USE_TRACE

libopensles/sync.c

@@ -35,7 +35,8 @@ void *sync_start(void *arg)
         object_lock_exclusive(&this->mObject);
         if (this->mEngine.mShutdown) {
             this->mEngine.mShutdownAck = SL_BOOLEAN_TRUE;
-            pthread_cond_signal(&this->mEngine.mShutdownCond);
+            // broadcast not signal, because this condition is also used for other purposes
+            object_cond_broadcast(&this->mObject);
             object_unlock_exclusive(&this->mObject);
             break;
         }

libopensles/trace.c

@@ -31,37 +31,50 @@
 // This should be the only global variable
 static unsigned slTraceEnabled = SL_TRACE_DEFAULT;
 
+
 void slTraceSetEnabled(unsigned enabled)
 {
     slTraceEnabled = enabled;
 }
 
+
 void slTraceEnterGlobal(const char *function)
 {
     if (SL_TRACE_ENTER & slTraceEnabled)
         LOGV("Entering %s\n", function);
 }
 
+
 void slTraceLeaveGlobal(const char *function, SLresult result)
 {
-    if ((SL_RESULT_SUCCESS != result) && (SL_TRACE_LEAVE_FAILURE & slTraceEnabled)) {
-        if (SLESUT_RESULT_MAX > result)
-            LOGV("Leaving %s (%s)\n", function, slesutResultStrings[result]);
-        else
-            LOGV("Leaving %s (0x%X)\n", function, (unsigned) result);
+    if (SL_RESULT_SUCCESS == result) {
+        if (SL_TRACE_LEAVE_SUCCESS & slTraceEnabled) {
+            LOGV("Leaving %s\n", function);
+        }
+    } else {
+        if (SL_TRACE_LEAVE_FAILURE & slTraceEnabled) {
+            if (SLESUT_RESULT_MAX > result)
+                LOGE("Leaving %s (%s)\n", function, slesutResultStrings[result]);
+            else
+                LOGE("Leaving %s (0x%X)\n", function, (unsigned) result);
+        }
     }
 }
 
+
 void slTraceEnterInterface(const char *function)
 {
+    if (!(SL_TRACE_ENTER & slTraceEnabled))
+        return;
     if (*function == 'I')
         ++function;
     const char *underscore = function;
     while (*underscore != '\0') {
         if (*underscore == '_') {
-            if ((strcmp(function, "BufferQueue_Enqueue") && strcmp(function, "BufferQueue_GetState")
-                && strcmp(function, "OutputMixExt_FillBuffer")) &&
-                (SL_TRACE_ENTER & slTraceEnabled)) {
+            if (/*(strcmp(function, "BufferQueue_Enqueue") &&
+                strcmp(function, "BufferQueue_GetState") &&
+                strcmp(function, "OutputMixExt_FillBuffer")) &&*/
+                true) {
                 LOGV("Entering %.*s::%s\n", (int) (underscore - function), function,
                     &underscore[1]);
             }
@@ -69,17 +82,32 @@ void slTraceEnterInterface(const char *function)
         }
         ++underscore;
     }
-    if (SL_TRACE_ENTER & slTraceEnabled)
-        LOGV("Entering %s\n", function);
+    LOGV("Entering %s\n", function);
 }
 
+
 void slTraceLeaveInterface(const char *function, SLresult result)
 {
-    if ((SL_RESULT_SUCCESS != result) && (SL_TRACE_LEAVE_FAILURE & slTraceEnabled)) {
-        if (*function == 'I')
-            ++function;
-        const char *underscore = function;
-        while (*underscore != '\0') {
+    if (!((SL_TRACE_LEAVE_SUCCESS | SL_TRACE_LEAVE_FAILURE) & slTraceEnabled))
+        return;
+    if (*function == 'I')
+        ++function;
+    const char *underscore = function;
+    while (*underscore != '\0') {
+        if (*underscore == '_') {
+            break;
+        }
+        ++underscore;
+    }
+    if (SL_RESULT_SUCCESS == result) {
+        if (SL_TRACE_LEAVE_SUCCESS & slTraceEnabled) {
+            if (*underscore == '_')
+                LOGV("Leaving %.*s::%s\n", (int) (underscore - function), function, &underscore[1]);
+            else
+                LOGV("Leaving %s\n", function);
+        }
+    } else {
+        if (SL_TRACE_LEAVE_FAILURE & slTraceEnabled) {
             if (*underscore == '_') {
                 if (SLESUT_RESULT_MAX > result)
                     LOGE("Leaving %.*s::%s (%s)\n", (int) (underscore - function), function,
@@ -87,23 +115,24 @@ void slTraceLeaveInterface(const char *function, SLresult result)
                 else
                     LOGE("Leaving %.*s::%s (0x%X)\n", (int) (underscore - function), function,
                         &underscore[1], (unsigned) result);
-                return;
+            } else {
+                if (SLESUT_RESULT_MAX > result)
+                    LOGE("Leaving %s (%s)\n", function, slesutResultStrings[result]);
+                else
+                    LOGE("Leaving %s (0x%X)\n", function, (unsigned) result);
             }
-            ++underscore;
         }
-        if (SLESUT_RESULT_MAX > result)
-            LOGE("Leaving %s (%s)\n", function, slesutResultStrings[result]);
-        else
-            LOGE("Leaving %s (0x%X)\n", function, (unsigned) result);
     }
 }
 
+
 void slTraceEnterInterfaceVoid(const char *function)
 {
     if (SL_TRACE_ENTER & slTraceEnabled)
         slTraceEnterInterface(function);
 }
 
+
 void slTraceLeaveInterfaceVoid(const char *function)
 {
     if (SL_TRACE_LEAVE_VOID & slTraceEnabled)

tests/automated/BufferQueue_test.cpp

@@ -134,15 +134,18 @@ protected:
     }
 
     virtual void TearDown() {
-        /* Clean up the engine, player and the mixer*/
-        if (*outputmixObject){
+        /* Clean up the player, mixer, and the engine (must be done in that order) */
+        if (playerObject){
+            (*playerObject)->Destroy(playerObject);
+            playerObject = NULL;
+        }
+        if (outputmixObject){
             (*outputmixObject)->Destroy(outputmixObject);
+            outputmixObject = NULL;
         }
-        if (*engineObject){
+        if (engineObject){
             (*engineObject)->Destroy(engineObject);
-        }
-        if (*playerObject){
-            (*playerObject)->Destroy(playerObject);
+            engineObject = NULL;
         }
     }
 
@@ -154,13 +157,13 @@ protected:
         SLInterfaceID ids[1] = { SL_IID_BUFFERQUEUE };
         SLboolean flags[1] = { SL_BOOLEAN_TRUE };
 
-        static const SLuint32 invalidNumBuffers[] = { 0, 0xFFFFFFFF, 0x80000000, 0x10002, 0x102, 0x101,
-                0x100 };
+        static const SLuint32 invalidNumBuffers[] = { 0, 0xFFFFFFFF, 0x80000000, 0x10002, 0x102,
+                0x101, 0x100 };
         for (i = 0; i < sizeof(invalidNumBuffers) / sizeof(invalidNumBuffers[0]); ++i) {
             locator_bufferqueue.numBuffers = invalidNumBuffers[i];
             LOGV("allocation buffer\n");
-            SLresult result = (*engineEngine)->CreateAudioPlayer(engineEngine, &playerObject, &audiosrc,
-                                                                         &audiosnk, 1, ids, flags);
+            SLresult result = (*engineEngine)->CreateAudioPlayer(engineEngine, &playerObject,
+                                                            &audiosrc, &audiosnk, 1, ids, flags);
             ASSERT_EQ(SL_RESULT_PARAMETER_INVALID, result);
         }
     }
@@ -171,8 +174,8 @@ protected:
         SLboolean flags2[1] = { SL_BOOLEAN_TRUE };
 
         locator_bufferqueue.numBuffers = validNumBuffers[numbuffer];
-        res = (*engineEngine)->CreateAudioPlayer(engineEngine, &playerObject, &audiosrc, &audiosnk, 1,
-                                                 ids2, flags2);
+        res = (*engineEngine)->CreateAudioPlayer(engineEngine, &playerObject, &audiosrc, &audiosnk,
+                                                1, ids2, flags2);
         CheckErr(res);
         res = (*playerObject)->Realize(playerObject, SL_BOOLEAN_FALSE);
         CheckErr(res);
@@ -254,7 +257,8 @@ protected:
 
     void PlayBufferQueue() {
         // enqueue a buffer
-        res = (*playerBufferQueue)->Enqueue(playerBufferQueue, stereoBuffer1, sizeof(stereoBuffer1));
+        res = (*playerBufferQueue)->Enqueue(playerBufferQueue, stereoBuffer1,
+            sizeof(stereoBuffer1));
         CheckErr(res);
         // set play state to playing
         res = (*playerPlay)->SetPlayState(playerPlay, SL_PLAYSTATE_PLAYING);
@@ -285,12 +289,11 @@ protected:
         LOGV("TestEnd");
     }
 };
-/*
+
 TEST_F(TestBufferQueue, testInvalidBuffer){
      LOGV("Test Fixture: InvalidBuffer\n");
      InvalidBuffer();
- }
-*/
+}
 
 TEST_F(TestBufferQueue, testValidBuffer) {
     PrepareValidBuffer(1);
@@ -366,12 +369,11 @@ TEST_F(TestBufferQueue, testStateTransitionNonEmptyQueue) {
     }
 }
 
-/*
 TEST_F(TestBufferQueue, testStatePlayBuffer){
      PrepareValidBuffer(8);
      PlayBufferQueue();
- }
-*/
+}
+
 int main(int argc, char **argv) {
     testing::InitGoogleTest(&argc, argv);
     return RUN_ALL_TESTS();