/* * Copyright (C) 2021 Huawei Device Co., Ltd. * 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 "event_logger.h" #include "securec.h" #include #include #include #include #include #include #include #include #include #include #include #include #include #include "parameter.h" #include "common_utils.h" #include "dfx_json_formatter.h" #include "event_source.h" #include "file_util.h" #include "freeze_json_util.h" #include "parameter_ex.h" #include "plugin_factory.h" #include "string_util.h" #include "sys_event.h" #include "sys_event_dao.h" #include "time_util.h" #include "event_log_task.h" #include "event_logger_config.h" #include "freeze_common.h" #include "utility/trace_collector.h" namespace OHOS { namespace HiviewDFX { REGISTER(EventLogger); DEFINE_LOG_LABEL(0xD002D01, "EventLogger"); bool EventLogger::IsInterestedPipelineEvent(std::shared_ptr event) { if (event == nullptr) { return false; } if (event->eventId_ > EVENT_MAX_ID) { return false; } auto sysEvent = Event::DownCastTo(event); if (eventLoggerConfig_.find(sysEvent->eventName_) == eventLoggerConfig_.end()) { return false; } HIVIEW_LOGD("event time:%{public}" PRIu64 " jsonExtraInfo is %{public}s", TimeUtil::GetMilliseconds(), sysEvent->AsJsonStr().c_str()); EventLoggerConfig::EventLoggerConfigData& configOut = eventLoggerConfig_[sysEvent->eventName_]; sysEvent->eventName_ = configOut.name; sysEvent->SetValue("eventLog_action", configOut.action); sysEvent->SetValue("eventLog_interval", configOut.interval); return true; } bool EventLogger::OnEvent(std::shared_ptr &onEvent) { if (onEvent == nullptr) { HIVIEW_LOGE("event == nullptr"); return false; } auto sysEvent = Event::DownCastTo(onEvent); if (!IsHandleAppfreeze(sysEvent)) { return true; } long pid = sysEvent->GetEventIntValue("PID"); pid = pid ? pid : sysEvent->GetPid(); HIVIEW_LOGI("event: domain=%{public}s, eventName=%{public}s, pid=%{public}ld", sysEvent->domain_.c_str(), sysEvent->eventName_.c_str(), pid); if (sysEvent->GetValue("eventLog_action").empty()) { HIVIEW_LOGI("eventName=%{public}s, pid=%{public}ld, eventLog_action is empty.", sysEvent->eventName_.c_str(), pid); UpdateDB(sysEvent, "nolog"); return true; } sysEvent->OnPending(); auto task = [this, sysEvent]() { HIVIEW_LOGD("event time:%{public}" PRIu64 " jsonExtraInfo is %{public}s", TimeUtil::GetMilliseconds(), sysEvent->AsJsonStr().c_str()); if (!JudgmentRateLimiting(sysEvent)) { return; } this->StartLogCollect(sysEvent); }; HIVIEW_LOGI("before add task to eventpool, eventName=%{public}s, pid=%{public}ld", sysEvent->eventName_.c_str(), pid); eventPool_->AddTask(task, "eventlogger"); HIVIEW_LOGI("after add task to eventpool, eventName=%{public}s, pid=%{public}ld", sysEvent->eventName_.c_str(), pid); return true; } int EventLogger::Getfile(std::shared_ptr event, std::string& logFile) { std::string idStr = event->eventName_.empty() ? std::to_string(event->eventId_) : event->eventName_; uint64_t logTime = event->happenTime_ / TimeUtil::SEC_TO_MILLISEC; int32_t pid = static_cast(event->GetEventIntValue("PID")); pid = pid ? pid : event->GetPid(); logFile = idStr + "-" + std::to_string(pid) + "-" + TimeUtil::TimestampFormatToDate(logTime, "%Y%m%d%H%M%S") + ".log"; if (FileUtil::FileExists(LOGGER_EVENT_LOG_PATH + "/" + logFile)) { HIVIEW_LOGW("filename: %{public}s is existed, direct use.", logFile.c_str()); UpdateDB(event, logFile); return -1; } return logStore_->CreateLogFile(logFile); } void EventLogger::StartLogCollect(std::shared_ptr event) { std::string logFile; int fd = Getfile(event, logFile); if (fd < 0) { HIVIEW_LOGE("create log file %{public}s failed, %{public}d", logFile.c_str(), fd); return; } int jsonFd = -1; if (FreezeJsonUtil::IsAppFreeze(event->eventName_)) { std::string jsonFilePath = FreezeJsonUtil::GetFilePath(event->GetEventIntValue("PID"), event->GetEventIntValue("UID"), event->happenTime_); jsonFd = FreezeJsonUtil::GetFd(jsonFilePath); } std::unique_ptr logTask = std::make_unique(fd, jsonFd, event); std::string cmdStr = event->GetValue("eventLog_action"); std::vector cmdList; StringUtil::SplitStr(cmdStr, ",", cmdList); for (const std::string& cmd : cmdList) { logTask->AddLog(cmd); } const uint32_t placeholder = 3; auto start = TimeUtil::GetMilliseconds(); uint64_t startTime = start / TimeUtil::SEC_TO_MILLISEC; std::ostringstream startTimeStr; startTimeStr << "start time: " << TimeUtil::TimestampFormatToDate(startTime, "%Y/%m/%d-%H:%M:%S"); startTimeStr << ":" << std::setw(placeholder) << std::setfill('0') << std::to_string(start % TimeUtil::SEC_TO_MILLISEC); startTimeStr << std::endl; FileUtil::SaveStringToFd(fd, startTimeStr.str()); WriteCommonHead(fd, event); WriteFreezeJsonInfo(fd, jsonFd, event); auto ret = logTask->StartCompose(); if (ret != EventLogTask::TASK_SUCCESS) { HIVIEW_LOGE("capture fail %{public}d", ret); } auto end = TimeUtil::GetMilliseconds(); std::string totalTime = "\n\nCatcher log total time is " + std::to_string(end - start) + "ms\n"; FileUtil::SaveStringToFd(fd, totalTime); close(fd); if (jsonFd >= 0) { close(jsonFd); } UpdateDB(event, logFile); constexpr int waitTime = 1; auto CheckFinishFun = std::bind(&EventLogger::CheckEventOnContinue, this, event); threadLoop_->AddTimerEvent(nullptr, nullptr, CheckFinishFun, waitTime, false); HIVIEW_LOGI("Collect on finish, name: %{public}s", logFile.c_str()); } bool ParseMsgForMessageAndEventHandler(const std::string& msg, std::string& message, std::string& eventHandlerStr) { std::vector lines; StringUtil::SplitStr(msg, "\n", lines, false, true); bool isGetMessage = false; std::string messageStartFlag = "Fault time:"; std::string messageEndFlag = "mainHandler dump is:"; std::string eventFlag = "Event {"; bool isGetEvent = false; std::regex eventStartFlag(".*((Immediate)|(High)|(Low)) priority event queue information:.*"); std::regex eventEndFlag(".*Total size of ((Immediate)|(High)|(Low)) events :.*"); std::list eventHandlerList; for (auto line = lines.begin(); line != lines.end(); line++) { if ((*line).find(messageStartFlag) != std::string::npos) { isGetMessage = true; continue; } if (isGetMessage) { if ((*line).find(messageEndFlag) != std::string::npos) { isGetMessage = false; HIVIEW_LOGI("Get FreezeJson message jsonStr: %{public}s", message.c_str()); continue; } message += StringUtil::TrimStr(*line); continue; } if (regex_match(*line, eventStartFlag)) { isGetEvent = true; continue; } if (isGetEvent) { if (regex_match(*line, eventEndFlag)) { isGetEvent = false; continue; } std::string::size_type pos = (*line).find(eventFlag); if (pos == std::string::npos) { continue; } std::string handlerStr = StringUtil::TrimStr(*line).substr(pos); HIVIEW_LOGI("Get EventHandler str: %{public}s.", handlerStr.c_str()); eventHandlerList.push_back(handlerStr); } } eventHandlerStr = FreezeJsonUtil::GetStrByList(eventHandlerList); return true; } void ParsePeerBinder(const std::string& binderInfo, std::string& binderInfoJsonStr) { std::vector lines; StringUtil::SplitStr(binderInfo, "\\n", lines, false, true); std::list infoList; std::map processNameMap; for (auto lineIt = lines.begin(); lineIt != lines.end(); lineIt++) { std::string line = *lineIt; if (line.empty() || line.find("async") != std::string::npos) { continue; } if (line.find("context") != line.npos) { break; } std::istringstream lineStream(line); std::vector strList; std::string tmpstr; while (lineStream >> tmpstr) { strList.push_back(tmpstr); } if (strList.size() != 7) { // 7: valid array size continue; } // 2: binder peer id std::string pidStr = strList[2].substr(0, strList[2].find(":")); if (pidStr == "") { continue; } if (processNameMap.find(pidStr) == processNameMap.end()) { std::ifstream cmdLineFile("/proc/" + pidStr + "/cmdline"); std::string processName; if (cmdLineFile) { std::getline(cmdLineFile, processName); cmdLineFile.close(); processName = StringUtil::FormatCmdLine(processName); processNameMap[pidStr] = processName; } else { HIVIEW_LOGE("Fail to open /proc/%{public}s/cmdline", pidStr.c_str()); } } std::string lineStr = line + " " + pidStr + FreezeJsonUtil::WrapByParenthesis(processNameMap[pidStr]); infoList.push_back(lineStr); } binderInfoJsonStr = FreezeJsonUtil::GetStrByList(infoList); } bool EventLogger::WriteCommonHead(int fd, std::shared_ptr event) { std::ostringstream headerStream; headerStream << "DOMAIN = " << event->domain_ << std::endl; headerStream << "EVENTNAME = " << event->eventName_ << std::endl; uint64_t logTime = event->happenTime_ / TimeUtil::SEC_TO_MILLISEC; uint64_t logTimeMs = event->happenTime_ % TimeUtil::SEC_TO_MILLISEC; std::string happenTime = TimeUtil::TimestampFormatToDate(logTime, "%Y/%m/%d-%H:%M:%S"); headerStream << "TIMESTAMP = " << happenTime << ":" << logTimeMs << std::endl; long pid = event->GetEventIntValue("PID"); pid = pid ? pid : event->GetPid(); headerStream << "PID = " << pid << std::endl; long uid = event->GetEventIntValue("UID"); uid = uid ? uid : event->GetUid(); headerStream << "UID = " << uid << std::endl; if (event->GetEventValue("MODULE_NAME") != "") { headerStream << "MODULE_NAME = " << event->GetEventValue("MODULE_NAME") << std::endl; } else { headerStream << "PACKAGE_NAME = " << event->GetEventValue("PACKAGE_NAME") << std::endl; } headerStream << "PROCESS_NAME = " << event->GetEventValue("PROCESS_NAME") << std::endl; headerStream << "eventLog_action = " << event->GetValue("eventLog_action") << std::endl; headerStream << "eventLog_interval = " << event->GetValue("eventLog_interval") << std::endl; FileUtil::SaveStringToFd(fd, headerStream.str()); return true; } bool EventLogger::WriteFreezeJsonInfo(int fd, int jsonFd, std::shared_ptr event) { std::string msg = StringUtil::ReplaceStr(event->GetEventValue("MSG"), "\\n", "\n"); std::string stack; std::string binderInfo = event -> GetEventValue("BINDER_INFO"); if (FreezeJsonUtil::IsAppFreeze(event -> eventName_)) { std::string message; std::string eventHandlerStr; ParseMsgForMessageAndEventHandler(msg, message, eventHandlerStr); std::string jsonStack = event->GetEventValue("STACK"); if (!jsonStack.empty() && jsonStack[0] == '[') { // json stack info should start with '[' jsonStack = StringUtil::UnescapeJsonStringValue(jsonStack); if (!DfxJsonFormatter::FormatJsonStack(jsonStack, stack)) { stack = jsonStack; } } else { stack = jsonStack; } if (jsonFd >= 0) { HIVIEW_LOGI("success to open FreezeJsonFile! jsonFd: %{public}d", jsonFd); FreezeJsonUtil::WriteKeyValue(jsonFd, "message", message); FreezeJsonUtil::WriteKeyValue(jsonFd, "event_handler", eventHandlerStr); FreezeJsonUtil::WriteKeyValue(jsonFd, "stack", jsonStack); } else { HIVIEW_LOGE("fail to open FreezeJsonFile! jsonFd: %{public}d", jsonFd); } if (!binderInfo.empty() && jsonFd >= 0) { std::string binderInfoJsonStr; ParsePeerBinder(binderInfo, binderInfoJsonStr); FreezeJsonUtil::WriteKeyValue(jsonFd, "peer_binder", binderInfoJsonStr); } } else { stack = event->GetEventValue("STACK"); } std::ostringstream oss; oss << "MSG = " << msg << std::endl; if (!stack.empty()) { oss << StringUtil::UnescapeJsonStringValue(stack) << std::endl; } if (!binderInfo.empty()) { oss << StringUtil::UnescapeJsonStringValue(binderInfo) << std::endl; } FileUtil::SaveStringToFd(fd, oss.str()); return true; } bool EventLogger::JudgmentRateLimiting(std::shared_ptr event) { int32_t interval = event->GetIntValue("eventLog_interval"); if (interval == 0) { return true; } int64_t pid = event->GetEventIntValue("PID"); pid = pid ? pid : event->GetPid(); std::string eventName = event->eventName_; std::string eventPid = std::to_string(pid); std::unique_lock lck(intervalMutex_); std::time_t now = std::time(0); for (auto it = eventTagTime_.begin(); it != eventTagTime_.end();) { if (it->first.find(eventName) != it->first.npos) { if ((now - it->second) >= interval) { it = eventTagTime_.erase(it); continue; } } ++it; } std::string tagTimeName = eventName + eventPid; auto it = eventTagTime_.find(tagTimeName); if (it != eventTagTime_.end()) { if ((now - it->second) < interval) { HIVIEW_LOGE("event: id:0x%{public}d, eventName:%{public}s pid:%{public}s. \ interval:%{public}" PRId32 " There's not enough interval", event->eventId_, eventName.c_str(), eventPid.c_str(), interval); return false; } } eventTagTime_[tagTimeName] = now; HIVIEW_LOGI("event: id:0x%{public}d, eventName:%{public}s pid:%{public}s. \ interval:%{public}" PRId32 " normal interval", event->eventId_, eventName.c_str(), eventPid.c_str(), interval); return true; } bool EventLogger::UpdateDB(std::shared_ptr event, std::string logFile) { if (logFile == "nolog") { HIVIEW_LOGI("set info_ with nolog into db."); event->SetEventValue(EventStore::EventCol::INFO, "nolog", false); } else { auto logPath = R"~(logPath:)~" + LOGGER_EVENT_LOG_PATH + "/" + logFile; event->SetEventValue(EventStore::EventCol::INFO, logPath, true); } return true; } bool EventLogger::IsHandleAppfreeze(std::shared_ptr event) { std::string bundleName = event->GetEventValue("PACKAGE_NAME"); if (bundleName.empty()) { bundleName = event->GetEventValue("MODULE_NAME"); } if (bundleName.empty()) { return true; } const int buffSize = 128; char paramOutBuff[buffSize] = {0}; GetParameter("hiviewdfx.appfreeze.filter_bundle_name", "", paramOutBuff, buffSize - 1); std::string str(paramOutBuff); if (str.find(bundleName) != std::string::npos) { HIVIEW_LOGW("appfreeze filtration %{public}s.", bundleName.c_str()); return false; } return true; } void EventLogger::CheckEventOnContinue(std::shared_ptr event) { event->ResetPendingStatus(); event->OnContinue(); } void EventLogger::OnLoad() { HIVIEW_LOGI("EventLogger OnLoad."); SetName("EventLogger"); SetVersion("1.0"); logStore_->SetMaxSize(MAX_FOLDER_SIZE); logStore_->SetMinKeepingFileNumber(MAX_FILE_NUM); logStore_->Init(); threadLoop_ = GetWorkLoop(); EventLoggerConfig logConfig; eventLoggerConfig_ = logConfig.GetConfig(); eventPool_ = std::make_shared(maxEventPoolCount, "EventLog"); eventPool_->Start(); activeKeyEvent_ = std::make_unique(); activeKeyEvent_ ->Init(eventPool_, logStore_); FreezeCommon freezeCommon; if (!freezeCommon.Init()) { HIVIEW_LOGE("FreezeCommon filed."); return; } std::set freezeeventNames = freezeCommon.GetPrincipalStringIds(); std::unordered_set eventNames; for (auto& i : freezeeventNames) { eventNames.insert(i); } auto context = GetHiviewContext(); if (context != nullptr) { auto plugin = context->GetPluginByName("FreezeDetectorPlugin"); HIVIEW_LOGE("plugin plugin %{public}s.", plugin->GetName().c_str()); context->AddDispatchInfo(plugin, {}, eventNames, {}, {}); auto ptr = std::static_pointer_cast(shared_from_this()); context->RegisterUnorderedEventListener(ptr); AddListenerInfo(Event::MessageType::PLUGIN_MAINTENANCE); } GetCmdlineContent(); GetRebootReasonConfig(); } void EventLogger::OnUnload() { HIVIEW_LOGD("called"); eventPool_->Stop(); } std::string EventLogger::GetListenerName() { return "EventLogger"; } void EventLogger::OnUnorderedEvent(const Event& msg) { if (CanProcessRebootEvent(msg)) { auto task = std::bind(&EventLogger::ProcessRebootEvent, this); threadLoop_->AddEvent(nullptr, nullptr, task); } } bool EventLogger::CanProcessRebootEvent(const Event& event) { return (event.messageType_ == Event::MessageType::PLUGIN_MAINTENANCE) && (event.eventId_ == Event::EventId::PLUGIN_LOADED); } void EventLogger::ProcessRebootEvent() { if (GetRebootReason() != LONG_PRESS) { return; } auto event = std::make_shared("EventLogger", nullptr, ""); if (event == nullptr) { HIVIEW_LOGW("event is null."); return; } event->domain_ = DOMAIN_LONGPRESS; event->eventName_ = STRINGID_LONGPRESS; event->happenTime_ = TimeUtil::GetMilliseconds(); event->messageType_ = Event::MessageType::SYS_EVENT; event->SetEventValue(EventStore::EventCol::DOMAIN, DOMAIN_LONGPRESS); event->SetEventValue(EventStore::EventCol::NAME, STRINGID_LONGPRESS); event->SetEventValue(EventStore::EventCol::TYPE, 1); event->SetEventValue(EventStore::EventCol::TS, TimeUtil::GetMilliseconds()); event->SetEventValue(EventStore::EventCol::TZ, TimeUtil::GetTimeZone()); event->SetEventValue("PID", 0); event->SetEventValue("UID", 0); event->SetEventValue("PACKAGE_NAME", STRINGID_LONGPRESS); event->SetEventValue("PROCESS_NAME", STRINGID_LONGPRESS); event->SetEventValue("MSG", STRINGID_LONGPRESS); auto context = GetHiviewContext(); if (context != nullptr) { auto seq = context->GetPipelineSequenceByName("EventloggerPipeline"); event->SetPipelineInfo("EventloggerPipeline", seq); event->OnContinue(); } } std::string EventLogger::GetRebootReason() const { std::string reboot = ""; std::string reset = ""; if (GetMatchString(cmdlineContent_, reboot, REBOOT_REASON + PATTERN_WITHOUT_SPACE) && GetMatchString(cmdlineContent_, reset, NORMAL_RESET_TYPE + PATTERN_WITHOUT_SPACE)) { if (std::any_of(rebootReasons_.begin(), rebootReasons_.end(), [&reboot, &reset](auto& reason) { return (reason == reboot || reason == reset); })) { HIVIEW_LOGI("get reboot reason: LONG_PRESS."); return LONG_PRESS; } } return ""; } void EventLogger::GetCmdlineContent() { if (FileUtil::LoadStringFromFile(cmdlinePath_, cmdlineContent_) == false) { HIVIEW_LOGE("failed to read cmdline:%{public}s.", cmdlinePath_.c_str()); } } void EventLogger::GetRebootReasonConfig() { rebootReasons_.clear(); if (rebootReasons_.size() == 0) { rebootReasons_.push_back(AP_S_PRESS6S); } } bool EventLogger::GetMatchString(const std::string& src, std::string& dst, const std::string& pattern) const { std::regex reg(pattern); std::smatch result; if (std::regex_search(src, result, reg)) { dst = StringUtil::TrimStr(result[1], '\n'); return true; } return false; } } // namesapce HiviewDFX } // namespace OHOS