aaudio: improve logging to help debugging

Use __func__ more often.
Show thread entry and exit.
Log illegal state transitions.
Remove some unnecessary logs.

Bug: 64310586
Test: use AAudio then look at the logs
Change-Id: I2e289698efc897640588ba534b5513ac39b15043
diff --git a/media/libaaudio/src/client/AudioStreamInternal.cpp b/media/libaaudio/src/client/AudioStreamInternal.cpp
index 6b25302..2a3e668 100644
--- a/media/libaaudio/src/client/AudioStreamInternal.cpp
+++ b/media/libaaudio/src/client/AudioStreamInternal.cpp
@@ -67,8 +67,6 @@
         , mWakeupDelayNanos(AAudioProperty_getWakeupDelayMicros() * AAUDIO_NANOS_PER_MICROSECOND)
         , mMinimumSleepNanos(AAudioProperty_getMinimumSleepMicros() * AAUDIO_NANOS_PER_MICROSECOND)
         {
-    ALOGD("%s - mWakeupDelayNanos = %d, mMinimumSleepNanos = %d",
-          __func__, mWakeupDelayNanos, mMinimumSleepNanos);
 }
 
 AudioStreamInternal::~AudioStreamInternal() {
@@ -231,8 +229,7 @@
 
 aaudio_result_t AudioStreamInternal::close() {
     aaudio_result_t result = AAUDIO_OK;
-    ALOGD("close(): mServiceStreamHandle = 0x%08X",
-             mServiceStreamHandle);
+    ALOGD("%s(): mServiceStreamHandle = 0x%08X", __func__, mServiceStreamHandle);
     if (mServiceStreamHandle != AAUDIO_HANDLE_INVALID) {
         // Don't close a stream while it is running.
         aaudio_stream_state_t currentState = getState();
@@ -243,8 +240,8 @@
             result = waitForStateChange(currentState, &nextState,
                                                        timeoutNanoseconds);
             if (result != AAUDIO_OK) {
-                ALOGE("close() waitForStateChange() returned %d %s",
-                result, AAudio_convertResultToText(result));
+                ALOGE("%s() waitForStateChange() returned %d %s",
+                __func__, result, AAudio_convertResultToText(result));
             }
         }
         setState(AAUDIO_STREAM_STATE_CLOSING);
diff --git a/media/libaaudio/src/client/AudioStreamInternalPlay.cpp b/media/libaaudio/src/client/AudioStreamInternalPlay.cpp
index 11b43c3..0c3b1fa 100644
--- a/media/libaaudio/src/client/AudioStreamInternalPlay.cpp
+++ b/media/libaaudio/src/client/AudioStreamInternalPlay.cpp
@@ -57,8 +57,7 @@
         return result;
     }
     if (mServiceStreamHandle == AAUDIO_HANDLE_INVALID) {
-        ALOGE("requestPauseInternal() mServiceStreamHandle invalid = 0x%08X",
-              mServiceStreamHandle);
+        ALOGE("%s() mServiceStreamHandle invalid", __func__);
         return AAUDIO_ERROR_INVALID_STATE;
     }
 
@@ -70,8 +69,7 @@
 
 aaudio_result_t AudioStreamInternalPlay::requestFlush() {
     if (mServiceStreamHandle == AAUDIO_HANDLE_INVALID) {
-        ALOGE("AudioStreamInternal::requestFlush() mServiceStreamHandle invalid = 0x%08X",
-              mServiceStreamHandle);
+        ALOGE("%s() mServiceStreamHandle invalid", __func__);
         return AAUDIO_ERROR_INVALID_STATE;
     }
 
@@ -86,7 +84,7 @@
     // Bump offset so caller does not see the retrograde motion in getFramesRead().
     int64_t offset = writeCounter - readCounter;
     mFramesOffsetFromService += offset;
-    ALOGD("advanceClientToMatchServerPosition() readN = %lld, writeN = %lld, offset = %lld",
+    ALOGV("%s() readN = %lld, writeN = %lld, offset = %lld", __func__,
           (long long)readCounter, (long long)writeCounter, (long long)mFramesOffsetFromService);
 
     // Force writeCounter to match readCounter.
@@ -100,9 +98,7 @@
 
 // Write the data, block if needed and timeoutMillis > 0
 aaudio_result_t AudioStreamInternalPlay::write(const void *buffer, int32_t numFrames,
-                                           int64_t timeoutNanoseconds)
-
-{
+                                               int64_t timeoutNanoseconds) {
     return processData((void *)buffer, numFrames, timeoutNanoseconds);
 }
 
@@ -121,7 +117,7 @@
         // Still haven't got any timestamps from server.
         // Keep waiting until we get some valid timestamps then start writing to the
         // current buffer position.
-        ALOGD("processDataNow() wait for valid timestamps");
+        ALOGD("%s() wait for valid timestamps", __func__);
         // Sleep very briefly and hope we get a timestamp soon.
         *wakeTimePtr = currentNanoTime + (2000 * AAUDIO_NANOS_PER_MICROSECOND);
         ATRACE_END();
@@ -203,8 +199,6 @@
 
 aaudio_result_t AudioStreamInternalPlay::writeNowWithConversion(const void *buffer,
                                                             int32_t numFrames) {
-    // ALOGD("AudioStreamInternal::writeNowWithConversion(%p, %d)",
-    //              buffer, numFrames);
     WrappingBuffer wrappingBuffer;
     uint8_t *byteBuffer = (uint8_t *) buffer;
     int32_t framesLeft = numFrames;
@@ -249,7 +243,6 @@
     int32_t framesWritten = numFrames - framesLeft;
     mAudioEndpoint.advanceWriteIndex(framesWritten);
 
-    // ALOGD("AudioStreamInternal::writeNowWithConversion() returns %d", framesWritten);
     return framesWritten;
 }
 
@@ -268,7 +261,6 @@
     } else {
         mLastFramesRead = framesRead;
     }
-    //ALOGD("AudioStreamInternalPlay::getFramesRead() returns %lld", (long long)framesRead);
     return framesRead;
 }
 
@@ -276,13 +268,13 @@
 {
     int64_t framesWritten = mAudioEndpoint.getDataWriteCounter()
                                + mFramesOffsetFromService;
-    //ALOGD("AudioStreamInternalPlay::getFramesWritten() returns %lld", (long long)framesWritten);
     return framesWritten;
 }
 
 
 // Render audio in the application callback and then write the data to the stream.
 void *AudioStreamInternalPlay::callbackLoop() {
+    ALOGD("%s() entering >>>>>>>>>>>>>>>", __func__);
     aaudio_result_t result = AAUDIO_OK;
     aaudio_data_callback_result_t callbackResult = AAUDIO_CALLBACK_RESULT_CONTINUE;
     if (!isDataCallbackSet()) return NULL;
@@ -297,7 +289,6 @@
             // Write audio data to stream. This is a BLOCKING WRITE!
             result = write(mCallbackBuffer, mCallbackFrames, timeoutNanos);
             if ((result != mCallbackFrames)) {
-                ALOGE("AudioStreamInternalPlay(): callbackLoop: write() returned %d", result);
                 if (result >= 0) {
                     // Only wrote some of the frames requested. Must have timed out.
                     result = AAUDIO_ERROR_TIMEOUT;
@@ -306,13 +297,13 @@
                 break;
             }
         } else if (callbackResult == AAUDIO_CALLBACK_RESULT_STOP) {
-            ALOGD("AudioStreamInternalPlay(): callback returned AAUDIO_CALLBACK_RESULT_STOP");
+            ALOGV("%s(): callback returned AAUDIO_CALLBACK_RESULT_STOP", __func__);
             break;
         }
     }
 
-    ALOGD("AudioStreamInternalPlay(): callbackLoop() exiting, result = %d, isActive() = %d",
-          result, (int) isActive());
+    ALOGD("%s() exiting, result = %d, isActive() = %d <<<<<<<<<<<<<<",
+          __func__, result, (int) isActive());
     return NULL;
 }
 
