base:port: fix debug messages

2 files changed, 190 insertions, 72 deletions

diff --git a/base/inc/portbase.h b/base/inc/portbase.h
index 7f4838b..dfcc811 100644
--- a/base/inc/portbase.h
+++ b/base/inc/portbase.h
@@ -155,6 +155,9 @@ private:
     /* omx standard callbacks */
     OMX_PTR appdata;
     OMX_CALLBACKTYPE *callbacks;
+
+    /* wrs component handle */
+    class ComponentBase *cbase;
 };
 
 /* end of PortBase */
diff --git a/base/src/portbase.cpp b/base/src/portbase.cpp
index 1ec7d4f..229dca5 100644
--- a/base/src/portbase.cpp
+++ b/base/src/portbase.cpp
@@ -15,7 +15,7 @@
 #include <portbase.h>
 #include <componentbase.h>
 
-#define LOG_NDEBUG 1
+//#define LOG_NDEBUG 0
 
 #define LOG_TAG "portbase"
 #include <log.h>
@@ -56,6 +56,8 @@ void PortBase::__PortBase(void)
     owner = NULL;
     appdata = NULL;
     callbacks = NULL;
+
+    cbase = NULL;
 }
 
 PortBase::PortBase()
@@ -106,6 +108,7 @@ PortBase::~PortBase()
 void PortBase::SetOwner(OMX_COMPONENTTYPE *handle)
 {
     owner = handle;
+    cbase = static_cast<ComponentBase *>(handle->pComponentPrivate);
 }
 
 OMX_COMPONENTTYPE *PortBase::GetOwner(void)
