Merge "libmediadrm: save IPC failure logs" into sc-dev
diff --git a/drm/libmediadrm/DrmHal.cpp b/drm/libmediadrm/DrmHal.cpp
index f8f2bc6..a84fd92 100644
--- a/drm/libmediadrm/DrmHal.cpp
+++ b/drm/libmediadrm/DrmHal.cpp
@@ -345,10 +345,10 @@
         // must be in passthrough mode, load the default passthrough service
         auto passthrough = IDrmFactory::getService();
         if (passthrough != NULL) {
-            ALOGI("makeDrmFactories: using default passthrough drm instance");
+            DrmUtils::LOG2BI("makeDrmFactories: using default passthrough drm instance");
             factories.push_back(passthrough);
         } else {
-            ALOGE("Failed to find any drm factories");
+            DrmUtils::LOG2BE("Failed to find any drm factories");
         }
     }
     return factories;
@@ -364,7 +364,7 @@
     Return<void> hResult = factory->createPlugin(uuid, appPackageName.string(),
             [&](Status status, const sp<IDrmPlugin>& hPlugin) {
                 if (status != Status::OK) {
-                    ALOGE("Failed to make drm plugin");
+                    DrmUtils::LOG2BE("Failed to make drm plugin: %d", status);
                     return;
                 }
                 plugin = hPlugin;
@@ -372,7 +372,7 @@
         );
 
     if (!hResult.isOk()) {
-        ALOGE("createPlugin remote call failed");
+        DrmUtils::LOG2BE("createPlugin remote call failed");
     }
 
     return plugin;
@@ -566,7 +566,8 @@
     Mutex::Autolock autoLock(mLock);
 
     for (ssize_t i = mFactories.size() - 1; i >= 0; i--) {
-        if (mFactories[i]->isCryptoSchemeSupported(uuid)) {
+        auto hResult = mFactories[i]->isCryptoSchemeSupported(uuid);
+        if (hResult.isOk() && hResult) {
             auto plugin = makeDrmPlugin(mFactories[i], uuid, appPackageName);
             if (plugin != NULL) {
                 mPlugin = plugin;
diff --git a/drm/libmediadrm/DrmUtils.cpp b/drm/libmediadrm/DrmUtils.cpp
index 82eadd9..f7e6717 100644
--- a/drm/libmediadrm/DrmUtils.cpp
+++ b/drm/libmediadrm/DrmUtils.cpp
@@ -27,6 +27,8 @@
 #include <android/hardware/drm/1.2/IDrmFactory.h>
 #include <android/hardware/drm/1.3/ICryptoFactory.h>
 #include <android/hardware/drm/1.3/IDrmFactory.h>
+#include <android/hardware/drm/1.4/ICryptoFactory.h>
+#include <android/hardware/drm/1.4/IDrmFactory.h>
 #include <android/hidl/manager/1.2/IServiceManager.h>
 #include <hidl/HidlSupport.h>
 
@@ -68,15 +70,15 @@
 void MakeHidlFactories(const uint8_t uuid[16], V &factories) {
     sp<HServiceManager> serviceManager = HServiceManager::getService();
     if (serviceManager == nullptr) {
-        ALOGE("Failed to get service manager");
-        exit(-1);
+        LOG2BE("Failed to get service manager");
+        return;
     }
 
     serviceManager->listManifestByInterface(Hal::descriptor, [&](const hidl_vec<hidl_string> &registered) {
         for (const auto &instance : registered) {
             auto factory = Hal::getService(instance);
             if (factory != nullptr) {
-                ALOGI("found %s %s", Hal::descriptor, instance.c_str());
+                LOG2BI("found %s %s", Hal::descriptor, instance.c_str());
                 if (!uuid || factory->isCryptoSchemeSupported(uuid)) {
                     factories.push_back(factory);
                 }
@@ -106,6 +108,7 @@
     factory->createPlugin(toHidlArray16(uuid), hidl_string(appPackageName),
                           [&](::V1_0::Status status, const sp<::V1_0::IDrmPlugin> &hPlugin) {
                               if (status != ::V1_0::Status::OK) {
+                                  LOG2BE("MakeDrmPlugin failed: %d", status);
                                   return;
                               }
                               plugin = hPlugin;
@@ -120,6 +123,7 @@
     factory->createPlugin(toHidlArray16(uuid), toHidlVec(initData, initDataSize),
                           [&](::V1_0::Status status, const sp<::V1_0::ICryptoPlugin> &hPlugin) {
                               if (status != ::V1_0::Status::OK) {
+                                  LOG2BE("MakeCryptoPlugin failed: %d", status);
                                   return;
                               }
                               plugin = hPlugin;
@@ -147,6 +151,7 @@
     MakeHidlFactories<::V1_1::IDrmFactory>(uuid, drmFactories);
     MakeHidlFactories<::V1_2::IDrmFactory>(uuid, drmFactories);
     MakeHidlFactories<::V1_3::IDrmFactory>(uuid, drmFactories);
+    MakeHidlFactories<::V1_4::IDrmFactory>(uuid, drmFactories);
     return drmFactories;
 }
 
@@ -165,6 +170,7 @@
     MakeHidlFactories<::V1_1::ICryptoFactory>(uuid, cryptoFactories);
     MakeHidlFactories<::V1_2::ICryptoFactory>(uuid, cryptoFactories);
     MakeHidlFactories<::V1_3::ICryptoFactory>(uuid, cryptoFactories);
+    MakeHidlFactories<::V1_4::ICryptoFactory>(uuid, cryptoFactories);
     return cryptoFactories;
 }
 
@@ -265,5 +271,65 @@
     return ERROR_DRM_UNKNOWN;
 }
 
+namespace {
+char logPriorityToChar(::V1_4::LogPriority priority) {
+    char p = 'U';
+    switch (priority) {
+        case ::V1_4::LogPriority::VERBOSE:  p = 'V'; break;
+        case ::V1_4::LogPriority::DEBUG:    p = 'D'; break;
+        case ::V1_4::LogPriority::INFO:     p = 'I'; break;
+        case ::V1_4::LogPriority::WARN:     p = 'W'; break;
+        case ::V1_4::LogPriority::ERROR:    p = 'E'; break;
+        case ::V1_4::LogPriority::FATAL:    p = 'F'; break;
+        default: p = 'U'; break;
+    }
+    return p;
+}
+}  // namespace
+
+std::string GetExceptionMessage(status_t err, const char *msg,
+                                const Vector<::V1_4::LogMessage> &logs) {
+    String8 msg8;
+    if (msg) {
+        msg8 += msg;
+        msg8 += ": ";
+    }
+    auto errStr = StrCryptoError(err);
+    msg8 += errStr.c_str();
+
+    for (auto log : logs) {
+        time_t seconds = log.timeMs / 1000;
+        int ms = log.timeMs % 1000;
+        char buf[64] = {0};
+        std::string timeStr = "00-00 00:00:00";
+        if (strftime(buf, sizeof buf, "%m-%d %H:%M:%S", std::localtime(&seconds))) {
+            timeStr = buf;
+        }
+
+        char p = logPriorityToChar(log.priority);
+        msg8 += String8::format("\n%s.%03d %c %s", timeStr.c_str(), ms, p, log.message.c_str());
+    }
+
+    return msg8.c_str();
+}
+
+void LogBuffer::addLog(const ::V1_4::LogMessage &log) {
+    std::unique_lock<std::mutex> lock(mMutex);
+    mBuffer.push_back(log);
+    while (mBuffer.size() > MAX_CAPACITY) {
+        mBuffer.pop_front();
+    }
+}
+
+Vector<::V1_4::LogMessage> LogBuffer::getLogs() {
+    std::unique_lock<std::mutex> lock(mMutex);
+    Vector<::V1_4::LogMessage> logs;
+    for (auto log : mBuffer) {
+        logs.push_back(log);
+    }
+    return logs;
+}
+
+LogBuffer gLogBuf;
 }  // namespace DrmUtils
 }  // namespace android
diff --git a/drm/libmediadrm/interface/mediadrm/DrmUtils.h b/drm/libmediadrm/interface/mediadrm/DrmUtils.h
index c362aa6..7fe3501 100644
--- a/drm/libmediadrm/interface/mediadrm/DrmUtils.h
+++ b/drm/libmediadrm/interface/mediadrm/DrmUtils.h
@@ -27,7 +27,14 @@
 #include <utils/String8.h>
 #include <utils/StrongPointer.h>
 #include <utils/Vector.h>
+#include <algorithm>
+#include <chrono>
+#include <cstddef>
+#include <cstdint>
 #include <ctime>
+#include <deque>
+#include <iterator>
+#include <mutex>
 #include <vector>
 
 
@@ -42,6 +49,53 @@
 
 namespace DrmUtils {
 
+// Log APIs
+class LogBuffer {
+  public:
+    static const int MAX_CAPACITY = 100;
+    void addLog(const ::V1_4::LogMessage &log);
+    Vector<::V1_4::LogMessage> getLogs();
+
+  private:
+    std::deque<::V1_4::LogMessage> mBuffer;
+    std::mutex mMutex;
+};
+
+extern LogBuffer gLogBuf;
+
+static inline int formatBuffer(char *buf, size_t size, const char *msg) {
+    return snprintf(buf, size, "%s", msg);
+}
+
+template <typename First, typename... Args>
+static inline int formatBuffer(char *buf, size_t size, const char *fmt, First first, Args... args) {
+    return snprintf(buf, size, fmt, first, args...);
+}
+
+template <typename... Args>
+void LogToBuffer(android_LogPriority level, const char *fmt, Args... args) {
+    const int LOG_BUF_SIZE = 256;
+    char buf[LOG_BUF_SIZE];
+    int len = formatBuffer(buf, LOG_BUF_SIZE, fmt, args...);
+    if (len <= 0) {
+        return;
+    }
+    __android_log_write(level, LOG_TAG, buf);
+    if (level >= ANDROID_LOG_INFO) {
+        int64_t epochTimeMs =
+                std::chrono::system_clock::now().time_since_epoch() / std::chrono::milliseconds(1);
+        gLogBuf.addLog({epochTimeMs, static_cast<::V1_4::LogPriority>(level), buf});
+    }
+}
+
+#ifndef LOG2BE
+#define LOG2BE(...) LogToBuffer(ANDROID_LOG_ERROR, __VA_ARGS__)
+#define LOG2BW(...) LogToBuffer(ANDROID_LOG_WARN, __VA_ARGS__)
+#define LOG2BI(...) LogToBuffer(ANDROID_LOG_INFO, __VA_ARGS__)
+#define LOG2BD(...) LogToBuffer(ANDROID_LOG_DEBUG, __VA_ARGS__)
+#define LOG2BV(...) LogToBuffer(ANDROID_LOG_VERBOSE, __VA_ARGS__)
+#endif
+
 bool UseDrmService();
 
 sp<IDrm> MakeDrm(status_t *pstatus = nullptr);
@@ -119,11 +173,14 @@
 template<typename T, typename U>
 status_t GetLogMessages(const sp<U> &obj, Vector<::V1_4::LogMessage> &logs) {
     sp<T> plugin = T::castFrom(obj);
-    if (plugin == NULL) {
-        return ERROR_UNSUPPORTED;
+    if (obj == NULL) {
+        LOG2BW("%s obj is null", U::descriptor);
+    } else if (plugin == NULL) {
+        LOG2BW("Cannot cast %s obj to %s plugin", U::descriptor, T::descriptor);
     }
 
     ::V1_4::Status err{};
+    std::vector<::V1_4::LogMessage> pluginLogs;
     ::V1_4::IDrmPlugin::getLogMessages_cb cb = [&](
             ::V1_4::Status status,
             hidl_vec<::V1_4::LogMessage> hLogs) {
@@ -131,62 +188,36 @@
             err = status;
             return;
         }
-        logs.appendArray(hLogs.data(), hLogs.size());
+        pluginLogs.assign(hLogs.data(), hLogs.data() + hLogs.size());
     };
 
-    Return<void> hResult = plugin->getLogMessages(cb);
-    if (!hResult.isOk()) {
-        return DEAD_OBJECT;
+    Return<void> hResult;
+    if (plugin != NULL) {
+        hResult = plugin->getLogMessages(cb);
     }
-    return toStatusT(err);
+    if (!hResult.isOk()) {
+        LOG2BW("%s::getLogMessages remote call failed", T::descriptor);
+    }
+
+    auto allLogs(gLogBuf.getLogs());
+    std::copy(pluginLogs.begin(), pluginLogs.end(), std::back_inserter(allLogs));
+    std::sort(allLogs.begin(), allLogs.end(),
+              [](const ::V1_4::LogMessage &a, const ::V1_4::LogMessage &b) {
+                  return a.timeMs < b.timeMs;
+              });
+
+    logs.appendVector(allLogs);
+    return OK;
 }
 
-namespace {
-static inline char logPriorityToChar(::V1_4::LogPriority priority) {
-    char p = 'U';
-    switch (priority) {
-        case ::V1_4::LogPriority::VERBOSE:  p = 'V'; break;
-        case ::V1_4::LogPriority::DEBUG:    p = 'D'; break;
-        case ::V1_4::LogPriority::INFO:     p = 'I'; break;
-        case ::V1_4::LogPriority::WARN:     p = 'W'; break;
-        case ::V1_4::LogPriority::ERROR:    p = 'E'; break;
-        case ::V1_4::LogPriority::FATAL:    p = 'F'; break;
-        default: p = 'U'; break;
-    }
-    return p;
-}
-}
+std::string GetExceptionMessage(status_t err, const char *msg,
+                                const Vector<::V1_4::LogMessage> &logs);
 
 template<typename T>
 std::string GetExceptionMessage(status_t err, const char *msg, const sp<T> &iface) {
-    String8 msg8;
-    if (msg) {
-        msg8 += msg;
-        msg8 += ": ";
-    }
-    auto errStr = StrCryptoError(err);
-    msg8 += errStr.c_str();
-
     Vector<::V1_4::LogMessage> logs;
-    if (iface->getLogMessages(logs) != NO_ERROR) {
-        return msg8.c_str();
-    }
-
-    for (auto log: logs) {
-        time_t seconds = log.timeMs / 1000;
-        int ms = log.timeMs % 1000;
-        char buf[64] = {0};
-        std::string timeStr = "00-00 00:00:00";
-        if (strftime(buf, sizeof buf, "%m-%d %H:%M:%S", std::localtime(&seconds))) {
-            timeStr = buf;
-        }
-
-        char p = logPriorityToChar(log.priority);
-        msg8 += String8::format("\n%s.%03d %c %s",
-                timeStr.c_str(), ms, p, log.message.c_str());
-    }
-
-    return msg8.c_str();
+    iface->getLogMessages(logs);
+    return GetExceptionMessage(err, msg, logs);
 }
 
 } // namespace DrmUtils