diff --git a/media/libaaudio/src/core/AudioStream.cpp b/media/libaaudio/src/core/AudioStream.cpp
index c4465fd..61e03db 100644
--- a/media/libaaudio/src/core/AudioStream.cpp
+++ b/media/libaaudio/src/core/AudioStream.cpp
@@ -104,17 +104,17 @@
     mErrorCallbackUserData = builder.getErrorCallbackUserData();
 
     // This is very helpful for debugging in the future. Please leave it in.
-    ALOGI("open() rate = %d, channels = %d, format = %d, sharing = %s, dir = %s",
+    ALOGI("open() rate   = %d, channels    = %d, format   = %d, sharing = %s, dir = %s",
           mSampleRate, mSamplesPerFrame, mFormat,
           AudioStream_convertSharingModeToShortText(mSharingMode),
           (getDirection() == AAUDIO_DIRECTION_OUTPUT) ? "OUTPUT" : "INPUT");
-    ALOGI("open() device = %d, sessionId = %d, perfMode = %d, callback: %s with frames = %d",
+    ALOGI("open() device = %d, sessionId   = %d, perfMode = %d, callback: %s with frames = %d",
           mDeviceId,
           mSessionId,
           mPerformanceMode,
           (isDataCallbackSet() ? "ON" : "OFF"),
           mFramesPerDataCallback);
-    ALOGI("open() usage = %d, contentType = %d, inputPreset = %d",
+    ALOGI("open() usage  = %d, contentType = %d, inputPreset = %d",
           mUsage, mContentType, mInputPreset);
 
     return AAUDIO_OK;
@@ -242,6 +242,22 @@
     return close();
 }
 
+void AudioStream::setState(aaudio_stream_state_t state) {
+    ALOGV("%s(%p) from %d to %d", __func__, this, mState, state);
+    // CLOSED is a final state
+    if (mState == AAUDIO_STREAM_STATE_CLOSED) {
+        ALOGE("%s(%p) tried to set to %d but already CLOSED", __func__, this, state);
+
+    // Once DISCONNECTED, we can only move to CLOSED state.
+    } else if (mState == AAUDIO_STREAM_STATE_DISCONNECTED
+               && state != AAUDIO_STREAM_STATE_CLOSED) {
+        ALOGE("%s(%p) tried to set to %d but already DISCONNECTED", __func__, this, state);
+
+    } else {
+        mState = state;
+    }
+}
+
 aaudio_result_t AudioStream::waitForStateChange(aaudio_stream_state_t currentState,
                                                 aaudio_stream_state_t *nextState,
                                                 int64_t timeoutNanoseconds)
@@ -313,7 +329,9 @@
     setPeriodNanoseconds(periodNanoseconds);
     int err = pthread_create(&mThread, nullptr, AudioStream_internalThreadProc, this);
     if (err != 0) {
-        return AAudioConvert_androidToAAudioResult(-errno);
+        android::status_t status = -errno;
+        ALOGE("createThread() - pthread_create() failed, %d", status);
+        return AAudioConvert_androidToAAudioResult(status);
     } else {
         // TODO Use AAudioThread or maybe AndroidThread
         // Name the thread with an increasing index, "AAudio_#", for debugging.
diff --git a/media/libaaudio/src/core/AudioStream.h b/media/libaaudio/src/core/AudioStream.h
index c0db0f9..5273e36 100644
--- a/media/libaaudio/src/core/AudioStream.h
+++ b/media/libaaudio/src/core/AudioStream.h
@@ -471,16 +471,7 @@
         mFormat = format;
     }
 
-    void setState(aaudio_stream_state_t state) {
-        if (mState == AAUDIO_STREAM_STATE_CLOSED) {
-            ; // CLOSED is a final state
-        } else if (mState == AAUDIO_STREAM_STATE_DISCONNECTED
-                && state != AAUDIO_STREAM_STATE_CLOSED) {
-            ; // Once DISCONNECTED, we can only move to CLOSED state.
-        } else {
-            mState = state;
-        }
-    }
+    void setState(aaudio_stream_state_t state);
 
     void setDeviceId(int32_t deviceId) {
         mDeviceId = deviceId;
diff --git a/services/oboeservice/AAudioEndpointManager.cpp b/services/oboeservice/AAudioEndpointManager.cpp
index 7b8d817..11fd9f6 100644
--- a/services/oboeservice/AAudioEndpointManager.cpp
+++ b/services/oboeservice/AAudioEndpointManager.cpp
@@ -201,14 +201,14 @@
         if (endpoint.get() != nullptr) {
             aaudio_result_t result = endpoint->open(request);
             if (result != AAUDIO_OK) {
-                ALOGE("openSharedEndpoint(), open failed");
+                ALOGE("%s(), open failed", __func__);
                 endpoint.clear();
             } else {
                 mSharedStreams.push_back(endpoint);
             }
         }
-        ALOGD("openSharedEndpoint(), created %p, requested device = %d, dir = %d",
-              endpoint.get(), configuration.getDeviceId(), (int)direction);
+        ALOGD("%s(), created endpoint %p, requested device = %d, dir = %d",
+              __func__, endpoint.get(), configuration.getDeviceId(), (int)direction);
         IPCThreadState::self()->restoreCallingIdentity(token);
     }
 
@@ -244,8 +244,8 @@
                 mExclusiveStreams.end());
 
         serviceEndpoint->close();
-        ALOGD("closeExclusiveEndpoint() %p for device %d",
-              serviceEndpoint.get(), serviceEndpoint->getDeviceId());
+        ALOGD("%s() %p for device %d",
+              __func__, serviceEndpoint.get(), serviceEndpoint->getDeviceId());
     }
 }
 
