1 /*
2 * Copyright (C) 2022 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 "src/trace_processor/importers/android_bugreport/android_log_parser.h"
18
19 #include <string.h>
20 #include <optional>
21
22 #include "perfetto/base/logging.h"
23 #include "perfetto/base/time.h"
24 #include "perfetto/ext/base/string_utils.h"
25 #include "src/trace_processor/types/trace_processor_context.h"
26
27 #include "protos/perfetto/common/android_log_constants.pbzero.h"
28
29 namespace perfetto {
30 namespace trace_processor {
31
32 namespace {
33
34 // Reads a base-10 number and advances the passed StringView beyond the *last*
35 // instance of `sep`. Example:
36 // Input: it="1234 bar".
37 // Output: it="bar", ret=1234.
38 //
39 // `decimal_scale` is used to parse decimals and defines the output resolution.
40 // E.g. input="1", decimal_scale=1000 -> res=100
41 // input="12", decimal_scale=1000 -> res=120
42 // input="123", decimal_scale=1000 -> res=123
43 // input="1234", decimal_scale=1000 -> res=123
44 // input="1234", decimal_scale=1000000 -> res=123400
ReadNumAndAdvance(base::StringView * it,char sep,int decimal_scale=0)45 std::optional<int> ReadNumAndAdvance(base::StringView* it,
46 char sep,
47 int decimal_scale = 0) {
48 int num = 0;
49 bool sep_found = false;
50 size_t next_it = 0;
51 bool invalid_chars_found = false;
52 for (size_t i = 0; i < it->size(); i++) {
53 char c = it->at(i);
54 if (c == sep) {
55 next_it = i + 1;
56 sep_found = true;
57 continue;
58 }
59 if (sep_found)
60 break;
61 if (c >= '0' && c <= '9') {
62 int digit = static_cast<int>(c - '0');
63 if (!decimal_scale) {
64 num = num * 10 + digit;
65 } else {
66 decimal_scale /= 10;
67 num += digit * decimal_scale;
68 }
69 continue;
70 }
71 // We found something that is not a digit. Keep looking for the next `sep`
72 // but flag the current token as invalid.
73 invalid_chars_found = true;
74 }
75 if (!sep_found)
76 return std::nullopt;
77 // If we find non-digit characters, we want to still skip the token but return
78 // std::nullopt. The parser below relies on token skipping to deal with cases
79 // where the uid (which we don't care about) is literal ("root" rather than
80 // 0).
81 *it = it->substr(next_it);
82 if (invalid_chars_found)
83 return std::nullopt;
84 return num;
85 }
86
87 enum class LogcatFormat {
88 kUnknown = 0,
89
90 // 01-02 03:04:05.678901 1000 2000 V Tag: Message
91 kPersistentLog,
92
93 // 06-24 15:57:11.346 1000 1493 1918 D Tag: Message
94 // or also
95 // 07-28 14:25:22.181 root 0 0 I Tag : Message
96 kBugreport
97 };
98
DetectFormat(base::StringView line)99 LogcatFormat DetectFormat(base::StringView line) {
100 auto p = base::SplitString(line.ToStdString(), " ");
101 if (p.size() < 5)
102 return LogcatFormat::kUnknown;
103
104 if (p[0].size() != 5 || p[0][2] != '-')
105 return LogcatFormat::kUnknown;
106
107 if (p[1].size() < 10 || p[1][2] != ':' || p[1][5] != ':' || p[1][8] != '.')
108 return LogcatFormat::kUnknown;
109
110 if (p[4].size() == 1 && p[4][0] >= 'A' && p[4][0] <= 'Z')
111 return LogcatFormat::kPersistentLog;
112
113 if (p[5].size() == 1 && p[5][0] >= 'A' && p[5][0] <= 'Z')
114 return LogcatFormat::kBugreport;
115
116 return LogcatFormat::kUnknown;
117 }
118
119 } // namespace
120
121 // Parses a bunch of logcat lines and appends broken down events into
122 // `log_events`.
ParseLogLines(std::vector<base::StringView> lines,std::vector<AndroidLogEvent> * log_events,size_t dedupe_idx)123 void AndroidLogParser::ParseLogLines(std::vector<base::StringView> lines,
124 std::vector<AndroidLogEvent>* log_events,
125 size_t dedupe_idx) {
126 int parse_failures = 0;
127 LogcatFormat fmt = LogcatFormat::kUnknown;
128 for (auto line : lines) {
129 if (line.size() < 30 ||
130 (line.at(0) == '-' && line.at(1) == '-' && line.at(2) == '-')) {
131 // These are markers like "--------- switch to radio" which we ignore.
132 // The smallest valid logcat line has around 30 chars, as follows:
133 // "06-24 23:10:00.123 1 1 D : ..."
134 continue;
135 }
136 if (fmt == LogcatFormat::kUnknown) {
137 fmt = DetectFormat(line);
138 if (fmt == LogcatFormat::kUnknown) {
139 PERFETTO_DLOG("Could not detect logcat format for: |%s|",
140 line.ToStdString().c_str());
141 storage_->IncrementStats(stats::android_log_format_invalid);
142 return;
143 }
144 }
145
146 base::StringView it = line;
147 // 06-24 16:24:23.441532 23153 23153 I wm_on_stop_called: message ...
148 // 07-28 14:25:13.506 root 0 0 I x86/fpu : Supporting XSAVE feature
149 // 0x002: 'SSE registers'
150 std::optional<int> month = ReadNumAndAdvance(&it, '-');
151 std::optional<int> day = ReadNumAndAdvance(&it, ' ');
152 std::optional<int> hour = ReadNumAndAdvance(&it, ':');
153 std::optional<int> minute = ReadNumAndAdvance(&it, ':');
154 std::optional<int> sec = ReadNumAndAdvance(&it, '.');
155 std::optional<int> ns = ReadNumAndAdvance(&it, ' ', 1000 * 1000 * 1000);
156
157 if (fmt == LogcatFormat::kBugreport)
158 ReadNumAndAdvance(&it, ' '); // Skip the UID column.
159
160 std::optional<int> pid = ReadNumAndAdvance(&it, ' ');
161 std::optional<int> tid = ReadNumAndAdvance(&it, ' ');
162
163 if (!month || !day || !hour || !minute || !sec || !ns || !pid || !tid) {
164 ++parse_failures;
165 continue;
166 }
167
168 if (it.size() < 4 || it.at(1) != ' ') {
169 ++parse_failures;
170 continue;
171 }
172
173 char prio_str = it.at(0);
174 int prio = protos::pbzero::AndroidLogPriority::PRIO_UNSPECIFIED;
175 if ('V' == prio_str) {
176 prio = protos::pbzero::AndroidLogPriority::PRIO_VERBOSE;
177 } else if ('D' == prio_str) {
178 prio = protos::pbzero::AndroidLogPriority::PRIO_DEBUG;
179 } else if ('I' == prio_str) {
180 prio = protos::pbzero::AndroidLogPriority::PRIO_INFO;
181 } else if ('W' == prio_str) {
182 prio = protos::pbzero::AndroidLogPriority::PRIO_WARN;
183 } else if ('E' == prio_str) {
184 prio = protos::pbzero::AndroidLogPriority::PRIO_ERROR;
185 } else if ('F' == prio_str) {
186 prio = protos::pbzero::AndroidLogPriority::PRIO_FATAL;
187 }
188
189 it = it.substr(2);
190
191 // Find the ': ' that defines the boundary between the tag and message.
192 // We can't just look for ':' because various HALs emit tags with a ':'.
193 base::StringView cat;
194 for (size_t i = 0; i < it.size() - 1; ++i) {
195 if (it.at(i) == ':' && it.at(i + 1) == ' ') {
196 cat = it.substr(0, i);
197 it = it.substr(i + 2);
198 break;
199 }
200 }
201 // Trim trailing spaces, happens in kernel events (e.g. "init :").
202 while (!cat.empty() && cat.at(cat.size() - 1) == ' ')
203 cat = cat.substr(0, cat.size() - 1);
204
205 base::StringView msg = it; // The rest is the log message.
206
207 int64_t secs = base::MkTime(year_, *month, *day, *hour, *minute, *sec);
208 int64_t ts = secs * 1000000000ll + *ns;
209
210 AndroidLogEvent evt{ts,
211 static_cast<uint32_t>(*pid),
212 static_cast<uint32_t>(*tid),
213 static_cast<uint32_t>(prio),
214 storage_->InternString(cat),
215 storage_->InternString(msg)};
216
217 if (dedupe_idx > 0) {
218 // Search for dupes before inserting.
219 // Events in the [0, dedupe_idx] range are sorted by timestamp with ns
220 // resolution. Here we search for dupes within the same millisecond of
221 // the event we are trying to insert. The /1000000*1000000 is to deal with
222 // the fact that events coming from the persistent log have us resolution,
223 // while events from dumpstate (which are often dupes of persistent ones)
224 // have only ms resolution. Here we consider an event a dupe if it has
225 // the same ms-truncated solution, same pid, tid and message.
226 AndroidLogEvent etrunc = evt;
227 etrunc.ts = etrunc.ts / 1000000 * 1000000;
228 auto begin = log_events->begin();
229 auto end = log_events->begin() + static_cast<ssize_t>(dedupe_idx);
230 bool dupe_found = false;
231 for (auto eit = std::lower_bound(begin, end, etrunc); eit < end; ++eit) {
232 if (eit->ts / 1000000 * 1000000 != etrunc.ts)
233 break;
234 if (eit->msg == evt.msg && eit->tag == evt.tag && eit->tid == evt.tid &&
235 eit->pid == evt.pid) {
236 dupe_found = true;
237 break;
238 }
239 }
240 if (dupe_found) {
241 continue; // Skip the current line.
242 }
243 } // if (dedupe_idx)
244
245 log_events->emplace_back(std::move(evt));
246 } // for (line : lines)
247 storage_->IncrementStats(stats::android_log_num_failed, parse_failures);
248 }
249
250 } // namespace trace_processor
251 } // namespace perfetto
252