]>
Commit | Line | Data |
---|---|---|
7c673cae FG |
1 | #include <gtest/gtest.h> |
2 | ||
3 | #include "log/Log.h" | |
4 | #include "common/Clock.h" | |
7c673cae FG |
5 | #include "include/coredumpctl.h" |
6 | #include "SubsystemMap.h" | |
7 | ||
11fdf7f2 TL |
8 | #include "global/global_init.h" |
9 | #include "common/ceph_argparse.h" | |
10 | #include "global/global_context.h" | |
11 | #include "common/dout.h" | |
12 | ||
7c673cae FG |
13 | using namespace ceph::logging; |
14 | ||
15 | TEST(Log, Simple) | |
16 | { | |
17 | SubsystemMap subs; | |
11fdf7f2 TL |
18 | subs.set_log_level(0, 10); |
19 | subs.set_gather_level(0, 10); | |
20 | ||
21 | subs.set_log_level(1, 20); | |
22 | subs.set_gather_level(1, 1); | |
23 | ||
24 | subs.set_log_level(2, 20); | |
25 | subs.set_gather_level(2, 2); | |
26 | ||
27 | subs.set_log_level(3, 10); | |
28 | subs.set_gather_level(3, 3); | |
7c673cae FG |
29 | |
30 | Log log(&subs); | |
31 | log.start(); | |
32 | ||
a8e16298 | 33 | log.set_log_file("foo"); |
7c673cae FG |
34 | log.reopen_log_file(); |
35 | ||
36 | log.set_stderr_level(5, -1); | |
37 | ||
38 | ||
39 | for (int i=0; i<100; i++) { | |
40 | int sys = i % 4; | |
41 | int l = 5 + (i%4); | |
42 | if (subs.should_gather(sys, l)) { | |
11fdf7f2 TL |
43 | MutableEntry e(l, sys); |
44 | log.submit_entry(std::move(e)); | |
7c673cae FG |
45 | } |
46 | } | |
47 | ||
48 | log.flush(); | |
49 | ||
50 | log.dump_recent(); | |
51 | ||
52 | log.stop(); | |
53 | } | |
54 | ||
11fdf7f2 TL |
55 | TEST(Log, ReuseBad) |
56 | { | |
57 | SubsystemMap subs; | |
58 | subs.set_log_level(1, 1); | |
59 | subs.set_gather_level(1, 1); | |
60 | Log log(&subs); | |
61 | log.start(); | |
62 | log.set_log_file("foo"); | |
63 | log.reopen_log_file(); | |
64 | ||
65 | const int l = 0; | |
66 | { | |
67 | MutableEntry e(l, 1); | |
68 | auto& out = e.get_ostream(); | |
69 | out << (std::streambuf*)nullptr; | |
70 | EXPECT_TRUE(out.bad()); // writing nullptr to a stream sets its badbit | |
71 | log.submit_entry(std::move(e)); | |
72 | } | |
73 | { | |
74 | MutableEntry e(l, 1); | |
75 | auto& out = e.get_ostream(); | |
76 | EXPECT_FALSE(out.bad()); // should not see failures from previous log entry | |
77 | out << "hello world"; | |
78 | log.submit_entry(std::move(e)); | |
79 | } | |
80 | ||
81 | log.flush(); | |
82 | log.stop(); | |
83 | } | |
84 | ||
7c673cae FG |
85 | int many = 10000; |
86 | ||
87 | TEST(Log, ManyNoGather) | |
88 | { | |
89 | SubsystemMap subs; | |
11fdf7f2 TL |
90 | subs.set_log_level(1, 1); |
91 | subs.set_gather_level(1, 1); | |
7c673cae FG |
92 | Log log(&subs); |
93 | log.start(); | |
a8e16298 | 94 | log.set_log_file("big"); |
7c673cae FG |
95 | log.reopen_log_file(); |
96 | for (int i=0; i<many; i++) { | |
97 | int l = 10; | |
98 | if (subs.should_gather(1, l)) | |
11fdf7f2 | 99 | log.submit_entry(MutableEntry(1, 0)); |
7c673cae FG |
100 | } |
101 | log.flush(); | |
102 | log.stop(); | |
103 | } | |
104 | ||
105 | ||
106 | TEST(Log, ManyGatherLog) | |
107 | { | |
108 | SubsystemMap subs; | |
11fdf7f2 TL |
109 | subs.set_log_level(1, 20); |
110 | subs.set_gather_level(1, 10); | |
7c673cae FG |
111 | Log log(&subs); |
112 | log.start(); | |
a8e16298 | 113 | log.set_log_file("big"); |
7c673cae FG |
114 | log.reopen_log_file(); |
115 | for (int i=0; i<many; i++) { | |
116 | int l = 10; | |
11fdf7f2 TL |
117 | if (subs.should_gather(1, l)) { |
118 | MutableEntry e(l, 1); | |
119 | e.get_ostream() << "this is a long string asdf asdf asdf asdf asdf asdf asd fasd fasdf "; | |
120 | log.submit_entry(std::move(e)); | |
121 | } | |
7c673cae FG |
122 | } |
123 | log.flush(); | |
124 | log.stop(); | |
125 | } | |
126 | ||
11fdf7f2 | 127 | TEST(Log, ManyGatherLogStackSpillover) |
7c673cae FG |
128 | { |
129 | SubsystemMap subs; | |
11fdf7f2 TL |
130 | subs.set_log_level(1, 20); |
131 | subs.set_gather_level(1, 10); | |
7c673cae FG |
132 | Log log(&subs); |
133 | log.start(); | |
a8e16298 | 134 | log.set_log_file("big"); |
7c673cae FG |
135 | log.reopen_log_file(); |
136 | for (int i=0; i<many; i++) { | |
137 | int l = 10; | |
138 | if (subs.should_gather(1, l)) { | |
11fdf7f2 TL |
139 | MutableEntry e(l, 1); |
140 | auto& s = e.get_ostream(); | |
141 | s << "foo"; | |
142 | s << std::string(sizeof(e) * 2, '-'); | |
143 | log.submit_entry(std::move(e)); | |
7c673cae FG |
144 | } |
145 | } | |
146 | log.flush(); | |
147 | log.stop(); | |
148 | } | |
11fdf7f2 TL |
149 | |
150 | TEST(Log, ManyGather) | |
7c673cae FG |
151 | { |
152 | SubsystemMap subs; | |
11fdf7f2 TL |
153 | subs.set_log_level(1, 20); |
154 | subs.set_gather_level(1, 1); | |
7c673cae FG |
155 | Log log(&subs); |
156 | log.start(); | |
a8e16298 | 157 | log.set_log_file("big"); |
7c673cae FG |
158 | log.reopen_log_file(); |
159 | for (int i=0; i<many; i++) { | |
160 | int l = 10; | |
11fdf7f2 TL |
161 | if (subs.should_gather(1, l)) |
162 | log.submit_entry(MutableEntry(l, 1)); | |
7c673cae FG |
163 | } |
164 | log.flush(); | |
165 | log.stop(); | |
166 | } | |
167 | ||
11fdf7f2 | 168 | void do_segv() |
7c673cae FG |
169 | { |
170 | SubsystemMap subs; | |
11fdf7f2 TL |
171 | subs.set_log_level(1, 20); |
172 | subs.set_gather_level(1, 1); | |
7c673cae FG |
173 | Log log(&subs); |
174 | log.start(); | |
a8e16298 | 175 | log.set_log_file("big"); |
7c673cae | 176 | log.reopen_log_file(); |
11fdf7f2 TL |
177 | |
178 | log.inject_segv(); | |
179 | MutableEntry e(10, 1); | |
180 | { | |
181 | PrCtl unset_dumpable; | |
182 | log.submit_entry(std::move(e)); // this should segv | |
7c673cae | 183 | } |
11fdf7f2 | 184 | |
7c673cae FG |
185 | log.flush(); |
186 | log.stop(); | |
187 | } | |
188 | ||
11fdf7f2 TL |
189 | TEST(Log, InternalSegv) |
190 | { | |
191 | ASSERT_DEATH(do_segv(), ".*"); | |
192 | } | |
193 | ||
194 | TEST(Log, LargeLog) | |
7c673cae FG |
195 | { |
196 | SubsystemMap subs; | |
11fdf7f2 TL |
197 | subs.set_log_level(1, 20); |
198 | subs.set_gather_level(1, 10); | |
7c673cae FG |
199 | Log log(&subs); |
200 | log.start(); | |
a8e16298 | 201 | log.set_log_file("big"); |
7c673cae | 202 | log.reopen_log_file(); |
11fdf7f2 TL |
203 | int l = 10; |
204 | { | |
205 | MutableEntry e(l, 1); | |
206 | std::string msg(10000000, 'a'); | |
207 | e.get_ostream() << msg; | |
208 | log.submit_entry(std::move(e)); | |
7c673cae FG |
209 | } |
210 | log.flush(); | |
211 | log.stop(); | |
212 | } | |
213 | ||
11fdf7f2 | 214 | TEST(Log, LargeFromSmallLog) |
7c673cae FG |
215 | { |
216 | SubsystemMap subs; | |
11fdf7f2 TL |
217 | subs.set_log_level(1, 20); |
218 | subs.set_gather_level(1, 10); | |
7c673cae FG |
219 | Log log(&subs); |
220 | log.start(); | |
a8e16298 | 221 | log.set_log_file("big"); |
7c673cae | 222 | log.reopen_log_file(); |
11fdf7f2 TL |
223 | int l = 10; |
224 | { | |
225 | MutableEntry e(l, 1); | |
226 | for (int i = 0; i < 1000000; i++) { | |
227 | std::string msg(10, 'a'); | |
228 | e.get_ostream() << msg; | |
229 | } | |
230 | log.submit_entry(std::move(e)); | |
7c673cae FG |
231 | } |
232 | log.flush(); | |
233 | log.stop(); | |
234 | } | |
235 | ||
11fdf7f2 TL |
236 | // Make sure nothing bad happens when we switch |
237 | ||
238 | TEST(Log, TimeSwitch) | |
7c673cae FG |
239 | { |
240 | SubsystemMap subs; | |
11fdf7f2 TL |
241 | subs.set_log_level(1, 20); |
242 | subs.set_gather_level(1, 10); | |
7c673cae FG |
243 | Log log(&subs); |
244 | log.start(); | |
11fdf7f2 | 245 | log.set_log_file("time_switch_log"); |
7c673cae | 246 | log.reopen_log_file(); |
11fdf7f2 TL |
247 | int l = 10; |
248 | bool coarse = true; | |
249 | for (auto i = 0U; i < 300; ++i) { | |
250 | MutableEntry e(l, 1); | |
251 | e.get_ostream() << "SQUID THEFT! PUNISHABLE BY DEATH!"; | |
252 | log.submit_entry(std::move(e)); | |
253 | if (i % 50) | |
254 | log.set_coarse_timestamps(coarse = !coarse); | |
255 | } | |
256 | log.flush(); | |
257 | log.stop(); | |
258 | } | |
7c673cae | 259 | |
11fdf7f2 TL |
260 | TEST(Log, TimeFormat) |
261 | { | |
262 | static constexpr auto buflen = 128u; | |
263 | char buf[buflen]; | |
264 | ceph::logging::log_clock clock; | |
7c673cae | 265 | { |
11fdf7f2 TL |
266 | clock.coarsen(); |
267 | auto t = clock.now(); | |
268 | ceph::logging::append_time(t, buf, buflen); | |
269 | auto c = std::strrchr(buf, '.'); | |
270 | ASSERT_NE(c, nullptr); | |
9f95a23c | 271 | ASSERT_EQ(8u, strlen(c + 1)); |
11fdf7f2 TL |
272 | } |
273 | { | |
274 | clock.refine(); | |
275 | auto t = clock.now(); | |
276 | ceph::logging::append_time(t, buf, buflen); | |
277 | auto c = std::strrchr(buf, '.'); | |
278 | ASSERT_NE(c, nullptr); | |
9f95a23c | 279 | ASSERT_EQ(11u, std::strlen(c + 1)); |
7c673cae | 280 | } |
11fdf7f2 | 281 | } |
7c673cae | 282 | |
11fdf7f2 TL |
283 | #define dout_subsys ceph_subsys_context |
284 | ||
285 | template <int depth, int x> struct do_log | |
286 | { | |
287 | void log(CephContext* cct); | |
288 | }; | |
289 | ||
290 | template <int x> struct do_log<12, x> | |
291 | { | |
292 | void log(CephContext* cct); | |
293 | }; | |
294 | ||
295 | template<int depth, int x> void do_log<depth,x>::log(CephContext* cct) | |
296 | { | |
297 | ldout(cct, 20) << "Log depth=" << depth << " x=" << x << dendl; | |
298 | if (rand() % 2) { | |
299 | do_log<depth+1, x*2> log; | |
300 | log.log(cct); | |
301 | } else { | |
302 | do_log<depth+1, x*2+1> log; | |
303 | log.log(cct); | |
304 | } | |
7c673cae FG |
305 | } |
306 | ||
11fdf7f2 | 307 | std::string recursion(CephContext* cct) |
7c673cae | 308 | { |
11fdf7f2 TL |
309 | ldout(cct, 20) << "Preparing recursion string" << dendl; |
310 | return "here-recursion"; | |
7c673cae FG |
311 | } |
312 | ||
11fdf7f2 | 313 | template<int x> void do_log<12, x>::log(CephContext* cct) |
7c673cae | 314 | { |
11fdf7f2 TL |
315 | if ((rand() % 16) == 0) { |
316 | ldout(cct, 20) << "End " << recursion(cct) << "x=" << x << dendl; | |
317 | } else { | |
318 | ldout(cct, 20) << "End x=" << x << dendl; | |
319 | } | |
320 | } | |
321 | ||
322 | TEST(Log, Speed_gather) | |
323 | { | |
324 | do_log<0,0> start; | |
325 | g_ceph_context->_conf->subsys.set_gather_level(ceph_subsys_context, 30); | |
326 | g_ceph_context->_conf->subsys.set_log_level(ceph_subsys_context, 0); | |
327 | for (int i=0; i<100000;i++) { | |
328 | ldout(g_ceph_context, 20) << "Iteration " << i << dendl; | |
329 | start.log(g_ceph_context); | |
330 | } | |
331 | } | |
332 | ||
333 | TEST(Log, Speed_nogather) | |
334 | { | |
335 | do_log<0,0> start; | |
336 | g_ceph_context->_conf->subsys.set_gather_level(ceph_subsys_context, 0); | |
337 | g_ceph_context->_conf->subsys.set_log_level(ceph_subsys_context, 0); | |
338 | for (int i=0; i<100000;i++) { | |
339 | ldout(g_ceph_context, 20) << "Iteration " << i << dendl; | |
340 | start.log(g_ceph_context); | |
341 | } | |
342 | } | |
343 | ||
344 | TEST(Log, GarbleRecovery) | |
345 | { | |
346 | static const char* test_file="log_for_moment"; | |
347 | ||
348 | Log* saved = g_ceph_context->_log; | |
349 | Log log(&g_ceph_context->_conf->subsys); | |
7c673cae | 350 | log.start(); |
11fdf7f2 TL |
351 | unlink(test_file); |
352 | log.set_log_file(test_file); | |
7c673cae | 353 | log.reopen_log_file(); |
11fdf7f2 | 354 | g_ceph_context->_log = &log; |
7c673cae | 355 | |
11fdf7f2 TL |
356 | std::string long_message(1000,'c'); |
357 | ldout(g_ceph_context, 0) << long_message << dendl; | |
358 | ldout(g_ceph_context, 0) << "Prologue" << (std::streambuf*)nullptr << long_message << dendl; | |
359 | ldout(g_ceph_context, 0) << "Epitaph" << long_message << dendl; | |
360 | ||
361 | g_ceph_context->_log = saved; | |
7c673cae FG |
362 | log.flush(); |
363 | log.stop(); | |
11fdf7f2 | 364 | struct stat file_status; |
f67539c2 | 365 | ASSERT_EQ(stat(test_file, &file_status), 0); |
11fdf7f2 TL |
366 | ASSERT_GT(file_status.st_size, 2000); |
367 | } | |
368 | ||
369 | int main(int argc, char **argv) | |
370 | { | |
371 | vector<const char*> args; | |
372 | argv_to_vec(argc, (const char **)argv, args); | |
373 | ||
374 | auto cct = global_init(NULL, args, CEPH_ENTITY_TYPE_CLIENT, | |
375 | CODE_ENVIRONMENT_UTILITY, | |
376 | CINIT_FLAG_NO_DEFAULT_CONFIG_FILE); | |
377 | common_init_finish(g_ceph_context); | |
378 | ||
379 | ::testing::InitGoogleTest(&argc, argv); | |
380 | return RUN_ALL_TESTS(); | |
7c673cae | 381 | } |