@@ -266,7 +266,7 @@
                 mSharedStreams.end());
 
         serviceEndpoint->close();
-        ALOGD("closeSharedEndpoint() %p for device %d",
-              serviceEndpoint.get(), serviceEndpoint->getDeviceId());
+        ALOGD("%s() %p for device %d",
+              __func__, serviceEndpoint.get(), serviceEndpoint->getDeviceId());
     }
 }
diff --git a/services/oboeservice/AAudioService.cpp b/services/oboeservice/AAudioService.cpp
index c708fee..ad5bb3a 100644
--- a/services/oboeservice/AAudioService.cpp
+++ b/services/oboeservice/AAudioService.cpp
@@ -165,7 +165,6 @@
 }
 
 aaudio_result_t AAudioService::closeStream(aaudio_handle_t streamHandle) {
-    ALOGD("closeStream(0x%08X)", streamHandle);
     // Check permission and ownership first.
     sp<AAudioServiceStreamBase> serviceStream = convertHandleToServiceStream(streamHandle);
     if (serviceStream.get() == nullptr) {
diff --git a/services/oboeservice/AAudioServiceEndpoint.cpp b/services/oboeservice/AAudioServiceEndpoint.cpp
index 33439fc..96e621a 100644
--- a/services/oboeservice/AAudioServiceEndpoint.cpp
+++ b/services/oboeservice/AAudioServiceEndpoint.cpp
@@ -39,7 +39,7 @@
 using namespace aaudio;   // TODO just import names needed
 
 AAudioServiceEndpoint::~AAudioServiceEndpoint() {
-    ALOGD("AAudioServiceEndpoint::~AAudioServiceEndpoint() destroying endpoint %p", this);
+    ALOGD("%s(%p) destroyed", __func__, this);
 }
 
 std::string AAudioServiceEndpoint::dump() const {
diff --git a/services/oboeservice/AAudioServiceEndpointMMAP.cpp b/services/oboeservice/AAudioServiceEndpointMMAP.cpp
index db01c88..52990da 100644
--- a/services/oboeservice/AAudioServiceEndpointMMAP.cpp
+++ b/services/oboeservice/AAudioServiceEndpointMMAP.cpp
@@ -98,8 +98,8 @@
             .flags = AUDIO_FLAG_LOW_LATENCY,
             .tags = ""
     };
-    ALOGV("open() MMAP attributes.usage = %d, content_type = %d, source = %d",
-          attributes.usage, attributes.content_type, attributes.source);
+    ALOGD("%s(%p) MMAP attributes.usage = %d, content_type = %d, source = %d",
+          __func__, this, attributes.usage, attributes.content_type, attributes.source);
 
     mMmapClient.clientUid = request.getUserId();
     mMmapClient.clientPid = request.getProcessId();
@@ -135,7 +135,7 @@
         mHardwareTimeOffsetNanos = INPUT_ESTIMATED_HARDWARE_OFFSET_NANOS; // frames at ADC earlier
 
     } else {
-        ALOGE("openMmapStream - invalid direction = %d", direction);
+        ALOGE("%s() invalid direction = %d", __func__, direction);
         return AAUDIO_ERROR_ILLEGAL_ARGUMENT;
     }
 
@@ -157,20 +157,20 @@
                                                           this, // callback
                                                           mMmapStream,
                                                           &mPortHandle);
