1 /*
2 * Copyright (C) 2020 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 #include "chre_host/log_message_parser.h"
18
19 #include <endian.h>
20 #include <string.h>
21 #include <optional>
22
23 #include "chre/util/macros.h"
24 #include "chre/util/time.h"
25 #include "chre_host/daemon_base.h"
26 #include "chre_host/file_stream.h"
27 #include "chre_host/log.h"
28 #include "include/chre_host/log_message_parser.h"
29
30 #include "pw_result/result.h"
31 #include "pw_span/span.h"
32 #include "pw_tokenizer/detokenize.h"
33
34 using chre::kOneMillisecondInNanoseconds;
35 using chre::kOneSecondInMilliseconds;
36 using chre::fbs::LogType;
37
38 namespace android {
39 namespace chre {
40
41 namespace {
42 #if defined(LOG_NDEBUG) || LOG_NDEBUG != 0
43 constexpr bool kVerboseLoggingEnabled = true;
44 #else
45 constexpr bool kVerboseLoggingEnabled = false;
46 #endif
47
48 //! Offset in bytes between the address and real start of a nanoapp binary.
49 constexpr size_t kImageHeaderSize = 0x1000;
50 //! The number of bytes in a string log entry in addition to the log payload.
51 //! The value indicate the size of the null terminator.
52 constexpr size_t kStringLogOverhead = 1;
53 //! The number of bytes in a tokenized log entry in addition to the log payload.
54 //! The value indicate the size of the uint8_t logSize field.
55 constexpr size_t kSystemTokenizedLogOffset = 1;
56 //! The number of bytes in a nanoapp tokenized log entry in addition to the log
57 //! payload. The value accounts for the size of the uint8_t logSize field and
58 //! the uint16_t instanceId field.
59 constexpr size_t kNanoappTokenizedLogOffset = 3;
60 //! This value is used to indicate that a nanoapp does not have a token database
61 //! section.
62 constexpr uint32_t kInvalidTokenDatabaseSize = 0;
63 } // anonymous namespace
64
LogMessageParser()65 LogMessageParser::LogMessageParser()
66 : mVerboseLoggingEnabled(kVerboseLoggingEnabled) {}
67
logDetokenizerInit()68 std::unique_ptr<Detokenizer> LogMessageParser::logDetokenizerInit() {
69 #ifdef CHRE_TOKENIZED_LOGGING_ENABLED
70 constexpr const char kLogDatabaseFilePath[] =
71 "/vendor/etc/chre/libchre_log_database.bin";
72 std::vector<uint8_t> tokenData;
73 if (readFileContents(kLogDatabaseFilePath, tokenData)) {
74 pw::tokenizer::TokenDatabase database =
75 pw::tokenizer::TokenDatabase::Create(tokenData);
76 if (database.ok()) {
77 LOGD("Log database initialized, creating detokenizer");
78 return std::make_unique<Detokenizer>(database);
79 } else {
80 LOGE("CHRE Token database creation not OK");
81 }
82 } else {
83 LOGE("Failed to read CHRE Token database file");
84 }
85 #endif
86 return std::unique_ptr<Detokenizer>(nullptr);
87 }
88
init(size_t nanoappImageHeaderSize)89 void LogMessageParser::init(size_t nanoappImageHeaderSize) {
90 mSystemDetokenizer = logDetokenizerInit();
91 mNanoappImageHeaderSize = nanoappImageHeaderSize;
92 }
93
dump(const uint8_t * buffer,size_t size)94 void LogMessageParser::dump(const uint8_t *buffer, size_t size) {
95 if (mVerboseLoggingEnabled) {
96 char line[32];
97 char lineChars[32];
98 int offset = 0;
99 int offsetChars = 0;
100
101 size_t orig_size = size;
102 if (size > 128) {
103 size = 128;
104 LOGV("Dumping first 128 bytes of buffer of size %zu", orig_size);
105 } else {
106 LOGV("Dumping buffer of size %zu bytes", size);
107 }
108 for (size_t i = 1; i <= size; ++i) {
109 offset += snprintf(&line[offset], sizeof(line) - offset, "%02x ",
110 buffer[i - 1]);
111 offsetChars +=
112 snprintf(&lineChars[offsetChars], sizeof(lineChars) - offsetChars,
113 "%c", (isprint(buffer[i - 1])) ? buffer[i - 1] : '.');
114 if ((i % 8) == 0) {
115 LOGV(" %s\t%s", line, lineChars);
116 offset = 0;
117 offsetChars = 0;
118 } else if ((i % 4) == 0) {
119 offset += snprintf(&line[offset], sizeof(line) - offset, " ");
120 }
121 }
122
123 if (offset > 0) {
124 char tabs[8];
125 char *pos = tabs;
126 while (offset < 28) {
127 *pos++ = '\t';
128 offset += 8;
129 }
130 *pos = '\0';
131 LOGV(" %s%s%s", line, tabs, lineChars);
132 }
133 }
134 }
135
chreLogLevelToAndroidLogPriority(uint8_t level)136 android_LogPriority LogMessageParser::chreLogLevelToAndroidLogPriority(
137 uint8_t level) {
138 switch (level) {
139 case LogLevel::ERROR:
140 return ANDROID_LOG_ERROR;
141 case LogLevel::WARNING:
142 return ANDROID_LOG_WARN;
143 case LogLevel::INFO:
144 return ANDROID_LOG_INFO;
145 case LogLevel::DEBUG:
146 return ANDROID_LOG_DEBUG;
147 default:
148 return ANDROID_LOG_SILENT;
149 }
150 }
151
getLogLevelFromMetadata(uint8_t metadata)152 uint8_t LogMessageParser::getLogLevelFromMetadata(uint8_t metadata) {
153 // The lower nibble of the metadata denotes the loglevel, as indicated
154 // by the schema in host_messages.fbs.
155 return metadata & 0xf;
156 }
157
log(const uint8_t * logBuffer,size_t logBufferSize)158 void LogMessageParser::log(const uint8_t *logBuffer, size_t logBufferSize) {
159 size_t bufferIndex = 0;
160 while (bufferIndex < logBufferSize) {
161 const LogMessage *message =
162 reinterpret_cast<const LogMessage *>(&logBuffer[bufferIndex]);
163 uint64_t timeNs = le64toh(message->timestampNanos);
164 emitLogMessage(message->logLevel, timeNs / kOneMillisecondInNanoseconds,
165 message->logMessage);
166 bufferIndex += sizeof(LogMessage) +
167 strnlen(message->logMessage, logBufferSize - bufferIndex) +
168 1;
169 }
170 }
171
172 std::optional<size_t>
parseAndEmitTokenizedLogMessageAndGetSize(const LogMessageV2 * message,size_t maxLogMessageLen)173 LogMessageParser::parseAndEmitTokenizedLogMessageAndGetSize(
174 const LogMessageV2 *message, size_t maxLogMessageLen) {
175 auto detokenizer = mSystemDetokenizer.get();
176 auto *encodedLog = reinterpret_cast<const EncodedLog *>(message->logMessage);
177 size_t logMessageSize = encodedLog->size + kSystemTokenizedLogOffset;
178 if (logMessageSize > maxLogMessageLen) {
179 LOGE("Dropping log due to log message size exceeds the end of log buffer");
180 return std::nullopt;
181 } else if (detokenizer != nullptr) {
182 DetokenizedString detokenizedString =
183 detokenizer->Detokenize(encodedLog->data, encodedLog->size);
184 std::string decodedString = detokenizedString.BestStringWithErrors();
185 emitLogMessage(getLogLevelFromMetadata(message->metadata),
186 le32toh(message->timestampMillis), decodedString.c_str());
187 } else {
188 // TODO(b/327515992): Stop decoding and emitting system log messages if
189 // detokenizer is null .
190 LOGE("Null detokenizer! Cannot decode log message");
191 }
192 return logMessageSize;
193 }
194
195 std::optional<size_t>
parseAndEmitNanoappTokenizedLogMessageAndGetSize(const LogMessageV2 * message,size_t maxLogMessageLen)196 LogMessageParser::parseAndEmitNanoappTokenizedLogMessageAndGetSize(
197 const LogMessageV2 *message, size_t maxLogMessageLen) {
198 std::lock_guard<std::mutex> lock(mNanoappMutex);
199 auto *tokenizedLog =
200 reinterpret_cast<const NanoappTokenizedLog *>(message->logMessage);
201 auto detokenizerIter = mNanoappDetokenizers.find(tokenizedLog->instanceId);
202 size_t logMessageSize = tokenizedLog->size + kNanoappTokenizedLogOffset;
203 if (detokenizerIter == mNanoappDetokenizers.end()) {
204 LOGE(
205 "Unable to find nanoapp log detokenizer associated with instance ID: "
206 "%" PRIu16,
207 tokenizedLog->instanceId);
208 return std::nullopt;
209 } else if (logMessageSize > maxLogMessageLen) {
210 LOGE("Dropping log due to log message size exceeds the end of log buffer");
211 logMessageSize = maxLogMessageLen;
212 } else {
213 auto detokenizer = detokenizerIter->second.detokenizer.get();
214 DetokenizedString detokenizedString =
215 detokenizer->Detokenize(tokenizedLog->data, tokenizedLog->size);
216 std::string decodedString = detokenizedString.BestStringWithErrors();
217 emitLogMessage(getLogLevelFromMetadata(message->metadata),
218 le32toh(message->timestampMillis), decodedString.c_str());
219 }
220 return logMessageSize;
221 }
222
parseAndEmitStringLogMessageAndGetSize(const LogMessageV2 * message,size_t maxLogMessageLen)223 std::optional<size_t> LogMessageParser::parseAndEmitStringLogMessageAndGetSize(
224 const LogMessageV2 *message, size_t maxLogMessageLen) {
225 maxLogMessageLen = maxLogMessageLen - kStringLogOverhead;
226 size_t logMessageSize = strnlen(message->logMessage, maxLogMessageLen);
227 if (message->logMessage[logMessageSize] != '\0') {
228 LOGE("Dropping string log due to invalid buffer structure");
229 return std::nullopt;
230 }
231 emitLogMessage(getLogLevelFromMetadata(message->metadata),
232 le32toh(message->timestampMillis), message->logMessage);
233 return logMessageSize + kStringLogOverhead;
234 }
235
updateAndPrintDroppedLogs(uint32_t numLogsDropped)236 void LogMessageParser::updateAndPrintDroppedLogs(uint32_t numLogsDropped) {
237 if (numLogsDropped < mNumLogsDropped) {
238 LOGE(
239 "The numLogsDropped value received from CHRE is less than the last "
240 "value received. Received: %" PRIu32 " Last value: %" PRIu32,
241 numLogsDropped, mNumLogsDropped);
242 }
243 // Log the number of logs dropped once before logging remaining logs from CHRE
244 uint32_t diffLogsDropped = numLogsDropped - mNumLogsDropped;
245 mNumLogsDropped = numLogsDropped;
246 if (diffLogsDropped > 0) {
247 LOGI("# logs dropped: %" PRIu32, diffLogsDropped);
248 }
249 }
250
emitLogMessage(uint8_t level,uint32_t timestampMillis,const char * logMessage)251 void LogMessageParser::emitLogMessage(uint8_t level, uint32_t timestampMillis,
252 const char *logMessage) {
253 constexpr const char kLogTag[] = "CHRE";
254 uint32_t timeSec = timestampMillis / kOneSecondInMilliseconds;
255 uint32_t timeMsRemainder = timestampMillis % kOneSecondInMilliseconds;
256 android_LogPriority priority = chreLogLevelToAndroidLogPriority(level);
257 LOG_PRI(priority, kLogTag, kHubLogFormatStr, timeSec, timeMsRemainder,
258 logMessage);
259 }
260
logV2(const uint8_t * logBuffer,size_t logBufferSize,uint32_t numLogsDropped)261 void LogMessageParser::logV2(const uint8_t *logBuffer, size_t logBufferSize,
262 uint32_t numLogsDropped) {
263 constexpr size_t kLogHeaderSize = sizeof(LogMessageV2);
264
265 updateAndPrintDroppedLogs(numLogsDropped);
266
267 std::optional<size_t> logMessageSize = std::nullopt;
268 size_t bufferIndex = 0;
269 const LogMessageV2 *message = nullptr;
270 size_t maxLogMessageLen = 0;
271 while (bufferIndex + kLogHeaderSize < logBufferSize) {
272 message = reinterpret_cast<const LogMessageV2 *>(&logBuffer[bufferIndex]);
273 maxLogMessageLen = (logBufferSize - bufferIndex) - kLogHeaderSize;
274 logMessageSize = std::nullopt;
275
276 switch (extractLogType(message)) {
277 // TODO(b/336467722): Rename the log types in fbs.
278 case LogType::STRING:
279 logMessageSize =
280 parseAndEmitStringLogMessageAndGetSize(message, maxLogMessageLen);
281 break;
282 case LogType::TOKENIZED:
283 logMessageSize = parseAndEmitTokenizedLogMessageAndGetSize(
284 message, maxLogMessageLen);
285 break;
286 case LogType::BLUETOOTH:
287 logMessageSize =
288 mBtLogParser.log(message->logMessage, maxLogMessageLen);
289 break;
290 case LogType::NANOAPP_TOKENIZED:
291 logMessageSize = parseAndEmitNanoappTokenizedLogMessageAndGetSize(
292 message, maxLogMessageLen);
293 break;
294 default:
295 LOGE("Unexpected log type 0x%" PRIx8,
296 (message->metadata & kLogTypeMask) >> kLogTypeBitOffset);
297 break;
298 }
299 if (!logMessageSize.has_value()) {
300 LOGE("Log message at offset %zu is corrupted, aborting...", bufferIndex);
301 return;
302 }
303 bufferIndex += kLogHeaderSize + logMessageSize.value();
304 }
305 }
306
addNanoappDetokenizer(uint64_t appId,uint16_t instanceId,uint64_t databaseOffset,size_t databaseSize)307 void LogMessageParser::addNanoappDetokenizer(uint64_t appId,
308 uint16_t instanceId,
309 uint64_t databaseOffset,
310 size_t databaseSize) {
311 std::shared_ptr<const std::vector<uint8_t>> appBinary =
312 fetchNanoappBinary(appId);
313 if (!appBinary) {
314 LOGE(
315 "Binary not in cache, can't extract log token database for app ID "
316 "0x%016" PRIx64,
317 appId);
318 } else {
319 removeNanoappDetokenizerAndBinary(appId);
320 if (databaseSize != kInvalidTokenDatabaseSize) {
321 if (checkTokenDatabaseOverflow(databaseOffset, databaseSize,
322 appBinary->size())) {
323 LOGE(
324 "Token database fails memory bounds check for nanoapp with app ID "
325 "0x%016" PRIx64 ". Token database offset received: %" PRIu32
326 "; size received: %zu; Size of the appBinary: %zu.",
327 appId, databaseOffset, databaseSize, appBinary->size());
328 } else {
329 const uint8_t *tokenDatabaseBinaryStart =
330 appBinary->data() + kImageHeaderSize + databaseOffset;
331
332 pw::span<const uint8_t> tokenEntries(tokenDatabaseBinaryStart,
333 databaseSize);
334 pw::Result<Detokenizer> nanoappDetokenizer =
335 pw::tokenizer::Detokenizer::FromElfSection(tokenEntries);
336
337 registerDetokenizer(appId, instanceId, std::move(nanoappDetokenizer));
338 }
339 }
340 }
341 }
342
registerDetokenizer(uint64_t appId,uint16_t instanceId,pw::Result<Detokenizer> nanoappDetokenizer)343 void LogMessageParser::registerDetokenizer(
344 uint64_t appId, uint16_t instanceId,
345 pw::Result<Detokenizer> nanoappDetokenizer) {
346 std::lock_guard<std::mutex> lock(mNanoappMutex);
347
348 if (nanoappDetokenizer.ok()) {
349 NanoappDetokenizer detokenizer;
350 detokenizer.appId = appId;
351 detokenizer.detokenizer =
352 std::make_unique<Detokenizer>(std::move(*nanoappDetokenizer));
353 mNanoappDetokenizers[instanceId] = std::move(detokenizer);
354 } else {
355 LOGE("Unable to parse log detokenizer for app with ID: 0x%016" PRIx64,
356 appId);
357 }
358 }
359
360 std::shared_ptr<const std::vector<uint8_t>>
fetchNanoappBinary(uint64_t appId)361 LogMessageParser::fetchNanoappBinary(uint64_t appId) {
362 std::lock_guard<std::mutex> lock(mNanoappMutex);
363 auto appBinaryIter = mNanoappAppIdToBinary.find(appId);
364 if (appBinaryIter != mNanoappAppIdToBinary.end()) {
365 return appBinaryIter->second;
366 }
367 return nullptr;
368 }
369
removeNanoappDetokenizerAndBinary(uint64_t appId)370 void LogMessageParser::removeNanoappDetokenizerAndBinary(uint64_t appId) {
371 std::lock_guard<std::mutex> lock(mNanoappMutex);
372 for (const auto &item : mNanoappDetokenizers) {
373 if (item.second.appId == appId) {
374 mNanoappDetokenizers.erase(item.first);
375 }
376 }
377 mNanoappAppIdToBinary.erase(appId);
378 }
379
resetNanoappDetokenizerState()380 void LogMessageParser::resetNanoappDetokenizerState() {
381 std::lock_guard<std::mutex> lock(mNanoappMutex);
382 mNanoappDetokenizers.clear();
383 mNanoappAppIdToBinary.clear();
384 }
385
onNanoappLoadStarted(uint64_t appId,std::shared_ptr<const std::vector<uint8_t>> nanoappBinary)386 void LogMessageParser::onNanoappLoadStarted(
387 uint64_t appId, std::shared_ptr<const std::vector<uint8_t>> nanoappBinary) {
388 std::lock_guard<std::mutex> lock(mNanoappMutex);
389 mNanoappAppIdToBinary[appId] = nanoappBinary;
390 }
391
onNanoappLoadFailed(uint64_t appId)392 void LogMessageParser::onNanoappLoadFailed(uint64_t appId) {
393 removeNanoappDetokenizerAndBinary(appId);
394 }
395
onNanoappUnloaded(uint64_t appId)396 void LogMessageParser::onNanoappUnloaded(uint64_t appId) {
397 removeNanoappDetokenizerAndBinary(appId);
398 }
399
checkTokenDatabaseOverflow(uint32_t databaseOffset,size_t databaseSize,size_t binarySize)400 bool LogMessageParser::checkTokenDatabaseOverflow(uint32_t databaseOffset,
401 size_t databaseSize,
402 size_t binarySize) {
403 return databaseOffset > binarySize || databaseSize > binarySize ||
404 databaseOffset + databaseSize > binarySize ||
405 databaseOffset + databaseSize < databaseOffset;
406 }
407
408 } // namespace chre
409 } // namespace android
410