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