-    ALOGD("open() mMapClient.uid = %d, pid = %d => portHandle = %d\n",
-          mMmapClient.clientUid,  mMmapClient.clientPid, mPortHandle);
+    ALOGD("%s() mMapClient.uid = %d, pid = %d => portHandle = %d\n",
+          __func__, mMmapClient.clientUid,  mMmapClient.clientPid, mPortHandle);
     if (status != OK) {
-        ALOGE("openMmapStream returned status %d", status);
+        ALOGE("%s() openMmapStream() returned status %d",  __func__, status);
         return AAUDIO_ERROR_UNAVAILABLE;
     }
 
     if (deviceId == AAUDIO_UNSPECIFIED) {
-        ALOGW("open() - openMmapStream() failed to set deviceId");
+        ALOGW("%s() openMmapStream() failed to set deviceId", __func__);
     }
     setDeviceId(deviceId);
 
     if (sessionId == AUDIO_SESSION_ALLOCATE) {
-        ALOGW("open() - openMmapStream() failed to set sessionId");
+        ALOGW("%s() - openMmapStream() failed to set sessionId", __func__);
     }
 
     aaudio_session_id_t actualSessionId =
@@ -178,7 +178,7 @@
             ? AAUDIO_SESSION_ID_NONE
             : (aaudio_session_id_t) sessionId;
     setSessionId(actualSessionId);
-    ALOGD("open() deviceId = %d, sessionId = %d", getDeviceId(), getSessionId());
+    ALOGD("%s() deviceId = %d, sessionId = %d", __func__, getDeviceId(), getSessionId());
 
     // Create MMAP/NOIRQ buffer.
     int32_t minSizeFrames = getBufferCapacity();
