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,bool wait_for_tz)123 AndroidLogReader::AndroidLogReader(TraceProcessorContext* context,
124 int32_t year,
125 bool wait_for_tz)
126 : context_(context), year_(year), wait_for_tz_(wait_for_tz) {}
127
128 AndroidLogReader::~AndroidLogReader() = default;
129
ParseLine(base::StringView line)130 base::Status AndroidLogReader::ParseLine(base::StringView line) {
131 if (line.size() < 30 ||
132 (line.at(0) == '-' && line.at(1) == '-' && line.at(2) == '-')) {
133 // These are markers like "--------- switch to radio" which we ignore.
134 // The smallest valid logcat line has around 30 chars, as follows:
135 // "06-24 23:10:00.123 1 1 D : ..."
136 return base::OkStatus();
137 }
138
139 if (!format_.has_value()) {
140 format_ = AndroidLogEvent::DetectFormat(line);
141 if (!format_.has_value()) {
142 PERFETTO_DLOG("Could not detect logcat format for: |%s|",
143 line.ToStdString().c_str());
144 context_->storage->IncrementStats(stats::android_log_format_invalid);
145 return base::OkStatus();
146 }
147 }
148
149 base::StringView it = line;
150 // 06-24 16:24:23.441532 23153 23153 I wm_on_stop_called: message ...
151 // 07-28 14:25:13.506 root 0 0 I x86/fpu : Supporting XSAVE feature
152 // 0x002: 'SSE registers'
153 std::optional<int> month = ReadNumAndAdvance(&it, '-');
154 std::optional<int> day = ReadNumAndAdvance(&it, ' ');
155 std::optional<int> hour = ReadNumAndAdvance(&it, ':');
156 std::optional<int> minute = ReadNumAndAdvance(&it, ':');
157 std::optional<int> sec = ReadNumAndAdvance(&it, '.');
158 std::optional<int> ns = ReadNumAndAdvance(&it, ' ', 1000 * 1000 * 1000);
159
160 if (format_ == AndroidLogEvent::Format::kBugreport)
161 ReadNumAndAdvance(&it, ' '); // Skip the UID column.
162
163 std::optional<int> pid = ReadNumAndAdvance(&it, ' ');
164 std::optional<int> tid = ReadNumAndAdvance(&it, ' ');
165
166 if (!month || !day || !hour || !minute || !sec || !ns || !pid || !tid) {
167 context_->storage->IncrementStats(stats::android_log_num_failed);
168 return base::OkStatus();
169 }
170
171 if (it.size() < 4 || it.at(1) != ' ') {
172 context_->storage->IncrementStats(stats::android_log_num_failed);
173 return base::OkStatus();
174 }
175
176 char prio_str = it.at(0);
177 int prio = protos::pbzero::AndroidLogPriority::PRIO_UNSPECIFIED;
178 if ('V' == prio_str) {
179 prio = protos::pbzero::AndroidLogPriority::PRIO_VERBOSE;
180 } else if ('D' == prio_str) {
181 prio = protos::pbzero::AndroidLogPriority::PRIO_DEBUG;
182 } else if ('I' == prio_str) {
183 prio = protos::pbzero::AndroidLogPriority::PRIO_INFO;
184 } else if ('W' == prio_str) {
185 prio = protos::pbzero::AndroidLogPriority::PRIO_WARN;
186 } else if ('E' == prio_str) {
187 prio = protos::pbzero::AndroidLogPriority::PRIO_ERROR;
188 } else if ('F' == prio_str) {
189 prio = protos::pbzero::AndroidLogPriority::PRIO_FATAL;
190 }
191
192 it = it.substr(2);
193
194 // Find the ': ' that defines the boundary between the tag and message.
195 // We can't just look for ':' because various HALs emit tags with a ':'.
196 base::StringView cat;
197 for (size_t i = 0; i < it.size() - 1; ++i) {
198 if (it.at(i) == ':' && it.at(i + 1) == ' ') {
199 cat = it.substr(0, i);
200 it = it.substr(i + 2);
201 break;
202 }
203 }
204 // Trim trailing spaces, happens in kernel events (e.g. "init :").
205 while (!cat.empty() && cat.at(cat.size() - 1) == ' ')
206 cat = cat.substr(0, cat.size() - 1);
207
208 base::StringView msg = it; // The rest is the log message.
209
210 int64_t secs = base::MkTime(year_, *month, *day, *hour, *minute, *sec);
211 std::chrono::nanoseconds event_ts(secs * 1000000000ll + *ns);
212
213 AndroidLogEvent event;
214 event.pid = static_cast<uint32_t>(*pid);
215 event.tid = static_cast<uint32_t>(*tid);
216 event.prio = static_cast<uint32_t>(prio);
217 event.tag = context_->storage->InternString(cat);
218 event.msg = context_->storage->InternString(msg);
219
220 return ProcessEvent(event_ts, std::move(event));
221 }
222
ProcessEvent(std::chrono::nanoseconds event_ts,AndroidLogEvent event)223 base::Status AndroidLogReader::ProcessEvent(std::chrono::nanoseconds event_ts,
224 AndroidLogEvent event) {
225 if (wait_for_tz_) {
226 if (!context_->clock_tracker->timezone_offset().has_value()) {
227 non_tz_adjusted_events_.push_back(TimestampedAndroidLogEvent{
228 std::chrono::duration_cast<std::chrono::milliseconds>(event_ts),
229 std::move(event), false});
230 return base::OkStatus();
231 } else {
232 RETURN_IF_ERROR(FlushNonTzAdjustedEvents());
233 }
234 }
235 return SendToSorter(event_ts, std::move(event));
236 }
237
SendToSorter(std::chrono::nanoseconds event_ts,AndroidLogEvent event)238 base::Status AndroidLogReader::SendToSorter(std::chrono::nanoseconds event_ts,
239 AndroidLogEvent event) {
240 int64_t ts =
241 event_ts.count() - context_->clock_tracker->timezone_offset().value_or(0);
242 ASSIGN_OR_RETURN(int64_t trace_ts,
243 context_->clock_tracker->ToTraceTime(
244 protos::pbzero::ClockSnapshot::Clock::REALTIME, ts));
245 context_->sorter->PushAndroidLogEvent(trace_ts, std::move(event));
246 return base::OkStatus();
247 }
248
FlushNonTzAdjustedEvents()249 base::Status AndroidLogReader::FlushNonTzAdjustedEvents() {
250 for (const TimestampedAndroidLogEvent& event : non_tz_adjusted_events_) {
251 RETURN_IF_ERROR(SendToSorter(event.ts, event.event));
252 }
253 non_tz_adjusted_events_.clear();
254 return base::OkStatus();
255 }
256
EndOfStream(base::StringView)257 void AndroidLogReader::EndOfStream(base::StringView) {
258 // Flush all events once we reach the end of input, regarddless of if we got
259 // a TZ offset or not.
260 FlushNonTzAdjustedEvents();
261 }
262
263 BufferingAndroidLogReader::~BufferingAndroidLogReader() = default;
264
ProcessEvent(std::chrono::nanoseconds event_ts,AndroidLogEvent event)265 base::Status BufferingAndroidLogReader::ProcessEvent(
266 std::chrono::nanoseconds event_ts,
267 AndroidLogEvent event) {
268 RETURN_IF_ERROR(AndroidLogReader::ProcessEvent(event_ts, event));
269 events_.push_back(TimestampedAndroidLogEvent{
270 std::chrono::duration_cast<std::chrono::milliseconds>(event_ts),
271 std::move(event), false});
272 return base::OkStatus();
273 }
274
DedupingAndroidLogReader(TraceProcessorContext * context,int32_t year,bool wait_for_tz,std::vector<TimestampedAndroidLogEvent> events)275 DedupingAndroidLogReader::DedupingAndroidLogReader(
276 TraceProcessorContext* context,
277 int32_t year,
278 bool wait_for_tz,
279 std::vector<TimestampedAndroidLogEvent> events)
280 : AndroidLogReader(context, year, wait_for_tz), events_(std::move(events)) {
281 std::sort(events_.begin(), events_.end());
282 }
283
~DedupingAndroidLogReader()284 DedupingAndroidLogReader::~DedupingAndroidLogReader() {}
285
ProcessEvent(std::chrono::nanoseconds event_ts,AndroidLogEvent event)286 base::Status DedupingAndroidLogReader::ProcessEvent(
287 std::chrono::nanoseconds event_ts,
288 AndroidLogEvent event) {
289 const auto comp = [](const TimestampedAndroidLogEvent& lhs,
290 std::chrono::milliseconds rhs_time) {
291 return lhs.ts < rhs_time;
292 };
293
294 const auto event_ms =
295 std::chrono::duration_cast<std::chrono::milliseconds>(event_ts);
296
297 for (auto it =
298 std::lower_bound(events_.begin(), events_.end(), event_ms, comp);
299 it != events_.end() && it->ts == event_ms; ++it) {
300 // Duplicate found
301 if (!it->matched && it->event == event) {
302 // "Remove" the entry from the list
303 it->matched = true;
304 return base::OkStatus();
305 }
306 }
307
308 return AndroidLogReader::ProcessEvent(event_ts, std::move(event));
309 }
310
311 } // namespace perfetto::trace_processor
312