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
22 #include "chre/util/time.h"
23 #include "chre_host/daemon_base.h"
24 #include "chre_host/file_stream.h"
25 #include "chre_host/log.h"
26 #include "include/chre_host/log_message_parser.h"
27
28 using chre::kOneMillisecondInNanoseconds;
29 using chre::kOneSecondInMilliseconds;
30
31 namespace android {
32 namespace chre {
33
34 namespace {
35 #if defined(LOG_NDEBUG) || LOG_NDEBUG != 0
36 constexpr bool kVerboseLoggingEnabled = true;
37 #else
38 constexpr bool kVerboseLoggingEnabled = false;
39 #endif
40 } // anonymous namespace
41
LogMessageParser()42 LogMessageParser::LogMessageParser()
43 : mVerboseLoggingEnabled(kVerboseLoggingEnabled) {}
44
logDetokenizerInit()45 std::unique_ptr<Detokenizer> LogMessageParser::logDetokenizerInit() {
46 #ifdef CHRE_TOKENIZED_LOGGING_ENABLED
47 constexpr const char kLogDatabaseFilePath[] =
48 "/vendor/etc/chre/libchre_log_database.bin";
49 std::vector<uint8_t> tokenData;
50 if (readFileContents(kLogDatabaseFilePath, tokenData)) {
51 pw::tokenizer::TokenDatabase database =
52 pw::tokenizer::TokenDatabase::Create(tokenData);
53 if (database.ok()) {
54 LOGD("Log database initialized, creating detokenizer");
55 return std::make_unique<Detokenizer>(database);
56 } else {
57 LOGE("CHRE Token database creation not OK");
58 }
59 } else {
60 LOGE("Failed to read CHRE Token database file");
61 }
62 #endif
63 return std::unique_ptr<Detokenizer>(nullptr);
64 }
65
init()66 void LogMessageParser::init() {
67 mDetokenizer = logDetokenizerInit();
68 }
69
dump(const uint8_t * buffer,size_t size)70 void LogMessageParser::dump(const uint8_t *buffer, size_t size) {
71 if (mVerboseLoggingEnabled) {
72 char line[32];
73 char lineChars[32];
74 int offset = 0;
75 int offsetChars = 0;
76
77 size_t orig_size = size;
78 if (size > 128) {
79 size = 128;
80 LOGV("Dumping first 128 bytes of buffer of size %zu", orig_size);
81 } else {
82 LOGV("Dumping buffer of size %zu bytes", size);
83 }
84 for (size_t i = 1; i <= size; ++i) {
85 offset += snprintf(&line[offset], sizeof(line) - offset, "%02x ",
86 buffer[i - 1]);
87 offsetChars +=
88 snprintf(&lineChars[offsetChars], sizeof(lineChars) - offsetChars,
89 "%c", (isprint(buffer[i - 1])) ? buffer[i - 1] : '.');
90 if ((i % 8) == 0) {
91 LOGV(" %s\t%s", line, lineChars);
92 offset = 0;
93 offsetChars = 0;
94 } else if ((i % 4) == 0) {
95 offset += snprintf(&line[offset], sizeof(line) - offset, " ");
96 }
97 }
98
99 if (offset > 0) {
100 char tabs[8];
101 char *pos = tabs;
102 while (offset < 28) {
103 *pos++ = '\t';
104 offset += 8;
105 }
106 *pos = '\0';
107 LOGV(" %s%s%s", line, tabs, lineChars);
108 }
109 }
110 }
111
chreLogLevelToAndroidLogPriority(uint8_t level)112 android_LogPriority LogMessageParser::chreLogLevelToAndroidLogPriority(
113 uint8_t level) {
114 switch (level) {
115 case LogLevel::ERROR:
116 return ANDROID_LOG_ERROR;
117 case LogLevel::WARNING:
118 return ANDROID_LOG_WARN;
119 case LogLevel::INFO:
120 return ANDROID_LOG_INFO;
121 case LogLevel::DEBUG:
122 return ANDROID_LOG_DEBUG;
123 default:
124 return ANDROID_LOG_SILENT;
125 }
126 }
127
getLogLevelFromMetadata(uint8_t metadata)128 uint8_t LogMessageParser::getLogLevelFromMetadata(uint8_t metadata) {
129 // The lower nibble of the metadata denotes the loglevel, as indicated
130 // by the schema in host_messages.fbs.
131 return metadata & 0xf;
132 }
133
isLogMessageEncoded(uint8_t metadata)134 bool LogMessageParser::isLogMessageEncoded(uint8_t metadata) {
135 // The upper nibble of the metadata denotes the encoding, as indicated
136 // by the schema in host_messages.fbs.
137 return (metadata & 0x10) != 0;
138 }
139
isBtSnoopLogMessage(uint8_t metadata)140 bool LogMessageParser::isBtSnoopLogMessage(uint8_t metadata) {
141 // The upper nibble of the metadata denotes the encoding, as indicated
142 // by the schema in host_messages.fbs.
143 return (metadata & 0x20) != 0;
144 }
145
log(const uint8_t * logBuffer,size_t logBufferSize)146 void LogMessageParser::log(const uint8_t *logBuffer, size_t logBufferSize) {
147 size_t bufferIndex = 0;
148 while (bufferIndex < logBufferSize) {
149 const LogMessage *message =
150 reinterpret_cast<const LogMessage *>(&logBuffer[bufferIndex]);
151 uint64_t timeNs = le64toh(message->timestampNanos);
152 emitLogMessage(message->logLevel, timeNs / kOneMillisecondInNanoseconds,
153 message->logMessage);
154 bufferIndex += sizeof(LogMessage) +
155 strnlen(message->logMessage, logBufferSize - bufferIndex) +
156 1;
157 }
158 }
159
parseAndEmitTokenizedLogMessageAndGetSize(const LogMessageV2 * message)160 size_t LogMessageParser::parseAndEmitTokenizedLogMessageAndGetSize(
161 const LogMessageV2 *message) {
162 size_t logMessageSize = 0;
163 auto detokenizer = mDetokenizer.get();
164 if (detokenizer != nullptr) {
165 auto *encodedLog = const_cast<EncodedLog *>(
166 reinterpret_cast<const EncodedLog *>(message->logMessage));
167 DetokenizedString detokenizedString =
168 detokenizer->Detokenize(encodedLog->data, encodedLog->size);
169 std::string decodedString = detokenizedString.BestStringWithErrors();
170 emitLogMessage(getLogLevelFromMetadata(message->metadata),
171 le32toh(message->timestampMillis), decodedString.c_str());
172 logMessageSize = encodedLog->size + sizeof(struct EncodedLog);
173 } else {
174 LOGE("Null detokenizer! Cannot decode log message");
175 }
176 return logMessageSize;
177 }
178
parseAndEmitLogMessage(const LogMessageV2 * message)179 void LogMessageParser::parseAndEmitLogMessage(const LogMessageV2 *message) {
180 emitLogMessage(getLogLevelFromMetadata(message->metadata),
181 le32toh(message->timestampMillis), message->logMessage);
182 }
183
updateAndPrintDroppedLogs(uint32_t numLogsDropped)184 void LogMessageParser::updateAndPrintDroppedLogs(uint32_t numLogsDropped) {
185 if (numLogsDropped < mNumLogsDropped) {
186 LOGE(
187 "The numLogsDropped value received from CHRE is less than the last "
188 "value received. Received: %" PRIu32 " Last value: %" PRIu32,
189 numLogsDropped, mNumLogsDropped);
190 }
191 // Log the number of logs dropped once before logging remaining logs from CHRE
192 uint32_t diffLogsDropped = numLogsDropped - mNumLogsDropped;
193 mNumLogsDropped = numLogsDropped;
194 if (diffLogsDropped > 0) {
195 LOGI("# logs dropped: %" PRIu32, diffLogsDropped);
196 }
197 }
198
emitLogMessage(uint8_t level,uint32_t timestampMillis,const char * logMessage)199 void LogMessageParser::emitLogMessage(uint8_t level, uint32_t timestampMillis,
200 const char *logMessage) {
201 constexpr const char kLogTag[] = "CHRE";
202 uint32_t timeSec = timestampMillis / kOneSecondInMilliseconds;
203 uint32_t timeMsRemainder = timestampMillis % kOneSecondInMilliseconds;
204 android_LogPriority priority = chreLogLevelToAndroidLogPriority(level);
205 LOG_PRI(priority, kLogTag, kHubLogFormatStr, timeSec, timeMsRemainder,
206 logMessage);
207 }
208
logV2(const uint8_t * logBuffer,size_t logBufferSize,uint32_t numLogsDropped)209 void LogMessageParser::logV2(const uint8_t *logBuffer, size_t logBufferSize,
210 uint32_t numLogsDropped) {
211 // Size of the struct with an empty string.
212 constexpr size_t kMinLogMessageV2Size = sizeof(LogMessageV2) + 1;
213
214 updateAndPrintDroppedLogs(numLogsDropped);
215
216 size_t bufferIndex = 0;
217 while (bufferIndex + kMinLogMessageV2Size <= logBufferSize) {
218 auto message =
219 reinterpret_cast<const LogMessageV2 *>(&logBuffer[bufferIndex]);
220
221 size_t logMessageSize = 0;
222 if (isBtSnoopLogMessage(message->metadata)) {
223 logMessageSize = mBtLogParser.log(message->logMessage);
224 } else if (isLogMessageEncoded(message->metadata)) {
225 logMessageSize = parseAndEmitTokenizedLogMessageAndGetSize(message);
226 } else {
227 size_t maxLogMessageLen =
228 (logBufferSize - bufferIndex) - kMinLogMessageV2Size;
229 size_t logMessageLen = strnlen(message->logMessage, maxLogMessageLen);
230 if (message->logMessage[logMessageLen] != '\0') {
231 LOGE("Dropping log due to invalid buffer structure");
232 break;
233 }
234 parseAndEmitLogMessage(message);
235 // Account for the terminating '\0'
236 logMessageSize = logMessageLen + 1;
237 }
238 bufferIndex += sizeof(LogMessageV2) + logMessageSize;
239 }
240 }
241
242 } // namespace chre
243 } // namespace android
244