Ark运行时日志不打印问题分析报告

鸿蒙使小强 2023-03-13 17:39:41

1 关键字

ark; LOG_ECMA; 日志;

2 问题描述

开发板型号：rk3568

OH版本：OpenHarmony 3.1 Release

问题现象：hilog中搜不到 LOG_ECMA 的输出（ark/runtime_core/libpandabase/utils/logger.h）日志

测试步骤：

烧镜像
终端输入hilog | grep Ark
eco跑一个demo

日志输出空

3 问题原因

3.1 正常机制

日志中出现如下格式的日志，有 Ark 函数名行号

03900/Ace: [jsi_declarative_engine.cpp(PrintLog)-(0)] Ark ecmascript::GenerateProgram Line:77 GenerateProgram /data/storage/el1/bundle/com.example.entry/assets/js/MainAbility/app.abc

3.2 异常机制

Ark 关键字的日志为空

4 解决方案

通过下面方式可以看到ark的日志输出

方法一：

修改ark\runtime_core\libpandabase\utils\logger.h文件的WriteMobileLog方法，将is_mlog_opened_的判断去掉，is_mlog_opened_此时的值是false,在判断里面会直接return，不会执行后面的打印日志流程。

if (mlog_buf_print == nullptr || !is_mlog_opened_) {
    return;
}

改为

if (mlog_buf_print == nullptr) {
    return;
}

方法二：

注释源码里面所有的Logger::SetMobileLogOpenFlag(false);

按照上面的方法可以在全量日志里看到ark相关的日志

5 定位过程

根据LOG_ECMA查找LOG_ECMA的定义
定义地方ark\js_runtime\ecmascript\ecma_macros.h

#define LOG_ECMA(type) \
LOG(type, ECMASCRIPT) << __func__ << " Line:" << __LINE__ << " "  // NOLINT(bugprone-lambda-function-name)

可以得出日志是以方法名 Line：行号的的形式输出。

再跟LOG到ark\runtime_core\libpandabase\utils\logger.h 文件中
最后调用的是

#define _LOG(level, component, p)
panda::Logger::IsLoggingOnOrAbort(panda::Logger::Level::level, panda::Logger::Component::component) && panda::Logger::Message(panda::Logger::Level::level, panda::Logger::Component::component, p).GetStream()

跟踪上步中的Message对象

class Message {
    public:
        Message(Level level, Component component, bool print_system_error): 
        level_(level), 
        component_(component),print_system_error_(print_system_error)
    {
    }

    ~Message();

    std::ostream &GetStream()
    {
        return stream_;
    }

    private:
        Level level_;
        Component component_;
        bool print_system_error_;
        std::ostringstream stream_;

        NO_COPY_SEMANTIC(Message);
        NO_MOVE_SEMANTIC(Message);
};

Logger::Message::~Message()
{
    if (print_system_error_) {
        stream_ << ": " << os::Error(errno).ToString();
    }
   
    Logger::Log(level_, component_, stream_.str());
   
    if (level_ == Level::FATAL) {
        std::abort();
    }
}

在析构函数中看到了Logger::Log(level_, component_, stream_.str());

跟踪Logger::Log函数发现该函数中调用了WriteMobileLog方法。
跟踪WriteMobileLog方法

void WriteMobileLog(Level level, const char *component, const char *message)
    {
        if (mlog_buf_print == nullptr || !is_mlog_opened_) {
            return;
    }
    PandaLog2MobileLog mlog_level = PandaLog2MobileLog::UNKNOWN;
    switch (level) {
        case Level::DEBUG:
            mlog_level = PandaLog2MobileLog::DEBUG;
        break;
        case Level::INFO:
            mlog_level = PandaLog2MobileLog::INFO;
        break;
        case Level::ERROR:
            mlog_level = PandaLog2MobileLog::ERROR;
        break;
        case Level::FATAL:
            mlog_level = PandaLog2MobileLog::FATAL;
        break;
        case Level::WARNING:
            mlog_level = PandaLog2MobileLog::WARN;
        break;
        default:
        UNREACHABLE();
    }
    std::string panda_component = "Ark " + std::string(component);
    mlog_buf_print(LOG_ID_MAIN, mlog_level, panda_component.c_str(), "%s", message);
}

