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