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 "perfetto/base/time.h"
20 #include "perfetto/ext/base/string_utils.h"
21 #include "src/trace_processor/storage/trace_storage.h"
22 #include "test/gtest_and_gmock.h"
23
24 #include "protos/perfetto/common/android_log_constants.pbzero.h"
25
26 namespace perfetto {
27 namespace trace_processor {
28
29 const int64_t kStoNs = 1000000000LL;
30
operator <<(std::ostream & stream,const AndroidLogEvent & e)31 inline std::ostream& operator<<(std::ostream& stream,
32 const AndroidLogEvent& e) {
33 char tms[32];
34 time_t secs = static_cast<time_t>(e.ts / kStoNs);
35 int ns = static_cast<int>(e.ts - secs * kStoNs);
36 strftime(tms, sizeof(tms), "%Y-%m-%d %H:%M:%S", gmtime(&secs));
37 base::StackString<64> tss("%s.%d", tms, ns);
38
39 stream << "{ts=" << tss.c_str() << ", pid=" << e.pid << ", tid=" << e.tid
40 << ", prio=" << e.prio << ", tag=" << e.tag.raw_id()
41 << ", msg=" << e.msg.raw_id() << "}";
42 return stream;
43 }
44
45 namespace {
46
47 using ::testing::ElementsAreArray;
48
TEST(AndroidLogParserTest,PersistentLogFormat)49 TEST(AndroidLogParserTest, PersistentLogFormat) {
50 TraceStorage storage;
51 AndroidLogParser alp(2020, &storage);
52 auto S = [&](const char* str) { return storage.InternString(str); };
53 using P = ::perfetto::protos::pbzero::AndroidLogPriority;
54
55 std::vector<AndroidLogEvent> events;
56 alp.ParseLogLines(
57 {
58 "01-02 03:04:05.678901 1000 2000 D Tag: message",
59 "01-02 03:04:05.678901 1000 2000 V Tag: message",
60 "12-31 23:59:00.123456 1 2 I [tag:with:colon]: moar long message",
61 "12-31 23:59:00.123 1 2 W [tag:with:colon]: moar long message",
62 "12-31 23:59:00.1 1 2 E [tag:with:colon]: moar long message",
63 "12-31 23:59:00.01 1 2 F [tag:with:colon]: moar long message",
64 },
65 &events);
66
67 EXPECT_EQ(storage.stats()[stats::android_log_num_failed].value, 0);
68 ASSERT_THAT(
69 events,
70 ElementsAreArray({
71 AndroidLogEvent{
72 base::MkTime(2020, 1, 2, 3, 4, 5) * kStoNs + 678901000, 1000,
73 2000, P::PRIO_DEBUG, S("Tag"), S("message")},
74 AndroidLogEvent{
75 base::MkTime(2020, 1, 2, 3, 4, 5) * kStoNs + 678901000, 1000,
76 2000, P::PRIO_VERBOSE, S("Tag"), S("message")},
77 AndroidLogEvent{
78 base::MkTime(2020, 12, 31, 23, 59, 0) * kStoNs + 123456000, 1, 2,
79 P::PRIO_INFO, S("[tag:with:colon]"), S("moar long message")},
80 AndroidLogEvent{
81 base::MkTime(2020, 12, 31, 23, 59, 0) * kStoNs + 123000000, 1, 2,
82 P::PRIO_WARN, S("[tag:with:colon]"), S("moar long message")},
83 AndroidLogEvent{
84 base::MkTime(2020, 12, 31, 23, 59, 0) * kStoNs + 100000000, 1, 2,
85 P::PRIO_ERROR, S("[tag:with:colon]"), S("moar long message")},
86 AndroidLogEvent{
87 base::MkTime(2020, 12, 31, 23, 59, 0) * kStoNs + 10000000, 1, 2,
88 P::PRIO_FATAL, S("[tag:with:colon]"), S("moar long message")},
89 }));
90 }
91
TEST(AndroidLogParserTest,BugreportFormat)92 TEST(AndroidLogParserTest, BugreportFormat) {
93 TraceStorage storage;
94 AndroidLogParser alp(2020, &storage);
95 auto S = [&](const char* str) { return storage.InternString(str); };
96 using P = ::perfetto::protos::pbzero::AndroidLogPriority;
97
98 std::vector<AndroidLogEvent> events;
99 alp.ParseLogLines(
100 {
101 "07-28 14:25:20.355 0 1 2 I init : Loaded kernel module",
102 "07-28 14:25:54.876 1000 643 644 D PackageManager: No files",
103 "08-24 23:39:12.272 root 0 1 I : c0 11835 binder: 1",
104 "08-24 23:39:12.421 radio 2532 2533 D TelephonyProvider: Using old",
105 },
106 &events);
107
108 EXPECT_EQ(storage.stats()[stats::android_log_num_failed].value, 0);
109 ASSERT_THAT(
110 events,
111 ElementsAreArray({
112 AndroidLogEvent{
113 base::MkTime(2020, 7, 28, 14, 25, 20) * kStoNs + 355000000, 1, 2,
114 P::PRIO_INFO, S("init"), S("Loaded kernel module")},
115 AndroidLogEvent{
116 base::MkTime(2020, 7, 28, 14, 25, 54) * kStoNs + 876000000, 643,
117 644, P::PRIO_DEBUG, S("PackageManager"), S("No files")},
118 AndroidLogEvent{
119 base::MkTime(2020, 8, 24, 23, 39, 12) * kStoNs + 272000000, 0, 1,
120 P::PRIO_INFO, S(""), S("c0 11835 binder: 1")},
121 AndroidLogEvent{
122 base::MkTime(2020, 8, 24, 23, 39, 12) * kStoNs + 421000000, 2532,
123 2533, P::PRIO_DEBUG, S("TelephonyProvider"), S("Using old")},
124 }));
125 }
126
127 // Tests the deduping logic. This is used when parsing events first from the
128 // persistent logcat (which has us resolution) and then from dumpstate (which
129 // has ms resolution and sometimes contains dupes of the persistent entries).
TEST(AndroidLogParserTest,Dedupe)130 TEST(AndroidLogParserTest, Dedupe) {
131 TraceStorage storage;
132 AndroidLogParser alp(2020, &storage);
133 auto S = [&](const char* str) { return storage.InternString(str); };
134 using P = ::perfetto::protos::pbzero::AndroidLogPriority;
135 std::vector<AndroidLogEvent> events;
136
137 // Parse some initial events without any deduping.
138 alp.ParseLogLines(
139 {
140 "01-01 00:00:01.100000 0 1 1 I tag : M1",
141 "01-01 00:00:01.100111 0 1 1 I tag : M2",
142 "01-01 00:00:01.100111 0 1 1 I tag : M3",
143 "01-01 00:00:01.100222 0 1 1 I tag : M4",
144 "01-01 00:00:01.101000 0 1 1 I tag : M5",
145 },
146 &events);
147
148 ASSERT_EQ(events.size(), 5u);
149
150 // Add a batch of events with truncated timestamps, some of which are dupes.
151 alp.ParseLogLines(
152 {
153 "01-01 00:00:01.100 0 1 1 I tag : M1", // Dupe
154 "01-01 00:00:01.100 0 1 1 I tag : M1.5",
155 "01-01 00:00:01.100 0 1 1 I tag : M3", // Dupe
156 "01-01 00:00:01.100 0 1 1 I tag : M4", // Dupe
157 "01-01 00:00:01.101 0 1 1 I tag : M5", // Dupe
158 "01-01 00:00:01.101 0 1 1 I tag : M6",
159 },
160 &events, /*dedupe_idx=*/5);
161 EXPECT_EQ(storage.stats()[stats::android_log_num_failed].value, 0);
162
163 std::stable_sort(events.begin(), events.end());
164 ASSERT_THAT(events,
165 ElementsAreArray({
166 AndroidLogEvent{
167 base::MkTime(2020, 1, 1, 0, 0, 1) * kStoNs + 100000000, 1,
168 1, P::PRIO_INFO, S("tag"), S("M1")},
169 AndroidLogEvent{
170 base::MkTime(2020, 1, 1, 0, 0, 1) * kStoNs + 100000000, 1,
171 1, P::PRIO_INFO, S("tag"), S("M1.5")},
172 AndroidLogEvent{
173 base::MkTime(2020, 1, 1, 0, 0, 1) * kStoNs + 100111000, 1,
174 1, P::PRIO_INFO, S("tag"), S("M2")},
175 AndroidLogEvent{
176 base::MkTime(2020, 1, 1, 0, 0, 1) * kStoNs + 100111000, 1,
177 1, P::PRIO_INFO, S("tag"), S("M3")},
178 AndroidLogEvent{
179 base::MkTime(2020, 1, 1, 0, 0, 1) * kStoNs + 100222000, 1,
180 1, P::PRIO_INFO, S("tag"), S("M4")},
181 AndroidLogEvent{
182 base::MkTime(2020, 1, 1, 0, 0, 1) * kStoNs + 101000000, 1,
183 1, P::PRIO_INFO, S("tag"), S("M5")},
184 AndroidLogEvent{
185 base::MkTime(2020, 1, 1, 0, 0, 1) * kStoNs + 101000000, 1,
186 1, P::PRIO_INFO, S("tag"), S("M6")},
187 }));
188 }
189
190 } // namespace
191 } // namespace trace_processor
192 } // namespace perfetto
193