Merge "stagefright: add runtime debug support" into lmp-mr1-dev

9 files changed, 764 insertions, 440 deletions

diff --git a/media/libstagefright/OMXCodec.cpp b/media/libstagefright/OMXCodec.cpp
index 288e07a..f26563e 100644
--- a/media/libstagefright/OMXCodec.cpp
+++ b/media/libstagefright/OMXCodec.cpp
@@ -47,10 +47,11 @@
 #include <media/stagefright/SkipCutBuffer.h>
 #include <utils/Vector.h>
 
-#include <OMX_Audio.h>
 #include <OMX_AudioExt.h>
 #include <OMX_Component.h>
 #include <OMX_IndexExt.h>
+#include <OMX_VideoExt.h>
+#include <OMX_AsString.h>
 
 #include "include/avc_utils.h"
 
@@ -4078,220 +4079,6 @@ void OMXCodec::signalBufferReturned(MediaBuffer *buffer) {
     CHECK(!"should not be here.");
 }
 
-static const char *imageCompressionFormatString(OMX_IMAGE_CODINGTYPE type) {
-    static const char *kNames[] = {
-        "OMX_IMAGE_CodingUnused",
-        "OMX_IMAGE_CodingAutoDetect",
-        "OMX_IMAGE_CodingJPEG",
-        "OMX_IMAGE_CodingJPEG2K",
-        "OMX_IMAGE_CodingEXIF",
-        "OMX_IMAGE_CodingTIFF",
-        "OMX_IMAGE_CodingGIF",
-        "OMX_IMAGE_CodingPNG",
-        "OMX_IMAGE_CodingLZW",
-        "OMX_IMAGE_CodingBMP",
-    };
-
-    size_t numNames = sizeof(kNames) / sizeof(kNames[0]);
-
-    if (type < 0 || (size_t)type >= numNames) {
-        return "UNKNOWN";
-    } else {
-        return kNames[type];
-    }
-}
-
-static const char *colorFormatString(OMX_COLOR_FORMATTYPE type) {
-    static const char *kNames[] = {
-        "OMX_COLOR_FormatUnused",
-        "OMX_COLOR_FormatMonochrome",
-        "OMX_COLOR_Format8bitRGB332",
-        "OMX_COLOR_Format12bitRGB444",
-        "OMX_COLOR_Format16bitARGB4444",
-        "OMX_COLOR_Format16bitARGB1555",
-        "OMX_COLOR_Format16bitRGB565",
-        "OMX_COLOR_Format16bitBGR565",
-        "OMX_COLOR_Format18bitRGB666",
-        "OMX_COLOR_Format18bitARGB1665",
-        "OMX_COLOR_Format19bitARGB1666",
-        "OMX_COLOR_Format24bitRGB888",
-        "OMX_COLOR_Format24bitBGR888",
-        "OMX_COLOR_Format24bitARGB1887",
-        "OMX_COLOR_Format25bitARGB1888",
-        "OMX_COLOR_Format32bitBGRA8888",
-        "OMX_COLOR_Format32bitARGB8888",
-        "OMX_COLOR_FormatYUV411Planar",
-        "OMX_COLOR_FormatYUV411PackedPlanar",
-        "OMX_COLOR_FormatYUV420Planar",
-        "OMX_COLOR_FormatYUV420PackedPlanar",
-        "OMX_COLOR_FormatYUV420SemiPlanar",
-        "OMX_COLOR_FormatYUV422Planar",
-        "OMX_COLOR_FormatYUV422PackedPlanar",
-        "OMX_COLOR_FormatYUV422SemiPlanar",
-        "OMX_COLOR_FormatYCbYCr",
-        "OMX_COLOR_FormatYCrYCb",
-        "OMX_COLOR_FormatCbYCrY",
-        "OMX_COLOR_FormatCrYCbY",
-        "OMX_COLOR_FormatYUV444Interleaved",
-        "OMX_COLOR_FormatRawBayer8bit",
-        "OMX_COLOR_FormatRawBayer10bit",
-        "OMX_COLOR_FormatRawBayer8bitcompressed",
-        "OMX_COLOR_FormatL2",
-        "OMX_COLOR_FormatL4",
-        "OMX_COLOR_FormatL8",
-        "OMX_COLOR_FormatL16",
-        "OMX_COLOR_FormatL24",
-        "OMX_COLOR_FormatL32",
-        "OMX_COLOR_FormatYUV420PackedSemiPlanar",
-        "OMX_COLOR_FormatYUV422PackedSemiPlanar",
-        "OMX_COLOR_Format18BitBGR666",
-        "OMX_COLOR_Format24BitARGB6666",
-        "OMX_COLOR_Format24BitABGR6666",
-    };
-
-    size_t numNames = sizeof(kNames) / sizeof(kNames[0]);
-
-    if (type == OMX_TI_COLOR_FormatYUV420PackedSemiPlanar) {
-        return "OMX_TI_COLOR_FormatYUV420PackedSemiPlanar";
-    } else if (type == OMX_QCOM_COLOR_FormatYVU420SemiPlanar) {
-        return "OMX_QCOM_COLOR_FormatYVU420SemiPlanar";
-    } else if (type < 0 || (size_t)type >= numNames) {
-        return "UNKNOWN";
-    } else {
-        return kNames[type];
-    }
-}
-
-static const char *videoCompressionFormatString(OMX_VIDEO_CODINGTYPE type) {
-    static const char *kNames[] = {
-        "OMX_VIDEO_CodingUnused",
-        "OMX_VIDEO_CodingAutoDetect",
-        "OMX_VIDEO_CodingMPEG2",
-        "OMX_VIDEO_CodingH263",
-        "OMX_VIDEO_CodingMPEG4",
-        "OMX_VIDEO_CodingWMV",
-        "OMX_VIDEO_CodingRV",
-        "OMX_VIDEO_CodingAVC",
-        "OMX_VIDEO_CodingMJPEG",
-    };
-
-    size_t numNames = sizeof(kNames) / sizeof(kNames[0]);
-
-    if (type < 0 || (size_t)type >= numNames) {
-        return "UNKNOWN";
-    } else {
-        return kNames[type];
-    }
-}
-
-static const char *audioCodingTypeString(OMX_AUDIO_CODINGTYPE type) {
-    static const char *kNames[] = {
-        "OMX_AUDIO_CodingUnused",
-        "OMX_AUDIO_CodingAutoDetect",
-        "OMX_AUDIO_CodingPCM",
-        "OMX_AUDIO_CodingADPCM",
-        "OMX_AUDIO_CodingAMR",
-        "OMX_AUDIO_CodingGSMFR",
-        "OMX_AUDIO_CodingGSMEFR",
-        "OMX_AUDIO_CodingGSMHR",
-        "OMX_AUDIO_CodingPDCFR",
-        "OMX_AUDIO_CodingPDCEFR",
-        "OMX_AUDIO_CodingPDCHR",
-        "OMX_AUDIO_CodingTDMAFR",
-        "OMX_AUDIO_CodingTDMAEFR",
-        "OMX_AUDIO_CodingQCELP8",
-        "OMX_AUDIO_CodingQCELP13",
-        "OMX_AUDIO_CodingEVRC",
-        "OMX_AUDIO_CodingSMV",
-        "OMX_AUDIO_CodingG711",
-        "OMX_AUDIO_CodingG723",
-        "OMX_AUDIO_CodingG726",
-        "OMX_AUDIO_CodingG729",
-        "OMX_AUDIO_CodingAAC",
-        "OMX_AUDIO_CodingMP3",
-        "OMX_AUDIO_CodingSBC",
-        "OMX_AUDIO_CodingVORBIS",
-        "OMX_AUDIO_CodingOPUS",
-        "OMX_AUDIO_CodingWMA",
-        "OMX_AUDIO_CodingRA",
-        "OMX_AUDIO_CodingMIDI",
-    };
-
-    size_t numNames = sizeof(kNames) / sizeof(kNames[0]);
-
-    if (type < 0 || (size_t)type >= numNames) {
-        return "UNKNOWN";
-    } else {
-        return kNames[type];
-    }
-}
-
-static const char *audioPCMModeString(OMX_AUDIO_PCMMODETYPE type) {
-    static const char *kNames[] = {
-        "OMX_AUDIO_PCMModeLinear",
-        "OMX_AUDIO_PCMModeALaw",
-        "OMX_AUDIO_PCMModeMULaw",
-    };
-
-    size_t numNames = sizeof(kNames) / sizeof(kNames[0]);
-
-    if (type < 0 || (size_t)type >= numNames) {
-        return "UNKNOWN";
-    } else {
-        return kNames[type];
-    }
-}
-
-static const char *amrBandModeString(OMX_AUDIO_AMRBANDMODETYPE type) {
-    static const char *kNames[] = {
-        "OMX_AUDIO_AMRBandModeUnused",
-        "OMX_AUDIO_AMRBandModeNB0",
-        "OMX_AUDIO_AMRBandModeNB1",
-        "OMX_AUDIO_AMRBandModeNB2",
-        "OMX_AUDIO_AMRBandModeNB3",
-        "OMX_AUDIO_AMRBandModeNB4",
-        "OMX_AUDIO_AMRBandModeNB5",
-        "OMX_AUDIO_AMRBandModeNB6",
-        "OMX_AUDIO_AMRBandModeNB7",
-        "OMX_AUDIO_AMRBandModeWB0",
-        "OMX_AUDIO_AMRBandModeWB1",
-        "OMX_AUDIO_AMRBandModeWB2",
-        "OMX_AUDIO_AMRBandModeWB3",
-        "OMX_AUDIO_AMRBandModeWB4",
-        "OMX_AUDIO_AMRBandModeWB5",
-        "OMX_AUDIO_AMRBandModeWB6",
-        "OMX_AUDIO_AMRBandModeWB7",
-        "OMX_AUDIO_AMRBandModeWB8",
-    };
-
-    size_t numNames = sizeof(kNames) / sizeof(kNames[0]);
-
-    if (type < 0 || (size_t)type >= numNames) {
-        return "UNKNOWN";
-    } else {
-        return kNames[type];
-    }
-}
-
-static const char *amrFrameFormatString(OMX_AUDIO_AMRFRAMEFORMATTYPE type) {
-    static const char *kNames[] = {
-        "OMX_AUDIO_AMRFrameFormatConformance",
-        "OMX_AUDIO_AMRFrameFormatIF1",
-        "OMX_AUDIO_AMRFrameFormatIF2",
-        "OMX_AUDIO_AMRFrameFormatFSF",
-        "OMX_AUDIO_AMRFrameFormatRTPPayload",
-        "OMX_AUDIO_AMRFrameFormatITU",
-    };
-
-    size_t numNames = sizeof(kNames) / sizeof(kNames[0]);
-
-    if (type < 0 || (size_t)type >= numNames) {
-        return "UNKNOWN";
-    } else {
-        return kNames[type];
-    }
-}
-
 void OMXCodec::dumpPortStatus(OMX_U32 portIndex) {
     OMX_PARAM_PORTDEFINITIONTYPE def;
     InitOMXParams(&def);
@@ -4322,10 +4109,10 @@ void OMXCodec::dumpPortStatus(OMX_U32 portIndex) {
             printf("  nStride = %" PRIu32 "\n", imageDef->nStride);
 
             printf("  eCompressionFormat = %s\n",
-                   imageCompressionFormatString(imageDef->eCompressionFormat));
+                   asString(imageDef->eCompressionFormat));
 
             printf("  eColorFormat = %s\n",
-                   colorFormatString(imageDef->eColorFormat));
+                   asString(imageDef->eColorFormat));
 
             break;
         }
