src/logging_unittest.cc

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