Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 8635cb19 authored by Robert Shih's avatar Robert Shih
Browse files

libmediadrm: save IPC failure logs 

Other misc changes included:
* enumerate V1_4 drm/crypto factories
* check isCryptoSchemeSupported hidl status

Bug: 162255728
Test: MediaDrmTest#testExceptionMessage
Change-Id: Ifb059fc7b8a109408dd9ae45f4b0327c8c312264
parent c74fd5f5

drm/libmediadrm/DrmHal.cpp

+6 −5
Original line number Diff line number Diff line
@@ -345,10 +345,10 @@ std::vector<sp<IDrmFactory>> DrmHal::makeDrmFactories() { 
        // 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 @@ sp<IDrmPlugin> DrmHal::makeDrmPlugin(const sp<IDrmFactory>& factory, 
    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 @@ sp<IDrmPlugin> DrmHal::makeDrmPlugin(const sp<IDrmFactory>& factory, 
        );



    if (!hResult.isOk()) {

        ALOGE("createPlugin remote call failed");

        DrmUtils::LOG2BE("createPlugin remote call failed");

    }



    return plugin;
@@ -566,7 +566,8 @@ status_t DrmHal::createPlugin(const uint8_t uuid[16], 
    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;

drm/libmediadrm/DrmUtils.cpp

+69 −3
Original line number Diff line number Diff line
@@ -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 @@ template <typename Hal, typename V> 
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 @@ sp<::V1_0::IDrmPlugin> MakeDrmPlugin(const sp<::V1_0::IDrmFactory> &factory, 
    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 @@ sp<::V1_0::ICryptoPlugin> MakeCryptoPlugin(const sp<::V1_0::ICryptoFactory> &fac 
    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 @@ std::vector<sp<::V1_0::IDrmFactory>> MakeDrmFactories(const uint8_t uuid[16]) { 
    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 @@ std::vector<sp<::V1_0::ICryptoFactory>> MakeCryptoFactories(const uint8_t uuid[1 
    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 @@ status_t toStatusT_1_4(::V1_4::Status status) { 
    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

drm/libmediadrm/interface/mediadrm/DrmUtils.h

+79 −48
Original line number Diff line number Diff line
@@ -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 @@ struct IDrm; 


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 @@ inline status_t toStatusT(const android::hardware::Return<T> &status) { 
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 @@ status_t GetLogMessages(const sp<U> &obj, Vector<::V1_4::LogMessage> &logs) { 
            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);

    }



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;

}

    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;

}



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