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_bugreport_parser.h"
18
19 #include <algorithm>
20 #include <optional>
21
22 #include "perfetto/base/logging.h"
23 #include "perfetto/ext/base/string_utils.h"
24 #include "perfetto/trace_processor/trace_blob.h"
25 #include "perfetto/trace_processor/trace_blob_view.h"
26 #include "src/trace_processor/importers/android_bugreport/android_log_parser.h"
27 #include "src/trace_processor/importers/common/clock_tracker.h"
28 #include "src/trace_processor/importers/common/process_tracker.h"
29 #include "src/trace_processor/importers/common/track_tracker.h"
30 #include "src/trace_processor/types/trace_processor_context.h"
31 #include "src/trace_processor/util/zip_reader.h"
32
33 #include "protos/perfetto/common/builtin_clock.pbzero.h"
34
35 namespace perfetto {
36 namespace trace_processor {
37
AndroidBugreportParser(TraceProcessorContext * ctx)38 AndroidBugreportParser::AndroidBugreportParser(TraceProcessorContext* ctx)
39 : context_(ctx), zip_reader_(new util::ZipReader()) {}
40
41 AndroidBugreportParser::~AndroidBugreportParser() = default;
42
Parse(TraceBlobView tbv)43 util::Status AndroidBugreportParser::Parse(TraceBlobView tbv) {
44 if (!first_chunk_seen_) {
45 first_chunk_seen_ = true;
46 // All logs in Android bugreports use wall time (which creates problems
47 // in case of early boot events before NTP kicks in, which get emitted as
48 // 1970), but that is the state of affairs.
49 context_->clock_tracker->SetTraceTimeClock(
50 protos::pbzero::BUILTIN_CLOCK_REALTIME);
51 }
52
53 return zip_reader_->Parse(tbv.data(), tbv.size());
54 }
55
NotifyEndOfFile()56 void AndroidBugreportParser::NotifyEndOfFile() {
57 if (!DetectYearAndBrFilename()) {
58 context_->storage->IncrementStats(stats::android_br_parse_errors);
59 return;
60 }
61
62 ParsePersistentLogcat();
63 ParseDumpstateTxt();
64 SortAndStoreLogcat();
65 }
66
ParseDumpstateTxt()67 void AndroidBugreportParser::ParseDumpstateTxt() {
68 // Dumpstate is organized in a two level hierarchy, beautifully flattened into
69 // one text file with load bearing ----- markers:
70 // 1. Various dumpstate sections, examples:
71 // ```
72 // ------ DUMPSYS CRITICAL (/system/bin/dumpsys) ------
73 // ...
74 // ------ SYSTEM LOG (logcat -v threadtime -v printable -v uid) ------
75 // ...
76 // ------ IPTABLES (iptables -L -nvx) ------
77 // ...
78 // ------ DUMPSYS HIGH (/system/bin/dumpsys) ------
79 // ...
80 // ------ DUMPSYS (/system/bin/dumpsys) ------
81 // ```
82 //
83 // 2. Within the "------ DUMPSYS" section (note dumpsys != dumpstate), there
84 // are multiple services. Note that there are at least 3 DUMPSYS sections
85 // (CRITICAL, HIGH and default), with multiple services in each:
86 // ```
87 // ------ DUMPSYS (/system/bin/dumpsys) ------
88 // DUMP OF SERVICE activity:
89 // ...
90 // ---------------------------------------------------------------------------
91 // DUMP OF SERVICE input_method:
92 // ...
93 // ---------------------------------------------------------------------------
94 // ```
95 // Here we put each line in a dedicated table, android_dumpstate, keeping
96 // track of the dumpstate `section` and dumpsys `service`.
97 AndroidLogParser log_parser(br_year_, context_->storage.get());
98 util::ZipFile* zf = zip_reader_->Find(dumpstate_fname_);
99 StringId section_id = StringId::Null(); // The current dumpstate section.
100 StringId service_id = StringId::Null(); // The current dumpsys service.
101 static constexpr size_t npos = base::StringView::npos;
102 enum { OTHER = 0, DUMPSYS, LOG } cur_sect = OTHER;
103 zf->DecompressLines([&](const std::vector<base::StringView>& lines) {
104 // Optimization for ParseLogLines() below. Avoids ctor/dtor-ing a new vector
105 // on every line.
106 std::vector<base::StringView> log_line(1);
107 for (const base::StringView& line : lines) {
108 if (line.StartsWith("------ ") && line.EndsWith(" ------")) {
109 // These lines mark the beginning and end of dumpstate sections:
110 // ------ DUMPSYS CRITICAL (/system/bin/dumpsys) ------
111 // ------ 0.356s was the duration of 'DUMPSYS CRITICAL' ------
112 base::StringView section = line.substr(7);
113 section = section.substr(0, section.size() - 7);
114 bool end_marker = section.find("was the duration of") != npos;
115 service_id = StringId::Null();
116 if (end_marker) {
117 section_id = StringId::Null();
118 } else {
119 section_id = context_->storage->InternString(section);
120 cur_sect = OTHER;
121 if (section.StartsWith("DUMPSYS")) {
122 cur_sect = DUMPSYS;
123 } else if (section.StartsWith("SYSTEM LOG") ||
124 section.StartsWith("EVENT LOG") ||
125 section.StartsWith("RADIO LOG")) {
126 // KERNEL LOG is deliberately omitted because SYSTEM LOG is a
127 // superset. KERNEL LOG contains all dupes.
128 cur_sect = LOG;
129 } else if (section.StartsWith("BLOCK STAT")) {
130 // Coalesce all the block stats into one section. Otherwise they
131 // pollute the table with one section per block device.
132 section_id = context_->storage->InternString("BLOCK STAT");
133 }
134 }
135 continue;
136 }
137 // Skip end marker lines for dumpsys sections.
138 if (cur_sect == DUMPSYS && line.StartsWith("--------- ") &&
139 line.find("was the duration of dumpsys") != npos) {
140 service_id = StringId::Null();
141 continue;
142 }
143 if (cur_sect == DUMPSYS && service_id.is_null() &&
144 line.StartsWith("----------------------------------------------")) {
145 continue;
146 }
147 if (cur_sect == DUMPSYS && line.StartsWith("DUMP OF SERVICE")) {
148 // DUMP OF SERVICE [CRITICAL|HIGH] ServiceName:
149 base::StringView svc = line.substr(line.rfind(' ') + 1);
150 svc = svc.substr(0, svc.size() - 1);
151 service_id = context_->storage->InternString(svc);
152 } else if (cur_sect == LOG) {
153 // Parse the non-persistent logcat and append to `log_events_`, together
154 // with the persistent one previously parsed by ParsePersistentLogcat().
155 // Skips entries that are already seen in the persistent logcat,
156 // handling us vs ms truncation.
157 PERFETTO_DCHECK(log_line.size() == 1);
158 log_line[0] = line;
159 log_parser.ParseLogLines(log_line, &log_events_,
160 log_events_last_sorted_idx_);
161 }
162
163 if (build_fpr_.empty() && line.StartsWith("Build fingerprint:")) {
164 build_fpr_ = line.substr(20, line.size() - 20).ToStdString();
165 }
166
167 // Append the line to the android_dumpstate table.
168 context_->storage->mutable_android_dumpstate_table()->Insert(
169 {section_id, service_id, context_->storage->InternString(line)});
170 }
171 });
172 }
173
ParsePersistentLogcat()174 void AndroidBugreportParser::ParsePersistentLogcat() {
175 // 1. List logcat files in reverse timestmap order (old to most recent).
176 // 2. Decode events from log lines into a vector. Dedupe and intern strings.
177 // 3. Globally sort all extracted events.
178 // 4. Insert into the android_logs table.
179
180 AndroidLogParser log_parser(br_year_, context_->storage.get());
181
182 // Sort files to ease the job of the subsequent line-based sort. Unfortunately
183 // lines within each file are not 100% timestamp-ordered, due to things like
184 // kernel messages where log time != event time.
185 std::vector<std::pair<uint64_t, std::string>> log_paths;
186 for (const util::ZipFile& zf : zip_reader_->files()) {
187 if (base::StartsWith(zf.name(), "FS/data/misc/logd/logcat") &&
188 !base::EndsWith(zf.name(), "logcat.id")) {
189 log_paths.emplace_back(std::make_pair(zf.GetDatetime(), zf.name()));
190 }
191 }
192 std::sort(log_paths.begin(), log_paths.end());
193
194 // Push all events into the AndroidLogParser. It will take care of string
195 // interning into the pool. Appends entries into `log_events`.
196 for (const auto& kv : log_paths) {
197 util::ZipFile* zf = zip_reader_->Find(kv.second);
198 zf->DecompressLines([&](const std::vector<base::StringView>& lines) {
199 log_parser.ParseLogLines(lines, &log_events_);
200 });
201 }
202
203 // Do an initial sorting pass. This is not the final sorting because we
204 // haven't ingested the latest logs from dumpstate yet. But we need this sort
205 // to be able to de-dupe the same lines showing both in dumpstate and in the
206 // persistent log.
207 SortLogEvents();
208 }
209
SortAndStoreLogcat()210 void AndroidBugreportParser::SortAndStoreLogcat() {
211 // Sort the union of all log events parsed from both /data/misc/logd
212 // (persistent logcat on disk) and the dumpstate file (last in-memory logcat).
213 // Before the std::stable_sort, entries in `log_events_` are already "mostly"
214 // sorted, because we processed files in order (see notes above about kernel
215 // logs on why we need a final sort here).
216 // We need stable-sort to preserve FIFO-ness of events emitted at the same
217 // time, logcat is not granular enough (us for persistent, ms for dumpstate).
218 SortLogEvents();
219
220 // Insert the globally sorted events into the android_logs table.
221 for (const auto& e : log_events_) {
222 UniquePid utid = context_->process_tracker->UpdateThread(e.tid, e.pid);
223 context_->storage->mutable_android_log_table()->Insert(
224 {e.ts, utid, e.prio, e.tag, e.msg});
225 }
226 }
227
228 // Populates the `year_` field from the bugreport-xxx.txt file name.
229 // This is because logcat events have only the month and day.
230 // This is obviously bugged for cases of bugreports collected across new year
231 // but we'll live with that.
DetectYearAndBrFilename()232 bool AndroidBugreportParser::DetectYearAndBrFilename() {
233 const util::ZipFile* br_file = nullptr;
234 for (const auto& zf : zip_reader_->files()) {
235 if (base::StartsWith(zf.name(), "bugreport-") &&
236 base::EndsWith(zf.name(), ".txt")) {
237 br_file = &zf;
238 break;
239 }
240 }
241
242 if (!br_file) {
243 PERFETTO_ELOG("Could not find bugreport-*.txt in the zip file");
244 return false;
245 }
246
247 // Typical name: "bugreport-product-TP1A.220623.001-2022-06-24-16-24-37.txt".
248 auto year_str = br_file->name().substr(
249 br_file->name().size() - strlen("2022-12-31-23-59-00.txt"), 4);
250 std::optional<int32_t> year = base::StringToInt32(year_str);
251 if (!year.has_value()) {
252 PERFETTO_ELOG("Could not parse the year from %s", br_file->name().c_str());
253 return false;
254 }
255 br_year_ = *year;
256 dumpstate_fname_ = br_file->name();
257 return true;
258 }
259
SortLogEvents()260 void AndroidBugreportParser::SortLogEvents() {
261 std::stable_sort(log_events_.begin(), log_events_.end());
262 log_events_last_sorted_idx_ = log_events_.size();
263 }
264
265 } // namespace trace_processor
266 } // namespace perfetto
267