有个判断条件 is_mlog_opened_ 日志控制开关
mlog_buf_print函数执行打印日志

跟踪mlog_buf_print赋值的地方

ark\runtime_core\libpandabase\utils\logger.h中SetMobileLogPrintEntryPointByPtr方法

  static void SetMobileLogPrintEntryPointByPtr(void *mlog_buf_print_ptr)
      {
          mlog_buf_print = reinterpret_cast<FUNC_MOBILE_LOG_PRINT>(mlog_buf_print_ptr);
      }

ark\js_runtime\ecmascript\napi\jsnapi.cpp中调用SetMobileLogPrintEntryPointByPtr方法的地方

bool JSNApi::CreateRuntime(const RuntimeOption &option)
{
    ...
  
    // Dfx
    base_options::Options baseOptions("");
    baseOptions.SetLogLevel(option.GetLogLevel());
    arg_list_t logComponents;
    logComponents.emplace_back("all");
    baseOptions.SetLogComponents(logComponents);
    Logger::Initialize(baseOptions);
    if (option.GetLogBufPrint() != nullptr) {
        Logger::SetMobileLogPrintEntryPointByPtr(reinterpret_cast<void *>(option.GetLogBufPrint()));
    }
    ...
  
    return true;
}

foundation\ace\ace_engine\frameworks\bridge\declarative_frontend\engine\jsi\ark\ark_js_runtime.cpp中调用SetLogBufPrint方法设置打印函数

bool ArkJSRuntime::Initialize(const std::string &libraryPath, bool isDebugMode)
{
    RuntimeOption option;
    option.SetGcType(RuntimeOption::GC_TYPE::GEN_GC);
    option.SetArkProperties(SystemProperties::GetArkProperties());
    const int64_t poolSize = 0x10000000;  // 256M
    option.SetGcPoolSize(poolSize);
    option.SetLogLevel(RuntimeOption::LOG_LEVEL::ERROR);
    option.SetLogBufPrint(print_);
    option.SetDebuggerLibraryPath(libraryPath);
    libPath_ = libraryPath;
    isDebugMode_ = isDebugMode;
  
    vm_ = JSNApi::CreateJSVM(option);
    return vm_ != nullptr;
}

设置的打印函数

//文件路径 
//foundation\ace\ace_engine\frameworks\bridge\declarative_frontend\engine\jsi\ark\ark_js_runtime.cpp
void ArkJSRuntime::SetLogPrint(LOG_PRINT out)
{
    print_ = out;
}

//文件路径 
//foundation\ace\ace_engine\frameworks\bridge\declarative_frontend\engine\jsi\jsi_declarative_engine.cpp
bool JsiDeclarativeEngineInstance::InitJsEnv(bool debuggerMode,
const std::unordered_map<std::string, void*>& extraNativeObject, const shared_ptr<JsRuntime>& runtime)
{
    ...
   
    runtime_->SetLogPrint(PrintLog);
   
    ...
}
   
int PrintLog(int id, int level, const char* tag, const char* fmt, const char* message)
{
    switch (JsLogLevel(level - 3)) {
        case JsLogLevel::INFO:
            LOGI("%{public}s::%{public}s", tag, message);
            break;
        case JsLogLevel::WARNING:
            LOGW("%{public}s::%{public}s", tag, message);
            break;
        case JsLogLevel::ERROR:
            LOGE("%{public}s::%{public}s", tag, message);
            break;
        case JsLogLevel::DEBUG:
            LOGD("%{public}s::%{public}s", tag, message);
            break;
        default:
            LOGF("%{public}s::%{public}s", tag, message);
            break;
    }
    return 0;
}

PrintLog中使用的打印方法是ACE子系统下的日志输出方式

以上逻辑分析完，日志打印流程正常，但Ark日志没有输出，返回第5步WriteMobileLog中去掉if判断条件中对is_mlog_opened_的判断，测试发现有Ark相应的日志输出。故is_mlog_opened_值被设置成了false。
修改方法是可以直接去掉对is_mlog_opened_的判断，或者将is_mlog_opened_更改为false的地方注释调Logger::SetMobileLogOpenFlag(false);