@@ -4341,10 +4128,10 @@ void OMXCodec::dumpPortStatus(OMX_U32 portIndex) {
             printf("  nStride = %" PRIu32 "\n", videoDef->nStride);
 
             printf("  eCompressionFormat = %s\n",
-                   videoCompressionFormatString(videoDef->eCompressionFormat));
+                   asString(videoDef->eCompressionFormat));
 
             printf("  eColorFormat = %s\n",
-                   colorFormatString(videoDef->eColorFormat));
+                   asString(videoDef->eColorFormat));
 
             break;
         }
@@ -4356,7 +4143,7 @@ void OMXCodec::dumpPortStatus(OMX_U32 portIndex) {
             printf("\n");
             printf("  // Audio\n");
             printf("  eEncoding = %s\n",
-                   audioCodingTypeString(audioDef->eEncoding));
+                   asString(audioDef->eEncoding));
 
             if (audioDef->eEncoding == OMX_AUDIO_CodingPCM) {
                 OMX_AUDIO_PARAM_PCMMODETYPE params;
@@ -4376,7 +4163,7 @@ void OMXCodec::dumpPortStatus(OMX_U32 portIndex) {
                        params.eNumData == OMX_NumericalDataSigned
                         ? "signed" : "unsigned");
 
-                printf("  ePCMMode = %s\n", audioPCMModeString(params.ePCMMode));
+                printf("  ePCMMode = %s\n", asString(params.ePCMMode));
             } else if (audioDef->eEncoding == OMX_AUDIO_CodingAMR) {
                 OMX_AUDIO_PARAM_AMRTYPE amr;
                 InitOMXParams(&amr);
@@ -4388,9 +4175,9 @@ void OMXCodec::dumpPortStatus(OMX_U32 portIndex) {
 
                 printf("  nChannels = %" PRIu32 "\n", amr.nChannels);
                 printf("  eAMRBandMode = %s\n",
-                        amrBandModeString(amr.eAMRBandMode));
+                        asString(amr.eAMRBandMode));
                 printf("  eAMRFrameFormat = %s\n",
-                        amrFrameFormatString(amr.eAMRFrameFormat));
+                        asString(amr.eAMRFrameFormat));
             }
 
             break;
@@ -4699,12 +4486,7 @@ status_t QueryCodec(
         const char *componentName, const char *mime,
         bool isEncoder,
         CodecCapabilities *caps) {
-    if (strncmp(componentName, "OMX.", 4)) {
-        // Not an OpenMax component but a software codec.
-        caps->mFlags = 0;
-        caps->mComponentName = componentName;
-        return OK;
-    }
+    bool isVideo = !strncasecmp(mime, "video/", 6);
 
     sp<OMXCodecObserver> observer = new OMXCodecObserver;
     IOMX::node_id node;
@@ -4719,59 +4501,62 @@ status_t QueryCodec(
     caps->mFlags = 0;
     caps->mComponentName = componentName;
 
-    OMX_VIDEO_PARAM_PROFILELEVELTYPE param;
-    InitOMXParams(&param);
+    // NOTE: OMX does not provide a way to query AAC profile support
+    if (isVideo) {
+        OMX_VIDEO_PARAM_PROFILELEVELTYPE param;
+        InitOMXParams(&param);
 
-    param.nPortIndex = !isEncoder ? 0 : 1;
+        param.nPortIndex = !isEncoder ? 0 : 1;
 
-    for (param.nProfileIndex = 0;; ++param.nProfileIndex) {
-        err = omx->getParameter(
-                node, OMX_IndexParamVideoProfileLevelQuerySupported,
-                &param, sizeof(param));
+        for (param.nProfileIndex = 0;; ++param.nProfileIndex) {
+            err = omx->getParameter(
+                    node, OMX_IndexParamVideoProfileLevelQuerySupported,
+                    &param, sizeof(param));
 
-        if (err != OK) {
-            break;
-        }
-
-        CodecProfileLevel profileLevel;
-        profileLevel.mProfile = param.eProfile;
-        profileLevel.mLevel = param.eLevel;
+            if (err != OK) {
+                break;
+            }
 
-        caps->mProfileLevels.push(profileLevel);
-    }
+            CodecProfileLevel profileLevel;
+            profileLevel.mProfile = param.eProfile;
+            profileLevel.mLevel = param.eLevel;
 
-    // Color format query
-    // return colors in the order reported by the OMX component
-    // prefix "flexible" standard ones with the flexible equivalent
-    OMX_VIDEO_PARAM_PORTFORMATTYPE portFormat;
-    InitOMXParams(&portFormat);
-    portFormat.nPortIndex = !isEncoder ? 1 : 0;
-    for (portFormat.nIndex = 0;; ++portFormat.nIndex)  {
-        err = omx->getParameter(
-                node, OMX_IndexParamVideoPortFormat,
-                &portFormat, sizeof(portFormat));
-        if (err != OK) {
-            break;
+            caps->mProfileLevels.push(profileLevel);
         }
 
-        OMX_U32 flexibleEquivalent;
-        if (ACodec::isFlexibleColorFormat(
-                    omx, node, portFormat.eColorFormat, &flexibleEquivalent)) {
-            bool marked = false;
-            for (size_t i = 0; i < caps->mColorFormats.size(); i++) {
-                if (caps->mColorFormats.itemAt(i) == flexibleEquivalent) {
-                    marked = true;
-                    break;
-                }
+        // Color format query
+        // return colors in the order reported by the OMX component
+        // prefix "flexible" standard ones with the flexible equivalent
+        OMX_VIDEO_PARAM_PORTFORMATTYPE portFormat;
+        InitOMXParams(&portFormat);
+        portFormat.nPortIndex = !isEncoder ? 1 : 0;
+        for (portFormat.nIndex = 0;; ++portFormat.nIndex)  {
+            err = omx->getParameter(
+                    node, OMX_IndexParamVideoPortFormat,
+                    &portFormat, sizeof(portFormat));
+            if (err != OK) {
+                break;
             }
-            if (!marked) {
-                caps->mColorFormats.push(flexibleEquivalent);
+
+            OMX_U32 flexibleEquivalent;
+            if (ACodec::isFlexibleColorFormat(
+                        omx, node, portFormat.eColorFormat, &flexibleEquivalent)) {
+                bool marked = false;
+                for (size_t i = 0; i < caps->mColorFormats.size(); i++) {
+                    if (caps->mColorFormats.itemAt(i) == flexibleEquivalent) {
+                        marked = true;
+                        break;
+                    }
+                }
+                if (!marked) {
+                    caps->mColorFormats.push(flexibleEquivalent);
+                }
             }
+            caps->mColorFormats.push(portFormat.eColorFormat);
         }
-        caps->mColorFormats.push(portFormat.eColorFormat);
     }
 
-    if (!isEncoder && !strncmp(mime, "video/", 6)) {
+    if (isVideo && !isEncoder) {
         if (omx->storeMetaDataInBuffers(
                     node, 1 /* port index */, OMX_TRUE) == OK ||
             omx->prepareForAdaptivePlayback(
diff --git a/media/libstagefright/foundation/ADebug.cpp b/media/libstagefright/foundation/ADebug.cpp
new file mode 100644
index 0000000..ec4a960
--- /dev/null
+++ b/media/libstagefright/foundation/ADebug.cpp
@@ -0,0 +1,117 @@
+/*
+ * Copyright 2014 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include <errno.h>
+#include <stdlib.h>
+#include <ctype.h>
+
+#define LOG_TAG "ADebug"
+#include <utils/Log.h>
+#include <utils/misc.h>
+
+#include <cutils/properties.h>
+
+#include <ADebug.h>
+#include <AStringUtils.h>
+#include <AUtils.h>
+
+namespace android {
+
+//static
+ADebug::Level ADebug::GetDebugLevelFromString(
+        const char *name, const char *value, ADebug::Level def) {
+    // split on ,
+    const char *next = value, *current;
+    const unsigned long maxLevel = (unsigned long)kDebugMax;
+    while (next != NULL) {
+        current = next;
+        next = strchr(current, ',');
+        if (next != NULL) {
+            ++next;  // pass ,
+        }
+
+        while (isspace(*current)) {
+            ++current;
+        }
+        // check for :
+        char *colon = strchr(current, ':');
+
+        // get level
+        char *end;
+        errno = 0;  // strtoul does not clear errno, but it can be set for any return value
+        unsigned long level = strtoul(current, &end, 10);
+        while (isspace(*end)) {
+            ++end;
+        }
+        if (errno != 0 || end == current || (end != colon && *end != '\0' && end != next)) {
+            // invalid level - skip
+            continue;
+        }
+        if (colon != NULL) {
+            // check if pattern matches
+            do {  // skip colon and spaces
+                ++colon;
+            } while (isspace(*colon));
+            size_t globLen = (next == NULL ? strlen(colon) : (next - 1 - colon));
+            while (globLen > 0 && isspace(colon[globLen - 1])) {
+                --globLen;  // trim glob
+            }
+
+            if (!AStringUtils::MatchesGlob(
+                    colon, globLen, name, strlen(name), true /* ignoreCase */)) {
+                continue;
+            }
+        }
+
+        // update debug level
+        def = (Level)min(level, maxLevel);
+    }
+    return def;
+}
+
+//static
+ADebug::Level ADebug::GetDebugLevelFromProperty(
+        const char *name, const char *propertyName, ADebug::Level def) {
+    char value[PROPERTY_VALUE_MAX];
+    if (property_get(propertyName, value, NULL)) {
+        return GetDebugLevelFromString(name, value, def);
+    }
+    return def;
+}
+
+//static
+char *ADebug::GetDebugName(const char *name) {
+    char *debugName = strdup(name);
+    const char *terms[] = { "omx", "video", "audio" };
+    for (size_t i = 0; i < NELEM(terms) && debugName != NULL; i++) {
+        const char *term = terms[i];
+        const size_t len = strlen(term);
+        char *match = strcasestr(debugName, term);
+        if (match != NULL && (match == debugName || match[-1] == '.'
+                || match[len] == '.' || match[len] == '\0')) {
+            char *src = match + len;
+            if (match == debugName || match[-1] == '.') {
+                src += (*src == '.');  // remove trailing or double .
+            }
+            memmove(match, src, debugName + strlen(debugName) - src + 1);
+        }
+    }
+
+    return debugName;
+}
+
+}  // namespace android
+
diff --git a/media/libstagefright/foundation/AStringUtils.cpp b/media/libstagefright/foundation/AStringUtils.cpp
new file mode 100644
index 0000000..e5a846c
--- /dev/null
+++ b/media/libstagefright/foundation/AStringUtils.cpp
@@ -0,0 +1,77 @@
+/*
+ * Copyright 2014 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include <string.h>
+#include <AStringUtils.h>
+
+namespace android {
+
+// static
+int AStringUtils::Compare(const char *a, const char *b, size_t len, bool ignoreCase) {
+    // this method relies on a trailing '\0' if a or b are shorter than len
+    return ignoreCase ? strncasecmp(a, b, len) : strncmp(a, b, len);
+}
+
+// static
+bool AStringUtils::MatchesGlob(
+        const char *glob, size_t globLen, const char *str, size_t strLen, bool ignoreCase) {
+    // this method does not assume a trailing '\0'
+    size_t ix = 0, globIx = 0;
+
+    // pattern must match until first '*'
+    while (globIx < globLen && glob[globIx] != '*') {
+        ++globIx;
+    }
+    if (strLen < globIx || Compare(str, glob, globIx /* len */, ignoreCase)) {
+        return false;
+    }
+    ix = globIx;
+
+    // process by * separated sections
+    while (globIx < globLen) {
+        ++globIx;
+        size_t start = globIx;
+        while (globIx < globLen && glob[globIx] != '*') {
+            ++globIx;
+        }
+        size_t len = globIx - start;
+        const char *pattern = glob + start;
+
+        if (globIx == globLen) {
+            // last pattern must match tail
+            if (ix + len > strLen) {
+                return false;
+            }
+            const char *tail = str + strLen - len;
+            return !Compare(tail, pattern, len, ignoreCase);
+        }
+        // progress after first occurrence of pattern
+        while (ix + len <= strLen && Compare(str + ix, pattern, len, ignoreCase)) {
+            ++ix;
+        }
+        if (ix + len > strLen) {
+            return false;
+        }
+        ix += len;
+        // we will loop around as globIx < globLen
+    }
+
+    // we only get here if there were no * in the pattern
+    return ix == strLen;
+}
+
+}  // namespace android
+
diff --git a/media/libstagefright/foundation/Android.mk b/media/libstagefright/foundation/Android.mk
index 90a6a23..c1dd6ce 100644
--- a/media/libstagefright/foundation/Android.mk
+++ b/media/libstagefright/foundation/Android.mk
@@ -5,6 +5,7 @@ LOCAL_SRC_FILES:=                 \
     AAtomizer.cpp                 \
     ABitReader.cpp                \
     ABuffer.cpp                   \
+    ADebug.cpp                    \
     AHandler.cpp                  \
     AHierarchicalStateMachine.cpp \
     ALooper.cpp                   \
@@ -12,6 +13,7 @@ LOCAL_SRC_FILES:=                 \
     AMessage.cpp                  \
     ANetworkSession.cpp           \
     AString.cpp                   \
+    AStringUtils.cpp              \
     ParsedMessage.cpp             \
     base64.cpp                    \
     hexdump.cpp
@@ -22,6 +24,7 @@ LOCAL_C_INCLUDES:= \
 LOCAL_SHARED_LIBRARIES := \
         libbinder         \
         libutils          \
+        libcutils         \
         liblog
 
 LOCAL_CFLAGS += -Wno-multichar -Werror
diff --git a/media/libstagefright/include/OMXNodeInstance.h b/media/libstagefright/include/OMXNodeInstance.h
index 24d431c..104dcfc 100644
--- a/media/libstagefright/include/OMXNodeInstance.h
+++ b/media/libstagefright/include/OMXNodeInstance.h
@@ -31,7 +31,7 @@ struct GraphicBufferSource;
 
 struct OMXNodeInstance {
     OMXNodeInstance(
-            OMX *owner, const sp<IOMXObserver> &observer);
+            OMX *owner, const sp<IOMXObserver> &observer, const char *name);
 
     void setHandle(OMX::node_id node_id, OMX_HANDLETYPE handle);
 
@@ -149,6 +149,18 @@ private:
     KeyedVector<OMX_BUFFERHEADERTYPE *, OMX::buffer_id> mBufferHeaderToBufferID;
 #endif
 
+    // For debug support
+    char *mName;
+    int DEBUG;
+    size_t mNumPortBuffers[2];  // modified under mLock, read outside for debug
+    Mutex mDebugLock;
+    // following are modified and read under mDebugLock
+    int DEBUG_BUMP;
+    SortedVector<OMX_BUFFERHEADERTYPE *> mInputBuffersWithCodec, mOutputBuffersWithCodec;
+    size_t mDebugLevelBumpPendingBuffers[2];
+    void bumpDebugLevel_l(size_t numInputBuffers, size_t numOutputBuffers);
+    void unbumpDebugLevel_l(size_t portIndex);
+
     ~OMXNodeInstance();
 
     void addActiveBuffer(OMX_U32 portIndex, OMX::buffer_id id);
@@ -186,6 +198,10 @@ private:
             OMX_U32 portIndex, OMX_BOOL enable,
             OMX_BOOL useGraphicBuffer, OMX_BOOL *usingGraphicBufferInMeta);
 
