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 <memory>
18 #include <ostream>
19 #include <utility>
20 #include <vector>
21
22 #include "perfetto/base/status.h"
23 #include "perfetto/base/time.h"
24 #include "perfetto/ext/base/string_utils.h"
25 #include "perfetto/trace_processor/trace_blob.h"
26 #include "perfetto/trace_processor/trace_blob_view.h"
27 #include "protos/perfetto/trace/clock_snapshot.pbzero.h"
28 #include "src/trace_processor/importers/android_bugreport/android_bugreport_reader.h"
29 #include "src/trace_processor/importers/android_bugreport/android_log_event.h"
30 #include "src/trace_processor/importers/android_bugreport/android_log_reader.h"
31 #include "src/trace_processor/importers/common/clock_tracker.h"
32 #include "src/trace_processor/importers/common/metadata_tracker.h"
33 #include "src/trace_processor/importers/common/trace_parser.h"
34 #include "src/trace_processor/sorter/trace_sorter.h"
35 #include "src/trace_processor/storage/trace_storage.h"
36 #include "src/trace_processor/types/trace_processor_context.h"
37 #include "test/gtest_and_gmock.h"
38
39 #include "protos/perfetto/common/android_log_constants.pbzero.h"
40
41 namespace perfetto::trace_processor {
42
PrintTo(const AndroidLogEvent & event,std::ostream * os)43 static void PrintTo(const AndroidLogEvent& event, std::ostream* os) {
44 *os << "(pid: " << event.pid << ", "
45 << "tid: " << event.tid << ", "
46 << "prio: " << event.prio << ", "
47 << "tag_id: " << event.tag.raw_id() << ", "
48 << "msg_id: " << event.msg.raw_id() << ")";
49 }
50
51 namespace {
52 const int64_t kStoNs = 1000000000LL;
53
54 class EventParserMock : public AndroidLogEventParser {
55 public:
56 ~EventParserMock() override = default;
57 MOCK_METHOD(void,
58 ParseAndroidLogEvent,
59 (int64_t, AndroidLogEvent),
60 (override));
61 };
62
63 class AndroidLogReaderTest : public ::testing::Test {
64 public:
AndroidLogReaderTest()65 AndroidLogReaderTest() {
66 context_.storage = std::make_shared<TraceStorage>();
67 context_.clock_tracker = std::make_unique<ClockTracker>(&context_);
68 context_.metadata_tracker =
69 std::make_unique<MetadataTracker>(context_.storage.get());
70 context_.clock_tracker->SetTraceTimeClock(
71 protos::pbzero::ClockSnapshot::Clock::REALTIME);
72 context_.sorter = std::make_unique<TraceSorter>(
73 &context_, TraceSorter::SortingMode::kDefault);
74 mock_parser_ = new EventParserMock();
75 context_.android_log_event_parser.reset(mock_parser_);
76 }
77
78 using P = ::perfetto::protos::pbzero::AndroidLogPriority;
79
S(const char * str)80 StringId S(const char* str) { return context_.storage->InternString(str); }
mock_parser()81 EventParserMock& mock_parser() { return *mock_parser_; }
82
context()83 TraceProcessorContext* context() { return &context_; }
84
85 private:
86 TraceProcessorContext context_;
87 EventParserMock* mock_parser_;
88 };
89
TEST_F(AndroidLogReaderTest,PersistentLogFormat)90 TEST_F(AndroidLogReaderTest, PersistentLogFormat) {
91 constexpr char kInput[] =
92 "01-02 03:04:05.678901 1000 2000 D Tag: message\n"
93 "12-31 23:59:00.123456 1 2 I [tag:with:colon]: moar long message\n"
94 "12-31 23:59:00.123 1 2 W [tag:with:colon]: moar long message\n"
95 "12-31 23:59:00.1 1 2 E [tag:with:colon]: moar long message\n"
96 "12-31 23:59:00.01 1 2 F [tag:with:colon]: moar long message\n";
97
98 AndroidLogReader reader(context(), 2020);
99
100 EXPECT_CALL(
101 mock_parser(),
102 ParseAndroidLogEvent(
103 base::MkTime(2020, 1, 2, 3, 4, 5) * kStoNs + 678901000,
104 AndroidLogEvent{1000, 2000, P::PRIO_DEBUG, S("Tag"), S("message")}));
105
106 EXPECT_CALL(mock_parser(),
107 ParseAndroidLogEvent(
108 base::MkTime(2020, 12, 31, 23, 59, 0) * kStoNs + 123456000,
109 AndroidLogEvent{1, 2, P::PRIO_INFO, S("[tag:with:colon]"),
110 S("moar long message")}));
111 EXPECT_CALL(mock_parser(),
112 ParseAndroidLogEvent(
113 base::MkTime(2020, 12, 31, 23, 59, 0) * kStoNs + 123000000,
114 AndroidLogEvent{1, 2, P::PRIO_WARN, S("[tag:with:colon]"),
115 S("moar long message")}));
116 EXPECT_CALL(mock_parser(),
117 ParseAndroidLogEvent(
118 base::MkTime(2020, 12, 31, 23, 59, 0) * kStoNs + 100000000,
119 AndroidLogEvent{1, 2, P::PRIO_ERROR, S("[tag:with:colon]"),
120 S("moar long message")}));
121 EXPECT_CALL(mock_parser(),
122 ParseAndroidLogEvent(
123 base::MkTime(2020, 12, 31, 23, 59, 0) * kStoNs + 10000000,
124 AndroidLogEvent{1, 2, P::PRIO_FATAL, S("[tag:with:colon]"),
125 S("moar long message")}));
126
127 EXPECT_TRUE(
128 reader.Parse(TraceBlobView(TraceBlob::CopyFrom(kInput, sizeof(kInput))))
129 .ok());
130 EXPECT_EQ(context()->storage->stats()[stats::android_log_num_failed].value,
131 0);
132
133 context()->sorter->ExtractEventsForced();
134 }
135
TEST_F(AndroidLogReaderTest,BugreportFormat)136 TEST_F(AndroidLogReaderTest, BugreportFormat) {
137 constexpr char kInput[] =
138 "07-28 14:25:20.355 0 1 2 I init : Loaded kernel module\n"
139 "07-28 14:25:54.876 1000 643 644 D PackageManager: No files\n"
140 "08-24 23:39:12.272 root 0 1 I : c0 11835 binder: 1\n"
141 "08-24 23:39:12.421 radio 2532 2533 D TelephonyProvider: Using old\n";
142
143 AndroidLogReader reader(context(), 2020);
144
145 EXPECT_CALL(mock_parser(),
146 ParseAndroidLogEvent(
147 base::MkTime(2020, 7, 28, 14, 25, 20) * kStoNs + 355000000,
148 AndroidLogEvent{1, 2, P::PRIO_INFO, S("init"),
149 S("Loaded kernel module")}));
150 EXPECT_CALL(mock_parser(),
151 ParseAndroidLogEvent(
152 base::MkTime(2020, 7, 28, 14, 25, 54) * kStoNs + 876000000,
153 AndroidLogEvent{643, 644, P::PRIO_DEBUG, S("PackageManager"),
154 S("No files")}));
155 EXPECT_CALL(mock_parser(),
156 ParseAndroidLogEvent(
157 base::MkTime(2020, 8, 24, 23, 39, 12) * kStoNs + 272000000,
158 AndroidLogEvent{0, 1, P::PRIO_INFO, S(""),
159 S("c0 11835 binder: 1")}));
160 EXPECT_CALL(mock_parser(),
161 ParseAndroidLogEvent(
162 base::MkTime(2020, 8, 24, 23, 39, 12) * kStoNs + 421000000,
163 AndroidLogEvent{2532, 2533, P::PRIO_DEBUG,
164 S("TelephonyProvider"), S("Using old")}));
165
166 EXPECT_TRUE(
167 reader.Parse(TraceBlobView(TraceBlob::CopyFrom(kInput, sizeof(kInput))))
168 .ok());
169 EXPECT_EQ(context()->storage->stats()[stats::android_log_num_failed].value,
170 0);
171
172 context()->sorter->ExtractEventsForced();
173 }
174
175 // Tests the deduping logic. This is used when parsing events first from the
176 // persistent logcat (which has us resolution) and then from dumpstate (which
177 // has ms resolution and sometimes contains dupes of the persistent entries).
TEST_F(AndroidLogReaderTest,Dedupe)178 TEST_F(AndroidLogReaderTest, Dedupe) {
179 constexpr char kLogcatInput[] =
180 "01-01 00:00:01.100000 0 1 1 I tag : M1\n"
181 "01-01 00:00:01.100111 0 1 1 I tag : M2\n"
182 "01-01 00:00:01.100111 0 1 1 I tag : M3\n"
183 "01-01 00:00:01.100222 0 1 1 I tag : M4\n"
184 "01-01 00:00:01.101000 0 1 1 I tag : M5\n";
185 constexpr char kDumpstateInput[] =
186 "01-01 00:00:01.100 0 1 1 I tag : M1\n" // Dupe
187 "01-01 00:00:01.100 0 1 1 I tag : M1\n" // Not a dupe
188 "01-01 00:00:01.100 0 1 1 I tag : M1.5\n"
189 "01-01 00:00:01.100 0 1 1 I tag : M3\n" // Dupe
190 "01-01 00:00:01.100 0 1 1 I tag : M4\n" // Dupe
191 "01-01 00:00:01.101 0 1 1 I tag : M5\n" // Dupe
192 "01-01 00:00:01.101 0 1 1 I tag : M6\n";
193
194 EXPECT_CALL(mock_parser(),
195 ParseAndroidLogEvent(
196 base::MkTime(2020, 1, 1, 0, 0, 1) * kStoNs + 100000000,
197 AndroidLogEvent{1, 1, P::PRIO_INFO, S("tag"), S("M1")}))
198 .Times(2);
199 EXPECT_CALL(mock_parser(),
200 ParseAndroidLogEvent(
201 base::MkTime(2020, 1, 1, 0, 0, 1) * kStoNs + 100000000,
202 AndroidLogEvent{1, 1, P::PRIO_INFO, S("tag"), S("M1.5")}));
203 EXPECT_CALL(mock_parser(),
204 ParseAndroidLogEvent(
205 base::MkTime(2020, 1, 1, 0, 0, 1) * kStoNs + 100111000,
206 AndroidLogEvent{1, 1, P::PRIO_INFO, S("tag"), S("M2")}));
207 EXPECT_CALL(mock_parser(),
208 ParseAndroidLogEvent(
209 base::MkTime(2020, 1, 1, 0, 0, 1) * kStoNs + 100111000,
210 AndroidLogEvent{1, 1, P::PRIO_INFO, S("tag"), S("M3")}));
211 EXPECT_CALL(mock_parser(),
212 ParseAndroidLogEvent(
213 base::MkTime(2020, 1, 1, 0, 0, 1) * kStoNs + 100222000,
214 AndroidLogEvent{1, 1, P::PRIO_INFO, S("tag"), S("M4")}));
215 EXPECT_CALL(mock_parser(),
216 ParseAndroidLogEvent(
217 base::MkTime(2020, 1, 1, 0, 0, 1) * kStoNs + 101000000,
218 AndroidLogEvent{1, 1, P::PRIO_INFO, S("tag"), S("M5")}));
219 EXPECT_CALL(mock_parser(),
220 ParseAndroidLogEvent(
221 base::MkTime(2020, 1, 1, 0, 0, 1) * kStoNs + 101000000,
222 AndroidLogEvent{1, 1, P::PRIO_INFO, S("tag"), S("M6")}));
223
224 BufferingAndroidLogReader logcat_reader(context(), 2020);
225
226 EXPECT_TRUE(logcat_reader
227 .Parse(TraceBlobView(
228 TraceBlob::CopyFrom(kLogcatInput, sizeof(kLogcatInput))))
229 .ok());
230
231 DedupingAndroidLogReader dumstate_reader(
232 context(), 2020, std::move(logcat_reader).ConsumeBufferedEvents());
233 EXPECT_TRUE(dumstate_reader
234 .Parse(TraceBlobView(TraceBlob::CopyFrom(
235 kDumpstateInput, sizeof(kDumpstateInput))))
236 .ok());
237 EXPECT_EQ(context()->storage->stats()[stats::android_log_num_failed].value,
238 0);
239
240 context()->sorter->ExtractEventsForced();
241 }
242
243 } // namespace
244 } // namespace perfetto::trace_processor
245