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_reader.h"
18
19 #include <algorithm>
20 #include <chrono>
21 #include <cstdint>
22 #include <ctime>
23 #include <optional>
24 #include <string>
25 #include <utility>
26
27 #include "perfetto/base/status.h"
28 #include "perfetto/base/time.h"
29 #include "protos/perfetto/common/android_log_constants.pbzero.h"
30 #include "protos/perfetto/trace/clock_snapshot.pbzero.h"
31 #include "src/trace_processor/importers/android_bugreport/android_log_event.h"
32 #include "src/trace_processor/importers/common/clock_converter.h"
33 #include "src/trace_processor/importers/common/clock_tracker.h"
34 #include "src/trace_processor/sorter/trace_sorter.h"
35 #include "src/trace_processor/storage/stats.h"
36 #include "src/trace_processor/types/trace_processor_context.h"
37 #include "src/trace_processor/util/status_macros.h"
38
39 namespace perfetto::trace_processor {
40
41 namespace {
42
43 // Reads a base-10 number and advances the passed StringView beyond the *last*
44 // instance of `sep`. Example:
45 // Input: it="1234 bar".
46 // Output: it="bar", ret=1234.
47 //
48 // `decimal_scale` is used to parse decimals and defines the output resolution.
49 // E.g. input="1", decimal_scale=1000 -> res=100
50 // input="12", decimal_scale=1000 -> res=120
51 // input="123", decimal_scale=1000 -> res=123
52 // input="1234", decimal_scale=1000 -> res=123
53 // input="1234", decimal_scale=1000000 -> res=123400
ReadNumAndAdvance(base::StringView * it,char sep,int decimal_scale=0)54 std::optional<int> ReadNumAndAdvance(base::StringView* it,
55 char sep,
56 int decimal_scale = 0) {
57 int num = 0;
58 bool sep_found = false;
59 size_t next_it = 0;
60 bool invalid_chars_found = false;
61 for (size_t i = 0; i < it->size(); i++) {
62 char c = it->at(i);
63 if (c == sep) {
64 next_it = i + 1;
65 sep_found = true;
66 continue;
67 }
68 if (sep_found)
69 break;
70 if (c >= '0' && c <= '9') {
71 int digit = static_cast<int>(c - '0');
72 if (!decimal_scale) {
73 num = num * 10 + digit;
74 } else {
75 decimal_scale /= 10;
76 num += digit * decimal_scale;
77 }
78 continue;
79 }
80 // We found something that is not a digit. Keep looking for the next `sep`
81 // but flag the current token as invalid.
82 invalid_chars_found = true;
83 }
84 if (!sep_found)
85 return std::nullopt;
86 // If we find non-digit characters, we want to still skip the token but return
87 // std::nullopt. The parser below relies on token skipping to deal with cases
88 // where the uid (which we don't care about) is literal ("root" rather than
89 // 0).
90 *it = it->substr(next_it);
91 if (invalid_chars_found)
92 return std::nullopt;
93 return num;
94 }
95
ToYear(std::chrono::seconds epoch)96 int32_t ToYear(std::chrono::seconds epoch) {
97 time_t time = static_cast<time_t>(epoch.count());
98 auto* time_tm = gmtime(&time);
99 return time_tm->tm_year + 1900;
100 }
101
GetCurrentYear()102 int32_t GetCurrentYear() {
103 return ToYear(base::GetWallTimeS());
104 }
105
GuessYear(TraceProcessorContext * context)106 int32_t GuessYear(TraceProcessorContext* context) {
107 if (context->sorter->max_timestamp() == 0) {
108 return GetCurrentYear();
109 }
110 auto time =
111 context->clock_converter->ToRealtime(context->sorter->max_timestamp());
112 if (!time.ok()) {
113 return GetCurrentYear();
114 }
115 std::chrono::nanoseconds ns(*time);
116 return ToYear(std::chrono::duration_cast<std::chrono::seconds>(ns));
117 }
118
119 } // namespace
AndroidLogReader(TraceProcessorContext * context)120 AndroidLogReader::AndroidLogReader(TraceProcessorContext* context)
121 : AndroidLogReader(context, GuessYear(context)) {}
122
AndroidLogReader(TraceProcessorContext * context,int32_t year)123 AndroidLogReader::AndroidLogReader(TraceProcessorContext* context, int32_t year)
124 : context_(context),
125 year_(year),
126 timezone_offset_(context_->clock_tracker->timezone_offset().value_or(0)) {
127 }
128
129 AndroidLogReader::~AndroidLogReader() = default;
130
ParseLine(base::StringView line)131 util::Status AndroidLogReader::ParseLine(base::StringView line) {
132 if (line.size() < 30 ||
133 (line.at(0) == '-' && line.at(1) == '-' && line.at(2) == '-')) {
134 // These are markers like "--------- switch to radio" which we ignore.
135 // The smallest valid logcat line has around 30 chars, as follows:
136 // "06-24 23:10:00.123 1 1 D : ..."
137 return base::OkStatus();
138 }
139
140 if (!format_.has_value()) {
141 format_ = AndroidLogEvent::DetectFormat(line);
142 if (!format_.has_value()) {
143 PERFETTO_DLOG("Could not detect logcat format for: |%s|",
144 line.ToStdString().c_str());
145 context_->storage->IncrementStats(stats::android_log_format_invalid);
146 return base::OkStatus();
147 }
148 }
149
150 base::StringView it = line;
151 // 06-24 16:24:23.441532 23153 23153 I wm_on_stop_called: message ...
152 // 07-28 14:25:13.506 root 0 0 I x86/fpu : Supporting XSAVE feature
153 // 0x002: 'SSE registers'
154 std::optional<int> month = ReadNumAndAdvance(&it, '-');
155 std::optional<int> day = ReadNumAndAdvance(&it, ' ');
156 std::optional<int> hour = ReadNumAndAdvance(&it, ':');
157 std::optional<int> minute = ReadNumAndAdvance(&it, ':');
158 std::optional<int> sec = ReadNumAndAdvance(&it, '.');
159 std::optional<int> ns = ReadNumAndAdvance(&it, ' ', 1000 * 1000 * 1000);
160
161 if (format_ == AndroidLogEvent::Format::kBugreport)
162 ReadNumAndAdvance(&it, ' '); // Skip the UID column.
163
164 std::optional<int> pid = ReadNumAndAdvance(&it, ' ');
165 std::optional<int> tid = ReadNumAndAdvance(&it, ' ');
166
167 if (!month || !day || !hour || !minute || !sec || !ns || !pid || !tid) {
168 context_->storage->IncrementStats(stats::android_log_num_failed);
169 return base::OkStatus();
170 }
171
172 if (it.size() < 4 || it.at(1) != ' ') {
173 context_->storage->IncrementStats(stats::android_log_num_failed);
174 return base::OkStatus();
175 }
176
177 char prio_str = it.at(0);
178 int prio = protos::pbzero::AndroidLogPriority::PRIO_UNSPECIFIED;
179 if ('V' == prio_str) {
180 prio = protos::pbzero::AndroidLogPriority::PRIO_VERBOSE;
181 } else if ('D' == prio_str) {
182 prio = protos::pbzero::AndroidLogPriority::PRIO_DEBUG;
183 } else if ('I' == prio_str) {
184 prio = protos::pbzero::AndroidLogPriority::PRIO_INFO;
185 } else if ('W' == prio_str) {
186 prio = protos::pbzero::AndroidLogPriority::PRIO_WARN;
187 } else if ('E' == prio_str) {
188 prio = protos::pbzero::AndroidLogPriority::PRIO_ERROR;
189 } else if ('F' == prio_str) {
190 prio = protos::pbzero::AndroidLogPriority::PRIO_FATAL;
191 }
192
193 it = it.substr(2);
194
195 // Find the ': ' that defines the boundary between the tag and message.
196 // We can't just look for ':' because various HALs emit tags with a ':'.
197 base::StringView cat;
198 for (size_t i = 0; i < it.size() - 1; ++i) {
199 if (it.at(i) == ':' && it.at(i + 1) == ' ') {
200 cat = it.substr(0, i);
201 it = it.substr(i + 2);
202 break;
203 }
204 }
205 // Trim trailing spaces, happens in kernel events (e.g. "init :").
206 while (!cat.empty() && cat.at(cat.size() - 1) == ' ')
207 cat = cat.substr(0, cat.size() - 1);
208
209 base::StringView msg = it; // The rest is the log message.
210
211 int64_t secs = base::MkTime(year_, *month, *day, *hour, *minute, *sec);
212 std::chrono::nanoseconds event_ts(secs * 1000000000ll + *ns);
213
214 AndroidLogEvent event;
215 event.pid = static_cast<uint32_t>(*pid);
216 event.tid = static_cast<uint32_t>(*tid);
217 event.prio = static_cast<uint32_t>(prio);
218 event.tag = context_->storage->InternString(cat);
219 event.msg = context_->storage->InternString(msg);
220
221 return ProcessEvent(event_ts, std::move(event));
222 }
223
ProcessEvent(std::chrono::nanoseconds event_ts,AndroidLogEvent event)224 util::Status AndroidLogReader::ProcessEvent(std::chrono::nanoseconds event_ts,
225 AndroidLogEvent event) {
226 return SendToSorter(event_ts, std::move(event));
227 }
228
SendToSorter(std::chrono::nanoseconds event_ts,AndroidLogEvent event)229 util::Status AndroidLogReader::SendToSorter(std::chrono::nanoseconds event_ts,
230 AndroidLogEvent event) {
231 event_ts -= timezone_offset_;
232 ASSIGN_OR_RETURN(
233 int64_t trace_ts,
234 context_->clock_tracker->ToTraceTime(
235 protos::pbzero::ClockSnapshot::Clock::REALTIME, event_ts.count()));
236 context_->sorter->PushAndroidLogEvent(trace_ts, std::move(event));
237 return base::OkStatus();
238 }
239
EndOfStream(base::StringView)240 void AndroidLogReader::EndOfStream(base::StringView) {}
241
242 BufferingAndroidLogReader::~BufferingAndroidLogReader() = default;
243
ProcessEvent(std::chrono::nanoseconds event_ts,AndroidLogEvent event)244 base::Status BufferingAndroidLogReader::ProcessEvent(
245 std::chrono::nanoseconds event_ts,
246 AndroidLogEvent event) {
247 RETURN_IF_ERROR(SendToSorter(event_ts, event));
248 events_.push_back(TimestampedAndroidLogEvent{
249 std::chrono::duration_cast<std::chrono::milliseconds>(event_ts),
250 std::move(event), false});
251 return base::OkStatus();
252 }
253
DedupingAndroidLogReader(TraceProcessorContext * context,int32_t year,std::vector<TimestampedAndroidLogEvent> events)254 DedupingAndroidLogReader::DedupingAndroidLogReader(
255 TraceProcessorContext* context,
256 int32_t year,
257 std::vector<TimestampedAndroidLogEvent> events)
258 : AndroidLogReader(context, year), events_(std::move(events)) {
259 std::sort(events_.begin(), events_.end());
260 }
261
~DedupingAndroidLogReader()262 DedupingAndroidLogReader::~DedupingAndroidLogReader() {}
263
ProcessEvent(std::chrono::nanoseconds event_ts,AndroidLogEvent event)264 base::Status DedupingAndroidLogReader::ProcessEvent(
265 std::chrono::nanoseconds event_ts,
266 AndroidLogEvent event) {
267 const auto comp = [](const TimestampedAndroidLogEvent& lhs,
268 std::chrono::milliseconds rhs_time) {
269 return lhs.ts < rhs_time;
270 };
271
272 const auto event_ms =
273 std::chrono::duration_cast<std::chrono::milliseconds>(event_ts);
274
275 for (auto it =
276 std::lower_bound(events_.begin(), events_.end(), event_ms, comp);
277 it != events_.end() && it->ts == event_ms; ++it) {
278 // Duplicate found
279 if (!it->matched && it->event == event) {
280 // "Remove" the entry from the list
281 it->matched = true;
282 return base::OkStatus();
283 }
284 }
285
286 return SendToSorter(event_ts, std::move(event));
287 }
288
289 } // namespace perfetto::trace_processor
290