src/logging_unittest.cc

   1 //
   2 // Copyright 2002 Google, Inc.
   3 // All Rights Reserved.
   4 //
   5 // Author: Ray Sidney
   6
   7 #include "utilities.h"
   8
   9 #include <fcntl.h>
  10 #include <glob.h>
  11 #include <sys/stat.h>
  12 #include <unistd.h>
  13
  14 #include <iomanip>
  15 #include <iostream>
  16 #include <queue>
  17 #include <sstream>
  18 #include <string>
  19 #include <vector>
  20
  21 #include "base/commandlineflags.h"
  22 #include "glog/logging.h"
  23 #include "glog/raw_logging.h"
  24 #include "googletest.h"
  25
  26 using namespace std;
  27 using namespace GOOGLE_NAMESPACE;
  28
  29 static void TestLogging(bool check_counts);
  30 static void TestRawLogging();
  31 static void LogWithLevels(int v, int severity, bool err, bool alsoerr);
  32 static void TestLoggingLevels();
  33 static void TestLogString();
  34 static void TestLogSink();
  35 static void TestLogSinkWaitTillSent();
  36 static void TestCHECK();
  37 static void TestDCHECK();
  38 static void TestSTREQ();
  39 static void TestBasename();
  40 static void TestSymlink();
  41 static void TestExtension();
  42 static void TestWrapper();
  43 static void TestErrno();
  44 static void TestTruncate();
  45
  46 static int x = -1;
  47 static void BM_Check1(int n) {
  48   while (n-- > 0) {
  49     CHECK_GE(n, x);
  50     CHECK_GE(n, x);
  51     CHECK_GE(n, x);
  52     CHECK_GE(n, x);
  53     CHECK_GE(n, x);
  54     CHECK_GE(n, x);
  55     CHECK_GE(n, x);
  56     CHECK_GE(n, x);
  57   }
  58 }
  59 BENCHMARK(BM_Check1);
  60
  61 static void CheckFailure(int a, int b, const char* file, int line, const char* msg);
  62 static void BM_Check3(int n) {
  63   while (n-- > 0) {
  64     if (n < x) CheckFailure(n, x, __FILE__, __LINE__, "n < x");
  65     if (n < x) CheckFailure(n, x, __FILE__, __LINE__, "n < x");
  66     if (n < x) CheckFailure(n, x, __FILE__, __LINE__, "n < x");
  67     if (n < x) CheckFailure(n, x, __FILE__, __LINE__, "n < x");
  68     if (n < x) CheckFailure(n, x, __FILE__, __LINE__, "n < x");
  69     if (n < x) CheckFailure(n, x, __FILE__, __LINE__, "n < x");
  70     if (n < x) CheckFailure(n, x, __FILE__, __LINE__, "n < x");
  71     if (n < x) CheckFailure(n, x, __FILE__, __LINE__, "n < x");
  72   }
  73 }
  74 BENCHMARK(BM_Check3);
  75
  76 static void BM_Check2(int n) {
  77   if (n == 17) {
  78     x = 5;
  79   }
  80   while (n-- > 0) {
  81     CHECK(n >= x);
  82     CHECK(n >= x);
  83     CHECK(n >= x);
  84     CHECK(n >= x);
  85     CHECK(n >= x);
  86     CHECK(n >= x);
  87     CHECK(n >= x);
  88     CHECK(n >= x);
  89   }
  90 }
  91 BENCHMARK(BM_Check2);
  92
  93 static void CheckFailure(int a, int b, const char* file, int line, const char* msg) {
  94 }
  95
  96 int main(int argc, char **argv) {
  97   // Test some basics before InitGoogleLogging:
  98   CaptureTestStderr();
  99   LogWithLevels(FLAGS_v, FLAGS_stderrthreshold,
 100                 FLAGS_logtostderr, FLAGS_alsologtostderr);
 101   LogWithLevels(0, 0, 0, 0);  // simulate "before global c-tors"
 102   const string early_stderr = GetCapturedTestStderr();
 103
 104   FLAGS_logtostderr = true;
 105
 106   InitGoogleLogging(argv[0]);
 107
 108   RunSpecifiedBenchmarks();
 109
 110   // so that death tests run before we use threads
 111   CHECK_EQ(RUN_ALL_TESTS(), 0);
 112
 113   CaptureTestStderr();
 114
 115   // re-emit early_stderr
 116   LogMessage("dummy", LogMessage::kNoLogPrefix, INFO).stream() << early_stderr;
 117
 118   TestLogging(true);
 119   TestRawLogging();
 120   TestLoggingLevels();
 121   TestLogString();
 122   TestLogSink();
 123   TestLogSinkWaitTillSent();
 124   TestCHECK();
 125   TestDCHECK();
 126   TestSTREQ();
 127
 128   // TODO: The golden test portion of this test is very flakey.
 129   EXPECT_TRUE(
 130       MungeAndDiffTestStderr(FLAGS_test_srcdir + "/src/logging_unittest.err"));
 131
 132   FLAGS_logtostderr = false;
 133
 134   TestBasename();
 135   TestSymlink();
 136   TestExtension();
 137   TestWrapper();
 138   TestErrno();
 139   TestTruncate();
 140
 141   LOG(INFO) << "PASS";
 142   return 0;
 143 }
 144
 145 void TestLogging(bool check_counts) {
 146   int64 base_num_infos   = LogMessage::num_messages(INFO);
 147   int64 base_num_warning = LogMessage::num_messages(WARNING);
 148   int64 base_num_errors  = LogMessage::num_messages(ERROR);
 149
 150   LOG(INFO) << string("foo ") << "bar " << 10 << ' ' << 3.4;
 151   for ( int i = 0; i < 10; ++i ) {
 152     int old_errno = errno;
 153     errno = i;
 154     PLOG_EVERY_N(ERROR, 2) << "Plog every 2, iteration " << COUNTER;
 155     errno = old_errno;
 156
 157     LOG_EVERY_N(ERROR, 3) << "Log every 3, iteration " << COUNTER << endl;
 158     LOG_EVERY_N(ERROR, 4) << "Log every 4, iteration " << COUNTER << endl;
 159
 160     LOG_IF_EVERY_N(WARNING, true, 5) << "Log if every 5, iteration " << COUNTER;
 161     LOG_IF_EVERY_N(WARNING, false, 3)
 162         << "Log if every 3, iteration " << COUNTER;
 163     LOG_IF_EVERY_N(INFO, true, 1) << "Log if every 1, iteration " << COUNTER;
 164     LOG_IF_EVERY_N(ERROR, (i < 3), 2)
 165         << "Log if less than 3 every 2, iteration " << COUNTER;
 166   }
 167   LOG_IF(WARNING, true) << "log_if this";
 168   LOG_IF(WARNING, false) << "don't log_if this";
 169
 170   char s[] = "array";
 171   LOG(INFO) << s;
 172   const char const_s[] = "const array";
 173   LOG(INFO) << const_s;
 174   int j = 1000;
 175   LOG(ERROR) << string("foo") << ' '<< j << ' ' << setw(10) << j << " "
 176              << setw(1) << hex << j;
 177
 178   LogMessage("foo", LogMessage::kNoLogPrefix, INFO).stream() << "no prefix";
 179
 180   if (check_counts) {
 181     CHECK_EQ(base_num_infos   + 14, LogMessage::num_messages(INFO));
 182     CHECK_EQ(base_num_warning + 3,  LogMessage::num_messages(WARNING));
 183     CHECK_EQ(base_num_errors  + 15, LogMessage::num_messages(ERROR));
 184   }
 185 }
 186
 187 static void NoAllocNewHook() {
 188   CHECK(false) << "unexpected new";
 189 }
 190
 191 struct NewHook {
 192   NewHook() {
 193     g_new_hook = &NoAllocNewHook;
 194   }
 195   ~NewHook() {
 196     g_new_hook = NULL;
 197   }
 198 };
 199
 200 TEST(DeathNoAllocNewHook, logging) {
 201   // tests that NewHook used below works
 202   NewHook new_hook;
 203   ASSERT_DEATH({
 204     new int;
 205   }, "unexpected new");
 206 }
 207
 208 void TestRawLogging() {
 209   string* foo = new string("foo ");
 210   string huge_str(50000, 'a');
 211
 212   FlagSaver saver;
 213
 214   // Check that RAW loggging does not use mallocs.
 215   NewHook new_hook;
 216
 217   RAW_LOG(INFO, "%s%s%d%c%f", foo->c_str(), "bar ", 10, ' ', 3.4);
 218   char s[] = "array";
 219   RAW_LOG(WARNING, "%s", s);
 220   const char const_s[] = "const array";
 221   RAW_LOG(INFO, "%s", const_s);
 222   void* p = reinterpret_cast<void*>(0x12345678);
 223   RAW_LOG(INFO, "ptr %p", p);
 224   p = NULL;
 225   RAW_LOG(INFO, "ptr %p", p);
 226   int j = 1000;
 227   RAW_LOG(ERROR, "%s%d%c%010d%s%1x", foo->c_str(), j, ' ', j, " ", j);
 228   RAW_VLOG(0, "foo %d", j);
 229
 230 #ifdef NDEBUG
 231   RAW_LOG(INFO, "foo %d", j);  // so that have same stderr to compare
 232 #else
 233   RAW_DLOG(INFO, "foo %d", j);  // test RAW_DLOG in debug mode
 234 #endif
 235
 236   // test how long messages are chopped:
 237   RAW_LOG(WARNING, "Huge string: %s", huge_str.c_str());
 238   RAW_VLOG(0, "Huge string: %s", huge_str.c_str());
 239
 240   FLAGS_v = 0;
 241   RAW_LOG(INFO, "log");
 242   RAW_VLOG(0, "vlog 0 on");
 243   RAW_VLOG(1, "vlog 1 off");
 244   RAW_VLOG(2, "vlog 2 off");
 245   RAW_VLOG(3, "vlog 3 off");
 246   FLAGS_v = 2;
 247   RAW_LOG(INFO, "log");
 248   RAW_VLOG(1, "vlog 1 on");
 249   RAW_VLOG(2, "vlog 2 on");
 250   RAW_VLOG(3, "vlog 3 off");
 251
 252 #ifdef NDEBUG
 253   RAW_DCHECK(1 == 2, " RAW_DCHECK's shouldn't be compiled in normal mode");
 254 #endif
 255
 256   RAW_CHECK(1 == 1, "should be ok");
 257   RAW_DCHECK(true, "should be ok");
 258
 259   delete foo;
 260 }
 261
 262 void LogWithLevels(int v, int severity, bool err, bool alsoerr) {
 263   RAW_LOG(INFO,
 264           "Test: v=%d stderrthreshold=%d logtostderr=%d alsologtostderr=%d",
 265           v, severity, err, alsoerr);
 266
 267   FlagSaver saver;
 268
 269   FLAGS_v = v;
 270   FLAGS_stderrthreshold = severity;
 271   FLAGS_logtostderr = err;
 272   FLAGS_alsologtostderr = alsoerr;
 273
 274   RAW_VLOG(-1, "vlog -1");
 275   RAW_VLOG(0, "vlog 0");
 276   RAW_VLOG(1, "vlog 1");
 277   RAW_LOG(INFO, "log info");
 278   RAW_LOG(WARNING, "log warning");
 279   RAW_LOG(ERROR, "log error");
 280
 281   VLOG(-1) << "vlog -1";
 282   VLOG(0) << "vlog 0";
 283   VLOG(1) << "vlog 1";
 284   LOG(INFO) << "log info";
 285   LOG(WARNING) << "log warning";
 286   LOG(ERROR) << "log error";
 287
 288   VLOG_IF(-1, true) << "vlog_if -1";
 289   VLOG_IF(-1, false) << "don't vlog_if -1";
 290   VLOG_IF(0, true) << "vlog_if 0";
 291   VLOG_IF(0, false) << "don't vlog_if 0";
 292   VLOG_IF(1, true) << "vlog_if 1";
 293   VLOG_IF(1, false) << "don't vlog_if 1";
 294   LOG_IF(INFO, true) << "log_if info";
 295   LOG_IF(INFO, false) << "don't log_if info";
 296   LOG_IF(WARNING, true) << "log_if warning";
 297   LOG_IF(WARNING, false) << "don't log_if warning";
 298   LOG_IF(ERROR, true) << "log_if error";
 299   LOG_IF(ERROR, false) << "don't log_if error";
 300
 301   int c;
 302   c = 1; VLOG_IF(100, c -= 2) << "vlog_if 100 expr"; EXPECT_EQ(c, -1);
 303   c = 1; VLOG_IF(0, c -= 2) << "vlog_if 0 expr"; EXPECT_EQ(c, -1);
 304   c = 1; LOG_IF(INFO, c -= 2) << "log_if info expr"; EXPECT_EQ(c, -1);
 305   c = 1; LOG_IF(ERROR, c -= 2) << "log_if error expr"; EXPECT_EQ(c, -1);
 306   c = 2; VLOG_IF(0, c -= 2) << "don't vlog_if 0 expr"; EXPECT_EQ(c, 0);
 307   c = 2; LOG_IF(ERROR, c -= 2) << "don't log_if error expr"; EXPECT_EQ(c, 0);
 308
 309   c = 3; LOG_IF_EVERY_N(INFO, c -= 4, 1) << "log_if info every 1 expr";
 310   EXPECT_EQ(c, -1);
 311   c = 3; LOG_IF_EVERY_N(ERROR, c -= 4, 1) << "log_if error every 1 expr";
 312   EXPECT_EQ(c, -1);
 313   c = 4; LOG_IF_EVERY_N(ERROR, c -= 4, 3) << "don't log_if info every 3 expr";
 314   EXPECT_EQ(c, 0);
 315   c = 4; LOG_IF_EVERY_N(ERROR, c -= 4, 3) << "don't log_if error every 3 expr";
 316   EXPECT_EQ(c, 0);
 317   c = 5; VLOG_IF_EVERY_N(0, c -= 4, 1) << "vlog_if 0 every 1 expr";
 318   EXPECT_EQ(c, 1);
 319   c = 5; VLOG_IF_EVERY_N(100, c -= 4, 3) << "vlog_if 100 every 3 expr";
 320   EXPECT_EQ(c, 1);
 321   c = 6; VLOG_IF_EVERY_N(0, c -= 6, 1) << "don't vlog_if 0 every 1 expr";
 322   EXPECT_EQ(c, 0);
 323   c = 6; VLOG_IF_EVERY_N(100, c -= 6, 3) << "don't vlog_if 100 every 1 expr";
 324   EXPECT_EQ(c, 0);
 325 }
 326
 327 void TestLoggingLevels() {
 328   LogWithLevels(0, INFO, false, false);
 329   LogWithLevels(1, INFO, false, false);
 330   LogWithLevels(-1, INFO, false, false);
 331   LogWithLevels(0, WARNING, false, false);
 332   LogWithLevels(0, ERROR, false, false);
 333   LogWithLevels(0, FATAL, false, false);
 334   LogWithLevels(0, FATAL, true, false);
 335   LogWithLevels(0, FATAL, false, true);
 336   LogWithLevels(1, WARNING, false, false);
 337   LogWithLevels(1, FATAL, false, true);
 338 }
 339
 340 TEST(DeathRawCHECK, logging) {
 341   ASSERT_DEATH(RAW_CHECK(false, "failure 1"),
 342                "RAW: Check false failed: failure 1");
 343   ASSERT_DEBUG_DEATH(RAW_DCHECK(1 == 2, "failure 2"),
 344                "RAW: Check 1 == 2 failed: failure 2");
 345 }
 346
 347 void TestLogString() {
 348   vector<string> errors;
 349   vector<string> *no_errors = NULL;
 350
 351   LOG_STRING(INFO, &errors) << "LOG_STRING: " << "collected info";
 352   LOG_STRING(WARNING, &errors) << "LOG_STRING: " << "collected warning";
 353   LOG_STRING(ERROR, &errors) << "LOG_STRING: " << "collected error";
 354
 355   LOG_STRING(INFO, no_errors) << "LOG_STRING: " << "reported info";
 356   LOG_STRING(WARNING, no_errors) << "LOG_STRING: " << "reported warning";
 357   LOG_STRING(ERROR, NULL) << "LOG_STRING: " << "reported error";
 358
 359   for (int i = 0; i < errors.size(); ++i) {
 360     LOG(INFO) << "Captured by LOG_STRING:  " << errors[i];
 361   }
 362 }
 363
 364 class TestLogSinkImpl : public LogSink {
 365  public:
 366   vector<string> errors;
 367   virtual void send(LogSeverity severity, const char* full_filename,
 368                     const char* base_filename, int line,
 369                     const struct tm* tm_time,
 370                     const char* message, size_t message_len) {
 371     errors.push_back(
 372       ToString(severity, base_filename, line, tm_time, message, message_len));
 373   }
 374 };
 375
 376 void TestLogSink() {
 377   TestLogSinkImpl sink;
 378   LogSink *no_sink = NULL;
 379
 380   LOG_TO_SINK(&sink, INFO) << "LOG_TO_SINK: " << "collected info";
 381   LOG_TO_SINK(&sink, WARNING) << "LOG_TO_SINK: " << "collected warning";
 382   LOG_TO_SINK(&sink, ERROR) << "LOG_TO_SINK: " << "collected error";
 383
 384   LOG_TO_SINK(no_sink, INFO) << "LOG_TO_SINK: " << "reported info";
 385   LOG_TO_SINK(no_sink, WARNING) << "LOG_TO_SINK: " << "reported warning";
 386   LOG_TO_SINK(NULL, ERROR) << "LOG_TO_SINK: " << "reported error";
 387
 388   LOG(INFO) << "Captured by LOG_TO_SINK:";
 389   for (int i = 0; i < sink.errors.size(); ++i) {
 390     LogMessage("foo", LogMessage::kNoLogPrefix, INFO).stream()
 391       << sink.errors[i];
 392   }
 393 }
 394
 395 // For testing using CHECK*() on anonymous enums.
 396 enum {
 397   CASE_A,
 398   CASE_B
 399 };
 400
 401 void TestCHECK() {
 402   // Tests using CHECK*() on int values.
 403   CHECK(1 == 1);
 404   CHECK_EQ(1, 1);
 405   CHECK_NE(1, 2);
 406   CHECK_GE(1, 1);
 407   CHECK_GE(2, 1);
 408   CHECK_LE(1, 1);
 409   CHECK_LE(1, 2);
 410   CHECK_GT(2, 1);
 411   CHECK_LT(1, 2);
 412
 413   // Tests using CHECK*() on anonymous enums.
 414   // Apple's GCC doesn't like this.
 415 #if !defined(OS_MACOSX)
 416   CHECK_EQ(CASE_A, CASE_A);
 417   CHECK_NE(CASE_A, CASE_B);
 418   CHECK_GE(CASE_A, CASE_A);
 419   CHECK_GE(CASE_B, CASE_A);
 420   CHECK_LE(CASE_A, CASE_A);
 421   CHECK_LE(CASE_A, CASE_B);
 422   CHECK_GT(CASE_B, CASE_A);
 423   CHECK_LT(CASE_A, CASE_B);
 424 #endif
 425 }
 426
 427 void TestDCHECK() {
 428 #ifdef NDEBUG
 429   DCHECK( 1 == 2 ) << " DCHECK's shouldn't be compiled in normal mode";
 430 #endif
 431   DCHECK( 1 == 1 );
 432   DCHECK_EQ(1, 1);
 433   DCHECK_NE(1, 2);
 434   DCHECK_GE(1, 1);
 435   DCHECK_GE(2, 1);
 436   DCHECK_LE(1, 1);
 437   DCHECK_LE(1, 2);
 438   DCHECK_GT(2, 1);
 439   DCHECK_LT(1, 2);
 440 }
 441
 442 void TestSTREQ() {
 443   CHECK_STREQ("this", "this");
 444   CHECK_STREQ(NULL, NULL);
 445   CHECK_STRCASEEQ("this", "tHiS");
 446   CHECK_STRCASEEQ(NULL, NULL);
 447   CHECK_STRNE("this", "tHiS");
 448   CHECK_STRNE("this", NULL);
 449   CHECK_STRCASENE("this", "that");
 450   CHECK_STRCASENE(NULL, "that");
 451   CHECK_STREQ((string("a")+"b").c_str(), "ab");
 452   CHECK_STREQ(string("test").c_str(),
 453               (string("te") + string("st")).c_str());
 454 }
 455
 456 TEST(DeathSTREQ, logging) {
 457   ASSERT_DEATH(CHECK_STREQ(NULL, "this"), "");
 458   ASSERT_DEATH(CHECK_STREQ("this", "siht"), "");
 459   ASSERT_DEATH(CHECK_STRCASEEQ(NULL, "siht"), "");
 460   ASSERT_DEATH(CHECK_STRCASEEQ("this", "siht"), "");
 461   ASSERT_DEATH(CHECK_STRNE(NULL, NULL), "");
 462   ASSERT_DEATH(CHECK_STRNE("this", "this"), "");
 463   ASSERT_DEATH(CHECK_STREQ((string("a")+"b").c_str(), "abc"), "");
 464 }
 465
 466 TEST(CheckNOTNULL, Simple) {
 467   int64 t;
 468   void *ptr = static_cast<void *>(&t);
 469   void *ref = CHECK_NOTNULL(ptr);
 470   EXPECT_EQ(ptr, ref);
 471   CHECK_NOTNULL(reinterpret_cast<char *>(&t));
 472   CHECK_NOTNULL(reinterpret_cast<unsigned char *>(&t));
 473   CHECK_NOTNULL(reinterpret_cast<int *>(&t));
 474   CHECK_NOTNULL(reinterpret_cast<int64 *>(&t));
 475 }
 476
 477 TEST(DeathCheckNN, Simple) {
 478   ASSERT_DEATH(CHECK_NOTNULL(static_cast<void *>(NULL)), "");
 479 }
 480
 481 // Get list of file names that match pattern
 482 static void GetFiles(const string& pattern, vector<string>* files) {
 483   files->clear();
 484   glob_t g;
 485   const int r = glob(pattern.c_str(), 0, NULL, &g);
 486   CHECK((r == 0) || (r == GLOB_NOMATCH)) << ": error matching " << pattern;
 487   for (int i = 0; i < g.gl_pathc; i++) {
 488     files->push_back(string(g.gl_pathv[i]));
 489   }
 490   globfree(&g);
 491 }
 492
 493 // Delete files patching pattern
 494 static void DeleteFiles(const string& pattern) {
 495   vector<string> files;
 496   GetFiles(pattern, &files);
 497   for (int i = 0; i < files.size(); i++) {
 498     CHECK(unlink(files[i].c_str()) == 0) << ": " << strerror(errno);
 499   }
 500 }
 501
 502 static void CheckFile(const string& name, const string& expected_string) {
 503   vector<string> files;
 504   GetFiles(name + "*", &files);
 505   CHECK_EQ(files.size(), 1);
 506
 507   FILE* file = fopen(files[0].c_str(), "r");
 508   CHECK(file != NULL) << ": could not open " << files[0];
 509   char buf[1000];
 510   while (fgets(buf, sizeof(buf), file) != NULL) {
 511     if (strstr(buf, expected_string.c_str()) != NULL) {
 512       fclose(file);
 513       return;
 514     }
 515   }
 516   fclose(file);
 517   LOG(FATAL) << "Did not find " << expected_string << " in " << files[0];
 518 }
 519
 520 static void TestBasename() {
 521   fprintf(stderr, "==== Test setting log file basename\n");
 522   string dest = FLAGS_test_tmpdir + "/logging_test_basename";
 523   DeleteFiles(dest + "*");
 524
 525   SetLogDestination(INFO, dest.c_str());
 526   LOG(INFO) << "message to new base";
 527   FlushLogFiles(INFO);
 528   CheckFile(dest, "message to new base");
 529
 530   DeleteFiles(dest + "*");
 531 }
 532
 533 static void TestSymlink() {
 534   fprintf(stderr, "==== Test setting log file symlink\n");
 535   string dest = FLAGS_test_tmpdir + "/logging_test_symlink";
 536   string sym = FLAGS_test_tmpdir + "/symlinkbase";
 537   DeleteFiles(dest + "*");
 538   DeleteFiles(sym + "*");
 539
 540   SetLogSymlink(INFO, "symlinkbase");
 541   SetLogDestination(INFO, dest.c_str());
 542   LOG(INFO) << "message to new symlink";
 543   FlushLogFiles(INFO);
 544   CheckFile(sym, "message to new symlink");
 545
 546   DeleteFiles(dest + "*");
 547   DeleteFiles(sym + "*");
 548 }
 549
 550 static void TestExtension() {
 551   fprintf(stderr, "==== Test setting log file extension\n");
 552   string dest = FLAGS_test_tmpdir + "/logging_test_extension";
 553   DeleteFiles(dest + "*");
 554
 555   SetLogDestination(INFO, dest.c_str());
 556   SetLogFilenameExtension("specialextension");
 557   LOG(INFO) << "message to new extension";
 558   FlushLogFiles(INFO);
 559   CheckFile(dest, "message to new extension");
 560
 561   // Check that file name ends with extension
 562   vector<string> filenames;
 563   GetFiles(dest + "*", &filenames);
 564   CHECK_EQ(filenames.size(), 1);
 565   CHECK(strstr(filenames[0].c_str(), "specialextension") != NULL);
 566
 567   DeleteFiles(dest + "*");
 568 }
 569
 570 struct MyLogger : public base::Logger {
 571   string data;
 572
 573   virtual void Write(bool should_flush,
 574                      time_t timestamp,
 575                      const char* message,
 576                      int length) {
 577     data.append(message, length);
 578   }
 579
 580   virtual void Flush() { }
 581
 582   virtual uint32 LogSize() { return data.length(); }
 583 };
 584
 585 static void TestWrapper() {
 586   fprintf(stderr, "==== Test log wrapper\n");
 587
 588   MyLogger my_logger;
 589   base::Logger* old_logger = base::GetLogger(INFO);
 590   base::SetLogger(INFO, &my_logger);
 591   LOG(INFO) << "Send to wrapped logger";
 592   FlushLogFiles(INFO);
 593   base::SetLogger(INFO, old_logger);
 594
 595   CHECK(strstr(my_logger.data.c_str(), "Send to wrapped logger") != NULL);
 596 }
 597
 598 static void TestErrno() {
 599   fprintf(stderr, "==== Test errno preservation\n");
 600
 601   errno = ENOENT;
 602   TestLogging(false);
 603   CHECK_EQ(errno, ENOENT);
 604 }
 605
 606 static void TestOneTruncate(const char *path, int64 limit, int64 keep,
 607                             int64 dsize, int64 ksize, int64 expect) {
 608   int fd;
 609   CHECK_ERR(fd = open(path, O_RDWR | O_CREAT | O_TRUNC, 0600));
 610
 611   const char *discardstr = "DISCARDME!", *keepstr = "KEEPME!";
 612
 613   // Fill the file with the requested data; first discard data, then kept data
 614   int64 written = 0;
 615   while (written < dsize) {
 616     int bytes = min<int64>(dsize - written, strlen(discardstr));
 617     CHECK_ERR(write(fd, discardstr, bytes));
 618     written += bytes;
 619   }
 620   written = 0;
 621   while (written < ksize) {
 622     int bytes = min<int64>(ksize - written, strlen(keepstr));
 623     CHECK_ERR(write(fd, keepstr, bytes));
 624     written += bytes;
 625   }
 626
 627   TruncateLogFile(path, limit, keep);
 628
 629   // File should now be shorter
 630   struct stat statbuf;
 631   CHECK_ERR(fstat(fd, &statbuf));
 632   CHECK_EQ(statbuf.st_size, expect);
 633   CHECK_ERR(lseek(fd, 0, SEEK_SET));
 634
 635   // File should contain the suffix of the original file
 636   char buf[statbuf.st_size + 1];
 637   memset(buf, 0, sizeof(buf));
 638   CHECK_ERR(read(fd, buf, sizeof(buf)));
 639
 640   const char *p = buf;
 641   int64 checked = 0;
 642   while (checked < expect) {
 643     int bytes = min<int64>(expect - checked, strlen(keepstr));
 644     CHECK(!memcmp(p, keepstr, bytes));
 645     checked += bytes;
 646   }
 647   close(fd);
 648 }
 649
 650 static void TestTruncate() {
 651   fprintf(stderr, "==== Test log truncation\n");
 652   string path = FLAGS_test_tmpdir + "/truncatefile";
 653
 654   // Test on a small file
 655   TestOneTruncate(path.c_str(), 10, 10, 10, 10, 10);
 656
 657   // And a big file (multiple blocks to copy)
 658   TestOneTruncate(path.c_str(), 2<<20, 4<<10, 3<<20, 4<<10, 4<<10);
 659
 660   // Check edge-case limits
 661   TestOneTruncate(path.c_str(), 10, 20, 0, 20, 20);
 662   TestOneTruncate(path.c_str(), 10, 0, 0, 0, 0);
 663   TestOneTruncate(path.c_str(), 10, 50, 0, 10, 10);
 664   TestOneTruncate(path.c_str(), 50, 100, 0, 30, 30);
 665
 666   // MacOSX 10.4 doesn't fail in this case. Let's just ignore this test.
 667 #if !defined(OS_MACOSX)
 668   // Through a symlink should fail to truncate
 669   string linkname = path + ".link";
 670   unlink(linkname.c_str());
 671   CHECK_ERR(symlink(path.c_str(), linkname.c_str()));
 672   TestOneTruncate(linkname.c_str(), 10, 10, 0, 30, 30);
 673 #endif
 674
 675   // The /proc/self path makes sense only for linux.
 676 #if defined(OS_LINUX)
 677   // Through an open fd symlink should work
 678   int fd;
 679   CHECK_ERR(fd = open(path.c_str(), O_APPEND | O_WRONLY));
 680   char fdpath[64];
 681   snprintf(fdpath, sizeof(fdpath), "/proc/self/fd/%d", fd);
 682   TestOneTruncate(fdpath, 10, 10, 10, 10, 10);
 683 #endif
 684 }
 685
 686 _START_GOOGLE_NAMESPACE_
 687 extern  // in logging.cc
 688 bool SafeFNMatch_(const char* pattern, size_t patt_len,
 689                   const char* str, size_t str_len);
 690 _END_GOOGLE_NAMESPACE_
 691
 692 static bool WrapSafeFNMatch(string pattern, string str) {
 693   pattern += "abc";
 694   str += "defgh";
 695   return SafeFNMatch_(pattern.data(), pattern.size() - 3,
 696                       str.data(), str.size() - 5);
 697 }
 698
 699 TEST(SafeFNMatch, logging) {
 700   CHECK(WrapSafeFNMatch("foo", "foo"));
 701   CHECK(!WrapSafeFNMatch("foo", "bar"));
 702   CHECK(!WrapSafeFNMatch("foo", "fo"));
 703   CHECK(!WrapSafeFNMatch("foo", "foo2"));
 704   CHECK(WrapSafeFNMatch("bar/foo.ext", "bar/foo.ext"));
 705   CHECK(WrapSafeFNMatch("*ba*r/fo*o.ext*", "bar/foo.ext"));
 706   CHECK(!WrapSafeFNMatch("bar/foo.ext", "bar/baz.ext"));
 707   CHECK(!WrapSafeFNMatch("bar/foo.ext", "bar/foo"));
 708   CHECK(!WrapSafeFNMatch("bar/foo.ext", "bar/foo.ext.zip"));
 709   CHECK(WrapSafeFNMatch("ba?/*.ext", "bar/foo.ext"));
 710   CHECK(WrapSafeFNMatch("ba?/*.ext", "baZ/FOO.ext"));
 711   CHECK(!WrapSafeFNMatch("ba?/*.ext", "barr/foo.ext"));
 712   CHECK(!WrapSafeFNMatch("ba?/*.ext", "bar/foo.ext2"));
 713   CHECK(WrapSafeFNMatch("ba?/*", "bar/foo.ext2"));
 714   CHECK(WrapSafeFNMatch("ba?/*", "bar/"));
 715   CHECK(!WrapSafeFNMatch("ba?/?", "bar/"));
 716   CHECK(!WrapSafeFNMatch("ba?/*", "bar"));
 717 }
 718
 719 // TestWaitingLogSink will save messages here
 720 // No lock: Accessed only by TestLogSinkWriter thread
 721 // and after its demise by its creator.
 722 static vector<string> global_messages;
 723
 724 // helper for TestWaitingLogSink below.
 725 // Thread that does the logic of TestWaitingLogSink
 726 // It's free to use LOG() itself.
 727 class TestLogSinkWriter : public Thread {
 728  public:
 729
 730   TestLogSinkWriter() : should_exit_(false) {
 731     SetJoinable(true);
 732     Start();
 733   }
 734
 735   // Just buffer it (can't use LOG() here).
 736   void Buffer(const string& message) {
 737     mutex_.Lock();
 738     RAW_LOG(INFO, "Buffering");
 739     messages_.push(message);
 740     mutex_.Unlock();
 741     RAW_LOG(INFO, "Buffered");
 742   }
 743
 744   // Wait for the buffer to clear (can't use LOG() here).
 745   void Wait() {
 746     RAW_LOG(INFO, "Waiting");
 747     mutex_.Lock();
 748     while (!NoWork()) {
 749       mutex_.Unlock();
 750       SleepForMilliseconds(1);
 751       mutex_.Lock();
 752     }
 753     RAW_LOG(INFO, "Waited");
 754     mutex_.Unlock();
 755   }
 756
 757   // Trigger thread exit.
 758   void Stop() {
 759     MutexLock l(&mutex_);
 760     should_exit_ = true;
 761   }
 762
 763  private:
 764
 765   // helpers ---------------
 766
 767   // For creating a "Condition".
 768   bool NoWork() { return messages_.empty(); }
 769   bool HaveWork() { return !messages_.empty() || should_exit_; }
 770
 771   // Thread body; CAN use LOG() here!
 772   virtual void Run() {
 773     while (1) {
 774       mutex_.Lock();
 775       while (!HaveWork()) {
 776         mutex_.Unlock();
 777         SleepForMilliseconds(1);
 778         mutex_.Lock();
 779       }
 780       if (should_exit_ && messages_.empty()) {
 781         mutex_.Unlock();
 782         break;
 783       }
 784       // Give the main thread time to log its message,
 785       // so that we get a reliable log capture to compare to golden file.
 786       // Same for the other sleep below.
 787       SleepForMilliseconds(20);
 788       RAW_LOG(INFO, "Sink got a messages");  // only RAW_LOG under mutex_ here
 789       string message = messages_.front();
 790       messages_.pop();
 791       // Normally this would be some more real/involved logging logic
 792       // where LOG() usage can't be eliminated,
 793       // e.g. pushing the message over with an RPC:
 794       int messages_left = messages_.size();
 795       mutex_.Unlock();
 796       SleepForMilliseconds(20);
 797       // May not use LOG while holding mutex_, because Buffer()
 798       // acquires mutex_, and Buffer is called from LOG(),
 799       // which has its own internal mutex:
 800       // LOG()->LogToSinks()->TestWaitingLogSink::send()->Buffer()
 801       LOG(INFO) << "Sink is sending out a message: " << message;
 802       LOG(INFO) << "Have " << messages_left << " left";
 803       global_messages.push_back(message);
 804     }
 805   }
 806
 807   // data ---------------
 808
 809   Mutex mutex_;
 810   bool should_exit_;
 811   queue<string> messages_;  // messages to be logged
 812 };
 813
 814 // A log sink that exercises WaitTillSent:
 815 // it pushes data to a buffer and wakes up another thread to do the logging
 816 // (that other thread can than use LOG() itself),
 817 class TestWaitingLogSink : public LogSink {
 818  public:
 819
 820   TestWaitingLogSink() {
 821     tid_ = pthread_self();  // for thread-specific behavior
 822     AddLogSink(this);
 823   }
 824   ~TestWaitingLogSink() {
 825     RemoveLogSink(this);
 826     writer_.Stop();
 827     writer_.Join();
 828   }
 829
 830   // (re)define LogSink interface
 831
 832   virtual void send(LogSeverity severity, const char* full_filename,
 833                     const char* base_filename, int line,
 834                     const struct tm* tm_time,
 835                     const char* message, size_t message_len) {
 836     // Push it to Writer thread if we are the original logging thread.
 837     // Note: Something like ThreadLocalLogSink is a better choice
 838     //       to do thread-specific LogSink logic for real.
 839     if (pthread_equal(tid_, pthread_self())) {
 840       writer_.Buffer(ToString(severity, base_filename, line,
 841                               tm_time, message, message_len));
 842     }
 843   }
 844   virtual void WaitTillSent() {
 845     // Wait for Writer thread if we are the original logging thread.
 846     if (pthread_equal(tid_, pthread_self()))  writer_.Wait();
 847   }
 848
 849  private:
 850
 851   pthread_t tid_;
 852   TestLogSinkWriter writer_;
 853 };
 854
 855 // Check that LogSink::WaitTillSent can be used in the advertised way.
 856 // We also do golden-stderr comparison.
 857 static void TestLogSinkWaitTillSent() {
 858   { TestWaitingLogSink sink;
 859     // Sleeps give the sink threads time to do all their work,
 860     // so that we get a reliable log capture to compare to the golden file.
 861     LOG(INFO) << "Message 1";
 862     SleepForMilliseconds(60);
 863     LOG(ERROR) << "Message 2";
 864     SleepForMilliseconds(60);
 865     LOG(WARNING) << "Message 3";
 866     SleepForMilliseconds(60);
 867   }
 868   for (int i = 0; i < global_messages.size(); ++i) {
 869     LOG(INFO) << "Sink capture: " << global_messages[i];
 870   }
 871   CHECK_EQ(global_messages.size(), 3);
 872 }
 873
 874 TEST(Strerror, logging) {
 875   int errcode = EINTR;
 876   char *msg = strdup(strerror(errcode));
 877   char buf[strlen(msg) + 1];
 878   CHECK_EQ(posix_strerror_r(errcode, NULL, 0), -1);
 879   buf[0] = 'A';
 880   CHECK_EQ(posix_strerror_r(errcode, buf, 0), -1);
 881   CHECK_EQ(buf[0], 'A');
 882   CHECK_EQ(posix_strerror_r(errcode, NULL, sizeof(buf)), -1);
 883 #if defined(OS_MACOSX) || defined(OS_FREEBSD)
 884   // MacOSX or FreeBSD considers this case is an error since there is
 885   // no enough space.
 886   CHECK_EQ(posix_strerror_r(errcode, buf, 1), -1);
 887 #else
 888   CHECK_EQ(posix_strerror_r(errcode, buf, 1), 0);
 889 #endif
 890   CHECK_STREQ(buf, "");
 891   CHECK_EQ(posix_strerror_r(errcode, buf, sizeof(buf)), 0);
 892   CHECK_STREQ(buf, msg);
 893   free(msg);
 894 }
 895
 896 // Simple routines to look at the sizes of generated code for LOG(FATAL) and
 897 // CHECK(..) via objdump
 898 void MyFatal() {
 899   LOG(FATAL) << "Failed";
 900 }
 901 void MyCheck(bool a, bool b) {
 902   CHECK_EQ(a, b);
 903 }
 904
 905 struct UserDefinedClass {
 906   bool operator==(const UserDefinedClass& rhs) const { return true; }
 907 };
 908
 909 inline ostream& operator<<(ostream& out, const UserDefinedClass& u) {
 910   out << "OK";
 911   return out;
 912 }
 913
 914 TEST(UserDefinedClass, logging) {
 915   UserDefinedClass u;
 916   vector<string> buf;
 917   LOG_STRING(INFO, &buf) << u;
 918   CHECK_EQ(1, buf.size());
 919   CHECK(buf[0].find("OK") != string::npos);
 920
 921   // We must be able to compile this.
 922   CHECK_EQ(u, u);
 923 }