| /* |
| * Copyright (C) 2020 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 "chre_host/log_message_parser.h" |
| |
| #include <endian.h> |
| #include <string.h> |
| #include <optional> |
| |
| #include "chre/util/macros.h" |
| #include "chre/util/time.h" |
| #include "chre_host/daemon_base.h" |
| #include "chre_host/file_stream.h" |
| #include "chre_host/log.h" |
| #include "include/chre_host/log_message_parser.h" |
| |
| #include "pw_result/result.h" |
| #include "pw_span/span.h" |
| #include "pw_tokenizer/detokenize.h" |
| |
| using chre::kOneMillisecondInNanoseconds; |
| using chre::kOneSecondInMilliseconds; |
| using chre::fbs::LogType; |
| |
| namespace android { |
| namespace chre { |
| |
| namespace { |
| #if defined(LOG_NDEBUG) || LOG_NDEBUG != 0 |
| constexpr bool kVerboseLoggingEnabled = true; |
| #else |
| constexpr bool kVerboseLoggingEnabled = false; |
| #endif |
| |
| //! Offset in bytes between the address and real start of a nanoapp binary. |
| constexpr size_t kImageHeaderSize = 0x1000; |
| //! The number of bytes in a string log entry in addition to the log payload. |
| //! The value indicate the size of the null terminator. |
| constexpr size_t kStringLogOverhead = 1; |
| //! The number of bytes in a tokenized log entry in addition to the log payload. |
| //! The value indicate the size of the uint8_t logSize field. |
| constexpr size_t kSystemTokenizedLogOffset = 1; |
| //! The number of bytes in a nanoapp tokenized log entry in addition to the log |
| //! payload. The value accounts for the size of the uint8_t logSize field and |
| //! the uint16_t instanceId field. |
| constexpr size_t kNanoappTokenizedLogOffset = 3; |
| //! This value is used to indicate that a nanoapp does not have a token database |
| //! section. |
| constexpr uint32_t kInvalidTokenDatabaseSize = 0; |
| } // anonymous namespace |
| |
| LogMessageParser::LogMessageParser() |
| : mVerboseLoggingEnabled(kVerboseLoggingEnabled) {} |
| |
| std::unique_ptr<Detokenizer> LogMessageParser::logDetokenizerInit() { |
| #ifdef CHRE_TOKENIZED_LOGGING_ENABLED |
| constexpr const char kLogDatabaseFilePath[] = |
| "/vendor/etc/chre/libchre_log_database.bin"; |
| std::vector<uint8_t> tokenData; |
| if (readFileContents(kLogDatabaseFilePath, tokenData)) { |
| pw::tokenizer::TokenDatabase database = |
| pw::tokenizer::TokenDatabase::Create(tokenData); |
| if (database.ok()) { |
| LOGD("Log database initialized, creating detokenizer"); |
| return std::make_unique<Detokenizer>(database); |
| } else { |
| LOGE("CHRE Token database creation not OK"); |
| } |
| } else { |
| LOGE("Failed to read CHRE Token database file"); |
| } |
| #endif |
| return std::unique_ptr<Detokenizer>(nullptr); |
| } |
| |
| void LogMessageParser::init(size_t nanoappImageHeaderSize) { |
| mSystemDetokenizer = logDetokenizerInit(); |
| mNanoappImageHeaderSize = nanoappImageHeaderSize; |
| } |
| |
| void LogMessageParser::dump(const uint8_t *buffer, size_t size) { |
| if (mVerboseLoggingEnabled) { |
| char line[32]; |
| char lineChars[32]; |
| int offset = 0; |
| int offsetChars = 0; |
| |
| size_t orig_size = size; |
| if (size > 128) { |
| size = 128; |
| LOGV("Dumping first 128 bytes of buffer of size %zu", orig_size); |
| } else { |
| LOGV("Dumping buffer of size %zu bytes", size); |
| } |
| for (size_t i = 1; i <= size; ++i) { |
| offset += snprintf(&line[offset], sizeof(line) - offset, "%02x ", |
| buffer[i - 1]); |
| offsetChars += |
| snprintf(&lineChars[offsetChars], sizeof(lineChars) - offsetChars, |
| "%c", (isprint(buffer[i - 1])) ? buffer[i - 1] : '.'); |
| if ((i % 8) == 0) { |
| LOGV(" %s\t%s", line, lineChars); |
| offset = 0; |
| offsetChars = 0; |
| } else if ((i % 4) == 0) { |
| offset += snprintf(&line[offset], sizeof(line) - offset, " "); |
| } |
| } |
| |
| if (offset > 0) { |
| char tabs[8]; |
| char *pos = tabs; |
| while (offset < 28) { |
| *pos++ = '\t'; |
| offset += 8; |
| } |
| *pos = '\0'; |
| LOGV(" %s%s%s", line, tabs, lineChars); |
| } |
| } |
| } |
| |
| android_LogPriority LogMessageParser::chreLogLevelToAndroidLogPriority( |
| uint8_t level) { |
| switch (level) { |
| case LogLevel::ERROR: |
| return ANDROID_LOG_ERROR; |
| case LogLevel::WARNING: |
| return ANDROID_LOG_WARN; |
| case LogLevel::INFO: |
| return ANDROID_LOG_INFO; |
| case LogLevel::DEBUG: |
| return ANDROID_LOG_DEBUG; |
| default: |
| return ANDROID_LOG_SILENT; |
| } |
| } |
| |
| uint8_t LogMessageParser::getLogLevelFromMetadata(uint8_t metadata) { |
| // The lower nibble of the metadata denotes the loglevel, as indicated |
| // by the schema in host_messages.fbs. |
| return metadata & 0xf; |
| } |
| |
| void LogMessageParser::log(const uint8_t *logBuffer, size_t logBufferSize) { |
| size_t bufferIndex = 0; |
| while (bufferIndex < logBufferSize) { |
| const LogMessage *message = |
| reinterpret_cast<const LogMessage *>(&logBuffer[bufferIndex]); |
| uint64_t timeNs = le64toh(message->timestampNanos); |
| emitLogMessage(message->logLevel, timeNs / kOneMillisecondInNanoseconds, |
| message->logMessage); |
| bufferIndex += sizeof(LogMessage) + |
| strnlen(message->logMessage, logBufferSize - bufferIndex) + |
| 1; |
| } |
| } |
| |
| std::optional<size_t> |
| LogMessageParser::parseAndEmitTokenizedLogMessageAndGetSize( |
| const LogMessageV2 *message, size_t maxLogMessageLen) { |
| auto detokenizer = mSystemDetokenizer.get(); |
| auto *encodedLog = reinterpret_cast<const EncodedLog *>(message->logMessage); |
| size_t logMessageSize = encodedLog->size + kSystemTokenizedLogOffset; |
| if (logMessageSize > maxLogMessageLen) { |
| LOGE("Dropping log due to log message size exceeds the end of log buffer"); |
| return std::nullopt; |
| } else if (detokenizer != nullptr) { |
| DetokenizedString detokenizedString = |
| detokenizer->Detokenize(encodedLog->data, encodedLog->size); |
| std::string decodedString = detokenizedString.BestStringWithErrors(); |
| emitLogMessage(getLogLevelFromMetadata(message->metadata), |
| le32toh(message->timestampMillis), decodedString.c_str()); |
| } else { |
| // TODO(b/327515992): Stop decoding and emitting system log messages if |
| // detokenizer is null . |
| LOGE("Null detokenizer! Cannot decode log message"); |
| } |
| return logMessageSize; |
| } |
| |
| std::optional<size_t> |
| LogMessageParser::parseAndEmitNanoappTokenizedLogMessageAndGetSize( |
| const LogMessageV2 *message, size_t maxLogMessageLen) { |
| std::lock_guard<std::mutex> lock(mNanoappMutex); |
| auto *tokenizedLog = |
| reinterpret_cast<const NanoappTokenizedLog *>(message->logMessage); |
| auto detokenizerIter = mNanoappDetokenizers.find(tokenizedLog->instanceId); |
| size_t logMessageSize = tokenizedLog->size + kNanoappTokenizedLogOffset; |
| if (detokenizerIter == mNanoappDetokenizers.end()) { |
| LOGE( |
| "Unable to find nanoapp log detokenizer associated with instance ID: " |
| "%" PRIu16, |
| tokenizedLog->instanceId); |
| return std::nullopt; |
| } else if (logMessageSize > maxLogMessageLen) { |
| LOGE("Dropping log due to log message size exceeds the end of log buffer"); |
| logMessageSize = maxLogMessageLen; |
| } else { |
| auto detokenizer = detokenizerIter->second.detokenizer.get(); |
| DetokenizedString detokenizedString = |
| detokenizer->Detokenize(tokenizedLog->data, tokenizedLog->size); |
| std::string decodedString = detokenizedString.BestStringWithErrors(); |
| emitLogMessage(getLogLevelFromMetadata(message->metadata), |
| le32toh(message->timestampMillis), decodedString.c_str()); |
| } |
| return logMessageSize; |
| } |
| |
| std::optional<size_t> LogMessageParser::parseAndEmitStringLogMessageAndGetSize( |
| const LogMessageV2 *message, size_t maxLogMessageLen) { |
| maxLogMessageLen = maxLogMessageLen - kStringLogOverhead; |
| size_t logMessageSize = strnlen(message->logMessage, maxLogMessageLen); |
| if (message->logMessage[logMessageSize] != '\0') { |
| LOGE("Dropping string log due to invalid buffer structure"); |
| return std::nullopt; |
| } |
| emitLogMessage(getLogLevelFromMetadata(message->metadata), |
| le32toh(message->timestampMillis), message->logMessage); |
| return logMessageSize + kStringLogOverhead; |
| } |
| |
| void LogMessageParser::updateAndPrintDroppedLogs(uint32_t numLogsDropped) { |
| if (numLogsDropped < mNumLogsDropped) { |
| LOGE( |
| "The numLogsDropped value received from CHRE is less than the last " |
| "value received. Received: %" PRIu32 " Last value: %" PRIu32, |
| numLogsDropped, mNumLogsDropped); |
| } |
| // Log the number of logs dropped once before logging remaining logs from CHRE |
| uint32_t diffLogsDropped = numLogsDropped - mNumLogsDropped; |
| mNumLogsDropped = numLogsDropped; |
| if (diffLogsDropped > 0) { |
| LOGI("# logs dropped: %" PRIu32, diffLogsDropped); |
| } |
| } |
| |
| void LogMessageParser::emitLogMessage(uint8_t level, uint32_t timestampMillis, |
| const char *logMessage) { |
| constexpr const char kLogTag[] = "CHRE"; |
| uint32_t timeSec = timestampMillis / kOneSecondInMilliseconds; |
| uint32_t timeMsRemainder = timestampMillis % kOneSecondInMilliseconds; |
| android_LogPriority priority = chreLogLevelToAndroidLogPriority(level); |
| LOG_PRI(priority, kLogTag, kHubLogFormatStr, timeSec, timeMsRemainder, |
| logMessage); |
| } |
| |
| void LogMessageParser::logV2(const uint8_t *logBuffer, size_t logBufferSize, |
| uint32_t numLogsDropped) { |
| constexpr size_t kLogHeaderSize = sizeof(LogMessageV2); |
| |
| updateAndPrintDroppedLogs(numLogsDropped); |
| |
| std::optional<size_t> logMessageSize = std::nullopt; |
| size_t bufferIndex = 0; |
| const LogMessageV2 *message = nullptr; |
| size_t maxLogMessageLen = 0; |
| while (bufferIndex + kLogHeaderSize < logBufferSize) { |
| message = reinterpret_cast<const LogMessageV2 *>(&logBuffer[bufferIndex]); |
| maxLogMessageLen = (logBufferSize - bufferIndex) - kLogHeaderSize; |
| logMessageSize = std::nullopt; |
| |
| switch (extractLogType(message)) { |
| // TODO(b/336467722): Rename the log types in fbs. |
| case LogType::STRING: |
| logMessageSize = |
| parseAndEmitStringLogMessageAndGetSize(message, maxLogMessageLen); |
| break; |
| case LogType::TOKENIZED: |
| logMessageSize = parseAndEmitTokenizedLogMessageAndGetSize( |
| message, maxLogMessageLen); |
| break; |
| case LogType::BLUETOOTH: |
| logMessageSize = |
| mBtLogParser.log(message->logMessage, maxLogMessageLen); |
| break; |
| case LogType::NANOAPP_TOKENIZED: |
| logMessageSize = parseAndEmitNanoappTokenizedLogMessageAndGetSize( |
| message, maxLogMessageLen); |
| break; |
| default: |
| LOGE("Unexpected log type 0x%" PRIx8, |
| (message->metadata & kLogTypeMask) >> kLogTypeBitOffset); |
| break; |
| } |
| if (!logMessageSize.has_value()) { |
| LOGE("Log message at offset %zu is corrupted, aborting...", bufferIndex); |
| return; |
| } |
| bufferIndex += kLogHeaderSize + logMessageSize.value(); |
| } |
| } |
| |
| void LogMessageParser::addNanoappDetokenizer(uint64_t appId, |
| uint16_t instanceId, |
| uint64_t databaseOffset, |
| size_t databaseSize) { |
| std::shared_ptr<const std::vector<uint8_t>> appBinary = |
| fetchNanoappBinary(appId); |
| if (!appBinary) { |
| LOGE( |
| "Binary not in cache, can't extract log token database for app ID " |
| "0x%016" PRIx64, |
| appId); |
| } else { |
| removeNanoappDetokenizerAndBinary(appId); |
| if (databaseSize != kInvalidTokenDatabaseSize) { |
| if (checkTokenDatabaseOverflow(databaseOffset, databaseSize, |
| appBinary->size())) { |
| LOGE( |
| "Token database fails memory bounds check for nanoapp with app ID " |
| "0x%016" PRIx64 ". Token database offset received: %" PRIu32 |
| "; size received: %zu; Size of the appBinary: %zu.", |
| appId, databaseOffset, databaseSize, appBinary->size()); |
| } else { |
| const uint8_t *tokenDatabaseBinaryStart = |
| appBinary->data() + kImageHeaderSize + databaseOffset; |
| |
| pw::span<const uint8_t> tokenEntries(tokenDatabaseBinaryStart, |
| databaseSize); |
| pw::Result<Detokenizer> nanoappDetokenizer = |
| pw::tokenizer::Detokenizer::FromElfSection(tokenEntries); |
| |
| registerDetokenizer(appId, instanceId, std::move(nanoappDetokenizer)); |
| } |
| } |
| } |
| } |
| |
| void LogMessageParser::registerDetokenizer( |
| uint64_t appId, uint16_t instanceId, |
| pw::Result<Detokenizer> nanoappDetokenizer) { |
| std::lock_guard<std::mutex> lock(mNanoappMutex); |
| |
| if (nanoappDetokenizer.ok()) { |
| NanoappDetokenizer detokenizer; |
| detokenizer.appId = appId; |
| detokenizer.detokenizer = |
| std::make_unique<Detokenizer>(std::move(*nanoappDetokenizer)); |
| mNanoappDetokenizers[instanceId] = std::move(detokenizer); |
| } else { |
| LOGE("Unable to parse log detokenizer for app with ID: 0x%016" PRIx64, |
| appId); |
| } |
| } |
| |
| std::shared_ptr<const std::vector<uint8_t>> |
| LogMessageParser::fetchNanoappBinary(uint64_t appId) { |
| std::lock_guard<std::mutex> lock(mNanoappMutex); |
| auto appBinaryIter = mNanoappAppIdToBinary.find(appId); |
| if (appBinaryIter != mNanoappAppIdToBinary.end()) { |
| return appBinaryIter->second; |
| } |
| return nullptr; |
| } |
| |
| void LogMessageParser::removeNanoappDetokenizerAndBinary(uint64_t appId) { |
| std::lock_guard<std::mutex> lock(mNanoappMutex); |
| for (const auto &item : mNanoappDetokenizers) { |
| if (item.second.appId == appId) { |
| mNanoappDetokenizers.erase(item.first); |
| } |
| } |
| mNanoappAppIdToBinary.erase(appId); |
| } |
| |
| void LogMessageParser::resetNanoappDetokenizerState() { |
| std::lock_guard<std::mutex> lock(mNanoappMutex); |
| mNanoappDetokenizers.clear(); |
| mNanoappAppIdToBinary.clear(); |
| } |
| |
| void LogMessageParser::onNanoappLoadStarted( |
| uint64_t appId, std::shared_ptr<const std::vector<uint8_t>> nanoappBinary) { |
| std::lock_guard<std::mutex> lock(mNanoappMutex); |
| mNanoappAppIdToBinary[appId] = nanoappBinary; |
| } |
| |
| void LogMessageParser::onNanoappLoadFailed(uint64_t appId) { |
| removeNanoappDetokenizerAndBinary(appId); |
| } |
| |
| void LogMessageParser::onNanoappUnloaded(uint64_t appId) { |
| removeNanoappDetokenizerAndBinary(appId); |
| } |
| |
| bool LogMessageParser::checkTokenDatabaseOverflow(uint32_t databaseOffset, |
| size_t databaseSize, |
| size_t binarySize) { |
| return databaseOffset > binarySize || databaseSize > binarySize || |
| databaseOffset + databaseSize > binarySize || |
| databaseOffset + databaseSize < databaseOffset; |
| } |
| |
| } // namespace chre |
| } // namespace android |