@@ -187,14 +187,14 @@
     }
     status = mMmapStream->createMmapBuffer(minSizeFrames, &mMmapBufferinfo);
     if (status != OK) {
-        ALOGE("open() - createMmapBuffer() failed with status %d %s",
-              status, strerror(-status));
+        ALOGE("%s() - createMmapBuffer() failed with status %d %s",
+              __func__, status, strerror(-status));
         result = AAUDIO_ERROR_UNAVAILABLE;
         goto error;
     } else {
-        ALOGD("createMmapBuffer status = %d, buffer_size = %d, burst_size %d"
+        ALOGD("%s() createMmapBuffer() returned = %d, buffer_size = %d, burst_size %d"
                       ", Sharable FD: %s",
-              status,
+              __func__, status,
               abs(mMmapBufferinfo.buffer_size_frames),
               mMmapBufferinfo.burst_size_frames,
               mMmapBufferinfo.buffer_size_frames < 0 ? "Yes" : "No");
@@ -214,7 +214,7 @@
             // Fallback is handled by caller but indicate what is possible in case
             // this is used in the future
             setSharingMode(AAUDIO_SHARING_MODE_SHARED);
-            ALOGW("open() - exclusive FD cannot be used by client");
+            ALOGW("%s() - exclusive FD cannot be used by client", __func__);
             result = AAUDIO_ERROR_UNAVAILABLE;
             goto error;
         }
@@ -229,7 +229,7 @@
     // Assume that AudioFlinger will close the original shared_memory_fd.
     mAudioDataFileDescriptor.reset(dup(mMmapBufferinfo.shared_memory_fd));
     if (mAudioDataFileDescriptor.get() == -1) {
-        ALOGE("open() - could not dup shared_memory_fd");
+        ALOGE("%s() - could not dup shared_memory_fd", __func__);
         result = AAUDIO_ERROR_INTERNAL;
         goto error;
     }
@@ -247,12 +247,12 @@
         burstMicros = mFramesPerBurst * static_cast<int64_t>(1000000) / getSampleRate();
     } while (burstMicros < burstMinMicros);
 
-    ALOGD("open() original burst = %d, minMicros = %d, to burst = %d\n",
-          mMmapBufferinfo.burst_size_frames, burstMinMicros, mFramesPerBurst);
+    ALOGD("%s() original burst = %d, minMicros = %d, to burst = %d\n",
+          __func__, mMmapBufferinfo.burst_size_frames, burstMinMicros, mFramesPerBurst);
 
-    ALOGD("open() actual rate = %d, channels = %d"
+    ALOGD("%s() actual rate = %d, channels = %d"
           ", deviceId = %d, capacity = %d\n",
-          getSampleRate(), getSamplesPerFrame(), deviceId, getBufferCapacity());
+          __func__, getSampleRate(), getSamplesPerFrame(), deviceId, getBufferCapacity());
 
     return result;
 
