blob: 8477157e9a1931f036e7a3d2e9a22b95a747fa59 [file] [log] [blame]
/*
* 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