+    status_t emptyBuffer_l(
+            OMX_BUFFERHEADERTYPE *header,
+            OMX_U32 flags, OMX_TICKS timestamp, intptr_t debugAddr);
+
     sp<GraphicBufferSource> getGraphicBufferSource();
     void setGraphicBufferSource(const sp<GraphicBufferSource>& bufferSource);
 
diff --git a/media/libstagefright/omx/OMX.cpp b/media/libstagefright/omx/OMX.cpp
index 41407e4..6d46eee 100644
--- a/media/libstagefright/omx/OMX.cpp
+++ b/media/libstagefright/omx/OMX.cpp
@@ -225,7 +225,7 @@ status_t OMX::allocateNode(
 
     *node = 0;
 
-    OMXNodeInstance *instance = new OMXNodeInstance(this, observer);
+    OMXNodeInstance *instance = new OMXNodeInstance(this, observer, name);
 
     OMX_COMPONENTTYPE *handle;
     OMX_ERRORTYPE err = mMaster->makeComponentInstance(
diff --git a/media/libstagefright/omx/OMXNodeInstance.cpp b/media/libstagefright/omx/OMXNodeInstance.cpp
index f9c84e2..c04d95f 100644
--- a/media/libstagefright/omx/OMXNodeInstance.cpp
+++ b/media/libstagefright/omx/OMXNodeInstance.cpp
@@ -18,11 +18,15 @@
 #define LOG_TAG "OMXNodeInstance"
 #include <utils/Log.h>
 
+#include <inttypes.h>
+
 #include "../include/OMXNodeInstance.h"
 #include "OMXMaster.h"
 #include "GraphicBufferSource.h"
 
 #include <OMX_Component.h>
+#include <OMX_IndexExt.h>
+#include <OMX_AsString.h>
 
 #include <binder/IMemory.h>
 #include <gui/BufferQueue.h>
@@ -30,7 +34,68 @@
 #include <media/stagefright/foundation/ADebug.h>
 #include <media/stagefright/MediaErrors.h>
 
+#include <utils/misc.h>
+
 static const OMX_U32 kPortIndexInput = 0;
+static const OMX_U32 kPortIndexOutput = 1;
+
+#define CLOGW(fmt, ...) ALOGW("[%x:%s] " fmt, mNodeID, mName, ##__VA_ARGS__)
+
+#define CLOG_ERROR_IF(cond, fn, err, fmt, ...) \
+    ALOGE_IF(cond, #fn "(%x:%s, " fmt ") ERROR: %s(%#x)", \
+    mNodeID, mName, ##__VA_ARGS__, asString(err), err)
+#define CLOG_ERROR(fn, err, fmt, ...) CLOG_ERROR_IF(true, fn, err, fmt, ##__VA_ARGS__)
+#define CLOG_IF_ERROR(fn, err, fmt, ...) \
+    CLOG_ERROR_IF((err) != OMX_ErrorNone, fn, err, fmt, ##__VA_ARGS__)
+
+#define CLOGI_(level, fn, fmt, ...) \
+    ALOGI_IF(DEBUG >= (level), #fn "(%x:%s, " fmt ")", mNodeID, mName, ##__VA_ARGS__)
+#define CLOGD_(level, fn, fmt, ...) \
+    ALOGD_IF(DEBUG >= (level), #fn "(%x:%s, " fmt ")", mNodeID, mName, ##__VA_ARGS__)
+
+#define CLOG_LIFE(fn, fmt, ...)     CLOGI_(ADebug::kDebugLifeCycle,     fn, fmt, ##__VA_ARGS__)
+#define CLOG_STATE(fn, fmt, ...)    CLOGI_(ADebug::kDebugState,         fn, fmt, ##__VA_ARGS__)
+#define CLOG_CONFIG(fn, fmt, ...)   CLOGI_(ADebug::kDebugConfig,        fn, fmt, ##__VA_ARGS__)
+#define CLOG_INTERNAL(fn, fmt, ...) CLOGD_(ADebug::kDebugInternalState, fn, fmt, ##__VA_ARGS__)
+
+#define CLOG_DEBUG_IF(cond, fn, fmt, ...) \
+    ALOGD_IF(cond, #fn "(%x, " fmt ")", mNodeID, ##__VA_ARGS__)
+
+#define CLOG_BUFFER(fn, fmt, ...) \
+    CLOG_DEBUG_IF(DEBUG >= ADebug::kDebugAll, fn, fmt, ##__VA_ARGS__)
+#define CLOG_BUMPED_BUFFER(fn, fmt, ...) \
+    CLOG_DEBUG_IF(DEBUG_BUMP >= ADebug::kDebugAll, fn, fmt, ##__VA_ARGS__)
+
+/* buffer formatting */
+#define BUFFER_FMT(port, fmt, ...) "%s:%u " fmt, portString(port), (port), ##__VA_ARGS__
+#define NEW_BUFFER_FMT(buffer_id, port, fmt, ...) \
+    BUFFER_FMT(port, fmt ") (#%zu => %#x", ##__VA_ARGS__, mActiveBuffers.size(), (buffer_id))
+
+#define SIMPLE_BUFFER(port, size, data) BUFFER_FMT(port, "%zu@%p", (size), (data))
+#define SIMPLE_NEW_BUFFER(buffer_id, port, size, data) \
+    NEW_BUFFER_FMT(buffer_id, port, "%zu@%p", (size), (data))
+
+#define EMPTY_BUFFER(addr, header) "%#x [%u@%p]", \
+    (addr), (header)->nAllocLen, (header)->pBuffer
+#define FULL_BUFFER(addr, header) "%#" PRIxPTR " [%u@%p (%u..+%u) f=%x ts=%lld]", \
+    (intptr_t)(addr), (header)->nAllocLen, (header)->pBuffer, \
+    (header)->nOffset, (header)->nFilledLen, (header)->nFlags, (header)->nTimeStamp
+
+#define WITH_STATS_WRAPPER(fmt, ...) fmt " { IN=%zu/%zu OUT=%zu/%zu }", ##__VA_ARGS__, \
+    mInputBuffersWithCodec.size(), mNumPortBuffers[kPortIndexInput], \
+    mOutputBuffersWithCodec.size(), mNumPortBuffers[kPortIndexOutput]
+// TRICKY: this is needed so formatting macros expand before substitution
+#define WITH_STATS(fmt, ...) WITH_STATS_WRAPPER(fmt, ##__VA_ARGS__)
+
+template<class T>
+static void InitOMXParams(T *params) {
+    memset(params, 0, sizeof(T));
+    params->nSize = sizeof(T);
+    params->nVersion.s.nVersionMajor = 1;
+    params->nVersion.s.nVersionMinor = 0;
+    params->nVersion.s.nRevision = 0;
+    params->nVersion.s.nStep = 0;
+}
 
 namespace android {
 
@@ -56,8 +121,8 @@ struct BufferMeta {
         }
 
         memcpy((OMX_U8 *)mMem->pointer() + header->nOffset,
-               header->pBuffer + header->nOffset,
-               header->nFilledLen);
+                header->pBuffer + header->nOffset,
+                header->nFilledLen);
     }
 
     void CopyToOMX(const OMX_BUFFERHEADERTYPE *header) {
@@ -66,8 +131,8 @@ struct BufferMeta {
         }
 
         memcpy(header->pBuffer + header->nOffset,
-               (const OMX_U8 *)mMem->pointer() + header->nOffset,
-               header->nFilledLen);
+                (const OMX_U8 *)mMem->pointer() + header->nOffset,
+                header->nFilledLen);
     }
 
     void setGraphicBuffer(const sp<GraphicBuffer> &graphicBuffer) {
@@ -89,8 +154,17 @@ OMX_CALLBACKTYPE OMXNodeInstance::kCallbacks = {
     &OnEvent, &OnEmptyBufferDone, &OnFillBufferDone
 };
 
+static inline const char *portString(OMX_U32 portIndex) {
+    switch (portIndex) {
+        case kPortIndexInput:  return "Input";
+        case kPortIndexOutput: return "Output";
+        case ~0:               return "All";
+        default:               return "port";
+    }
+}
+
 OMXNodeInstance::OMXNodeInstance(
-        OMX *owner, const sp<IOMXObserver> &observer)
+        OMX *owner, const sp<IOMXObserver> &observer, const char *name)
     : mOwner(owner),
       mNodeID(0),
       mHandle(NULL),
@@ -100,15 +174,25 @@ OMXNodeInstance::OMXNodeInstance(
       , mBufferIDCount(0)
 #endif
 {
+    mName = ADebug::GetDebugName(name);
+    DEBUG = ADebug::GetDebugLevelFromProperty(name, "debug.stagefright.omx-debug");
+    ALOGV("debug level for %s is %d", name, DEBUG);
+    DEBUG_BUMP = DEBUG;
+    mNumPortBuffers[0] = 0;
+    mNumPortBuffers[1] = 0;
+    mDebugLevelBumpPendingBuffers[0] = 0;
+    mDebugLevelBumpPendingBuffers[1] = 0;
 }
 
 OMXNodeInstance::~OMXNodeInstance() {
+    free(mName);
     CHECK(mHandle == NULL);
 }
 
 void OMXNodeInstance::setHandle(OMX::node_id node_id, OMX_HANDLETYPE handle) {
-    CHECK(mHandle == NULL);
     mNodeID = node_id;
+    CLOG_LIFE(allocateNode, "handle=%p", handle);
+    CHECK(mHandle == NULL);
     mHandle = handle;
 }
 
@@ -120,6 +204,7 @@ sp<GraphicBufferSource> OMXNodeInstance::getGraphicBufferSource() {
 void OMXNodeInstance::setGraphicBufferSource(
         const sp<GraphicBufferSource>& bufferSource) {
     Mutex::Autolock autoLock(mGraphicBufferSourceLock);
+    CLOG_INTERNAL(setGraphicBufferSource, "%p", bufferSource.get());
     mGraphicBufferSource = bufferSource;
 }
 
@@ -140,6 +225,7 @@ static status_t StatusFromOMXError(OMX_ERRORTYPE err) {
         case OMX_ErrorNone:
             return OK;
         case OMX_ErrorUnsupportedSetting:
+        case OMX_ErrorUnsupportedIndex:
             return ERROR_UNSUPPORTED;
         default:
             return UNKNOWN_ERROR;
@@ -147,6 +233,7 @@ static status_t StatusFromOMXError(OMX_ERRORTYPE err) {
 }
 
 status_t OMXNodeInstance::freeNode(OMXMaster *master) {
+    CLOG_LIFE(freeNode, "handle=%p", mHandle);
     static int32_t kMaxNumIterations = 10;
 
     // exit if we have already freed the node
@@ -175,10 +262,11 @@ status_t OMXNodeInstance::freeNode(OMXMaster *master) {
             OMX_ERRORTYPE err;
             int32_t iteration = 0;
             while ((err = OMX_GetState(mHandle, &state)) == OMX_ErrorNone
-                   && state != OMX_StateIdle
-                   && state != OMX_StateInvalid) {
+                    && state != OMX_StateIdle
+                    && state != OMX_StateInvalid) {
                 if (++iteration > kMaxNumIterations) {
-                    ALOGE("component failed to enter Idle state, aborting.");
+                    CLOGW("failed to enter Idle state (now %s(%d), aborting.",
+                            asString(state), state);
                     state = OMX_StateInvalid;
                     break;
                 }
@@ -204,10 +292,11 @@ status_t OMXNodeInstance::freeNode(OMXMaster *master) {
             OMX_ERRORTYPE err;
             int32_t iteration = 0;
             while ((err = OMX_GetState(mHandle, &state)) == OMX_ErrorNone
-                   && state != OMX_StateLoaded
-                   && state != OMX_StateInvalid) {
+                    && state != OMX_StateLoaded
+                    && state != OMX_StateInvalid) {
                 if (++iteration > kMaxNumIterations) {
-                    ALOGE("component failed to enter Loaded state, aborting.");
+                    CLOGW("failed to enter Loaded state (now %s(%d), aborting.",
+                            asString(state), state);
                     state = OMX_StateInvalid;
                     break;
                 }
@@ -225,20 +314,18 @@ status_t OMXNodeInstance::freeNode(OMXMaster *master) {
             break;
 
         default:
-            CHECK(!"should not be here, unknown state.");
+            LOG_ALWAYS_FATAL("unknown state %s(%#x).", asString(state), state);
             break;
     }
 
-    ALOGV("calling destroyComponentInstance");
+    ALOGV("[%x:%s] calling destroyComponentInstance", mNodeID, mName);
     OMX_ERRORTYPE err = master->destroyComponentInstance(
             static_cast<OMX_COMPONENTTYPE *>(mHandle));
-    ALOGV("destroyComponentInstance returned err %d", err);
 
     mHandle = NULL;
-
-    if (err != OMX_ErrorNone) {
-        ALOGE("FreeHandle FAILED with error 0x%08x.", err);
-    }
+    CLOG_IF_ERROR(freeNode, err, "");
+    free(mName);
+    mName = NULL;
 
     mOwner->invalidateNodeID(mNodeID);
     mNodeID = 0;
@@ -270,7 +357,17 @@ status_t OMXNodeInstance::sendCommand(
 
     Mutex::Autolock autoLock(mLock);
 
+    // bump internal-state debug level for 2 input and output frames past a command
+    {
+        Mutex::Autolock _l(mDebugLock);
+        bumpDebugLevel_l(2 /* numInputBuffers */, 2 /* numOutputBuffers */);
+    }
+
+    const char *paramString =
+        cmd == OMX_CommandStateSet ? asString((OMX_STATETYPE)param) : portString(param);
+    CLOG_STATE(sendCommand, "%s(%d), %s(%d)", asString(cmd), cmd, paramString, param);
     OMX_ERRORTYPE err = OMX_SendCommand(mHandle, cmd, param, NULL);
+    CLOG_IF_ERROR(sendCommand, err, "%s(%d), %s(%d)", asString(cmd), cmd, paramString, param);
     return StatusFromOMXError(err);
 }
 
@@ -279,17 +376,23 @@ status_t OMXNodeInstance::getParameter(
     Mutex::Autolock autoLock(mLock);
 
     OMX_ERRORTYPE err = OMX_GetParameter(mHandle, index, params);
-    ALOGE_IF(err != OMX_ErrorNone, "getParameter(%d) ERROR: %#x", index, err);
+    OMX_INDEXEXTTYPE extIndex = (OMX_INDEXEXTTYPE)index;
+    // some errors are expected for getParameter
+    if (err != OMX_ErrorNoMore) {
+        CLOG_IF_ERROR(getParameter, err, "%s(%#x)", asString(extIndex), index);
+    }
     return StatusFromOMXError(err);
 }
 
 status_t OMXNodeInstance::setParameter(
-        OMX_INDEXTYPE index, const void *params, size_t /* size */) {
+        OMX_INDEXTYPE index, const void *params, size_t size) {
     Mutex::Autolock autoLock(mLock);
+    OMX_INDEXEXTTYPE extIndex = (OMX_INDEXEXTTYPE)index;
+    CLOG_CONFIG(setParameter, "%s(%#x), %zu@%p)", asString(extIndex), index, size, params);
 
     OMX_ERRORTYPE err = OMX_SetParameter(
             mHandle, index, const_cast<void *>(params));
-    ALOGE_IF(err != OMX_ErrorNone, "setParameter(%d) ERROR: %#x", index, err);
+    CLOG_IF_ERROR(setParameter, err, "%s(%#x)", asString(extIndex), index);
     return StatusFromOMXError(err);
 }
 
@@ -298,16 +401,23 @@ status_t OMXNodeInstance::getConfig(
     Mutex::Autolock autoLock(mLock);
 
     OMX_ERRORTYPE err = OMX_GetConfig(mHandle, index, params);
+    OMX_INDEXEXTTYPE extIndex = (OMX_INDEXEXTTYPE)index;
+    // some errors are expected for getConfig
+    if (err != OMX_ErrorNoMore) {
+        CLOG_IF_ERROR(getConfig, err, "%s(%#x)", asString(extIndex), index);
+    }
     return StatusFromOMXError(err);
 }
 
 status_t OMXNodeInstance::setConfig(
-        OMX_INDEXTYPE index, const void *params, size_t /* size */) {
+        OMX_INDEXTYPE index, const void *params, size_t size) {
     Mutex::Autolock autoLock(mLock);
+    OMX_INDEXEXTTYPE extIndex = (OMX_INDEXEXTTYPE)index;
+    CLOG_CONFIG(setConfig, "%s(%#x), %zu@%p)", asString(extIndex), index, size, params);
 
     OMX_ERRORTYPE err = OMX_SetConfig(
             mHandle, index, const_cast<void *>(params));
-
+    CLOG_IF_ERROR(setConfig, err, "%s(%#x)", asString(extIndex), index);
     return StatusFromOMXError(err);
 }
 
@@ -315,13 +425,14 @@ status_t OMXNodeInstance::getState(OMX_STATETYPE* state) {
     Mutex::Autolock autoLock(mLock);
 
     OMX_ERRORTYPE err = OMX_GetState(mHandle, state);
-
+    CLOG_IF_ERROR(getState, err, "");
     return StatusFromOMXError(err);
 }
 
 status_t OMXNodeInstance::enableGraphicBuffers(
         OMX_U32 portIndex, OMX_BOOL enable) {
     Mutex::Autolock autoLock(mLock);
+    CLOG_CONFIG(enableGraphicBuffers, "%s:%u, %d", portString(portIndex), portIndex, enable);
     OMX_STRING name = const_cast<OMX_STRING>(
             "OMX.google.android.index.enableAndroidNativeBuffers");
 
@@ -329,32 +440,19 @@ status_t OMXNodeInstance::enableGraphicBuffers(
     OMX_ERRORTYPE err = OMX_GetExtensionIndex(mHandle, name, &index);
 
     if (err != OMX_ErrorNone) {
-        if (enable) {
-            ALOGE("OMX_GetExtensionIndex %s failed", name);
-        }
-
+        CLOG_ERROR_IF(enable, getExtensionIndex, err, "%s", name);
         return StatusFromOMXError(err);
     }
 
-    OMX_VERSIONTYPE ver;
-    ver.s.nVersionMajor = 1;
-    ver.s.nVersionMinor = 0;
-    ver.s.nRevision = 0;
-    ver.s.nStep = 0;
-    EnableAndroidNativeBuffersParams params = {
-        sizeof(EnableAndroidNativeBuffersParams), ver, portIndex, enable,
-    };
+    EnableAndroidNativeBuffersParams params;
+    InitOMXParams(&params);
+    params.nPortIndex = portIndex;
+    params.enable = enable;
 
     err = OMX_SetParameter(mHandle, index, &params);
-
-    if (err != OMX_ErrorNone) {
-        ALOGE("OMX_EnableAndroidNativeBuffers failed with error %d (0x%08x)",
-                err, err);
-
-        return UNKNOWN_ERROR;
-    }
-
-    return OK;
+    CLOG_IF_ERROR(setParameter, err, "%s(%#x): %s:%u en=%d", name, index,
+            portString(portIndex), portIndex, enable);
+    return StatusFromOMXError(err);
 }
 
 status_t OMXNodeInstance::getGraphicBufferUsage(
@@ -367,26 +465,19 @@ status_t OMXNodeInstance::getGraphicBufferUsage(
     OMX_ERRORTYPE err = OMX_GetExtensionIndex(mHandle, name, &index);
 
     if (err != OMX_ErrorNone) {
-        ALOGE("OMX_GetExtensionIndex %s failed", name);
-
+        CLOG_ERROR(getExtensionIndex, err, "%s", name);
         return StatusFromOMXError(err);
     }
 
-    OMX_VERSIONTYPE ver;
-    ver.s.nVersionMajor = 1;
-    ver.s.nVersionMinor = 0;
-    ver.s.nRevision = 0;
-    ver.s.nStep = 0;
-    GetAndroidNativeBufferUsageParams params = {
-        sizeof(GetAndroidNativeBufferUsageParams), ver, portIndex, 0,
-    };
+    GetAndroidNativeBufferUsageParams params;
+    InitOMXParams(&params);
+    params.nPortIndex = portIndex;
 
     err = OMX_GetParameter(mHandle, index, &params);
-
     if (err != OMX_ErrorNone) {
-        ALOGE("OMX_GetAndroidNativeBufferUsage failed with error %d (0x%08x)",
-                err, err);
-        return UNKNOWN_ERROR;
+        CLOG_ERROR(getParameter, err, "%s(%#x): %s:%u", name, index,
+                portString(portIndex), portIndex);
+        return StatusFromOMXError(err);
     }
 
     *usage = params.nUsage;
@@ -398,6 +489,7 @@ status_t OMXNodeInstance::storeMetaDataInBuffers(
         OMX_U32 portIndex,
         OMX_BOOL enable) {
     Mutex::Autolock autolock(mLock);
+    CLOG_CONFIG(storeMetaDataInBuffers, "%s:%u en:%d", portString(portIndex), portIndex, enable);
     return storeMetaDataInBuffers_l(
             portIndex, enable,
             OMX_FALSE /* useGraphicBuffer */, NULL /* usingGraphicBufferInMetadata */);
@@ -424,37 +516,42 @@ status_t OMXNodeInstance::storeMetaDataInBuffers_l(
                 : OMX_ErrorBadParameter;
     if (err == OMX_ErrorNone) {
         *usingGraphicBufferInMetadata = OMX_TRUE;
+        name = graphicBufferName;
     } else {
-        *usingGraphicBufferInMetadata = OMX_FALSE;
         err = OMX_GetExtensionIndex(mHandle, name, &index);
     }
 
-    if (err != OMX_ErrorNone) {
-        ALOGE("OMX_GetExtensionIndex %s failed", name);
-        return StatusFromOMXError(err);
-    }
-
-    StoreMetaDataInBuffersParams params;
-    memset(&params, 0, sizeof(params));
-    params.nSize = sizeof(params);
+    OMX_ERRORTYPE xerr = err;
+    if (err == OMX_ErrorNone) {
+        StoreMetaDataInBuffersParams params;
+        InitOMXParams(&params);
+        params.nPortIndex = portIndex;
+        params.bStoreMetaData = enable;
 
-    // Version: 1.0.0.0
-    params.nVersion.s.nVersionMajor = 1;
+        err = OMX_SetParameter(mHandle, index, &params);
+    }
 
-    params.nPortIndex = portIndex;
-    params.bStoreMetaData = enable;
-    if ((err = OMX_SetParameter(mHandle, index, &params)) != OMX_ErrorNone) {
-        ALOGE("OMX_SetParameter() failed for StoreMetaDataInBuffers: 0x%08x", err);
+    // don't log loud error if component does not support metadata mode on the output
+    if (err != OMX_ErrorNone) {
         *usingGraphicBufferInMetadata = OMX_FALSE;
-        return UNKNOWN_ERROR;
+        if (err == OMX_ErrorUnsupportedIndex && portIndex == kPortIndexOutput) {
+            CLOGW("component does not support metadata mode; using fallback");
+        } else if (xerr != OMX_ErrorNone) {
+            CLOG_ERROR(getExtensionIndex, xerr, "%s", name);
+        } else {
+            CLOG_ERROR(setParameter, err, "%s(%#x): %s:%u en=%d GB=%d", name, index,
+                    portString(portIndex), portIndex, enable, useGraphicBuffer);
+        }
     }
-    return err;
+    return StatusFromOMXError(err);
 }
 
 status_t OMXNodeInstance::prepareForAdaptivePlayback(
         OMX_U32 portIndex, OMX_BOOL enable, OMX_U32 maxFrameWidth,
         OMX_U32 maxFrameHeight) {
     Mutex::Autolock autolock(mLock);
+    CLOG_CONFIG(prepareForAdaptivePlayback, "%s:%u en=%d max=%ux%u",
+            portString(portIndex), portIndex, enable, maxFrameWidth, maxFrameHeight);
 
     OMX_INDEXTYPE index;
     OMX_STRING name = const_cast<OMX_STRING>(
@@ -462,33 +559,29 @@ status_t OMXNodeInstance::prepareForAdaptivePlayback(
 
     OMX_ERRORTYPE err = OMX_GetExtensionIndex(mHandle, name, &index);
     if (err != OMX_ErrorNone) {
-        ALOGW_IF(enable, "OMX_GetExtensionIndex %s failed", name);
+        CLOG_ERROR_IF(enable, getExtensionIndex, err, "%s", name);
         return StatusFromOMXError(err);
     }
 
     PrepareForAdaptivePlaybackParams params;
-    params.nSize = sizeof(params);
-    params.nVersion.s.nVersionMajor = 1;
-    params.nVersion.s.nVersionMinor = 0;
-    params.nVersion.s.nRevision = 0;
-    params.nVersion.s.nStep = 0;
-
+    InitOMXParams(&params);
     params.nPortIndex = portIndex;
     params.bEnable = enable;
     params.nMaxFrameWidth = maxFrameWidth;
     params.nMaxFrameHeight = maxFrameHeight;
-    if ((err = OMX_SetParameter(mHandle, index, &params)) != OMX_ErrorNone) {
-        ALOGW("OMX_SetParameter failed for PrepareForAdaptivePlayback "
-              "with error %d (0x%08x)", err, err);
-        return UNKNOWN_ERROR;
-    }
-    return err;
+
+    err = OMX_SetParameter(mHandle, index, &params);
+    CLOG_IF_ERROR(setParameter, err, "%s(%#x): %s:%u en=%d max=%ux%u", name, index,
+            portString(portIndex), portIndex, enable, maxFrameWidth, maxFrameHeight);
+    return StatusFromOMXError(err);
 }
 
 status_t OMXNodeInstance::configureVideoTunnelMode(
         OMX_U32 portIndex, OMX_BOOL tunneled, OMX_U32 audioHwSync,
         native_handle_t **sidebandHandle) {
     Mutex::Autolock autolock(mLock);
+    CLOG_CONFIG(configureVideoTunnelMode, "%s:%u tun=%d sync=%u",
+            portString(portIndex), portIndex, tunneled, audioHwSync);
 
     OMX_INDEXTYPE index;
     OMX_STRING name = const_cast<OMX_STRING>(
@@ -496,36 +589,33 @@ status_t OMXNodeInstance::configureVideoTunnelMode(
 
     OMX_ERRORTYPE err = OMX_GetExtensionIndex(mHandle, name, &index);
     if (err != OMX_ErrorNone) {
-        ALOGE("configureVideoTunnelMode extension is missing!");
+        CLOG_ERROR_IF(tunneled, getExtensionIndex, err, "%s", name);
         return StatusFromOMXError(err);
     }
 
     ConfigureVideoTunnelModeParams tunnelParams;
-    tunnelParams.nSize = sizeof(tunnelParams);
-    tunnelParams.nVersion.s.nVersionMajor = 1;
-    tunnelParams.nVersion.s.nVersionMinor = 0;
-    tunnelParams.nVersion.s.nRevision = 0;
-    tunnelParams.nVersion.s.nStep = 0;
-
+    InitOMXParams(&tunnelParams);
     tunnelParams.nPortIndex = portIndex;
     tunnelParams.bTunneled = tunneled;
     tunnelParams.nAudioHwSync = audioHwSync;
     err = OMX_SetParameter(mHandle, index, &tunnelParams);
     if (err != OMX_ErrorNone) {
-        ALOGE("configureVideoTunnelMode failed! (err %d).", err);
-        return UNKNOWN_ERROR;
+        CLOG_ERROR(setParameter, err, "%s(%#x): %s:%u tun=%d sync=%u", name, index,
+                portString(portIndex), portIndex, tunneled, audioHwSync);
+        return StatusFromOMXError(err);
     }
 
     err = OMX_GetParameter(mHandle, index, &tunnelParams);
     if (err != OMX_ErrorNone) {
-        ALOGE("GetVideoTunnelWindow failed! (err %d).", err);
-        return UNKNOWN_ERROR;
+        CLOG_ERROR(getParameter, err, "%s(%#x): %s:%u tun=%d sync=%u", name, index,
+                portString(portIndex), portIndex, tunneled, audioHwSync);
+        return StatusFromOMXError(err);
     }
     if (sidebandHandle) {
         *sidebandHandle = (native_handle_t*)tunnelParams.pSidebandWindow;
     }
 
-    return err;
+    return OK;
 }
 
 status_t OMXNodeInstance::useBuffer(
@@ -542,14 +632,14 @@ status_t OMXNodeInstance::useBuffer(
             params->size(), static_cast<OMX_U8 *>(params->pointer()));
 
     if (err != OMX_ErrorNone) {
-        ALOGE("OMX_UseBuffer failed with error %d (0x%08x)", err, err);
+        CLOG_ERROR(useBuffer, err, SIMPLE_BUFFER(portIndex, params->size(), params->pointer()));
 
         delete buffer_meta;
         buffer_meta = NULL;
 
         *buffer = 0;
 
-        return UNKNOWN_ERROR;
+        return StatusFromOMXError(err);
     }
 
     CHECK_EQ(header->pAppPrivate, buffer_meta);
@@ -563,6 +653,8 @@ status_t OMXNodeInstance::useBuffer(
         bufferSource->addCodecBuffer(header);
     }
 
+    CLOG_BUFFER(useBuffer, NEW_BUFFER_FMT(
+            *buffer, portIndex, "%zu@%p", params->size(), params->pointer()));
     return OK;
 }
 
@@ -572,17 +664,14 @@ status_t OMXNodeInstance::useGraphicBuffer2_l(
 
     // port definition
     OMX_PARAM_PORTDEFINITIONTYPE def;
-    def.nSize = sizeof(OMX_PARAM_PORTDEFINITIONTYPE);
-    def.nVersion.s.nVersionMajor = 1;
-    def.nVersion.s.nVersionMinor = 0;
-    def.nVersion.s.nRevision = 0;
-    def.nVersion.s.nStep = 0;
+    InitOMXParams(&def);
     def.nPortIndex = portIndex;
     OMX_ERRORTYPE err = OMX_GetParameter(mHandle, OMX_IndexParamPortDefinition, &def);
-    if (err != OMX_ErrorNone)
-    {
-        ALOGE("%s::%d:Error getting OMX_IndexParamPortDefinition", __FUNCTION__, __LINE__);
-        return err;
+    if (err != OMX_ErrorNone) {
+        OMX_INDEXTYPE index = OMX_IndexParamPortDefinition;
+        CLOG_ERROR(getParameter, err, "%s(%#x): %s:%u",
+                asString(index), index, portString(portIndex), portIndex);
+        return UNKNOWN_ERROR;
     }
 
     BufferMeta *bufferMeta = new BufferMeta(graphicBuffer);
@@ -600,11 +689,11 @@ status_t OMXNodeInstance::useGraphicBuffer2_l(
             bufferHandle);
 
     if (err != OMX_ErrorNone) {
-        ALOGE("OMX_UseBuffer failed with error %d (0x%08x)", err, err);
+        CLOG_ERROR(useBuffer, err, BUFFER_FMT(portIndex, "%u@%p", def.nBufferSize, bufferHandle));
         delete bufferMeta;
         bufferMeta = NULL;
         *buffer = 0;
-        return UNKNOWN_ERROR;
+        return StatusFromOMXError(err);
     }
 
     CHECK_EQ(header->pBuffer, bufferHandle);
@@ -613,7 +702,8 @@ status_t OMXNodeInstance::useGraphicBuffer2_l(
     *buffer = makeBufferID(header);
 
     addActiveBuffer(portIndex, *buffer);
-
+    CLOG_BUFFER(useGraphicBuffer2, NEW_BUFFER_FMT(
+            *buffer, portIndex, "%u@%p", def.nBufferSize, bufferHandle));
     return OK;
 }
 
@@ -637,10 +727,8 @@ status_t OMXNodeInstance::useGraphicBuffer(
     OMX_STRING name = const_cast<OMX_STRING>(
         "OMX.google.android.index.useAndroidNativeBuffer");
     OMX_ERRORTYPE err = OMX_GetExtensionIndex(mHandle, name, &index);
-
     if (err != OMX_ErrorNone) {
-        ALOGE("OMX_GetExtensionIndex %s failed", name);
-
+        CLOG_ERROR(getExtensionIndex, err, "%s", name);
         return StatusFromOMXError(err);
     }
 
@@ -661,15 +749,15 @@ status_t OMXNodeInstance::useGraphicBuffer(
     err = OMX_SetParameter(mHandle, index, &params);
 
     if (err != OMX_ErrorNone) {
-        ALOGE("OMX_UseAndroidNativeBuffer failed with error %d (0x%08x)", err,
-                err);
+        CLOG_ERROR(setParameter, err, "%s(%#x): %s:%u meta=%p GB=%p", name, index,
+                portString(portIndex), portIndex, bufferMeta, graphicBuffer->handle);
 
         delete bufferMeta;
         bufferMeta = NULL;
 
         *buffer = 0;
 
-        return UNKNOWN_ERROR;
+        return StatusFromOMXError(err);
     }
 
     CHECK_EQ(header->pAppPrivate, bufferMeta);
@@ -677,12 +765,13 @@ status_t OMXNodeInstance::useGraphicBuffer(
     *buffer = makeBufferID(header);
 
     addActiveBuffer(portIndex, *buffer);
-
+    CLOG_BUFFER(useGraphicBuffer, NEW_BUFFER_FMT(
+            *buffer, portIndex, "GB=%p", graphicBuffer->handle));
     return OK;
 }
 
 status_t OMXNodeInstance::updateGraphicBufferInMeta(
-        OMX_U32 /* portIndex */, const sp<GraphicBuffer>& graphicBuffer,
+        OMX_U32 portIndex, const sp<GraphicBuffer>& graphicBuffer,
         OMX::buffer_id buffer) {
     Mutex::Autolock autoLock(mLock);
 
@@ -693,7 +782,8 @@ status_t OMXNodeInstance::updateGraphicBufferInMeta(
     bufferMeta->setGraphicBuffer(graphicBuffer);
     metadata->eType = kMetadataBufferTypeGrallocSource;
     metadata->pHandle = graphicBuffer->handle;
-
+    CLOG_BUFFER(updateGraphicBufferInMeta, "%s:%u, %#x := %p",
+            portString(portIndex), portIndex, buffer, graphicBuffer->handle);
     return OK;
 }
 
@@ -719,19 +809,21 @@ status_t OMXNodeInstance::createInputSurface(
     // Retrieve the width and height of the graphic buffer, set when the
     // codec was configured.
     OMX_PARAM_PORTDEFINITIONTYPE def;
-    def.nSize = sizeof(def);
-    def.nVersion.s.nVersionMajor = 1;
-    def.nVersion.s.nVersionMinor = 0;
-    def.nVersion.s.nRevision = 0;
-    def.nVersion.s.nStep = 0;
+    InitOMXParams(&def);
     def.nPortIndex = portIndex;
     OMX_ERRORTYPE oerr = OMX_GetParameter(
             mHandle, OMX_IndexParamPortDefinition, &def);
-    CHECK(oerr == OMX_ErrorNone);
+    if (oerr != OMX_ErrorNone) {
+        OMX_INDEXTYPE index = OMX_IndexParamPortDefinition;
+        CLOG_ERROR(getParameter, oerr, "%s(%#x): %s:%u",
+                asString(index), index, portString(portIndex), portIndex);
+        return UNKNOWN_ERROR;
+    }
 
     if (def.format.video.eColorFormat != OMX_COLOR_FormatAndroidOpaque) {
-        ALOGE("createInputSurface requires COLOR_FormatSurface "
-              "(AndroidOpaque) color format");
+        CLOGW("createInputSurface requires COLOR_FormatSurface "
+                "(AndroidOpaque) color format instead of %s(%#x)",
+                asString(def.format.video.eColorFormat), def.format.video.eColorFormat);
         return INVALID_OPERATION;
     }
 
@@ -754,9 +846,9 @@ status_t OMXNodeInstance::signalEndOfInputStream() {
     // flag set).  Seems easier than doing the equivalent from here.
     sp<GraphicBufferSource> bufferSource(getGraphicBufferSource());
     if (bufferSource == NULL) {
-        ALOGW("signalEndOfInputStream can only be used with Surface input");
+        CLOGW("signalEndOfInputStream can only be used with Surface input");
         return INVALID_OPERATION;
-    };
+    }
     return bufferSource->signalEndOfInputStream();
 }
 
@@ -773,14 +865,13 @@ status_t OMXNodeInstance::allocateBuffer(
             mHandle, &header, portIndex, buffer_meta, size);
 
     if (err != OMX_ErrorNone) {
-        ALOGE("OMX_AllocateBuffer failed with error %d (0x%08x)", err, err);
-
+        CLOG_ERROR(allocateBuffer, err, BUFFER_FMT(portIndex, "%zu@", size));
         delete buffer_meta;
         buffer_meta = NULL;
 
         *buffer = 0;
 
-        return UNKNOWN_ERROR;
+        return StatusFromOMXError(err);
     }
 
     CHECK_EQ(header->pAppPrivate, buffer_meta);
@@ -794,6 +885,7 @@ status_t OMXNodeInstance::allocateBuffer(
     if (bufferSource != NULL && portIndex == kPortIndexInput) {
         bufferSource->addCodecBuffer(header);
     }
+    CLOG_BUFFER(allocateBuffer, NEW_BUFFER_FMT(*buffer, portIndex, "%zu@%p", size, *buffer_data));
 
     return OK;
 }
@@ -811,14 +903,14 @@ status_t OMXNodeInstance::allocateBufferWithBackup(
             mHandle, &header, portIndex, buffer_meta, params->size());
 
     if (err != OMX_ErrorNone) {
-        ALOGE("OMX_AllocateBuffer failed with error %d (0x%08x)", err, err);
-
+        CLOG_ERROR(allocateBufferWithBackup, err,
+                SIMPLE_BUFFER(portIndex, params->size(), params->pointer()));
         delete buffer_meta;
         buffer_meta = NULL;
 
         *buffer = 0;
 
-        return UNKNOWN_ERROR;
+        return StatusFromOMXError(err);
     }
 
     CHECK_EQ(header->pAppPrivate, buffer_meta);
@@ -832,12 +924,16 @@ status_t OMXNodeInstance::allocateBufferWithBackup(
         bufferSource->addCodecBuffer(header);
     }
 
+    CLOG_BUFFER(allocateBufferWithBackup, NEW_BUFFER_FMT(*buffer, portIndex, "%zu@%p :> %p",
+            params->size(), params->pointer(), header->pBuffer));
+
     return OK;
 }
 
 status_t OMXNodeInstance::freeBuffer(
         OMX_U32 portIndex, OMX::buffer_id buffer) {
     Mutex::Autolock autoLock(mLock);
+    CLOG_BUFFER(freeBuffer, "%s:%u %#x", portString(portIndex), portIndex, buffer);
 
     removeActiveBuffer(portIndex, buffer);
 
@@ -845,6 +941,7 @@ status_t OMXNodeInstance::freeBuffer(
     BufferMeta *buffer_meta = static_cast<BufferMeta *>(header->pAppPrivate);
 
     OMX_ERRORTYPE err = OMX_FreeBuffer(mHandle, portIndex, header);
+    CLOG_IF_ERROR(freeBuffer, err, "%s:%u %#x", portString(portIndex), portIndex, buffer);
 
     delete buffer_meta;
     buffer_meta = NULL;
@@ -861,8 +958,18 @@ status_t OMXNodeInstance::fillBuffer(OMX::buffer_id buffer) {
     header->nOffset = 0;
     header->nFlags = 0;
 
-    OMX_ERRORTYPE err = OMX_FillThisBuffer(mHandle, header);
+    {
+        Mutex::Autolock _l(mDebugLock);
+        mOutputBuffersWithCodec.add(header);
+        CLOG_BUMPED_BUFFER(fillBuffer, WITH_STATS(EMPTY_BUFFER(buffer, header)));
+    }
 
+    OMX_ERRORTYPE err = OMX_FillThisBuffer(mHandle, header);
+    if (err != OMX_ErrorNone) {
+        CLOG_ERROR(fillBuffer, err, EMPTY_BUFFER(buffer, header));
+        Mutex::Autolock _l(mDebugLock);
+        mOutputBuffersWithCodec.remove(header);
+    }
     return StatusFromOMXError(err);
 }
 
@@ -875,14 +982,66 @@ status_t OMXNodeInstance::emptyBuffer(
     OMX_BUFFERHEADERTYPE *header = findBufferHeader(buffer);
     header->nFilledLen = rangeLength;
     header->nOffset = rangeOffset;
-    header->nFlags = flags;
-    header->nTimeStamp = timestamp;
 
     BufferMeta *buffer_meta =
         static_cast<BufferMeta *>(header->pAppPrivate);
     buffer_meta->CopyToOMX(header);
 
+    return emptyBuffer_l(header, flags, timestamp, (intptr_t)buffer);
+}
+
+// log queued buffer activity for the next few input and/or output frames
+// if logging at internal state level
+void OMXNodeInstance::bumpDebugLevel_l(size_t numInputBuffers, size_t numOutputBuffers) {
+    if (DEBUG == ADebug::kDebugInternalState) {
+        DEBUG_BUMP = ADebug::kDebugAll;
+        if (numInputBuffers > 0) {
+            mDebugLevelBumpPendingBuffers[kPortIndexInput] = numInputBuffers;
+        }
+        if (numOutputBuffers > 0) {
+            mDebugLevelBumpPendingBuffers[kPortIndexOutput] = numOutputBuffers;
+        }
+    }
+}
+
+void OMXNodeInstance::unbumpDebugLevel_l(size_t portIndex) {
+    if (mDebugLevelBumpPendingBuffers[portIndex]) {
+        --mDebugLevelBumpPendingBuffers[portIndex];
+    }
+    if (!mDebugLevelBumpPendingBuffers[0]
+            && !mDebugLevelBumpPendingBuffers[1]) {
+        DEBUG_BUMP = DEBUG;
+    }
+}
+
+status_t OMXNodeInstance::emptyBuffer_l(
+        OMX_BUFFERHEADERTYPE *header, OMX_U32 flags, OMX_TICKS timestamp, intptr_t debugAddr) {
+    header->nFlags = flags;
+    header->nTimeStamp = timestamp;
+
+    {
+        Mutex::Autolock _l(mDebugLock);
+        mInputBuffersWithCodec.add(header);
+
+        // bump internal-state debug level for 2 input frames past a buffer with CSD
+        if ((flags & OMX_BUFFERFLAG_CODECCONFIG) != 0) {
+            bumpDebugLevel_l(2 /* numInputBuffers */, 0 /* numOutputBuffers */);
+        }
+
+        CLOG_BUMPED_BUFFER(emptyBuffer, WITH_STATS(FULL_BUFFER(debugAddr, header)));
+    }
+
     OMX_ERRORTYPE err = OMX_EmptyThisBuffer(mHandle, header);
+    CLOG_IF_ERROR(emptyBuffer, err, FULL_BUFFER(debugAddr, header));
+
+    {
+        Mutex::Autolock _l(mDebugLock);
+        if (err != OMX_ErrorNone) {
+            mInputBuffersWithCodec.remove(header);
+        } else if (!(flags & OMX_BUFFERFLAG_CODECCONFIG)) {
+            unbumpDebugLevel_l(kPortIndexInput);
+        }
+    }
 
     return StatusFromOMXError(err);
 }
@@ -896,15 +1055,8 @@ status_t OMXNodeInstance::emptyDirectBuffer(
 
     header->nFilledLen = rangeLength;
     header->nOffset = rangeOffset;
-    header->nFlags = flags;
-    header->nTimeStamp = timestamp;
-
-    OMX_ERRORTYPE err = OMX_EmptyThisBuffer(mHandle, header);
-    if (err != OMX_ErrorNone) {
-        ALOGW("emptyDirectBuffer failed, OMX err=0x%x", err);
-    }
 
-    return StatusFromOMXError(err);
+    return emptyBuffer_l(header, flags, timestamp, (intptr_t)header->pBuffer);
 }
 
 status_t OMXNodeInstance::getExtensionIndex(
@@ -917,11 +1069,25 @@ status_t OMXNodeInstance::getExtensionIndex(
     return StatusFromOMXError(err);
 }
 
+inline static const char *asString(IOMX::InternalOptionType i, const char *def = "??") {
+    switch (i) {
+        case IOMX::INTERNAL_OPTION_SUSPEND:           return "SUSPEND";
+        case IOMX::INTERNAL_OPTION_REPEAT_PREVIOUS_FRAME_DELAY:
+            return "REPEAT_PREVIOUS_FRAME_DELAY";
+        case IOMX::INTERNAL_OPTION_MAX_TIMESTAMP_GAP: return "MAX_TIMESTAMP_GAP";
+        case IOMX::INTERNAL_OPTION_START_TIME:        return "START_TIME";
+        case IOMX::INTERNAL_OPTION_TIME_LAPSE:        return "TIME_LAPSE";
+        default:                                      return def;
+    }
+}
+
 status_t OMXNodeInstance::setInternalOption(
         OMX_U32 portIndex,
         IOMX::InternalOptionType type,
         const void *data,
         size_t size) {
+    CLOG_CONFIG(setInternalOption, "%s(%d): %s:%u %zu@%p",
+            asString(type), type, portString(portIndex), portIndex, size, data);
     switch (type) {
         case IOMX::INTERNAL_OPTION_SUSPEND:
         case IOMX::INTERNAL_OPTION_REPEAT_PREVIOUS_FRAME_DELAY:
@@ -933,6 +1099,7 @@ status_t OMXNodeInstance::setInternalOption(
                 getGraphicBufferSource();
 
             if (bufferSource == NULL || portIndex != kPortIndexInput) {
+                CLOGW("setInternalOption is only for Surface input");
                 return ERROR_UNSUPPORTED;
             }
 
@@ -942,6 +1109,7 @@ status_t OMXNodeInstance::setInternalOption(
                 }
 
                 bool suspend = *(bool *)data;
+                CLOG_CONFIG(setInternalOption, "suspend=%d", suspend);
                 bufferSource->suspend(suspend);
             } else if (type ==
                     IOMX::INTERNAL_OPTION_REPEAT_PREVIOUS_FRAME_DELAY){
@@ -950,7 +1118,7 @@ status_t OMXNodeInstance::setInternalOption(
                 }
 
                 int64_t delayUs = *(int64_t *)data;
-
+                CLOG_CONFIG(setInternalOption, "delayUs=%lld", (long long)delayUs);
                 return bufferSource->setRepeatPreviousFrameDelayUs(delayUs);
             } else if (type ==
                     IOMX::INTERNAL_OPTION_MAX_TIMESTAMP_GAP){
@@ -959,7 +1127,7 @@ status_t OMXNodeInstance::setInternalOption(
                 }
 
                 int64_t maxGapUs = *(int64_t *)data;
-
+                CLOG_CONFIG(setInternalOption, "gapUs=%lld", (long long)maxGapUs);
                 return bufferSource->setMaxTimestampGapUs(maxGapUs);
             } else if (type == IOMX::INTERNAL_OPTION_START_TIME) {
                 if (size != sizeof(int64_t)) {
@@ -967,13 +1135,18 @@ status_t OMXNodeInstance::setInternalOption(
                 }
 
                 int64_t skipFramesBeforeUs = *(int64_t *)data;
-
+                CLOG_CONFIG(setInternalOption, "beforeUs=%lld", (long long)skipFramesBeforeUs);
                 bufferSource->setSkipFramesBeforeUs(skipFramesBeforeUs);
             } else { // IOMX::INTERNAL_OPTION_TIME_LAPSE
                 if (size != sizeof(int64_t) * 2) {
                     return INVALID_OPERATION;
                 }
 
+                int64_t timePerFrameUs = ((int64_t *)data)[0];
+                int64_t timePerCaptureUs = ((int64_t *)data)[1];
+                CLOG_CONFIG(setInternalOption, "perFrameUs=%lld perCaptureUs=%lld",
+                        (long long)timePerFrameUs, (long long)timePerCaptureUs);
+
                 bufferSource->setTimeLapseUs((int64_t *)data);
             }
 
@@ -992,6 +1165,16 @@ void OMXNodeInstance::onMessage(const omx_message &msg) {
         OMX_BUFFERHEADERTYPE *buffer =
             findBufferHeader(msg.u.extended_buffer_data.buffer);
 
+        {
+            Mutex::Autolock _l(mDebugLock);
+            mOutputBuffersWithCodec.remove(buffer);
+
+            CLOG_BUMPED_BUFFER(
+                    FBD, WITH_STATS(FULL_BUFFER(msg.u.extended_buffer_data.buffer, buffer)));
+
+            unbumpDebugLevel_l(kPortIndexOutput);
+        }
+
         BufferMeta *buffer_meta =
             static_cast<BufferMeta *>(buffer->pAppPrivate);
 
@@ -1007,16 +1190,23 @@ void OMXNodeInstance::onMessage(const omx_message &msg) {
             return;
         }
     } else if (msg.type == omx_message::EMPTY_BUFFER_DONE) {
+        OMX_BUFFERHEADERTYPE *buffer =
+            findBufferHeader(msg.u.buffer_data.buffer);
+
+        {
+            Mutex::Autolock _l(mDebugLock);
+            mInputBuffersWithCodec.remove(buffer);
+
+            CLOG_BUMPED_BUFFER(
+                    EBD, WITH_STATS(EMPTY_BUFFER(msg.u.buffer_data.buffer, buffer)));
+        }
+
         if (bufferSource != NULL) {
             // This is one of the buffers used exclusively by
             // GraphicBufferSource.
             // Don't dispatch a message back to ACodec, since it doesn't
             // know that anyone asked to have the buffer emptied and will
             // be very confused.
-
-            OMX_BUFFERHEADERTYPE *buffer =
-                findBufferHeader(msg.u.buffer_data.buffer);
-
             bufferSource->codecBufferEmptied(buffer);
             return;
         }
@@ -1040,6 +1230,43 @@ void OMXNodeInstance::onGetHandleFailed() {
 // Don't try to acquire mLock here -- in rare circumstances this will hang.
 void OMXNodeInstance::onEvent(
         OMX_EVENTTYPE event, OMX_U32 arg1, OMX_U32 arg2) {
+    const char *arg1String = "??";
+    const char *arg2String = "??";
+    ADebug::Level level = ADebug::kDebugInternalState;
+
+    switch (event) {
+        case OMX_EventCmdComplete:
+            arg1String = asString((OMX_COMMANDTYPE)arg1);
+            switch (arg1) {
+                case OMX_CommandStateSet:
+                    arg2String = asString((OMX_STATETYPE)arg2);
+                    level = ADebug::kDebugState;
+                    break;
+                case OMX_CommandFlush:
+                case OMX_CommandPortEnable:
+                {
+                    // bump internal-state debug level for 2 input and output frames
+                    Mutex::Autolock _l(mDebugLock);
+                    bumpDebugLevel_l(2 /* numInputBuffers */, 2 /* numOutputBuffers */);
+                }
+                // fall through
+                default:
+                    arg2String = portString(arg2);
+            }
+            break;
+        case OMX_EventError:
+            arg1String = asString((OMX_ERRORTYPE)arg1);
+            level = ADebug::kDebugLifeCycle;
+            break;
+        case OMX_EventPortSettingsChanged:
+            arg2String = asString((OMX_INDEXEXTTYPE)arg2);
+            // fall through
+        default:
+            arg1String = portString(arg1);
+    }
+
+    CLOGI_(level, onEvent, "%s(%x), %s(%x), %s(%x)",
+            asString(event), event, arg1String, arg1, arg2String, arg2);
     const sp<GraphicBufferSource>& bufferSource(getGraphicBufferSource());
 
     if (bufferSource != NULL
@@ -1097,23 +1324,27 @@ void OMXNodeInstance::addActiveBuffer(OMX_U32 portIndex, OMX::buffer_id id) {
     active.mPortIndex = portIndex;
     active.mID = id;
     mActiveBuffers.push(active);
+
+    if (portIndex < NELEM(mNumPortBuffers)) {
+        ++mNumPortBuffers[portIndex];
+    }
 }
 
 void OMXNodeInstance::removeActiveBuffer(
         OMX_U32 portIndex, OMX::buffer_id id) {
-    bool found = false;
     for (size_t i = 0; i < mActiveBuffers.size(); ++i) {
         if (mActiveBuffers[i].mPortIndex == portIndex
-            && mActiveBuffers[i].mID == id) {
-            found = true;
+                && mActiveBuffers[i].mID == id) {
             mActiveBuffers.removeItemsAt(i);
-            break;
+
+            if (portIndex < NELEM(mNumPortBuffers)) {
+                --mNumPortBuffers[portIndex];
+            }
+            return;
         }
     }
 
-    if (!found) {
-        ALOGW("Attempt to remove an active buffer we know nothing about...");
-    }
+     CLOGW("Attempt to remove an active buffer [%#x] we know nothing about...", id);
 }
 
 void OMXNodeInstance::freeActiveBuffers() {
@@ -1134,7 +1365,7 @@ OMX::buffer_id OMXNodeInstance::makeBufferID(OMX_BUFFERHEADERTYPE *bufferHeader)
     OMX::buffer_id buffer;
     do { // handle the very unlikely case of ID overflow
         if (++mBufferIDCount == 0) {
-           ++mBufferIDCount;
+            ++mBufferIDCount;
         }
         buffer = (OMX::buffer_id)mBufferIDCount;
     } while (mBufferIDToBufferHeader.indexOfKey(buffer) >= 0);
diff --git a/media/libstagefright/omx/SoftOMXComponent.cpp b/media/libstagefright/omx/SoftOMXComponent.cpp
index 646cd32..df978f8 100644
--- a/media/libstagefright/omx/SoftOMXComponent.cpp
+++ b/media/libstagefright/omx/SoftOMXComponent.cpp
@@ -283,7 +283,7 @@ OMX_ERRORTYPE SoftOMXComponent::setConfig(
 
 OMX_ERRORTYPE SoftOMXComponent::getExtensionIndex(
         const char * /* name */, OMX_INDEXTYPE * /* index */) {
-    return OMX_ErrorUndefined;
+    return OMX_ErrorUnsupportedIndex;
 }
 
 OMX_ERRORTYPE SoftOMXComponent::useBuffer(
diff --git a/media/libstagefright/tests/Utils_test.cpp b/media/libstagefright/tests/Utils_test.cpp
index f2825dd..43e0269 100644
--- a/media/libstagefright/tests/Utils_test.cpp
+++ b/media/libstagefright/tests/Utils_test.cpp
@@ -24,6 +24,7 @@
 #include <unistd.h>
 
 #include <media/stagefright/foundation/ADebug.h>
+#include <media/stagefright/foundation/AStringUtils.h>
 #include <media/stagefright/foundation/AUtils.h>
 #include <media/stagefright/Utils.h>
 
@@ -32,6 +33,100 @@ namespace android {
 class UtilsTest : public ::testing::Test {
 };
 
+TEST_F(UtilsTest, TestStringUtils) {
+    ASSERT_EQ(AStringUtils::Compare("Audio", "AudioExt", 5, false), 0);
+    ASSERT_EQ(AStringUtils::Compare("Audio", "audiOExt", 5, true), 0);
+    ASSERT_NE(AStringUtils::Compare("Audio", "audioExt", 5, false), 0);
+    ASSERT_NE(AStringUtils::Compare("Audio", "AudiOExt", 5, false), 0);
+
+    ASSERT_LT(AStringUtils::Compare("Audio", "AudioExt", 7, false), 0);
+    ASSERT_LT(AStringUtils::Compare("Audio", "audiOExt", 7, true), 0);
+
+    ASSERT_GT(AStringUtils::Compare("AudioExt", "Audio", 7, false), 0);
+    ASSERT_GT(AStringUtils::Compare("audiOext", "Audio", 7, true), 0);
+
+    ASSERT_LT(AStringUtils::Compare("Audio", "Video", 5, false), 0);
+    ASSERT_LT(AStringUtils::Compare("Audio1", "Audio2", 6, false), 0);
+    ASSERT_LT(AStringUtils::Compare("audio", "VIDEO", 5, true), 0);
+    ASSERT_LT(AStringUtils::Compare("audio1", "AUDIO2", 6, true), 0);
+
+    ASSERT_GT(AStringUtils::Compare("Video", "Audio", 5, false), 0);
+    ASSERT_GT(AStringUtils::Compare("Audio2", "Audio1", 6, false), 0);
+    ASSERT_GT(AStringUtils::Compare("VIDEO", "audio", 5, true), 0);
+    ASSERT_GT(AStringUtils::Compare("AUDIO2", "audio1", 6, true), 0);
+
+    ASSERT_TRUE(AStringUtils::MatchesGlob("AudioA", 5, "AudioB", 5, false));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("AudioA", 6, "AudioA", 5, false));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("AudioA", 5, "AudioA", 6, false));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("AudioA", 5, "audiOB", 5, false));
+    ASSERT_TRUE(AStringUtils::MatchesGlob("AudioA", 5, "audiOB", 5, true));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("AudioA", 6, "AudioA", 5, true));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("AudioA", 5, "AudioA", 6, true));
+
+    ASSERT_TRUE(AStringUtils::MatchesGlob("*1", 1, "String8", 6, true));
+    ASSERT_TRUE(AStringUtils::MatchesGlob("*1", 1, "String8", 6, false));
+    ASSERT_TRUE(AStringUtils::MatchesGlob("*1", 1, "String8", 0, true));
+    ASSERT_TRUE(AStringUtils::MatchesGlob("*1", 1, "String8", 0, false));
+
+    ASSERT_TRUE(AStringUtils::MatchesGlob("*ring1", 5, "String8", 6, false));
+    ASSERT_TRUE(AStringUtils::MatchesGlob("*ring2", 5, "STRING8", 6, true));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("*ring4", 5, "StRing8", 6, false));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("*ring5", 5, "StrinG8", 6, false));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("*ring8", 5, "String8", 7, false));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("*ring8", 5, "String8", 7, true));
+
+    ASSERT_TRUE(AStringUtils::MatchesGlob("Str*1", 4, "String8", 6, false));
+    ASSERT_TRUE(AStringUtils::MatchesGlob("Str*2", 4, "STRING8", 6, true));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("Str*3", 4, "string8", 6, false));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("Str*4", 4, "StRing8", 6, false));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("Str*5", 4, "AString8", 7, false));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("Str*6", 4, "AString8", 7, true));
+
+    ASSERT_TRUE(AStringUtils::MatchesGlob("Str*ng1", 6, "String8", 6, false));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("Str*ng2", 6, "string8", 6, false));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("Str*ng3", 6, "StRing8", 6, false));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("Str*ng4", 6, "StriNg8", 6, false));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("Str*ng5", 6, "StrinG8", 6, false));
+    ASSERT_TRUE(AStringUtils::MatchesGlob("Str*ng6", 6, "STRING8", 6, true));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("Str*ng8", 6, "AString8", 7, false));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("Str*ng1", 6, "String16", 7, false));
+    ASSERT_TRUE(AStringUtils::MatchesGlob("Str*ing9", 7, "String8", 6, false));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("Str*ringA", 8, "String8", 6, false));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("Str*ng8", 6, "AString8", 7, true));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("Str*ng1", 6, "String16", 7, true));
+    ASSERT_TRUE(AStringUtils::MatchesGlob("Str*ing9", 7, "STRING8", 6, true));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("Str*ringA", 8, "String8", 6, true));
+
+    ASSERT_TRUE(AStringUtils::MatchesGlob("*str*str1", 8, "bestrestroom", 9, false));
+    ASSERT_TRUE(AStringUtils::MatchesGlob("*str*str1", 8, "bestrestrestroom", 13, false));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("*str*stro", 8, "bestrestrestroom", 14, false));
+    ASSERT_TRUE(AStringUtils::MatchesGlob("*str*str*1", 9, "bestrestrestroom", 14, false));
+    ASSERT_TRUE(AStringUtils::MatchesGlob("*str*str1", 8, "beSTReSTRoom", 9, true));
+    ASSERT_TRUE(AStringUtils::MatchesGlob("*str*str1", 8, "beSTRestreSTRoom", 13, true));
+    ASSERT_FALSE(AStringUtils::MatchesGlob("*str*stro", 8, "bestreSTReSTRoom", 14, true));
+    ASSERT_TRUE(AStringUtils::MatchesGlob("*str*str*1", 9, "bestreSTReSTRoom", 14, true));
+}
+
+TEST_F(UtilsTest, TestDebug) {
+#define LVL(x) (ADebug::Level)(x)
+    ASSERT_EQ(ADebug::GetDebugLevelFromString("video", "", LVL(5)), LVL(5));
+    ASSERT_EQ(ADebug::GetDebugLevelFromString("video", "   \t  \n ", LVL(2)), LVL(2));
+    ASSERT_EQ(ADebug::GetDebugLevelFromString("video", "3", LVL(5)), LVL(3));
+    ASSERT_EQ(ADebug::GetDebugLevelFromString("video", "3:*deo", LVL(5)), LVL(3));
+    ASSERT_EQ(ADebug::GetDebugLevelFromString(
+            "video", "\t\n 3 \t\n:\t\n video \t\n", LVL(5)), LVL(3));
+    ASSERT_EQ(ADebug::GetDebugLevelFromString("video", "3:*deo,2:vid*", LVL(5)), LVL(2));
+    ASSERT_EQ(ADebug::GetDebugLevelFromString(
+            "avideo", "\t\n 3 \t\n:\t\n avideo \t\n,\t\n 2 \t\n:\t\n video \t\n", LVL(5)), LVL(3));
+    ASSERT_EQ(ADebug::GetDebugLevelFromString(
+            "audio.omx", "4:*omx,3:*d*o*,2:audio*", LVL(5)), LVL(2));
+    ASSERT_EQ(ADebug::GetDebugLevelFromString(
+            "video.omx", "4:*omx,3:*d*o*,2:audio*", LVL(5)), LVL(3));
+    ASSERT_EQ(ADebug::GetDebugLevelFromString("video", "4:*omx,3:*d*o*,2:audio*", LVL(5)), LVL(3));
+    ASSERT_EQ(ADebug::GetDebugLevelFromString("omx", "4:*omx,3:*d*o*,2:audio*", LVL(5)), LVL(4));
+#undef LVL
+}
+
 TEST_F(UtilsTest, TestFourCC) {
     ASSERT_EQ(FOURCC('s', 't', 'm' , 'u'), 'stmu');
 }