@@ -262,9 +262,8 @@
 }
 
 aaudio_result_t AAudioServiceEndpointMMAP::close() {
-
     if (mMmapStream != 0) {
-        ALOGD("close() clear() endpoint");
+        ALOGD("%s() clear() endpoint", __func__);
         // Needs to be explicitly cleared or CTS will fail but it is not clear why.
         mMmapStream.clear();
         // Apparently the above close is asynchronous. An attempt to open a new device
@@ -299,20 +298,18 @@
 aaudio_result_t AAudioServiceEndpointMMAP::startClient(const android::AudioClient& client,
                                                        audio_port_handle_t *clientHandle) {
     if (mMmapStream == nullptr) return AAUDIO_ERROR_NULL;
-    ALOGD("startClient(%p(uid=%d, pid=%d))",
-          &client, client.clientUid, client.clientPid);
+    ALOGV("%s(%p(uid=%d, pid=%d))", __func__, &client, client.clientUid, client.clientPid);
     audio_port_handle_t originalHandle =  *clientHandle;
     status_t status = mMmapStream->start(client, clientHandle);
     aaudio_result_t result = AAudioConvert_androidToAAudioResult(status);
-    ALOGD("startClient() , %d => %d returns %d",
-          originalHandle, *clientHandle, result);
+    ALOGV("%s() , %d => %d returns %d", __func__, originalHandle, *clientHandle, result);
     return result;
 }
 
 aaudio_result_t AAudioServiceEndpointMMAP::stopClient(audio_port_handle_t clientHandle) {
     if (mMmapStream == nullptr) return AAUDIO_ERROR_NULL;
     aaudio_result_t result = AAudioConvert_androidToAAudioResult(mMmapStream->stop(clientHandle));
-    ALOGD("stopClient(%d) returns %d", clientHandle, result);
+    ALOGV("%s(%d) returns %d", __func__, clientHandle, result);
     return result;
 }
 
@@ -324,13 +321,13 @@
         return AAUDIO_ERROR_NULL;
     }
     status_t status = mMmapStream->getMmapPosition(&position);
-    ALOGV("getFreeRunningPosition() status= %d, pos = %d, nanos = %lld\n",
-          status, position.position_frames, (long long) position.time_nanoseconds);
+    ALOGV("%s() status= %d, pos = %d, nanos = %lld\n",
+          __func__, status, position.position_frames, (long long) position.time_nanoseconds);
     aaudio_result_t result = AAudioConvert_androidToAAudioResult(status);
     if (result == AAUDIO_ERROR_UNAVAILABLE) {
-        ALOGW("sendCurrentTimestamp(): getMmapPosition() has no position data available");
+        ALOGW("%s(): getMmapPosition() has no position data available", __func__);
     } else if (result != AAUDIO_OK) {
-        ALOGE("sendCurrentTimestamp(): getMmapPosition() returned status %d", status);
+        ALOGE("%s(): getMmapPosition() returned status %d", __func__, status);
     } else {
         // Convert 32-bit position to 64-bit position.
         mFramesTransferred.update32(position.position_frames);
@@ -347,15 +344,16 @@
 
 
 void AAudioServiceEndpointMMAP::onTearDown() {
-    ALOGD("onTearDown() called");
+    ALOGD("%s(%p) called", __func__, this);
     disconnectRegisteredStreams();
 };
 
 void AAudioServiceEndpointMMAP::onVolumeChanged(audio_channel_mask_t channels,
                                               android::Vector<float> values) {
-    // TODO do we really need a different volume for each channel?
+    // TODO Do we really need a different volume for each channel?
+    // We get called with an array filled with a single value!
     float volume = values[0];
-    ALOGD("onVolumeChanged() volume[0] = %f", volume);
+    ALOGD("%s(%p) volume[0] = %f", __func__, this, volume);
     std::lock_guard<std::mutex> lock(mLockStreams);
     for(const auto stream : mRegisteredStreams) {
         stream->onVolumeChanged(volume);
@@ -363,8 +361,7 @@
 };
 
 void AAudioServiceEndpointMMAP::onRoutingChanged(audio_port_handle_t deviceId) {
-    ALOGD("onRoutingChanged() called with dev %d, old = %d",
-          deviceId, getDeviceId());
+    ALOGD("%s(%p) called with dev %d, old = %d", __func__, this, deviceId, getDeviceId());
     if (getDeviceId() != AUDIO_PORT_HANDLE_NONE  && getDeviceId() != deviceId) {
         disconnectRegisteredStreams();
     }
diff --git a/services/oboeservice/AAudioServiceEndpointPlay.cpp b/services/oboeservice/AAudioServiceEndpointPlay.cpp
index 2601f3f..a274466 100644
--- a/services/oboeservice/AAudioServiceEndpointPlay.cpp
+++ b/services/oboeservice/AAudioServiceEndpointPlay.cpp
@@ -43,10 +43,12 @@
 
 AAudioServiceEndpointPlay::AAudioServiceEndpointPlay(AAudioService &audioService)
         : mStreamInternalPlay(audioService, true) {
+    ALOGD("%s(%p) created", __func__, this);
     mStreamInternal = &mStreamInternalPlay;
 }
 
 AAudioServiceEndpointPlay::~AAudioServiceEndpointPlay() {
+    ALOGD("%s(%p) destroyed", __func__, this);
 }
 
 aaudio_result_t AAudioServiceEndpointPlay::open(const aaudio::AAudioStreamRequest &request) {
@@ -68,6 +70,7 @@
 
 // Mix data from each application stream and write result to the shared MMAP stream.
 void *AAudioServiceEndpointPlay::callbackLoop() {
+    ALOGD("%s() entering >>>>>>>>>>>>>>> MIXER", __func__);
     aaudio_result_t result = AAUDIO_OK;
     int64_t timeoutNanos = getStreamInternal()->calculateReasonableTimeout();
 
@@ -152,5 +155,7 @@
         }
     }
 
+    ALOGD("%s() exiting, enabled = %d, state = %d, result = %d <<<<<<<<<<<<< MIXER",
+          __func__, mCallbackEnabled.load(), getStreamInternal()->getState(), result);
     return NULL; // TODO review
 }
diff --git a/services/oboeservice/AAudioServiceEndpointShared.h b/services/oboeservice/AAudioServiceEndpointShared.h
index 74cd817..227250c 100644
--- a/services/oboeservice/AAudioServiceEndpointShared.h
+++ b/services/oboeservice/AAudioServiceEndpointShared.h
@@ -54,12 +54,13 @@
 
     virtual void            *callbackLoop() = 0;
 
+
+protected:
+
     AudioStreamInternal *getStreamInternal() const {
         return mStreamInternal;
     };
 
-protected:
-
     aaudio_result_t          startSharingThread_l();
 
     aaudio_result_t          stopSharingThread();
diff --git a/services/oboeservice/AAudioServiceStreamBase.cpp b/services/oboeservice/AAudioServiceStreamBase.cpp
index e8c9e41..18f14ee 100644
--- a/services/oboeservice/AAudioServiceStreamBase.cpp
+++ b/services/oboeservice/AAudioServiceStreamBase.cpp
@@ -93,7 +93,7 @@
     {
         std::lock_guard<std::mutex> lock(mUpMessageQueueLock);
         if (mUpMessageQueue != nullptr) {
-            ALOGE("open() called twice");
+            ALOGE("%s() called twice", __func__);
             return AAUDIO_ERROR_INVALID_STATE;
         }
 
@@ -108,7 +108,7 @@
                                                          request,
                                                          sharingMode);
         if (mServiceEndpoint == nullptr) {
-            ALOGE("open() openEndpoint() failed");
+            ALOGE("%s() openEndpoint() failed", __func__);
             result = AAUDIO_ERROR_UNAVAILABLE;
             goto error;
         }
@@ -167,7 +167,7 @@
     }
 
     if (mServiceEndpoint == nullptr) {
-        ALOGE("start() missing endpoint");
+        ALOGE("%s() missing endpoint", __func__);
         result = AAUDIO_ERROR_INVALID_STATE;
         goto error;
     }
@@ -201,7 +201,7 @@
         return result;
     }
     if (mServiceEndpoint == nullptr) {
-        ALOGE("pause() missing endpoint");
+        ALOGE("%s() missing endpoint", __func__);
         return AAUDIO_ERROR_INVALID_STATE;
     }
 
@@ -217,7 +217,7 @@
 
     result = mServiceEndpoint->stopStream(this, mClientHandle);
     if (result != AAUDIO_OK) {
-        ALOGE("pause() mServiceEndpoint returned %d", result);
+        ALOGE("%s() mServiceEndpoint returned %d, %s", __func__, result, getTypeText());
         disconnect(); // TODO should we return or pause Base first?
     }
 
@@ -233,7 +233,7 @@
     }
 
     if (mServiceEndpoint == nullptr) {
-        ALOGE("stop() missing endpoint");
+        ALOGE("%s() missing endpoint", __func__);
         return AAUDIO_ERROR_INVALID_STATE;
     }
 
