1 /*
2 * Copyright (C) 2021 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 "perfetto/base/logging.h"
18
19 #include <stdint.h>
20
21 #include <condition_variable>
22 #include <mutex>
23 #include <thread>
24 #include <vector>
25
26 #include "perfetto/ext/base/crash_keys.h"
27 #include "perfetto/ext/base/string_utils.h"
28 #include "src/base/log_ring_buffer.h"
29 #include "test/gtest_and_gmock.h"
30
31 namespace perfetto {
32 namespace base {
33 namespace {
34
35 char g_last_line[256];
36
TEST(LoggingTest,Basic)37 TEST(LoggingTest, Basic) {
38 SetLogMessageCallback(nullptr);
39 LogMessage(kLogDebug, "file.cc", 100, "test message %d", 1);
40
41 SetLogMessageCallback(+[](LogMessageCallbackArgs log) {
42 base::SprintfTrunc(g_last_line, sizeof(g_last_line), "%d:%s:%d:%s",
43 log.level, log.filename, log.line, log.message);
44 });
45
46 g_last_line[0] = 0;
47 LogMessage(kLogDebug, "file.cc", 101, "test message %d", 2);
48 ASSERT_STREQ(g_last_line, "0:file.cc:101:test message 2");
49
50 g_last_line[0] = 0;
51 SetLogMessageCallback(nullptr);
52 LogMessage(kLogDebug, "file.cc", 102, "test message %d", 3);
53 ASSERT_STREQ(g_last_line, "");
54 }
55
TEST(LogRingBufferTest,SimpleCases)56 TEST(LogRingBufferTest, SimpleCases) {
57 char buf[4096];
58 memset(buf, 'x', sizeof(buf)); // Deliberately not 0-initialized.
59
60 LogRingBuffer lrb;
61 EXPECT_EQ(0u, lrb.Read(buf, sizeof(buf)));
62 EXPECT_STREQ(buf, "");
63
64 // Append one entry and read back.
65 lrb.Append("tstamp1,", "src1.cc", "message1");
66 EXPECT_EQ(25u, lrb.Read(buf, sizeof(buf)));
67 EXPECT_STREQ(buf, "tstamp1,src1.cc message1\n");
68
69 lrb.Append("tstamp2,", "src2.cc", "message2");
70 EXPECT_EQ(50u, lrb.Read(buf, sizeof(buf)));
71 EXPECT_STREQ(buf, "tstamp1,src1.cc message1\ntstamp2,src2.cc message2\n");
72 }
73
TEST(LogRingBufferTest,Truncation)74 TEST(LogRingBufferTest, Truncation) {
75 // Append a long entry that overflows the event slot.
76 std::string long_msg;
77 long_msg.resize(kLogRingBufMsgLen * 2);
78 for (size_t i = 0; i < long_msg.size(); i++)
79 long_msg[i] = static_cast<char>('a' + (i % 27));
80 LogRingBuffer lrb;
81 lrb.Append("A", "B", StringView(long_msg));
82
83 // Check that it gets truncated with no side effects.
84 char buf[4096];
85 memset(buf, 'x', sizeof(buf)); // Deliberately not 0-initialized.
86 auto expected = "AB " + long_msg.substr(0, kLogRingBufMsgLen - 4) + "\n";
87 EXPECT_EQ(expected.size(), lrb.Read(buf, sizeof(buf)));
88 EXPECT_EQ(buf, expected);
89
90 // Append a short message and check everything still works.
91 lrb.Append("X", "Y", "foo");
92 EXPECT_EQ(expected.size() + 7, lrb.Read(buf, sizeof(buf)));
93 EXPECT_EQ(buf, expected + "XY foo\n");
94 }
95
TEST(LogRingBufferTest,Wrapping)96 TEST(LogRingBufferTest, Wrapping) {
97 LogRingBuffer lrb;
98
99 std::vector<std::string> expected_logs;
100 for (uint32_t i = 0; i < 128; i++) {
101 std::string id = std::to_string(i);
102 std::string tstamp = "tstamp" + id + ",";
103 std::string src = "src";
104 std::string msg;
105 msg.resize(1 + (i % 16));
106 for (size_t c = 0; c < msg.size(); c++)
107 msg[c] = static_cast<char>('a' + c);
108 lrb.Append(StringView(tstamp), StringView(src), StringView(msg));
109 auto expected_log =
110 (tstamp + src + " " + msg).substr(0, kLogRingBufMsgLen) + "\n";
111 expected_logs.emplace_back(expected_log);
112 }
113
114 std::string expected;
115 for (size_t i = expected_logs.size() - kLogRingBufEntries;
116 i < expected_logs.size(); i++) {
117 expected += expected_logs[i];
118 }
119
120 char buf[kLogRingBufMsgLen * kLogRingBufEntries];
121 memset(buf, 'x', sizeof(buf)); // Deliberately not 0-initialized.
122 lrb.Read(buf, sizeof(buf));
123 EXPECT_EQ(buf, expected);
124
125 // Do a partial readback which will cause output truncation.
126 lrb.Read(buf, 127);
127 EXPECT_EQ(buf, expected.substr(0, 127 - 1)); // - 1 for the NUL terminator.
128 }
129
130 // Writes concurrently into the ring buffer and check that all the events are
131 // seen in some order.
TEST(LogRingBufferTest,MultiThreadedWrites)132 TEST(LogRingBufferTest, MultiThreadedWrites) {
133 LogRingBuffer lrb;
134
135 std::vector<std::thread> threads;
136 const size_t kNumThreads = 8;
137
138 std::mutex mutex;
139 std::condition_variable cond;
140 bool sync_start = false;
141
142 auto thread_main = [&](size_t thread_idx) {
143 std::unique_lock<std::mutex> lock(mutex);
144 cond.wait(lock, [&] { return sync_start; });
145
146 std::string tstamp = "ts" + std::to_string(thread_idx) + ",";
147 std::string src = "src";
148 std::string msg(thread_idx + 1, '.'); // A variable number of dots.
149 lrb.Append(StringView(tstamp), StringView(src), StringView(msg));
150 };
151
152 std::vector<std::string> expected_events;
153 for (size_t i = 0; i < kNumThreads; i++) {
154 threads.emplace_back(thread_main, i);
155 std::string id = std::to_string(i);
156 expected_events.emplace_back("ts" + id + ",src " + std::string(i + 1, '.'));
157 }
158
159 // Unlock all the threads as close as possible to maximize races.
160 {
161 std::unique_lock<std::mutex> lock(mutex);
162 sync_start = true;
163 cond.notify_all();
164 }
165
166 for (auto& thread : threads)
167 thread.join();
168
169 char buf[kLogRingBufEntries * 40];
170 memset(buf, 'x', sizeof(buf)); // Deliberately not 0-initialized.
171 lrb.Read(buf, sizeof(buf));
172
173 std::vector<std::string> actual_events = SplitString(buf, "\n");
174 EXPECT_THAT(actual_events,
175 testing::UnorderedElementsAreArray(expected_events));
176 }
177
TEST(CrashKeysTest,SetClearAndLongKeys)178 TEST(CrashKeysTest, SetClearAndLongKeys) {
179 UnregisterAllCrashKeysForTesting();
180
181 char buf[1024];
182 memset(buf, 'x', sizeof(buf));
183 EXPECT_EQ(0u, SerializeCrashKeys(buf, sizeof(buf)));
184 EXPECT_STREQ(buf, "");
185
186 CrashKey k1("key1");
187 CrashKey k2("key2");
188 CrashKey k3("key3");
189 CrashKey k4("key4");
190
191 k1.Set(0);
192 k1.Clear();
193
194 k2.Set(42);
195
196 k3.Set("xx");
197 k3.Clear();
198
199 k4.Set("value");
200
201 EXPECT_EQ(21u, SerializeCrashKeys(buf, sizeof(buf)));
202 EXPECT_STREQ(buf, "key2: 42\nkey4: value\n");
203
204 EXPECT_EQ(0u, SerializeCrashKeys(buf, 0));
205
206 EXPECT_EQ(0u, SerializeCrashKeys(buf, 1));
207 EXPECT_STREQ(buf, "");
208
209 // Test truncated output.
210 EXPECT_EQ(5u, SerializeCrashKeys(buf, 5 + 1));
211 EXPECT_STREQ(buf, "key2:");
212
213 k2.Clear();
214
215 std::string long_str(1024, 'x');
216 k4.Set(StringView(long_str));
217
218 EXPECT_EQ(6 + kCrashKeyMaxStrSize, SerializeCrashKeys(buf, sizeof(buf)));
219 std::string expected =
220 "key4: " + long_str.substr(0, kCrashKeyMaxStrSize - 1) + "\n";
221 EXPECT_EQ(buf, expected);
222
223 UnregisterAllCrashKeysForTesting();
224 }
225
TEST(CrashKeysTest,ScopedSet)226 TEST(CrashKeysTest, ScopedSet) {
227 UnregisterAllCrashKeysForTesting();
228
229 char buf[1024];
230 memset(buf, 'x', sizeof(buf));
231
232 CrashKey k1("key1");
233 CrashKey k2("key2");
234
235 auto scoped_key = k1.SetScoped(42);
236 EXPECT_GT(SerializeCrashKeys(buf, sizeof(buf)), 0u);
237 EXPECT_STREQ(buf, "key1: 42\n");
238
239 {
240 auto scoped_key2 = k2.SetScoped("foo");
241 EXPECT_GT(SerializeCrashKeys(buf, sizeof(buf)), 0u);
242 EXPECT_STREQ(buf, "key1: 42\nkey2: foo\n");
243 }
244
245 EXPECT_GT(SerializeCrashKeys(buf, sizeof(buf)), 0u);
246 EXPECT_STREQ(buf, "key1: 42\n");
247
248 k1.Clear();
249 EXPECT_EQ(0u, SerializeCrashKeys(buf, sizeof(buf)));
250 EXPECT_STREQ(buf, "");
251
252 UnregisterAllCrashKeysForTesting();
253 }
254
255 } // namespace
256 } // namespace base
257 } // namespace perfetto
258