@@ -267,23 +270,25 @@ OMX_ERRORTYPE PortBase::UseBuffer(OMX_BUFFERHEADERTYPE **ppBufferHdr,
     OMX_BUFFERHEADERTYPE *buffer_hdr;
     struct list *entry;
 
-    LOGV("%s(): enter, nPortIndex=%lu, nSizeBytes=%lu\n", __func__,
-         nPortIndex, nSizeBytes);
+    LOGV("%s(): %s:%s:PortIndex %lu: enter, nSizeBytes=%lu\n", __FUNCTION__,
+         cbase->GetName(), cbase->GetWorkingRole(), nPortIndex, nSizeBytes);
 
     pthread_mutex_lock(&hdrs_lock);
 
     if (portdefinition.bPopulated == OMX_TRUE) {
         pthread_mutex_unlock(&hdrs_lock);
-        LOGV("%s(): exit, already populated (ret = 0x%08x)\n", __func__,
-             OMX_ErrorNone);
+        LOGV("%s(): %s:%s:PortIndex %lu: exit done, already populated\n",
+             __FUNCTION__, cbase->GetName(), cbase->GetWorkingRole(),
+             nPortIndex);
         return OMX_ErrorNone;
     }
 
     buffer_hdr = (OMX_BUFFERHEADERTYPE *)calloc(1, sizeof(*buffer_hdr));
     if (!buffer_hdr) {
         pthread_mutex_unlock(&hdrs_lock);
-        LOGE("%s(): exit (ret = 0x%08x)\n",
-             __func__, OMX_ErrorInsufficientResources);
+        LOGE("%s(): %s:%s:PortIndex %lu: exit failure, "
+             "connot allocate buffer header\n", __FUNCTION__,
+             cbase->GetName(), cbase->GetWorkingRole(), nPortIndex);
         return OMX_ErrorInsufficientResources;
     }
 
@@ -291,8 +296,9 @@ OMX_ERRORTYPE PortBase::UseBuffer(OMX_BUFFERHEADERTYPE **ppBufferHdr,
     if (!entry) {
         free(buffer_hdr);
         pthread_mutex_unlock(&hdrs_lock);
-        LOGE("%s(): exit (ret = 0x%08x)\n",
-             __func__, OMX_ErrorInsufficientResources);
+        LOGE("%s(): %s:%s:PortIndex %lu: exit failure, "
+             "cannot allocate list entry\n", __FUNCTION__,
+             cbase->GetName(), cbase->GetWorkingRole(), nPortIndex);
         return OMX_ErrorInsufficientResources;
     }
 
@@ -316,21 +322,26 @@ OMX_ERRORTYPE PortBase::UseBuffer(OMX_BUFFERHEADERTYPE **ppBufferHdr,
     buffer_hdrs = __list_add_tail(buffer_hdrs, entry);
     nr_buffer_hdrs++;
 
-    LOGV("%s(): a buffer allocated (%lu/%lu)\n", __func__,
-         nr_buffer_hdrs, portdefinition.nBufferCountActual);
+    LOGV("%s(): %s:%s:PortIndex %lu: a buffer allocated (%p:%lu/%lu)\n",
+         __FUNCTION__,
+         cbase->GetName(), cbase->GetWorkingRole(), nPortIndex,
+         buffer_hdr, nr_buffer_hdrs, portdefinition.nBufferCountActual);
 
     if (nr_buffer_hdrs >= portdefinition.nBufferCountActual) {
         portdefinition.bPopulated = OMX_TRUE;
         buffer_hdrs_completion = true;
         pthread_cond_signal(&hdrs_wait);
-        LOGV("%s(): allocate all buffers, nBufferCountActual (%lu)\n",
-             __func__, portdefinition.nBufferCountActual);
+        LOGV("%s(): %s:%s:PortIndex %lu: allocate all buffers (%lu)\n",
+             __FUNCTION__, cbase->GetName(), cbase->GetWorkingRole(),
+             nPortIndex, portdefinition.nBufferCountActual);
     }
 
     *ppBufferHdr = buffer_hdr;
 
     pthread_mutex_unlock(&hdrs_lock);
-    LOGV("%s(): exit (ret = 0x%08x)\n", __func__, OMX_ErrorNone);
+
+    LOGV("%s(): %s:%s:PortIndex %lu: exit done\n", __FUNCTION__,
+         cbase->GetName(), cbase->GetWorkingRole(), nPortIndex);
     return OMX_ErrorNone;
 }
 
@@ -342,14 +353,15 @@ OMX_ERRORTYPE PortBase::AllocateBuffer(OMX_BUFFERHEADERTYPE **ppBuffer,
     OMX_BUFFERHEADERTYPE *buffer_hdr;
     struct list *entry;
 
-    LOGV("%s(): enter, nPortIndex=%lu, nSizeBytes=%lu\n", __func__,
-         nPortIndex, nSizeBytes);
+    LOGV("%s(): %s:%s:PortIndex %lu: enter, nSizeBytes=%lu\n", __FUNCTION__,
+         cbase->GetName(), cbase->GetWorkingRole(), nPortIndex, nSizeBytes);
 
     pthread_mutex_lock(&hdrs_lock);
     if (portdefinition.bPopulated == OMX_TRUE) {
         pthread_mutex_unlock(&hdrs_lock);
-        LOGV("%s(): exit, already populated (ret = 0x%08x)\n", __func__,
-             OMX_ErrorNone);
+        LOGV("%s(): %s:%s:PortIndex %lu: exit done, already populated\n",
+             __FUNCTION__, cbase->GetName(), cbase->GetWorkingRole(),
+             nPortIndex);
         return OMX_ErrorNone;
     }
 
@@ -357,8 +369,9 @@ OMX_ERRORTYPE PortBase::AllocateBuffer(OMX_BUFFERHEADERTYPE **ppBuffer,
         calloc(1, sizeof(*buffer_hdr) + nSizeBytes);
     if (!buffer_hdr) {
         pthread_mutex_unlock(&hdrs_lock);
-        LOGE("%s(): exit (ret = 0x%08x)\n",
-             __func__, OMX_ErrorInsufficientResources);
+        LOGE("%s(): %s:%s:PortIndex %lu: exit failure, "
+             "connot allocate buffer header\n", __FUNCTION__,
+             cbase->GetName(), cbase->GetWorkingRole(), nPortIndex);
         return OMX_ErrorInsufficientResources;
     }
 
@@ -366,8 +379,9 @@ OMX_ERRORTYPE PortBase::AllocateBuffer(OMX_BUFFERHEADERTYPE **ppBuffer,
     if (!entry) {
         free(buffer_hdr);
         pthread_mutex_unlock(&hdrs_lock);
-        LOGE("%s(): exit (ret = 0x%08x)\n",
-             __func__, OMX_ErrorInsufficientResources);
+        LOGE("%s(): %s:%s:PortIndex %lu: exit failure, "
+             "connot allocate list entry\n", __FUNCTION__,
+             cbase->GetName(), cbase->GetWorkingRole(), nPortIndex);
         return OMX_ErrorInsufficientResources;
     }
 
@@ -391,21 +405,26 @@ OMX_ERRORTYPE PortBase::AllocateBuffer(OMX_BUFFERHEADERTYPE **ppBuffer,
     buffer_hdrs = __list_add_tail(buffer_hdrs, entry);
     nr_buffer_hdrs++;
 
-    LOGV("%s(): a buffer allocated (%lu/%lu)\n", __func__,
-         nr_buffer_hdrs, portdefinition.nBufferCountActual);
+    LOGV("%s(): %s:%s:PortIndex %lu: a buffer allocated (%p:%lu/%lu)\n",
+         __FUNCTION__,
+         cbase->GetName(), cbase->GetWorkingRole(), nPortIndex,
+         buffer_hdr, nr_buffer_hdrs, portdefinition.nBufferCountActual);
 
     if (nr_buffer_hdrs == portdefinition.nBufferCountActual) {
         portdefinition.bPopulated = OMX_TRUE;
         buffer_hdrs_completion = true;
         pthread_cond_signal(&hdrs_wait);
-        LOGV("%s(): allocate all buffers, nBufferCountActual (%lu)\n",
-             __func__, portdefinition.nBufferCountActual);
+        LOGV("%s(): %s:%s:PortIndex %lu: allocate all buffers (%lu)\n",
+             __FUNCTION__, cbase->GetName(), cbase->GetWorkingRole(),
+             nPortIndex, portdefinition.nBufferCountActual);
     }
 
     *ppBuffer = buffer_hdr;
 
     pthread_mutex_unlock(&hdrs_lock);
-    LOGV("%s(): exit (ret = 0x%08x)\n", __func__, OMX_ErrorNone);
+
+    LOGV("%s(): %s:%s:PortIndex %lu: exit done\n", __FUNCTION__,
+         cbase->GetName(), cbase->GetWorkingRole(), nPortIndex);
     return OMX_ErrorNone;
 }
 
@@ -415,49 +434,59 @@ OMX_ERRORTYPE PortBase::FreeBuffer(OMX_U32 nPortIndex,
     struct list *entry;
     OMX_ERRORTYPE ret;
 
-    LOGV("%s(): enter, nPortIndex=%lu\n", __func__, nPortIndex);
+    LOGV("%s(): %s:%s:PortIndex %lu:pBuffer %p: enter\n", __FUNCTION__,
+         cbase->GetName(), cbase->GetWorkingRole(), nPortIndex, pBuffer);
 
     pthread_mutex_lock(&hdrs_lock);
     entry = list_find(buffer_hdrs, pBuffer);
 
     if (!entry) {
         pthread_mutex_unlock(&hdrs_lock);
-        LOGV("%s(): exit (ret = 0x%08x)\n", __func__, OMX_ErrorNone);
-        return OMX_ErrorNone;
+        LOGE("%s(): %s:%s:PortIndex %lu:pBuffer %p: exit failure, "
+             "cannot find list entry for pBuffer\n", __FUNCTION__,
+             cbase->GetName(), cbase->GetWorkingRole(), nPortIndex, pBuffer);
+        return OMX_ErrorBadParameter;
     }
 
     if (entry->data != pBuffer) {
         pthread_mutex_unlock(&hdrs_lock);
-        LOGE("%s(): exit, (entry->data != pBuffer) (ret = 0x%08x)\n", __func__,
-             OMX_ErrorBadParameter);
+        LOGE("%s(): %s:%s:PortIndex %lu:pBuffer %p: exit failure,"
+             "mismatch list entry\n" , __FUNCTION__,
+             cbase->GetName(), cbase->GetWorkingRole(), nPortIndex, pBuffer);
         return OMX_ErrorBadParameter;
     }
 
     ret = ComponentBase::CheckTypeHeader(pBuffer, sizeof(*pBuffer));
     if (ret != OMX_ErrorNone) {
         pthread_mutex_unlock(&hdrs_lock);
-        LOGE("%s(): exit (ret = 0x%08x)\n",
-             __func__, OMX_ErrorInsufficientResources);
+        LOGE("%s(): %s:%s:PortIndex %lu:pBuffer %p: exit failure,"
+             "invalid type header\n", __FUNCTION__,
+             cbase->GetName(), cbase->GetWorkingRole(), nPortIndex, pBuffer);
         return ret;
     }
 
     buffer_hdrs = __list_delete(buffer_hdrs, entry);
     nr_buffer_hdrs--;
 
-    LOGV("%s(): free a buffer (%lu/%lu)\n", __func__,
-         nr_buffer_hdrs, portdefinition.nBufferCountActual);
+    LOGV("%s(): %s:%s:PortIndex %lu:pBuffer %p: free a buffer (%lu/%lu)\n",
+         __FUNCTION__, cbase->GetName(), cbase->GetWorkingRole(), nPortIndex,
+         pBuffer, nr_buffer_hdrs, portdefinition.nBufferCountActual);
+
+    free(pBuffer);
 
     portdefinition.bPopulated = OMX_FALSE;
     if (!nr_buffer_hdrs) {
         buffer_hdrs_completion = true;
         pthread_cond_signal(&hdrs_wait);
-        LOGV("%s(): free all allocated buffers\n", __func__);
+        LOGV("%s(): %s:%s:PortIndex %lu: free all allocated buffers (%lu)\n",
+             __FUNCTION__, cbase->GetName(), cbase->GetWorkingRole(),
+             nPortIndex, portdefinition.nBufferCountActual);
     }
 
-    free(pBuffer);
-
     pthread_mutex_unlock(&hdrs_lock);
-    LOGV("%s(): exit (ret = 0x%08x)\n", __func__, OMX_ErrorNone);
+
+    LOGV("%s(): %s:%s:PortIndex %lu: exit done\n", __FUNCTION__,
+         cbase->GetName(), cbase->GetWorkingRole(), nPortIndex);
     return OMX_ErrorNone;
 }
 
@@ -465,9 +494,13 @@ void PortBase::WaitPortBufferCompletion(void)
 {
     pthread_mutex_lock(&hdrs_lock);
     if (!buffer_hdrs_completion) {
-        LOGV("%s(): wait for buffer header completion\n", __func__);
+        LOGV("%s(): %s:%s:PortIndex %lu: wait for buffer header completion\n",
+             __FUNCTION__, cbase->GetName(), cbase->GetWorkingRole(),
+             portdefinition.nPortIndex);
         pthread_cond_wait(&hdrs_wait, &hdrs_lock);
-        LOGV("%s(): wokeup (buffer header completion)\n", __func__);
+        LOGV("%s(): %s:%s:PortIndex %lu: wokeup (buffer header completion)\n",
+             __FUNCTION__, cbase->GetName(), cbase->GetWorkingRole(),
+             portdefinition.nPortIndex);
     }
     buffer_hdrs_completion = !buffer_hdrs_completion;
     pthread_mutex_unlock(&hdrs_lock);
@@ -478,6 +511,10 @@ OMX_ERRORTYPE PortBase::PushThisBuffer(OMX_BUFFERHEADERTYPE *pBuffer)
 {
     int ret;
 
+    LOGV_IF(pBuffer != NULL, "%s(): %s:%s:PortIndex %lu:pBuffer %p:\n",
+            __FUNCTION__, cbase->GetName(), cbase->GetWorkingRole(),
+            portdefinition.nPortIndex, pBuffer);
+
     pthread_mutex_lock(&bufferq_lock);
     ret = queue_push_tail(&bufferq, pBuffer);
     pthread_mutex_unlock(&bufferq_lock);
@@ -496,6 +533,10 @@ OMX_BUFFERHEADERTYPE *PortBase::PopBuffer(void)
     buffer = (OMX_BUFFERHEADERTYPE *)queue_pop_head(&bufferq);
     pthread_mutex_unlock(&bufferq_lock);
 
+    LOGV_IF(buffer != NULL, "%s(): %s:%s:PortIndex %lu:pBuffer %p:\n",
+            __FUNCTION__, cbase->GetName(), cbase->GetWorkingRole(),
+            portdefinition.nPortIndex, buffer);
+
     return buffer;
 }
 
@@ -519,11 +560,15 @@ OMX_ERRORTYPE PortBase::ReturnThisBuffer(OMX_BUFFERHEADERTYPE *pBuffer)
                                          OMX_BUFFERHEADERTYPE *);
     OMX_ERRORTYPE ret;
 
-    LOGV("%s(): enter\n", __func__);
+    LOGV("%s(): %s:%s:PortIndex %lu:pBuffer %p: enter\n", __FUNCTION__,
+         cbase->GetName(), cbase->GetWorkingRole(), portdefinition.nPortIndex,
+         pBuffer);
 
     if (!pBuffer) {
-        LOGE("%s(): exit, invalid buffer pointer (ret = 0x%08x)\n", __func__,
-             OMX_ErrorBadParameter);
+        LOGE("%s(): %s:%s:PortIndex %lu:pBuffer %p: exit failure, "
+             "invalid buffer pointer\n",
+             __FUNCTION__, cbase->GetName(), cbase->GetWorkingRole(),
+             portdefinition.nPortIndex, pBuffer);
         return OMX_ErrorBadParameter;
     }
 
@@ -536,28 +581,39 @@ OMX_ERRORTYPE PortBase::ReturnThisBuffer(OMX_BUFFERHEADERTYPE *pBuffer)
         bufferdone_callback = callbacks->FillBufferDone;
     }
     else {
-        LOGE("%s(): exit, invalid direction (%d) (ret = 0x%08x)\n", __func__,
-             direction, OMX_ErrorBadParameter);
+        LOGE("%s(): %s:%s:PortIndex %lu:pBuffer %p: exit failure, "
+             "invalid direction (%d)\n",
+             __FUNCTION__, cbase->GetName(), cbase->GetWorkingRole(),
+             portdefinition.nPortIndex, pBuffer,
+             direction);
         return OMX_ErrorBadParameter;
     }
 
-    LOGV("%s(): direction=%d, port_index=%lu\n",
-         __func__, direction, port_index);
-
     if (port_index != portdefinition.nPortIndex) {
-        LOGE("%s(): exit, not matched port index (%lu/%lu) (ret = 0x%08x)\n",
-             __func__, port_index, portdefinition.nPortIndex,
-             OMX_ErrorBadParameter);
+        LOGE("%s(): %s:%s:PortIndex %lu:pBuffer %p: exit failure, "
+             "invalid port index (%lu)\n", __FUNCTION__,
+             cbase->GetName(), cbase->GetWorkingRole(),
+             portdefinition.nPortIndex, pBuffer, port_index);
         return OMX_ErrorBadParameter;
     }
 
     if (pBuffer->nFlags & OMX_BUFFERFLAG_EOS) {
+        LOGV("%s(): %s:%s:PortIndex %lu:pBuffer %p: "
+             "Report OMX_EventBufferFlag (OMX_BUFFERFLAG_EOS)\n",
+             __FUNCTION__, cbase->GetName(), cbase->GetWorkingRole(),
+             portdefinition.nPortIndex, pBuffer);
+
         callbacks->EventHandler(owner, appdata,
                                 OMX_EventBufferFlag,
                                 port_index, pBuffer->nFlags, NULL);
     }
 
     if (pBuffer->hMarkTargetComponent == owner) {
+        LOGV("%s(): %s:%s:PortIndex %lu:pBuffer %p: "
+             "Report OMX_EventMark\n",
+             __FUNCTION__, cbase->GetName(), cbase->GetWorkingRole(),
+             portdefinition.nPortIndex, pBuffer);
+
         callbacks->EventHandler(owner, appdata, OMX_EventMark,
                                 0, 0, pBuffer->pMarkData);
         pBuffer->hMarkTargetComponent = NULL;
@@ -565,9 +621,13 @@ OMX_ERRORTYPE PortBase::ReturnThisBuffer(OMX_BUFFERHEADERTYPE *pBuffer)
     }
 
     ret = bufferdone_callback(owner, appdata, pBuffer);
-    LOGV("%s(): exit, after calling bufferdone callback (ret = 0x%08x)\n",
-         __func__, ret);
-    return ret;
+
+    LOGV("%s(): %s:%s:PortIndex %lu: exit done, "
+         "callback returned (0x%08x)\n", __FUNCTION__,
+         cbase->GetName(), cbase->GetWorkingRole(), portdefinition.nPortIndex,
+         ret);
+
+    return OMX_ErrorNone;
 }
 
 /* retain buffer */
@@ -576,11 +636,20 @@ OMX_ERRORTYPE PortBase::RetainThisBuffer(OMX_BUFFERHEADERTYPE *pBuffer,
 {
     int ret;
 
+    LOGV("%s(): %s:%s:PortIndex %lu:pBuffer %p: enter, %s\n", __FUNCTION__,
+         cbase->GetName(), cbase->GetWorkingRole(), portdefinition.nPortIndex,
+         pBuffer, (accumulate == true) ? "accumulate" : "getagain");
+
     /* push at tail of retainedbufferq */
     if (accumulate == true) {
         /* do not accumulate a buffer set EOS flag */
-        if (pBuffer->nFlags & OMX_BUFFERFLAG_EOS)
+        if (pBuffer->nFlags & OMX_BUFFERFLAG_EOS) {
+            LOGE("%s(): %s:%s:PortIndex %lu:pBuffer %p: exit failure, "
+                 "cannot accumulate EOS buffer\n", __FUNCTION__,
+                 cbase->GetName(), cbase->GetWorkingRole(),
+                 portdefinition.nPortIndex, pBuffer);
             return OMX_ErrorBadParameter;
+        }
 
         pthread_mutex_lock(&retainedbufferq_lock);
         if ((OMX_U32)queue_length(&retainedbufferq) <
@@ -588,8 +657,11 @@ OMX_ERRORTYPE PortBase::RetainThisBuffer(OMX_BUFFERHEADERTYPE *pBuffer,
             ret = queue_push_tail(&retainedbufferq, pBuffer);
         else {
             ret = OMX_ErrorInsufficientResources;
-            LOGE("%s(): retained bufferq length (%d) exceeds port's "
-                 "nBufferCountActual (%lu)", __func__,
+            LOGE("%s(): %s:%s:PortIndex %lu:pBuffer %p: exit failure, "
+                 "retained bufferq length (%d) exceeds port's actual count "
+                 "(%lu)\n", __FUNCTION__,
+                 cbase->GetName(), cbase->GetWorkingRole(),
+                 portdefinition.nPortIndex, pBuffer,
                  queue_length(&retainedbufferq),
                  portdefinition.nBufferCountActual);
         }
@@ -608,6 +680,9 @@ OMX_ERRORTYPE PortBase::RetainThisBuffer(OMX_BUFFERHEADERTYPE *pBuffer,
     if (ret)
         return OMX_ErrorInsufficientResources;
 
+    LOGV("%s(): %s:%s:PortIndex %lu:pBuffer %p: exit done\n", __FUNCTION__,
+         cbase->GetName(), cbase->GetWorkingRole(),
+         portdefinition.nPortIndex, pBuffer);
     return OMX_ErrorNone;
 }
 
@@ -615,7 +690,7 @@ void PortBase::ReturnAllRetainedBuffers(void)
 {
     OMX_BUFFERHEADERTYPE *buffer;
     OMX_ERRORTYPE ret;
-    int i;
+    int i = 0;
 
     pthread_mutex_lock(&retainedbufferq_lock);
 
@@ -623,18 +698,26 @@ void PortBase::ReturnAllRetainedBuffers(void)
         buffer = (OMX_BUFFERHEADERTYPE *)queue_pop_head(&retainedbufferq);
 
         if (buffer) {
-            LOGV("%s(): returns a retained buffer (%lu / %d)\n", __func__,
-                 i++, queue_length(&retainedbufferq));
+            LOGV("%s(): %s:%s:PortIndex %lu: returns a retained buffer "
+                 "(%p:%d/%d)\n", __FUNCTION__, cbase->GetName(),
+                 cbase->GetWorkingRole(), portdefinition.nPortIndex,
+                 buffer, i++, queue_length(&retainedbufferq));
 
             ret = ReturnThisBuffer(buffer);
             if (ret != OMX_ErrorNone)
-                LOGE("%s(): ReturnThisBuffer failed (ret 0x%x08x)\n", __func__,
-                     ret);
+                LOGE("%s(): %s:%s:PortIndex %lu: failed (ret : 0x%x08x)\n",
+                     __FUNCTION__,
+                     cbase->GetName(), cbase->GetWorkingRole(),
+                     portdefinition.nPortIndex, ret);
         }
     } while (buffer);
 
-    LOGV("%s(): returned all retained buffers\n", __func__);
     pthread_mutex_unlock(&retainedbufferq_lock);
+
+    LOGV_IF(i != 0,
+            "%s(): %s:%s:PortIndex %lu: returned all retained buffers (%d)\n",
+            __FUNCTION__, cbase->GetName(), cbase->GetWorkingRole(),
+            portdefinition.nPortIndex, i);
 }
 
 /* SendCommand:Flush/PortEnable/Disable */
@@ -643,11 +726,19 @@ OMX_ERRORTYPE PortBase::FlushPort(void)
 {
     OMX_BUFFERHEADERTYPE *buffer;
 
+    LOGV("%s(): %s:%s:PortIndex %lu: enter\n", __FUNCTION__,
+         cbase->GetName(), cbase->GetWorkingRole(),
+         portdefinition.nPortIndex);
+
     ReturnAllRetainedBuffers();
 
     while ((buffer = PopBuffer()))
         ReturnThisBuffer(buffer);
 
+    LOGV("%s(): %s:%s:PortIndex %lu: exit\n", __FUNCTION__,
+         cbase->GetName(), cbase->GetWorkingRole(),
+         portdefinition.nPortIndex);
+
     return OMX_ErrorNone;
 }
 
@@ -718,12 +809,29 @@ OMX_MARKTYPE *PortBase::PopMark(void)
     return mark;
 }
 
+static const char *state_name[PortBase::OMX_PortEnabled+2] = {
+    "OMX_PortDisabled",
+    "OMX_PortEnabled",
+    "UnKnown Port State",
+};
+
+const char *GetPortStateName(OMX_U8 state)
+{
+    if (state > PortBase::OMX_PortEnabled)
+        state = PortBase::OMX_PortEnabled+1;
+
+    return state_name[state];
+}
+
 OMX_ERRORTYPE PortBase::TransState(OMX_U8 transition)
 {
     OMX_U8 current;
     OMX_ERRORTYPE ret = OMX_ErrorNone;
 
-    LOGV("%s(): enter, transition=%d\n", __func__, transition);
+    LOGV("%s(): %s:%s:PortIndex %lu: enter, transition from %s to %s\n",
+         __FUNCTION__,
+         cbase->GetName(), cbase->GetWorkingRole(), portdefinition.nPortIndex,
+         GetPortStateName(state), GetPortStateName(transition));
 
     pthread_mutex_lock(&state_lock);
 
@@ -731,8 +839,10 @@ OMX_ERRORTYPE PortBase::TransState(OMX_U8 transition)
 
     if (current == transition) {
         ret = OMX_ErrorSameState;
-        LOGE("%s(): exit, same state (%d) (ret = 0x%08x)\n",
-             __func__, current, OMX_ErrorSameState);
+        LOGE("%s(): %s:%s:PortIndex %lu: exit failure, same state (%s)\n",
+             __FUNCTION__,
+             cbase->GetName(), cbase->GetWorkingRole(),
+             portdefinition.nPortIndex, GetPortStateName(current));
         goto unlock;
     }
 
@@ -747,14 +857,19 @@ OMX_ERRORTYPE PortBase::TransState(OMX_U8 transition)
     }
     else {
         ret = OMX_ErrorBadParameter;
-        LOGE("%s(): exit, invalid transition (%d) (ret = 0x%08x)\n",
-             __func__, transition, OMX_ErrorSameState);
+        LOGE("%s(): %s:%s:PortIndex %lu: exit failure, invalid transition "
+             "(%s)\n", __FUNCTION__,
+             cbase->GetName(), cbase->GetWorkingRole(),
+             portdefinition.nPortIndex, GetPortStateName(transition));
         goto unlock;
     }
 
     state = transition;
-    LOGV("%s(): transition from %d to %d completed\n", __func__,
-         current, transition);
+
+    LOGV("%s(): %s:%s:PortIndex %lu: transition from %s to %s complete\n",
+         __FUNCTION__,
+         cbase->GetName(), cbase->GetWorkingRole(), portdefinition.nPortIndex,
+         GetPortStateName(current), GetPortStateName(state));
 
 unlock:
     pthread_mutex_unlock(&state_lock);