@@ -251,7 +251,7 @@
     // TODO wait for data to be played out
     result = mServiceEndpoint->stopStream(this, mClientHandle);
     if (result != AAUDIO_OK) {
-        ALOGE("stop() mServiceEndpoint returned %d", result);
+        ALOGE("%s() mServiceEndpoint returned %d, %s", __func__, result, getTypeText());
         disconnect();
         // TODO what to do with result here?
     }
@@ -284,7 +284,7 @@
 
 // implement Runnable, periodically send timestamps to client
 void AAudioServiceStreamBase::run() {
-    ALOGD("run() entering ----------------");
+    ALOGD("%s() %s entering >>>>>>>>>>>>>> TIMESTAMPS", __func__, getTypeText());
     TimestampScheduler timestampScheduler;
     timestampScheduler.setBurstPeriod(mFramesPerBurst, getSampleRate());
     timestampScheduler.start(AudioClock::getNanoseconds());
@@ -302,7 +302,7 @@
             AudioClock::sleepUntilNanoTime(nextTime);
         }
     }
-    ALOGD("run() exiting ----------------");
+    ALOGD("%s() %s exiting <<<<<<<<<<<<<< TIMESTAMPS", __func__, getTypeText());
 }
 
 void AAudioServiceStreamBase::disconnect() {
@@ -333,12 +333,12 @@
 aaudio_result_t AAudioServiceStreamBase::writeUpMessageQueue(AAudioServiceMessage *command) {
     std::lock_guard<std::mutex> lock(mUpMessageQueueLock);
     if (mUpMessageQueue == nullptr) {
-        ALOGE("writeUpMessageQueue(): mUpMessageQueue null! - stream not open");
+        ALOGE("%s(): mUpMessageQueue null! - stream not open", __func__);
         return AAUDIO_ERROR_NULL;
     }
     int32_t count = mUpMessageQueue->getFifoBuffer()->write(command, 1);
     if (count != 1) {
-        ALOGE("writeUpMessageQueue(): Queue full. Did client die?");
+        ALOGE("%s(): Queue full. Did client die? %s", __func__, getTypeText());
         return AAUDIO_ERROR_WOULD_BLOCK;
     } else {
         return AAUDIO_OK;
@@ -355,7 +355,7 @@
     aaudio_result_t result = getFreeRunningPosition(&command.timestamp.position,
                                                     &command.timestamp.timestamp);
     if (result == AAUDIO_OK) {
-        ALOGV("sendCurrentTimestamp() SERVICE  %8lld at %lld",
+        ALOGV("%s() SERVICE  %8lld at %lld", __func__,
               (long long) command.timestamp.position,
               (long long) command.timestamp.timestamp);
         command.what = AAudioServiceMessage::code::TIMESTAMP_SERVICE;
@@ -366,7 +366,7 @@
             result = getHardwareTimestamp(&command.timestamp.position,
                                           &command.timestamp.timestamp);
             if (result == AAUDIO_OK) {
-                ALOGV("sendCurrentTimestamp() HARDWARE %8lld at %lld",
+                ALOGV("%s() HARDWARE %8lld at %lld", __func__,
                       (long long) command.timestamp.position,
                       (long long) command.timestamp.timestamp);
                 command.what = AAudioServiceMessage::code::TIMESTAMP_HARDWARE;
@@ -389,7 +389,7 @@
     {
         std::lock_guard<std::mutex> lock(mUpMessageQueueLock);
         if (mUpMessageQueue == nullptr) {
-            ALOGE("getDescription(): mUpMessageQueue null! - stream not open");
+            ALOGE("%s(): mUpMessageQueue null! - stream not open", __func__);
             return AAUDIO_ERROR_NULL;
         }
         // Gather information on the message queue.
diff --git a/services/oboeservice/AAudioServiceStreamBase.h b/services/oboeservice/AAudioServiceStreamBase.h
index 5f5bb98..3720596 100644
--- a/services/oboeservice/AAudioServiceStreamBase.h
+++ b/services/oboeservice/AAudioServiceStreamBase.h
@@ -55,7 +55,7 @@
     , public Runnable  {
 
 public:
-    AAudioServiceStreamBase(android::AAudioService &aAudioService);
+    explicit AAudioServiceStreamBase(android::AAudioService &aAudioService);
 
     virtual ~AAudioServiceStreamBase();
 
@@ -219,6 +219,8 @@
         mCloseNeeded.store(needed);
     }
 
+    virtual const char *getTypeText() const { return "Base"; }
+
 protected:
 
     /**
diff --git a/services/oboeservice/AAudioServiceStreamMMAP.h b/services/oboeservice/AAudioServiceStreamMMAP.h
index e2415d0..1509f7d 100644
--- a/services/oboeservice/AAudioServiceStreamMMAP.h
+++ b/services/oboeservice/AAudioServiceStreamMMAP.h
@@ -69,9 +69,7 @@
 
     aaudio_result_t close() override;
 
-    /**
-     * Send a MMAP/NOIRQ buffer timestamp to the client.
-     */
+    const char *getTypeText() const override { return "MMAP"; }
 
 protected:
 
diff --git a/services/oboeservice/AAudioServiceStreamShared.h b/services/oboeservice/AAudioServiceStreamShared.h
index 3b12e61..61769b5 100644
--- a/services/oboeservice/AAudioServiceStreamShared.h
+++ b/services/oboeservice/AAudioServiceStreamShared.h
@@ -43,7 +43,7 @@
 class AAudioServiceStreamShared : public AAudioServiceStreamBase {
 
 public:
-    AAudioServiceStreamShared(android::AAudioService &aAudioService);
+    explicit AAudioServiceStreamShared(android::AAudioService &aAudioService);
     virtual ~AAudioServiceStreamShared() = default;
 
     static std::string dumpHeader();
@@ -87,6 +87,8 @@
         return mXRunCount.load();
     }
 
+    const char *getTypeText() const override { return "Shared"; }
+
 protected:
 
     aaudio_result_t getAudioDataDescription(AudioEndpointParcelable &parcelable) override;
diff --git a/services/oboeservice/AAudioThread.h b/services/oboeservice/AAudioThread.h
index ffc9b7b..dcce68a 100644
--- a/services/oboeservice/AAudioThread.h
+++ b/services/oboeservice/AAudioThread.h
@@ -44,7 +44,7 @@
 public:
     AAudioThread();
 
-    AAudioThread(const char *prefix);
+    explicit AAudioThread(const char *prefix);
 
     virtual ~AAudioThread() = default;