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   auto *tokenizedLog =
199       reinterpret_cast<const NanoappTokenizedLog *>(message->logMessage);
200   auto detokenizerIter = mNanoappDetokenizers.find(tokenizedLog->instanceId);
201   size_t logMessageSize = tokenizedLog->size + kNanoappTokenizedLogOffset;
202   if (detokenizerIter == mNanoappDetokenizers.end()) {
203     LOGE(
204         "Unable to find nanoapp log detokenizer associated with instance ID: "
205         "%" PRIu16,
206         tokenizedLog->instanceId);
207     return std::nullopt;
208   } else if (logMessageSize > maxLogMessageLen) {
209     LOGE("Dropping log due to log message size exceeds the end of log buffer");
210     logMessageSize = maxLogMessageLen;
211   } else {
212     auto detokenizer = detokenizerIter->second.detokenizer.get();
213     DetokenizedString detokenizedString =
214         detokenizer->Detokenize(tokenizedLog->data, tokenizedLog->size);
215     std::string decodedString = detokenizedString.BestStringWithErrors();
216     emitLogMessage(getLogLevelFromMetadata(message->metadata),
217                    le32toh(message->timestampMillis), decodedString.c_str());
218   }
219   return logMessageSize;
220 }
221 
parseAndEmitStringLogMessageAndGetSize(const LogMessageV2 * message,size_t maxLogMessageLen)222 std::optional<size_t> LogMessageParser::parseAndEmitStringLogMessageAndGetSize(
223     const LogMessageV2 *message, size_t maxLogMessageLen) {
224   maxLogMessageLen = maxLogMessageLen - kStringLogOverhead;
225   size_t logMessageSize = strnlen(message->logMessage, maxLogMessageLen);
226   if (message->logMessage[logMessageSize] != '\0') {
227     LOGE("Dropping string log due to invalid buffer structure");
228     return std::nullopt;
229   }
230   emitLogMessage(getLogLevelFromMetadata(message->metadata),
231                  le32toh(message->timestampMillis), message->logMessage);
232   return logMessageSize + kStringLogOverhead;
233 }
234 
updateAndPrintDroppedLogs(uint32_t numLogsDropped)235 void LogMessageParser::updateAndPrintDroppedLogs(uint32_t numLogsDropped) {
236   if (numLogsDropped < mNumLogsDropped) {
237     LOGE(
238         "The numLogsDropped value received from CHRE is less than the last "
239         "value received. Received: %" PRIu32 " Last value: %" PRIu32,
240         numLogsDropped, mNumLogsDropped);
241   }
242   // Log the number of logs dropped once before logging remaining logs from CHRE
243   uint32_t diffLogsDropped = numLogsDropped - mNumLogsDropped;
244   mNumLogsDropped = numLogsDropped;
245   if (diffLogsDropped > 0) {
246     LOGI("# logs dropped: %" PRIu32, diffLogsDropped);
247   }
248 }
249 
emitLogMessage(uint8_t level,uint32_t timestampMillis,const char * logMessage)250 void LogMessageParser::emitLogMessage(uint8_t level, uint32_t timestampMillis,
251                                       const char *logMessage) {
252   constexpr const char kLogTag[] = "CHRE";
253   uint32_t timeSec = timestampMillis / kOneSecondInMilliseconds;
254   uint32_t timeMsRemainder = timestampMillis % kOneSecondInMilliseconds;
255   android_LogPriority priority = chreLogLevelToAndroidLogPriority(level);
256   LOG_PRI(priority, kLogTag, kHubLogFormatStr, timeSec, timeMsRemainder,
257           logMessage);
258 }
259 
logV2(const uint8_t * logBuffer,size_t logBufferSize,uint32_t numLogsDropped)260 void LogMessageParser::logV2(const uint8_t *logBuffer, size_t logBufferSize,
261                              uint32_t numLogsDropped) {
262   constexpr size_t kLogHeaderSize = sizeof(LogMessageV2);
263 
264   updateAndPrintDroppedLogs(numLogsDropped);
265 
266   std::optional<size_t> logMessageSize = std::nullopt;
267   size_t bufferIndex = 0;
268   const LogMessageV2 *message = nullptr;
269   size_t maxLogMessageLen = 0;
270   while (bufferIndex + kLogHeaderSize <= logBufferSize) {
271     message = reinterpret_cast<const LogMessageV2 *>(&logBuffer[bufferIndex]);
272     maxLogMessageLen = (logBufferSize - bufferIndex) - kLogHeaderSize;
273     logMessageSize = std::nullopt;
274 
275     switch (extractLogType(message)) {
276       // TODO(b/336467722): Rename the log types in fbs.
277       case LogType::STRING:
278         logMessageSize =
279             parseAndEmitStringLogMessageAndGetSize(message, maxLogMessageLen);
280         break;
281       case LogType::TOKENIZED:
282         logMessageSize = parseAndEmitTokenizedLogMessageAndGetSize(
283             message, maxLogMessageLen);
284         break;
285       case LogType::BLUETOOTH:
286         logMessageSize =
287             mBtLogParser.log(message->logMessage, maxLogMessageLen);
288         break;
289       case LogType::NANOAPP_TOKENIZED:
290         logMessageSize = parseAndEmitNanoappTokenizedLogMessageAndGetSize(
291             message, maxLogMessageLen);
292         break;
293       default:
294         LOGE("Unexpected log type 0x%" PRIx8,
295              (message->metadata & kLogTypeMask) >> kLogTypeBitOffset);
296         break;
297     }
298     if (!logMessageSize.has_value()) {
299       LOGE("Log message at offset %zu is corrupted, aborting...", bufferIndex);
300       return;
301     }
302     bufferIndex += kLogHeaderSize + logMessageSize.value();
303   }
304 }
305 
addNanoappDetokenizer(uint64_t appId,uint16_t instanceId,uint64_t databaseOffset,size_t databaseSize)306 void LogMessageParser::addNanoappDetokenizer(uint64_t appId,
307                                              uint16_t instanceId,
308                                              uint64_t databaseOffset,
309                                              size_t databaseSize) {
310   auto appBinaryIter = mNanoappAppIdToBinary.find(appId);
311   if (appBinaryIter == mNanoappAppIdToBinary.end()) {
312     LOGE(
313         "Binary not in cache, can't extract log token database for app ID "
314         "0x%016" PRIx64,
315         appId);
316   } else if (databaseSize == kInvalidTokenDatabaseSize) {
317     // Remove and free the nanoapp binary.
318     mNanoappAppIdToBinary.erase(appId);
319   } else if (checkTokenDatabaseOverflow(databaseOffset, databaseSize,
320                                         appBinaryIter->second->size())) {
321     LOGE(
322         "Token database fails memory bounds check for nanoapp with app ID "
323         "0x%016" PRIx64 ". Token database offset received: %" PRIu32
324         "; size received: %zu; Size of the appBinary: %zu.",
325         appId, databaseOffset, databaseSize, appBinaryIter->second->size());
326   } else {
327     const uint8_t *tokenDatabaseBinaryStart =
328         appBinaryIter->second->data() + kImageHeaderSize + databaseOffset;
329 
330     pw::span<const uint8_t> tokenEntries(tokenDatabaseBinaryStart,
331                                          databaseSize);
332     pw::Result<Detokenizer> nanoappDetokenizer =
333         pw::tokenizer::Detokenizer::FromElfSection(tokenEntries);
334 
335     // Clear out any stale detokenizer instance and clean up memory.
336     appBinaryIter->second.reset();
337     removeNanoappDetokenizerAndBinary(appId);
338 
339     if (nanoappDetokenizer.ok()) {
340       NanoappDetokenizer detokenizer;
341       detokenizer.appId = appId;
342       detokenizer.detokenizer =
343           std::make_unique<Detokenizer>(std::move(*nanoappDetokenizer));
344       mNanoappDetokenizers[instanceId] = std::move(detokenizer);
345     } else {
346       LOGE("Unable to parse log detokenizer for app with ID: 0x%016" PRIx64,
347            appId);
348     }
349   }
350 }
351 
removeNanoappDetokenizerAndBinary(uint64_t appId)352 void LogMessageParser::removeNanoappDetokenizerAndBinary(uint64_t appId) {
353   for (const auto &item : mNanoappDetokenizers) {
354     if (item.second.appId == appId) {
355       mNanoappDetokenizers.erase(item.first);
356     }
357   }
358   mNanoappAppIdToBinary.erase(appId);
359 }
360 
resetNanoappDetokenizerState()361 void LogMessageParser::resetNanoappDetokenizerState() {
362   mNanoappDetokenizers.clear();
363   mNanoappAppIdToBinary.clear();
364 }
365 
onNanoappLoadStarted(uint64_t appId,std::shared_ptr<const std::vector<uint8_t>> nanoappBinary)366 void LogMessageParser::onNanoappLoadStarted(
367     uint64_t appId, std::shared_ptr<const std::vector<uint8_t>> nanoappBinary) {
368   mNanoappAppIdToBinary[appId] = nanoappBinary;
369 }
370 
onNanoappLoadFailed(uint64_t appId)371 void LogMessageParser::onNanoappLoadFailed(uint64_t appId) {
372   removeNanoappDetokenizerAndBinary(appId);
373 }
374 
onNanoappUnloaded(uint64_t appId)375 void LogMessageParser::onNanoappUnloaded(uint64_t appId) {
376   removeNanoappDetokenizerAndBinary(appId);
377 }
378 
checkTokenDatabaseOverflow(uint32_t databaseOffset,size_t databaseSize,size_t binarySize)379 bool LogMessageParser::checkTokenDatabaseOverflow(uint32_t databaseOffset,
380                                                   size_t databaseSize,
381                                                   size_t binarySize) {
382   return databaseOffset > binarySize || databaseSize > binarySize ||
383          databaseOffset + databaseSize > binarySize ||
384          databaseOffset + databaseSize < databaseOffset;
385 }
386 
387 }  // namespace chre
388 }  // namespace android
389