ceph/src/log/test.cc

   1 #include <gtest/gtest.h>
   2
   3 #include "log/Log.h"
   4 #include "common/Clock.h"
   5 #include "include/coredumpctl.h"
   6 #include "SubsystemMap.h"
   7
   8 #include "global/global_init.h"
   9 #include "common/ceph_argparse.h"
  10 #include "global/global_context.h"
  11 #include "common/dout.h"
  12
  13 #include <unistd.h>
  14
  15 #include <limits.h>
  16
  17 using namespace std;
  18 using namespace ceph::logging;
  19
  20 TEST(Log, Simple)
  21 {
  22   SubsystemMap subs;
  23   subs.set_log_level(0, 10);
  24   subs.set_gather_level(0, 10);
  25
  26   subs.set_log_level(1, 20);
  27   subs.set_gather_level(1, 1);
  28
  29   subs.set_log_level(2, 20);
  30   subs.set_gather_level(2, 2);
  31
  32   subs.set_log_level(3, 10);
  33   subs.set_gather_level(3, 3);
  34
  35   Log log(&subs);
  36   log.start();
  37
  38   log.set_log_file("foo");
  39   log.reopen_log_file();
  40
  41   log.set_stderr_level(5, -1);
  42
  43
  44   for (int i=0; i<100; i++) {
  45     int sys = i % 4;
  46     int l = 5 + (i%4);
  47     if (subs.should_gather(sys, l)) {
  48       MutableEntry e(l, sys);
  49       log.submit_entry(std::move(e));
  50     }
  51   }
  52
  53   log.flush();
  54
  55   log.dump_recent();
  56
  57   log.stop();
  58 }
  59
  60 TEST(Log, ReuseBad)
  61 {
  62   SubsystemMap subs;
  63   subs.set_log_level(1, 1);
  64   subs.set_gather_level(1, 1);
  65   Log log(&subs);
  66   log.start();
  67   log.set_log_file("foo");
  68   log.reopen_log_file();
  69
  70   const int l = 0;
  71   {
  72     MutableEntry e(l, 1);
  73     auto& out = e.get_ostream();
  74     out << (std::streambuf*)nullptr;
  75     EXPECT_TRUE(out.bad()); // writing nullptr to a stream sets its badbit
  76     log.submit_entry(std::move(e));
  77   }
  78   {
  79     MutableEntry e(l, 1);
  80     auto& out = e.get_ostream();
  81     EXPECT_FALSE(out.bad()); // should not see failures from previous log entry
  82     out << "hello world";
  83     log.submit_entry(std::move(e));
  84   }
  85
  86   log.flush();
  87   log.stop();
  88 }
  89
  90 int many = 10000;
  91
  92 TEST(Log, ManyNoGather)
  93 {
  94   SubsystemMap subs;
  95   subs.set_log_level(1, 1);
  96   subs.set_gather_level(1, 1);
  97   Log log(&subs);
  98   log.start();
  99   log.set_log_file("big");
 100   log.reopen_log_file();
 101   for (int i=0; i<many; i++) {
 102     int l = 10;
 103     if (subs.should_gather(1, l))
 104       log.submit_entry(MutableEntry(1, 0));
 105   }
 106   log.flush();
 107   log.stop();
 108 }
 109
 110
 111 TEST(Log, ManyGatherLog)
 112 {
 113   SubsystemMap subs;
 114   subs.set_log_level(1, 20);
 115   subs.set_gather_level(1, 10);
 116   Log log(&subs);
 117   log.start();
 118   log.set_log_file("big");
 119   log.reopen_log_file();
 120   for (int i=0; i<many; i++) {
 121     int l = 10;
 122     if (subs.should_gather(1, l)) {
 123       MutableEntry e(l, 1);
 124       e.get_ostream() << "this is a long string asdf asdf asdf asdf asdf asdf asd fasd fasdf ";
 125       log.submit_entry(std::move(e));
 126     }
 127   }
 128   log.flush();
 129   log.stop();
 130 }
 131
 132 TEST(Log, ManyGatherLogStackSpillover)
 133 {
 134   SubsystemMap subs;
 135   subs.set_log_level(1, 20);
 136   subs.set_gather_level(1, 10);
 137   Log log(&subs);
 138   log.start();
 139   log.set_log_file("big");
 140   log.reopen_log_file();
 141   for (int i=0; i<many; i++) {
 142     int l = 10;
 143     if (subs.should_gather(1, l)) {
 144       MutableEntry e(l, 1);
 145       auto& s = e.get_ostream();
 146       s << "foo";
 147       s << std::string(sizeof(e) * 2, '-');
 148       log.submit_entry(std::move(e));
 149     }
 150   }
 151   log.flush();
 152   log.stop();
 153 }
 154
 155 TEST(Log, ManyGather)
 156 {
 157   SubsystemMap subs;
 158   subs.set_log_level(1, 20);
 159   subs.set_gather_level(1, 1);
 160   Log log(&subs);
 161   log.start();
 162   log.set_log_file("big");
 163   log.reopen_log_file();
 164   for (int i=0; i<many; i++) {
 165     int l = 10;
 166     if (subs.should_gather(1, l))
 167       log.submit_entry(MutableEntry(l, 1));
 168   }
 169   log.flush();
 170   log.stop();
 171 }
 172
 173 static void readpipe(int fd, int verify)
 174 {
 175   while (1) {
 176     /* Use larger buffer on receiver as Linux will allow pipes buffers to
 177      * exceed PIPE_BUF. We can't avoid tearing due to small read buffers from
 178      * the Ceph side.
 179      */
 180
 181     char buf[65536] = "";
 182     int rc = read(fd, buf, (sizeof buf) - 1);
 183     if (rc == 0) {
 184       _exit(0);
 185     } else if (rc == -1) {
 186       _exit(1);
 187     } else if (rc > 0) {
 188       if (verify) {
 189         char* p = strrchr(buf, '\n');
 190         /* verify no torn writes */
 191         if (p == NULL) {
 192           _exit(2);
 193         } else if (p[1] != '\0') {
 194           write(2, buf, strlen(buf));
 195           _exit(3);
 196         }
 197       }
 198     } else _exit(100);
 199     usleep(500);
 200   }
 201 }
 202
 203 TEST(Log, StderrPipeAtomic)
 204 {
 205   int pfd[2] = {-1, -1};
 206   int rc = pipe(pfd);
 207   ASSERT_EQ(rc, 0);
 208   pid_t pid = fork();
 209   if (pid == 0) {
 210     close(pfd[1]);
 211     readpipe(pfd[0], 1);
 212   } else if (pid == (pid_t)-1) {
 213     ASSERT_EQ(0, 1);
 214   }
 215   close(pfd[0]);
 216
 217   SubsystemMap subs;
 218   subs.set_log_level(1, 20);
 219   subs.set_gather_level(1, 10);
 220   Log log(&subs);
 221   log.start();
 222   log.set_log_file("");
 223   log.reopen_log_file();
 224   log.set_stderr_fd(pfd[1]);
 225   log.set_stderr_level(1, 20);
 226   /* -128 for prefix space */
 227   for (int i = 0; i < PIPE_BUF-128; i++) {
 228     MutableEntry e(1, 1);
 229     auto& s = e.get_ostream();
 230     for (int j = 0; j < i; j++) {
 231       char c = 'a';
 232       c += (j % 26);
 233       s << c;
 234     }
 235     log.submit_entry(std::move(e));
 236   }
 237   log.flush();
 238   log.stop();
 239   close(pfd[1]);
 240   int status;
 241   pid_t waited = waitpid(pid, &status, 0);
 242   ASSERT_EQ(pid, waited);
 243   ASSERT_NE(WIFEXITED(status), 0);
 244   ASSERT_EQ(WEXITSTATUS(status), 0);
 245 }
 246
 247 TEST(Log, StderrPipeBig)
 248 {
 249   int pfd[2] = {-1, -1};
 250   int rc = pipe(pfd);
 251   ASSERT_EQ(rc, 0);
 252   pid_t pid = fork();
 253   if (pid == 0) {
 254     /* no verification as some reads will be torn due to size > PIPE_BUF */
 255     close(pfd[1]);
 256     readpipe(pfd[0], 0);
 257   } else if (pid == (pid_t)-1) {
 258     ASSERT_EQ(0, 1);
 259   }
 260   close(pfd[0]);
 261
 262   SubsystemMap subs;
 263   subs.set_log_level(1, 20);
 264   subs.set_gather_level(1, 10);
 265   Log log(&subs);
 266   log.start();
 267   log.set_log_file("");
 268   log.reopen_log_file();
 269   log.set_stderr_fd(pfd[1]);
 270   log.set_stderr_level(1, 20);
 271   /* -128 for prefix space */
 272   for (int i = 0; i < PIPE_BUF*2; i++) {
 273     MutableEntry e(1, 1);
 274     auto& s = e.get_ostream();
 275     for (int j = 0; j < i; j++) {
 276       char c = 'a';
 277       c += (j % 26);
 278       s << c;
 279     }
 280     log.submit_entry(std::move(e));
 281   }
 282   log.flush();
 283   log.stop();
 284   close(pfd[1]);
 285   int status;
 286   pid_t waited = waitpid(pid, &status, 0);
 287   ASSERT_EQ(pid, waited);
 288   ASSERT_NE(WIFEXITED(status), 0);
 289   ASSERT_EQ(WEXITSTATUS(status), 0);
 290 }
 291
 292 void do_segv()
 293 {
 294   SubsystemMap subs;
 295   subs.set_log_level(1, 20);
 296   subs.set_gather_level(1, 1);
 297   Log log(&subs);
 298   log.start();
 299   log.set_log_file("big");
 300   log.reopen_log_file();
 301
 302   log.inject_segv();
 303   MutableEntry e(10, 1);
 304   {
 305     PrCtl unset_dumpable;
 306     log.submit_entry(std::move(e));  // this should segv
 307   }
 308
 309   log.flush();
 310   log.stop();
 311 }
 312
 313 TEST(Log, InternalSegv)
 314 {
 315   ASSERT_DEATH(do_segv(), ".*");
 316 }
 317
 318 TEST(Log, LargeLog)
 319 {
 320   SubsystemMap subs;
 321   subs.set_log_level(1, 20);
 322   subs.set_gather_level(1, 10);
 323   Log log(&subs);
 324   log.start();
 325   log.set_log_file("big");
 326   log.reopen_log_file();
 327   int l = 10;
 328   {
 329     MutableEntry e(l, 1);
 330     std::string msg(10000000, 'a');
 331     e.get_ostream() << msg;
 332     log.submit_entry(std::move(e));
 333   }
 334   log.flush();
 335   log.stop();
 336 }
 337
 338 TEST(Log, LargeFromSmallLog)
 339 {
 340   SubsystemMap subs;
 341   subs.set_log_level(1, 20);
 342   subs.set_gather_level(1, 10);
 343   Log log(&subs);
 344   log.start();
 345   log.set_log_file("big");
 346   log.reopen_log_file();
 347   int l = 10;
 348   {
 349     MutableEntry e(l, 1);
 350     for (int i = 0; i < 1000000; i++) {
 351       std::string msg(10, 'a');
 352       e.get_ostream() << msg;
 353     }
 354     log.submit_entry(std::move(e));
 355   }
 356   log.flush();
 357   log.stop();
 358 }
 359
 360 // Make sure nothing bad happens when we switch
 361
 362 TEST(Log, TimeSwitch)
 363 {
 364   SubsystemMap subs;
 365   subs.set_log_level(1, 20);
 366   subs.set_gather_level(1, 10);
 367   Log log(&subs);
 368   log.start();
 369   log.set_log_file("time_switch_log");
 370   log.reopen_log_file();
 371   int l = 10;
 372   bool coarse = true;
 373   for (auto i = 0U; i < 300; ++i) {
 374     MutableEntry e(l, 1);
 375     e.get_ostream() << "SQUID THEFT! PUNISHABLE BY DEATH!";
 376     log.submit_entry(std::move(e));
 377     if (i % 50)
 378       log.set_coarse_timestamps(coarse = !coarse);
 379   }
 380   log.flush();
 381   log.stop();
 382 }
 383
 384 TEST(Log, TimeFormat)
 385 {
 386   static constexpr auto buflen = 128u;
 387   char buf[buflen];
 388   ceph::logging::log_clock clock;
 389   {
 390     clock.coarsen();
 391     auto t = clock.now();
 392     ceph::logging::append_time(t, buf, buflen);
 393     auto c = std::strrchr(buf, '.');
 394     ASSERT_NE(c, nullptr);
 395     ASSERT_EQ(8u, strlen(c + 1));
 396   }
 397   {
 398     clock.refine();
 399     auto t = clock.now();
 400     ceph::logging::append_time(t, buf, buflen);
 401     auto c = std::strrchr(buf, '.');
 402     ASSERT_NE(c, nullptr);
 403     ASSERT_EQ(11u, std::strlen(c + 1));
 404   }
 405 }
 406
 407 #define dout_subsys ceph_subsys_context
 408
 409 template <int depth, int x> struct do_log
 410 {
 411   void log(CephContext* cct);
 412 };
 413
 414 template <int x> struct do_log<12, x>
 415 {
 416   void log(CephContext* cct);
 417 };
 418
 419 template<int depth, int x> void do_log<depth,x>::log(CephContext* cct)
 420 {
 421   ldout(cct, 20) << "Log depth=" << depth << " x=" << x << dendl;
 422   if (rand() % 2) {
 423     do_log<depth+1, x*2> log;
 424     log.log(cct);
 425   } else {
 426     do_log<depth+1, x*2+1> log;
 427     log.log(cct);
 428   }
 429 }
 430
 431 std::string recursion(CephContext* cct)
 432 {
 433   ldout(cct, 20) << "Preparing recursion string" << dendl;
 434   return "here-recursion";
 435 }
 436
 437 template<int x> void do_log<12, x>::log(CephContext* cct)
 438 {
 439   if ((rand() % 16) == 0) {
 440     ldout(cct, 20) << "End " << recursion(cct) << "x=" << x << dendl;
 441   } else {
 442     ldout(cct, 20) << "End x=" << x << dendl;
 443   }
 444 }
 445
 446 TEST(Log, Speed_gather)
 447 {
 448   do_log<0,0> start;
 449   g_ceph_context->_conf->subsys.set_gather_level(ceph_subsys_context, 30);
 450   g_ceph_context->_conf->subsys.set_log_level(ceph_subsys_context, 0);
 451   for (int i=0; i<100000;i++) {
 452     ldout(g_ceph_context, 20) << "Iteration " << i << dendl;
 453     start.log(g_ceph_context);
 454   }
 455 }
 456
 457 TEST(Log, Speed_nogather)
 458 {
 459   do_log<0,0> start;
 460   g_ceph_context->_conf->subsys.set_gather_level(ceph_subsys_context, 0);
 461   g_ceph_context->_conf->subsys.set_log_level(ceph_subsys_context, 0);
 462   for (int i=0; i<100000;i++) {
 463     ldout(g_ceph_context, 20) << "Iteration " << i << dendl;
 464     start.log(g_ceph_context);
 465   }
 466 }
 467
 468 TEST(Log, GarbleRecovery)
 469 {
 470   static const char* test_file="log_for_moment";
 471
 472   Log* saved = g_ceph_context->_log;
 473   Log log(&g_ceph_context->_conf->subsys);
 474   log.start();
 475   unlink(test_file);
 476   log.set_log_file(test_file);
 477   log.reopen_log_file();
 478   g_ceph_context->_log = &log;
 479
 480   std::string long_message(1000,'c');
 481   ldout(g_ceph_context, 0) << long_message << dendl;
 482   ldout(g_ceph_context, 0) << "Prologue" << (std::streambuf*)nullptr << long_message << dendl;
 483   ldout(g_ceph_context, 0) << "Epitaph" << long_message << dendl;
 484
 485   g_ceph_context->_log = saved;
 486   log.flush();
 487   log.stop();
 488   struct stat file_status;
 489   ASSERT_EQ(stat(test_file, &file_status), 0);
 490   ASSERT_GT(file_status.st_size, 2000);
 491 }
 492
 493 int main(int argc, char **argv)
 494 {
 495   auto args = argv_to_vec(argc, argv);
 496
 497   auto cct = global_init(nullptr, args, CEPH_ENTITY_TYPE_CLIENT,
 498                          CODE_ENVIRONMENT_UTILITY,
 499                          CINIT_FLAG_NO_DEFAULT_CONFIG_FILE);
 500   common_init_finish(g_ceph_context);
 501
 502   ::testing::InitGoogleTest(&argc, argv);
 503   return RUN_ALL_TESTS();
 504 }