James Kuszmaul | ba0ac1a | 2022-08-12 16:29:30 -0700 | [diff] [blame^] | 1 | // Copyright (c) 2002, Google Inc. |
| 2 | // All rights reserved. |
| 3 | // |
| 4 | // Redistribution and use in source and binary forms, with or without |
| 5 | // modification, are permitted provided that the following conditions are |
| 6 | // met: |
| 7 | // |
| 8 | // * Redistributions of source code must retain the above copyright |
| 9 | // notice, this list of conditions and the following disclaimer. |
| 10 | // * Redistributions in binary form must reproduce the above |
| 11 | // copyright notice, this list of conditions and the following disclaimer |
| 12 | // in the documentation and/or other materials provided with the |
| 13 | // distribution. |
| 14 | // * Neither the name of Google Inc. nor the names of its |
| 15 | // contributors may be used to endorse or promote products derived from |
| 16 | // this software without specific prior written permission. |
| 17 | // |
| 18 | // THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS |
| 19 | // "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT |
| 20 | // LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR |
| 21 | // A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT |
| 22 | // OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, |
| 23 | // SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT |
| 24 | // LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, |
| 25 | // DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY |
| 26 | // THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT |
| 27 | // (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE |
| 28 | // OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. |
| 29 | // |
| 30 | // Author: Ray Sidney |
| 31 | |
| 32 | #include "utilities.h" |
| 33 | |
| 34 | #include <fcntl.h> |
| 35 | #ifdef HAVE_GLOB_H |
| 36 | # include <glob.h> |
| 37 | #endif |
| 38 | #include <sys/stat.h> |
| 39 | #ifdef HAVE_UNISTD_H |
| 40 | # include <unistd.h> |
| 41 | #endif |
| 42 | #ifdef HAVE_SYS_WAIT_H |
| 43 | # include <sys/wait.h> |
| 44 | #endif |
| 45 | |
| 46 | #include <cstdio> |
| 47 | #include <cstdlib> |
| 48 | #include <fstream> |
| 49 | #include <iomanip> |
| 50 | #include <iostream> |
| 51 | #include <fstream> |
| 52 | #include <memory> |
| 53 | #include <queue> |
| 54 | #include <sstream> |
| 55 | #include <string> |
| 56 | #include <vector> |
| 57 | |
| 58 | #include "base/commandlineflags.h" |
| 59 | #include <glog/logging.h> |
| 60 | #include <glog/raw_logging.h> |
| 61 | #include "googletest.h" |
| 62 | |
| 63 | DECLARE_string(log_backtrace_at); // logging.cc |
| 64 | |
| 65 | #ifdef HAVE_LIB_GFLAGS |
| 66 | #include <gflags/gflags.h> |
| 67 | using namespace GFLAGS_NAMESPACE; |
| 68 | #endif |
| 69 | |
| 70 | #ifdef HAVE_LIB_GMOCK |
| 71 | #include <gmock/gmock.h> |
| 72 | #include "mock-log.h" |
| 73 | // Introduce several symbols from gmock. |
| 74 | using testing::_; |
| 75 | using testing::AnyNumber; |
| 76 | using testing::HasSubstr; |
| 77 | using testing::AllOf; |
| 78 | using testing::StrNe; |
| 79 | using testing::StrictMock; |
| 80 | using testing::InitGoogleMock; |
| 81 | using GOOGLE_NAMESPACE::glog_testing::ScopedMockLog; |
| 82 | #endif |
| 83 | |
| 84 | using namespace std; |
| 85 | using namespace GOOGLE_NAMESPACE; |
| 86 | |
| 87 | // Some non-advertised functions that we want to test or use. |
| 88 | _START_GOOGLE_NAMESPACE_ |
| 89 | namespace base { |
| 90 | namespace internal { |
| 91 | bool GetExitOnDFatal(); |
| 92 | void SetExitOnDFatal(bool value); |
| 93 | } // namespace internal |
| 94 | } // namespace base |
| 95 | _END_GOOGLE_NAMESPACE_ |
| 96 | |
| 97 | static void TestLogging(bool check_counts); |
| 98 | static void TestRawLogging(); |
| 99 | static void LogWithLevels(int v, int severity, bool err, bool alsoerr); |
| 100 | static void TestLoggingLevels(); |
| 101 | static void TestLogString(); |
| 102 | static void TestLogSink(); |
| 103 | static void TestLogToString(); |
| 104 | static void TestLogSinkWaitTillSent(); |
| 105 | static void TestCHECK(); |
| 106 | static void TestDCHECK(); |
| 107 | static void TestSTREQ(); |
| 108 | static void TestBasename(); |
| 109 | static void TestBasenameAppendWhenNoTimestamp(); |
| 110 | static void TestTwoProcessesWrite(); |
| 111 | static void TestSymlink(); |
| 112 | static void TestExtension(); |
| 113 | static void TestWrapper(); |
| 114 | static void TestErrno(); |
| 115 | static void TestTruncate(); |
| 116 | static void TestCustomLoggerDeletionOnShutdown(); |
| 117 | |
| 118 | static int x = -1; |
| 119 | static void BM_Check1(int n) { |
| 120 | while (n-- > 0) { |
| 121 | CHECK_GE(n, x); |
| 122 | CHECK_GE(n, x); |
| 123 | CHECK_GE(n, x); |
| 124 | CHECK_GE(n, x); |
| 125 | CHECK_GE(n, x); |
| 126 | CHECK_GE(n, x); |
| 127 | CHECK_GE(n, x); |
| 128 | CHECK_GE(n, x); |
| 129 | } |
| 130 | } |
| 131 | BENCHMARK(BM_Check1) |
| 132 | |
| 133 | static void CheckFailure(int a, int b, const char* file, int line, const char* msg); |
| 134 | static void BM_Check3(int n) { |
| 135 | while (n-- > 0) { |
| 136 | if (n < x) CheckFailure(n, x, __FILE__, __LINE__, "n < x"); |
| 137 | if (n < x) CheckFailure(n, x, __FILE__, __LINE__, "n < x"); |
| 138 | if (n < x) CheckFailure(n, x, __FILE__, __LINE__, "n < x"); |
| 139 | if (n < x) CheckFailure(n, x, __FILE__, __LINE__, "n < x"); |
| 140 | if (n < x) CheckFailure(n, x, __FILE__, __LINE__, "n < x"); |
| 141 | if (n < x) CheckFailure(n, x, __FILE__, __LINE__, "n < x"); |
| 142 | if (n < x) CheckFailure(n, x, __FILE__, __LINE__, "n < x"); |
| 143 | if (n < x) CheckFailure(n, x, __FILE__, __LINE__, "n < x"); |
| 144 | } |
| 145 | } |
| 146 | BENCHMARK(BM_Check3) |
| 147 | |
| 148 | static void BM_Check2(int n) { |
| 149 | if (n == 17) { |
| 150 | x = 5; |
| 151 | } |
| 152 | while (n-- > 0) { |
| 153 | CHECK(n >= x); |
| 154 | CHECK(n >= x); |
| 155 | CHECK(n >= x); |
| 156 | CHECK(n >= x); |
| 157 | CHECK(n >= x); |
| 158 | CHECK(n >= x); |
| 159 | CHECK(n >= x); |
| 160 | CHECK(n >= x); |
| 161 | } |
| 162 | } |
| 163 | BENCHMARK(BM_Check2) |
| 164 | |
| 165 | static void CheckFailure(int, int, const char* /* file */, int /* line */, |
| 166 | const char* /* msg */) { |
| 167 | } |
| 168 | |
| 169 | static void BM_logspeed(int n) { |
| 170 | while (n-- > 0) { |
| 171 | LOG(INFO) << "test message"; |
| 172 | } |
| 173 | } |
| 174 | BENCHMARK(BM_logspeed) |
| 175 | |
| 176 | static void BM_vlog(int n) { |
| 177 | while (n-- > 0) { |
| 178 | VLOG(1) << "test message"; |
| 179 | } |
| 180 | } |
| 181 | BENCHMARK(BM_vlog) |
| 182 | |
| 183 | // Dynamically generate a prefix using the default format and write it to the stream. |
| 184 | void PrefixAttacher(std::ostream &s, const LogMessageInfo &l, void* data) { |
| 185 | // Assert that `data` contains the expected contents before producing the |
| 186 | // prefix (otherwise causing the tests to fail): |
| 187 | if (data == NULL || *static_cast<string*>(data) != "good data") { |
| 188 | return; |
| 189 | } |
| 190 | |
| 191 | s << l.severity[0] |
| 192 | << setw(4) << 1900 + l.time.year() |
| 193 | << setw(2) << 1 + l.time.month() |
| 194 | << setw(2) << l.time.day() |
| 195 | << ' ' |
| 196 | << setw(2) << l.time.hour() << ':' |
| 197 | << setw(2) << l.time.min() << ':' |
| 198 | << setw(2) << l.time.sec() << "." |
| 199 | << setw(6) << l.time.usec() |
| 200 | << ' ' |
| 201 | << setfill(' ') << setw(5) |
| 202 | << l.thread_id << setfill('0') |
| 203 | << ' ' |
| 204 | << l.filename << ':' << l.line_number << "]"; |
| 205 | } |
| 206 | |
| 207 | int main(int argc, char **argv) { |
| 208 | FLAGS_colorlogtostderr = false; |
| 209 | FLAGS_timestamp_in_logfile_name = true; |
| 210 | |
| 211 | // Make sure stderr is not buffered as stderr seems to be buffered |
| 212 | // on recent windows. |
| 213 | setbuf(stderr, NULL); |
| 214 | |
| 215 | // Test some basics before InitGoogleLogging: |
| 216 | CaptureTestStderr(); |
| 217 | LogWithLevels(FLAGS_v, FLAGS_stderrthreshold, |
| 218 | FLAGS_logtostderr, FLAGS_alsologtostderr); |
| 219 | LogWithLevels(0, 0, 0, 0); // simulate "before global c-tors" |
| 220 | const string early_stderr = GetCapturedTestStderr(); |
| 221 | |
| 222 | EXPECT_FALSE(IsGoogleLoggingInitialized()); |
| 223 | |
| 224 | // Setting a custom prefix generator (it will use the default format so that |
| 225 | // the golden outputs can be reused): |
| 226 | string prefix_attacher_data = "good data"; |
| 227 | InitGoogleLogging(argv[0], &PrefixAttacher, static_cast<void*>(&prefix_attacher_data)); |
| 228 | |
| 229 | EXPECT_TRUE(IsGoogleLoggingInitialized()); |
| 230 | |
| 231 | RunSpecifiedBenchmarks(); |
| 232 | |
| 233 | FLAGS_logtostderr = true; |
| 234 | |
| 235 | InitGoogleTest(&argc, argv); |
| 236 | #ifdef HAVE_LIB_GMOCK |
| 237 | InitGoogleMock(&argc, argv); |
| 238 | #endif |
| 239 | |
| 240 | #ifdef HAVE_LIB_GFLAGS |
| 241 | ParseCommandLineFlags(&argc, &argv, true); |
| 242 | #endif |
| 243 | |
| 244 | // so that death tests run before we use threads |
| 245 | CHECK_EQ(RUN_ALL_TESTS(), 0); |
| 246 | |
| 247 | CaptureTestStderr(); |
| 248 | |
| 249 | // re-emit early_stderr |
| 250 | LogMessage("dummy", LogMessage::kNoLogPrefix, GLOG_INFO).stream() << early_stderr; |
| 251 | |
| 252 | TestLogging(true); |
| 253 | TestRawLogging(); |
| 254 | TestLoggingLevels(); |
| 255 | TestLogString(); |
| 256 | TestLogSink(); |
| 257 | TestLogToString(); |
| 258 | TestLogSinkWaitTillSent(); |
| 259 | TestCHECK(); |
| 260 | TestDCHECK(); |
| 261 | TestSTREQ(); |
| 262 | |
| 263 | // TODO: The golden test portion of this test is very flakey. |
| 264 | EXPECT_TRUE( |
| 265 | MungeAndDiffTestStderr(FLAGS_test_srcdir + "/src/logging_custom_prefix_unittest.err")); |
| 266 | |
| 267 | FLAGS_logtostderr = false; |
| 268 | |
| 269 | TestBasename(); |
| 270 | TestBasenameAppendWhenNoTimestamp(); |
| 271 | TestTwoProcessesWrite(); |
| 272 | TestSymlink(); |
| 273 | TestExtension(); |
| 274 | TestWrapper(); |
| 275 | TestErrno(); |
| 276 | TestTruncate(); |
| 277 | TestCustomLoggerDeletionOnShutdown(); |
| 278 | |
| 279 | fprintf(stdout, "PASS\n"); |
| 280 | return 0; |
| 281 | } |
| 282 | |
| 283 | void TestLogging(bool check_counts) { |
| 284 | int64 base_num_infos = LogMessage::num_messages(GLOG_INFO); |
| 285 | int64 base_num_warning = LogMessage::num_messages(GLOG_WARNING); |
| 286 | int64 base_num_errors = LogMessage::num_messages(GLOG_ERROR); |
| 287 | |
| 288 | LOG(INFO) << string("foo ") << "bar " << 10 << ' ' << 3.4; |
| 289 | for ( int i = 0; i < 10; ++i ) { |
| 290 | int old_errno = errno; |
| 291 | errno = i; |
| 292 | PLOG_EVERY_N(ERROR, 2) << "Plog every 2, iteration " << COUNTER; |
| 293 | errno = old_errno; |
| 294 | |
| 295 | LOG_EVERY_N(ERROR, 3) << "Log every 3, iteration " << COUNTER << endl; |
| 296 | LOG_EVERY_N(ERROR, 4) << "Log every 4, iteration " << COUNTER << endl; |
| 297 | |
| 298 | LOG_IF_EVERY_N(WARNING, true, 5) << "Log if every 5, iteration " << COUNTER; |
| 299 | LOG_IF_EVERY_N(WARNING, false, 3) |
| 300 | << "Log if every 3, iteration " << COUNTER; |
| 301 | LOG_IF_EVERY_N(INFO, true, 1) << "Log if every 1, iteration " << COUNTER; |
| 302 | LOG_IF_EVERY_N(ERROR, (i < 3), 2) |
| 303 | << "Log if less than 3 every 2, iteration " << COUNTER; |
| 304 | } |
| 305 | LOG_IF(WARNING, true) << "log_if this"; |
| 306 | LOG_IF(WARNING, false) << "don't log_if this"; |
| 307 | |
| 308 | char s[] = "array"; |
| 309 | LOG(INFO) << s; |
| 310 | const char const_s[] = "const array"; |
| 311 | LOG(INFO) << const_s; |
| 312 | int j = 1000; |
| 313 | LOG(ERROR) << string("foo") << ' '<< j << ' ' << setw(10) << j << " " |
| 314 | << setw(1) << hex << j; |
| 315 | LOG(INFO) << "foo " << std::setw(10) << 1.0; |
| 316 | |
| 317 | { |
| 318 | google::LogMessage outer(__FILE__, __LINE__, GLOG_ERROR); |
| 319 | outer.stream() << "outer"; |
| 320 | |
| 321 | LOG(ERROR) << "inner"; |
| 322 | } |
| 323 | |
| 324 | LogMessage("foo", LogMessage::kNoLogPrefix, GLOG_INFO).stream() << "no prefix"; |
| 325 | |
| 326 | if (check_counts) { |
| 327 | CHECK_EQ(base_num_infos + 15, LogMessage::num_messages(GLOG_INFO)); |
| 328 | CHECK_EQ(base_num_warning + 3, LogMessage::num_messages(GLOG_WARNING)); |
| 329 | CHECK_EQ(base_num_errors + 17, LogMessage::num_messages(GLOG_ERROR)); |
| 330 | } |
| 331 | } |
| 332 | |
| 333 | static void NoAllocNewHook() { |
| 334 | LOG(FATAL) << "unexpected new"; |
| 335 | } |
| 336 | |
| 337 | struct NewHook { |
| 338 | NewHook() { |
| 339 | g_new_hook = &NoAllocNewHook; |
| 340 | } |
| 341 | ~NewHook() { |
| 342 | g_new_hook = NULL; |
| 343 | } |
| 344 | }; |
| 345 | |
| 346 | TEST(DeathNoAllocNewHook, logging) { |
| 347 | // tests that NewHook used below works |
| 348 | NewHook new_hook; |
| 349 | ASSERT_DEATH({ |
| 350 | new int; |
| 351 | }, "unexpected new"); |
| 352 | } |
| 353 | |
| 354 | void TestRawLogging() { |
| 355 | string* foo = new string("foo "); |
| 356 | string huge_str(50000, 'a'); |
| 357 | |
| 358 | FlagSaver saver; |
| 359 | |
| 360 | // Check that RAW loggging does not use mallocs. |
| 361 | NewHook new_hook; |
| 362 | |
| 363 | RAW_LOG(INFO, "%s%s%d%c%f", foo->c_str(), "bar ", 10, ' ', 3.4); |
| 364 | char s[] = "array"; |
| 365 | RAW_LOG(WARNING, "%s", s); |
| 366 | const char const_s[] = "const array"; |
| 367 | RAW_LOG(INFO, "%s", const_s); |
| 368 | void* p = reinterpret_cast<void*>(PTR_TEST_VALUE); |
| 369 | RAW_LOG(INFO, "ptr %p", p); |
| 370 | p = NULL; |
| 371 | RAW_LOG(INFO, "ptr %p", p); |
| 372 | int j = 1000; |
| 373 | RAW_LOG(ERROR, "%s%d%c%010d%s%1x", foo->c_str(), j, ' ', j, " ", j); |
| 374 | RAW_VLOG(0, "foo %d", j); |
| 375 | |
| 376 | #if defined(NDEBUG) |
| 377 | RAW_LOG(INFO, "foo %d", j); // so that have same stderr to compare |
| 378 | #else |
| 379 | RAW_DLOG(INFO, "foo %d", j); // test RAW_DLOG in debug mode |
| 380 | #endif |
| 381 | |
| 382 | // test how long messages are chopped: |
| 383 | RAW_LOG(WARNING, "Huge string: %s", huge_str.c_str()); |
| 384 | RAW_VLOG(0, "Huge string: %s", huge_str.c_str()); |
| 385 | |
| 386 | FLAGS_v = 0; |
| 387 | RAW_LOG(INFO, "log"); |
| 388 | RAW_VLOG(0, "vlog 0 on"); |
| 389 | RAW_VLOG(1, "vlog 1 off"); |
| 390 | RAW_VLOG(2, "vlog 2 off"); |
| 391 | RAW_VLOG(3, "vlog 3 off"); |
| 392 | FLAGS_v = 2; |
| 393 | RAW_LOG(INFO, "log"); |
| 394 | RAW_VLOG(1, "vlog 1 on"); |
| 395 | RAW_VLOG(2, "vlog 2 on"); |
| 396 | RAW_VLOG(3, "vlog 3 off"); |
| 397 | |
| 398 | #if defined(NDEBUG) |
| 399 | RAW_DCHECK(1 == 2, " RAW_DCHECK's shouldn't be compiled in normal mode"); |
| 400 | #endif |
| 401 | |
| 402 | RAW_CHECK(1 == 1, "should be ok"); |
| 403 | RAW_DCHECK(true, "should be ok"); |
| 404 | |
| 405 | delete foo; |
| 406 | } |
| 407 | |
| 408 | void LogWithLevels(int v, int severity, bool err, bool alsoerr) { |
| 409 | RAW_LOG(INFO, |
| 410 | "Test: v=%d stderrthreshold=%d logtostderr=%d alsologtostderr=%d", |
| 411 | v, severity, err, alsoerr); |
| 412 | |
| 413 | FlagSaver saver; |
| 414 | |
| 415 | FLAGS_v = v; |
| 416 | FLAGS_stderrthreshold = severity; |
| 417 | FLAGS_logtostderr = err; |
| 418 | FLAGS_alsologtostderr = alsoerr; |
| 419 | |
| 420 | RAW_VLOG(-1, "vlog -1"); |
| 421 | RAW_VLOG(0, "vlog 0"); |
| 422 | RAW_VLOG(1, "vlog 1"); |
| 423 | RAW_LOG(INFO, "log info"); |
| 424 | RAW_LOG(WARNING, "log warning"); |
| 425 | RAW_LOG(ERROR, "log error"); |
| 426 | |
| 427 | VLOG(-1) << "vlog -1"; |
| 428 | VLOG(0) << "vlog 0"; |
| 429 | VLOG(1) << "vlog 1"; |
| 430 | LOG(INFO) << "log info"; |
| 431 | LOG(WARNING) << "log warning"; |
| 432 | LOG(ERROR) << "log error"; |
| 433 | |
| 434 | VLOG_IF(-1, true) << "vlog_if -1"; |
| 435 | VLOG_IF(-1, false) << "don't vlog_if -1"; |
| 436 | VLOG_IF(0, true) << "vlog_if 0"; |
| 437 | VLOG_IF(0, false) << "don't vlog_if 0"; |
| 438 | VLOG_IF(1, true) << "vlog_if 1"; |
| 439 | VLOG_IF(1, false) << "don't vlog_if 1"; |
| 440 | LOG_IF(INFO, true) << "log_if info"; |
| 441 | LOG_IF(INFO, false) << "don't log_if info"; |
| 442 | LOG_IF(WARNING, true) << "log_if warning"; |
| 443 | LOG_IF(WARNING, false) << "don't log_if warning"; |
| 444 | LOG_IF(ERROR, true) << "log_if error"; |
| 445 | LOG_IF(ERROR, false) << "don't log_if error"; |
| 446 | |
| 447 | int c; |
| 448 | c = 1; VLOG_IF(100, c -= 2) << "vlog_if 100 expr"; EXPECT_EQ(c, -1); |
| 449 | c = 1; VLOG_IF(0, c -= 2) << "vlog_if 0 expr"; EXPECT_EQ(c, -1); |
| 450 | c = 1; LOG_IF(INFO, c -= 2) << "log_if info expr"; EXPECT_EQ(c, -1); |
| 451 | c = 1; LOG_IF(ERROR, c -= 2) << "log_if error expr"; EXPECT_EQ(c, -1); |
| 452 | c = 2; VLOG_IF(0, c -= 2) << "don't vlog_if 0 expr"; EXPECT_EQ(c, 0); |
| 453 | c = 2; LOG_IF(ERROR, c -= 2) << "don't log_if error expr"; EXPECT_EQ(c, 0); |
| 454 | |
| 455 | c = 3; LOG_IF_EVERY_N(INFO, c -= 4, 1) << "log_if info every 1 expr"; |
| 456 | EXPECT_EQ(c, -1); |
| 457 | c = 3; LOG_IF_EVERY_N(ERROR, c -= 4, 1) << "log_if error every 1 expr"; |
| 458 | EXPECT_EQ(c, -1); |
| 459 | c = 4; LOG_IF_EVERY_N(ERROR, c -= 4, 3) << "don't log_if info every 3 expr"; |
| 460 | EXPECT_EQ(c, 0); |
| 461 | c = 4; LOG_IF_EVERY_N(ERROR, c -= 4, 3) << "don't log_if error every 3 expr"; |
| 462 | EXPECT_EQ(c, 0); |
| 463 | c = 5; VLOG_IF_EVERY_N(0, c -= 4, 1) << "vlog_if 0 every 1 expr"; |
| 464 | EXPECT_EQ(c, 1); |
| 465 | c = 5; VLOG_IF_EVERY_N(100, c -= 4, 3) << "vlog_if 100 every 3 expr"; |
| 466 | EXPECT_EQ(c, 1); |
| 467 | c = 6; VLOG_IF_EVERY_N(0, c -= 6, 1) << "don't vlog_if 0 every 1 expr"; |
| 468 | EXPECT_EQ(c, 0); |
| 469 | c = 6; VLOG_IF_EVERY_N(100, c -= 6, 3) << "don't vlog_if 100 every 1 expr"; |
| 470 | EXPECT_EQ(c, 0); |
| 471 | } |
| 472 | |
| 473 | void TestLoggingLevels() { |
| 474 | LogWithLevels(0, GLOG_INFO, false, false); |
| 475 | LogWithLevels(1, GLOG_INFO, false, false); |
| 476 | LogWithLevels(-1, GLOG_INFO, false, false); |
| 477 | LogWithLevels(0, GLOG_WARNING, false, false); |
| 478 | LogWithLevels(0, GLOG_ERROR, false, false); |
| 479 | LogWithLevels(0, GLOG_FATAL, false, false); |
| 480 | LogWithLevels(0, GLOG_FATAL, true, false); |
| 481 | LogWithLevels(0, GLOG_FATAL, false, true); |
| 482 | LogWithLevels(1, GLOG_WARNING, false, false); |
| 483 | LogWithLevels(1, GLOG_FATAL, false, true); |
| 484 | } |
| 485 | |
| 486 | TEST(DeathRawCHECK, logging) { |
| 487 | ASSERT_DEATH(RAW_CHECK(false, "failure 1"), |
| 488 | "RAW: Check false failed: failure 1"); |
| 489 | ASSERT_DEBUG_DEATH(RAW_DCHECK(1 == 2, "failure 2"), |
| 490 | "RAW: Check 1 == 2 failed: failure 2"); |
| 491 | } |
| 492 | |
| 493 | void TestLogString() { |
| 494 | vector<string> errors; |
| 495 | vector<string> *no_errors = NULL; |
| 496 | |
| 497 | LOG_STRING(INFO, &errors) << "LOG_STRING: " << "collected info"; |
| 498 | LOG_STRING(WARNING, &errors) << "LOG_STRING: " << "collected warning"; |
| 499 | LOG_STRING(ERROR, &errors) << "LOG_STRING: " << "collected error"; |
| 500 | |
| 501 | LOG_STRING(INFO, no_errors) << "LOG_STRING: " << "reported info"; |
| 502 | LOG_STRING(WARNING, no_errors) << "LOG_STRING: " << "reported warning"; |
| 503 | LOG_STRING(ERROR, NULL) << "LOG_STRING: " << "reported error"; |
| 504 | |
| 505 | for (size_t i = 0; i < errors.size(); ++i) { |
| 506 | LOG(INFO) << "Captured by LOG_STRING: " << errors[i]; |
| 507 | } |
| 508 | } |
| 509 | |
| 510 | void TestLogToString() { |
| 511 | string error; |
| 512 | string* no_error = NULL; |
| 513 | |
| 514 | LOG_TO_STRING(INFO, &error) << "LOG_TO_STRING: " << "collected info"; |
| 515 | LOG(INFO) << "Captured by LOG_TO_STRING: " << error; |
| 516 | LOG_TO_STRING(WARNING, &error) << "LOG_TO_STRING: " << "collected warning"; |
| 517 | LOG(INFO) << "Captured by LOG_TO_STRING: " << error; |
| 518 | LOG_TO_STRING(ERROR, &error) << "LOG_TO_STRING: " << "collected error"; |
| 519 | LOG(INFO) << "Captured by LOG_TO_STRING: " << error; |
| 520 | |
| 521 | LOG_TO_STRING(INFO, no_error) << "LOG_TO_STRING: " << "reported info"; |
| 522 | LOG_TO_STRING(WARNING, no_error) << "LOG_TO_STRING: " << "reported warning"; |
| 523 | LOG_TO_STRING(ERROR, NULL) << "LOG_TO_STRING: " << "reported error"; |
| 524 | } |
| 525 | |
| 526 | class TestLogSinkImpl : public LogSink { |
| 527 | public: |
| 528 | vector<string> errors; |
| 529 | virtual void send(LogSeverity severity, const char* /* full_filename */, |
| 530 | const char* base_filename, int line, |
| 531 | const LogMessageTime &logmsgtime, |
| 532 | const char* message, size_t message_len) { |
| 533 | errors.push_back( |
| 534 | ToString(severity, base_filename, line, logmsgtime, message, message_len)); |
| 535 | } |
| 536 | }; |
| 537 | |
| 538 | void TestLogSink() { |
| 539 | TestLogSinkImpl sink; |
| 540 | LogSink *no_sink = NULL; |
| 541 | |
| 542 | LOG_TO_SINK(&sink, INFO) << "LOG_TO_SINK: " << "collected info"; |
| 543 | LOG_TO_SINK(&sink, WARNING) << "LOG_TO_SINK: " << "collected warning"; |
| 544 | LOG_TO_SINK(&sink, ERROR) << "LOG_TO_SINK: " << "collected error"; |
| 545 | |
| 546 | LOG_TO_SINK(no_sink, INFO) << "LOG_TO_SINK: " << "reported info"; |
| 547 | LOG_TO_SINK(no_sink, WARNING) << "LOG_TO_SINK: " << "reported warning"; |
| 548 | LOG_TO_SINK(NULL, ERROR) << "LOG_TO_SINK: " << "reported error"; |
| 549 | |
| 550 | LOG_TO_SINK_BUT_NOT_TO_LOGFILE(&sink, INFO) |
| 551 | << "LOG_TO_SINK_BUT_NOT_TO_LOGFILE: " << "collected info"; |
| 552 | LOG_TO_SINK_BUT_NOT_TO_LOGFILE(&sink, WARNING) |
| 553 | << "LOG_TO_SINK_BUT_NOT_TO_LOGFILE: " << "collected warning"; |
| 554 | LOG_TO_SINK_BUT_NOT_TO_LOGFILE(&sink, ERROR) |
| 555 | << "LOG_TO_SINK_BUT_NOT_TO_LOGFILE: " << "collected error"; |
| 556 | |
| 557 | LOG_TO_SINK_BUT_NOT_TO_LOGFILE(no_sink, INFO) |
| 558 | << "LOG_TO_SINK_BUT_NOT_TO_LOGFILE: " << "thrashed info"; |
| 559 | LOG_TO_SINK_BUT_NOT_TO_LOGFILE(no_sink, WARNING) |
| 560 | << "LOG_TO_SINK_BUT_NOT_TO_LOGFILE: " << "thrashed warning"; |
| 561 | LOG_TO_SINK_BUT_NOT_TO_LOGFILE(NULL, ERROR) |
| 562 | << "LOG_TO_SINK_BUT_NOT_TO_LOGFILE: " << "thrashed error"; |
| 563 | |
| 564 | LOG(INFO) << "Captured by LOG_TO_SINK:"; |
| 565 | for (size_t i = 0; i < sink.errors.size(); ++i) { |
| 566 | LogMessage("foo", LogMessage::kNoLogPrefix, GLOG_INFO).stream() |
| 567 | << sink.errors[i]; |
| 568 | } |
| 569 | } |
| 570 | |
| 571 | // For testing using CHECK*() on anonymous enums. |
| 572 | enum { |
| 573 | CASE_A, |
| 574 | CASE_B |
| 575 | }; |
| 576 | |
| 577 | void TestCHECK() { |
| 578 | // Tests using CHECK*() on int values. |
| 579 | CHECK(1 == 1); |
| 580 | CHECK_EQ(1, 1); |
| 581 | CHECK_NE(1, 2); |
| 582 | CHECK_GE(1, 1); |
| 583 | CHECK_GE(2, 1); |
| 584 | CHECK_LE(1, 1); |
| 585 | CHECK_LE(1, 2); |
| 586 | CHECK_GT(2, 1); |
| 587 | CHECK_LT(1, 2); |
| 588 | |
| 589 | // Tests using CHECK*() on anonymous enums. |
| 590 | // Apple's GCC doesn't like this. |
| 591 | #if !defined(GLOG_OS_MACOSX) |
| 592 | CHECK_EQ(CASE_A, CASE_A); |
| 593 | CHECK_NE(CASE_A, CASE_B); |
| 594 | CHECK_GE(CASE_A, CASE_A); |
| 595 | CHECK_GE(CASE_B, CASE_A); |
| 596 | CHECK_LE(CASE_A, CASE_A); |
| 597 | CHECK_LE(CASE_A, CASE_B); |
| 598 | CHECK_GT(CASE_B, CASE_A); |
| 599 | CHECK_LT(CASE_A, CASE_B); |
| 600 | #endif |
| 601 | } |
| 602 | |
| 603 | void TestDCHECK() { |
| 604 | #if defined(NDEBUG) |
| 605 | DCHECK( 1 == 2 ) << " DCHECK's shouldn't be compiled in normal mode"; |
| 606 | #endif |
| 607 | DCHECK( 1 == 1 ); |
| 608 | DCHECK_EQ(1, 1); |
| 609 | DCHECK_NE(1, 2); |
| 610 | DCHECK_GE(1, 1); |
| 611 | DCHECK_GE(2, 1); |
| 612 | DCHECK_LE(1, 1); |
| 613 | DCHECK_LE(1, 2); |
| 614 | DCHECK_GT(2, 1); |
| 615 | DCHECK_LT(1, 2); |
| 616 | |
| 617 | int64* orig_ptr = new int64; |
| 618 | int64* ptr = DCHECK_NOTNULL(orig_ptr); |
| 619 | CHECK_EQ(ptr, orig_ptr); |
| 620 | delete orig_ptr; |
| 621 | } |
| 622 | |
| 623 | void TestSTREQ() { |
| 624 | CHECK_STREQ("this", "this"); |
| 625 | CHECK_STREQ(NULL, NULL); |
| 626 | CHECK_STRCASEEQ("this", "tHiS"); |
| 627 | CHECK_STRCASEEQ(NULL, NULL); |
| 628 | CHECK_STRNE("this", "tHiS"); |
| 629 | CHECK_STRNE("this", NULL); |
| 630 | CHECK_STRCASENE("this", "that"); |
| 631 | CHECK_STRCASENE(NULL, "that"); |
| 632 | CHECK_STREQ((string("a")+"b").c_str(), "ab"); |
| 633 | CHECK_STREQ(string("test").c_str(), |
| 634 | (string("te") + string("st")).c_str()); |
| 635 | } |
| 636 | |
| 637 | TEST(DeathSTREQ, logging) { |
| 638 | ASSERT_DEATH(CHECK_STREQ(NULL, "this"), ""); |
| 639 | ASSERT_DEATH(CHECK_STREQ("this", "siht"), ""); |
| 640 | ASSERT_DEATH(CHECK_STRCASEEQ(NULL, "siht"), ""); |
| 641 | ASSERT_DEATH(CHECK_STRCASEEQ("this", "siht"), ""); |
| 642 | ASSERT_DEATH(CHECK_STRNE(NULL, NULL), ""); |
| 643 | ASSERT_DEATH(CHECK_STRNE("this", "this"), ""); |
| 644 | ASSERT_DEATH(CHECK_STREQ((string("a")+"b").c_str(), "abc"), ""); |
| 645 | } |
| 646 | |
| 647 | TEST(CheckNOTNULL, Simple) { |
| 648 | int64 t; |
| 649 | void *ptr = static_cast<void *>(&t); |
| 650 | void *ref = CHECK_NOTNULL(ptr); |
| 651 | EXPECT_EQ(ptr, ref); |
| 652 | CHECK_NOTNULL(reinterpret_cast<char *>(ptr)); |
| 653 | CHECK_NOTNULL(reinterpret_cast<unsigned char *>(ptr)); |
| 654 | CHECK_NOTNULL(reinterpret_cast<int *>(ptr)); |
| 655 | CHECK_NOTNULL(reinterpret_cast<int64 *>(ptr)); |
| 656 | } |
| 657 | |
| 658 | TEST(DeathCheckNN, Simple) { |
| 659 | ASSERT_DEATH(CHECK_NOTNULL(static_cast<void *>(NULL)), ""); |
| 660 | } |
| 661 | |
| 662 | // Get list of file names that match pattern |
| 663 | static void GetFiles(const string& pattern, vector<string>* files) { |
| 664 | files->clear(); |
| 665 | #if defined(HAVE_GLOB_H) |
| 666 | glob_t g; |
| 667 | const int r = glob(pattern.c_str(), 0, NULL, &g); |
| 668 | CHECK((r == 0) || (r == GLOB_NOMATCH)) << ": error matching " << pattern; |
| 669 | for (size_t i = 0; i < g.gl_pathc; i++) { |
| 670 | files->push_back(string(g.gl_pathv[i])); |
| 671 | } |
| 672 | globfree(&g); |
| 673 | #elif defined(GLOG_OS_WINDOWS) |
| 674 | WIN32_FIND_DATAA data; |
| 675 | HANDLE handle = FindFirstFileA(pattern.c_str(), &data); |
| 676 | size_t index = pattern.rfind('\\'); |
| 677 | if (index == string::npos) { |
| 678 | LOG(FATAL) << "No directory separator."; |
| 679 | } |
| 680 | const string dirname = pattern.substr(0, index + 1); |
| 681 | if (handle == INVALID_HANDLE_VALUE) { |
| 682 | // Finding no files is OK. |
| 683 | return; |
| 684 | } |
| 685 | do { |
| 686 | files->push_back(dirname + data.cFileName); |
| 687 | } while (FindNextFileA(handle, &data)); |
| 688 | BOOL result = FindClose(handle); |
| 689 | LOG_SYSRESULT(result != 0); |
| 690 | #else |
| 691 | # error There is no way to do glob. |
| 692 | #endif |
| 693 | } |
| 694 | |
| 695 | // Delete files patching pattern |
| 696 | static void DeleteFiles(const string& pattern) { |
| 697 | vector<string> files; |
| 698 | GetFiles(pattern, &files); |
| 699 | for (size_t i = 0; i < files.size(); i++) { |
| 700 | CHECK(unlink(files[i].c_str()) == 0) << ": " << strerror(errno); |
| 701 | } |
| 702 | } |
| 703 | |
| 704 | //check string is in file (or is *NOT*, depending on optional checkInFileOrNot) |
| 705 | static void CheckFile(const string& name, const string& expected_string, const bool checkInFileOrNot = true) { |
| 706 | vector<string> files; |
| 707 | GetFiles(name + "*", &files); |
| 708 | CHECK_EQ(files.size(), 1UL); |
| 709 | |
| 710 | FILE* file = fopen(files[0].c_str(), "r"); |
| 711 | CHECK(file != NULL) << ": could not open " << files[0]; |
| 712 | char buf[1000]; |
| 713 | while (fgets(buf, sizeof(buf), file) != NULL) { |
| 714 | char* first = strstr(buf, expected_string.c_str()); |
| 715 | //if first == NULL, not found. |
| 716 | //Terser than if (checkInFileOrNot && first != NULL || !check... |
| 717 | if (checkInFileOrNot != (first == NULL)) { |
| 718 | fclose(file); |
| 719 | return; |
| 720 | } |
| 721 | } |
| 722 | fclose(file); |
| 723 | LOG(FATAL) << "Did " << (checkInFileOrNot? "not " : "") << "find " << expected_string << " in " << files[0]; |
| 724 | } |
| 725 | |
| 726 | static void TestBasename() { |
| 727 | fprintf(stderr, "==== Test setting log file basename\n"); |
| 728 | const string dest = FLAGS_test_tmpdir + "/logging_test_basename"; |
| 729 | DeleteFiles(dest + "*"); |
| 730 | |
| 731 | SetLogDestination(GLOG_INFO, dest.c_str()); |
| 732 | LOG(INFO) << "message to new base"; |
| 733 | FlushLogFiles(GLOG_INFO); |
| 734 | |
| 735 | CheckFile(dest, "message to new base"); |
| 736 | |
| 737 | // Release file handle for the destination file to unlock the file in Windows. |
| 738 | LogToStderr(); |
| 739 | DeleteFiles(dest + "*"); |
| 740 | } |
| 741 | |
| 742 | static void TestBasenameAppendWhenNoTimestamp() { |
| 743 | fprintf(stderr, "==== Test setting log file basename without timestamp and appending properly\n"); |
| 744 | const string dest = FLAGS_test_tmpdir + "/logging_test_basename_append_when_no_timestamp"; |
| 745 | DeleteFiles(dest + "*"); |
| 746 | |
| 747 | ofstream out(dest.c_str()); |
| 748 | out << "test preexisting content" << endl; |
| 749 | out.close(); |
| 750 | |
| 751 | CheckFile(dest, "test preexisting content"); |
| 752 | |
| 753 | FLAGS_timestamp_in_logfile_name=false; |
| 754 | SetLogDestination(GLOG_INFO, dest.c_str()); |
| 755 | LOG(INFO) << "message to new base, appending to preexisting file"; |
| 756 | FlushLogFiles(GLOG_INFO); |
| 757 | FLAGS_timestamp_in_logfile_name=true; |
| 758 | |
| 759 | //if the logging overwrites the file instead of appending it will fail. |
| 760 | CheckFile(dest, "test preexisting content"); |
| 761 | CheckFile(dest, "message to new base, appending to preexisting file"); |
| 762 | |
| 763 | // Release file handle for the destination file to unlock the file in Windows. |
| 764 | LogToStderr(); |
| 765 | DeleteFiles(dest + "*"); |
| 766 | } |
| 767 | |
| 768 | static void TestTwoProcessesWrite() { |
| 769 | // test only implemented for platforms with fork & wait; the actual implementation relies on flock |
| 770 | #if defined(HAVE_SYS_WAIT_H) && defined(HAVE_UNISTD_H) && defined(HAVE_FCNTL) |
| 771 | fprintf(stderr, "==== Test setting log file basename and two processes writing - second should fail\n"); |
| 772 | const string dest = FLAGS_test_tmpdir + "/logging_test_basename_two_processes_writing"; |
| 773 | DeleteFiles(dest + "*"); |
| 774 | |
| 775 | //make both processes write into the same file (easier test) |
| 776 | FLAGS_timestamp_in_logfile_name=false; |
| 777 | SetLogDestination(GLOG_INFO, dest.c_str()); |
| 778 | LOG(INFO) << "message to new base, parent"; |
| 779 | FlushLogFiles(GLOG_INFO); |
| 780 | |
| 781 | pid_t pid = fork(); |
| 782 | CHECK_ERR(pid); |
| 783 | if (pid == 0) { |
| 784 | LOG(INFO) << "message to new base, child - should only appear on STDERR not on the file"; |
| 785 | ShutdownGoogleLogging(); //for children proc |
| 786 | exit(EXIT_SUCCESS); |
| 787 | } else if (pid > 0) { |
| 788 | wait(NULL); |
| 789 | } |
| 790 | FLAGS_timestamp_in_logfile_name=true; |
| 791 | |
| 792 | CheckFile(dest, "message to new base, parent"); |
| 793 | CheckFile(dest, "message to new base, child - should only appear on STDERR not on the file", false); |
| 794 | |
| 795 | // Release |
| 796 | LogToStderr(); |
| 797 | DeleteFiles(dest + "*"); |
| 798 | #endif |
| 799 | } |
| 800 | |
| 801 | static void TestSymlink() { |
| 802 | #ifndef GLOG_OS_WINDOWS |
| 803 | fprintf(stderr, "==== Test setting log file symlink\n"); |
| 804 | string dest = FLAGS_test_tmpdir + "/logging_test_symlink"; |
| 805 | string sym = FLAGS_test_tmpdir + "/symlinkbase"; |
| 806 | DeleteFiles(dest + "*"); |
| 807 | DeleteFiles(sym + "*"); |
| 808 | |
| 809 | SetLogSymlink(GLOG_INFO, "symlinkbase"); |
| 810 | SetLogDestination(GLOG_INFO, dest.c_str()); |
| 811 | LOG(INFO) << "message to new symlink"; |
| 812 | FlushLogFiles(GLOG_INFO); |
| 813 | CheckFile(sym, "message to new symlink"); |
| 814 | |
| 815 | DeleteFiles(dest + "*"); |
| 816 | DeleteFiles(sym + "*"); |
| 817 | #endif |
| 818 | } |
| 819 | |
| 820 | static void TestExtension() { |
| 821 | fprintf(stderr, "==== Test setting log file extension\n"); |
| 822 | string dest = FLAGS_test_tmpdir + "/logging_test_extension"; |
| 823 | DeleteFiles(dest + "*"); |
| 824 | |
| 825 | SetLogDestination(GLOG_INFO, dest.c_str()); |
| 826 | SetLogFilenameExtension("specialextension"); |
| 827 | LOG(INFO) << "message to new extension"; |
| 828 | FlushLogFiles(GLOG_INFO); |
| 829 | CheckFile(dest, "message to new extension"); |
| 830 | |
| 831 | // Check that file name ends with extension |
| 832 | vector<string> filenames; |
| 833 | GetFiles(dest + "*", &filenames); |
| 834 | CHECK_EQ(filenames.size(), 1UL); |
| 835 | CHECK(strstr(filenames[0].c_str(), "specialextension") != NULL); |
| 836 | |
| 837 | // Release file handle for the destination file to unlock the file in Windows. |
| 838 | LogToStderr(); |
| 839 | DeleteFiles(dest + "*"); |
| 840 | } |
| 841 | |
| 842 | struct MyLogger : public base::Logger { |
| 843 | string data; |
| 844 | |
| 845 | virtual void Write(bool /* should_flush */, |
| 846 | time_t /* timestamp */, |
| 847 | const char* message, |
| 848 | size_t length) { |
| 849 | data.append(message, length); |
| 850 | } |
| 851 | |
| 852 | virtual void Flush() { } |
| 853 | |
| 854 | virtual uint32 LogSize() { return data.length(); } |
| 855 | }; |
| 856 | |
| 857 | static void TestWrapper() { |
| 858 | fprintf(stderr, "==== Test log wrapper\n"); |
| 859 | |
| 860 | MyLogger my_logger; |
| 861 | base::Logger* old_logger = base::GetLogger(GLOG_INFO); |
| 862 | base::SetLogger(GLOG_INFO, &my_logger); |
| 863 | LOG(INFO) << "Send to wrapped logger"; |
| 864 | FlushLogFiles(GLOG_INFO); |
| 865 | base::SetLogger(GLOG_INFO, old_logger); |
| 866 | |
| 867 | CHECK(strstr(my_logger.data.c_str(), "Send to wrapped logger") != NULL); |
| 868 | } |
| 869 | |
| 870 | static void TestErrno() { |
| 871 | fprintf(stderr, "==== Test errno preservation\n"); |
| 872 | |
| 873 | errno = ENOENT; |
| 874 | TestLogging(false); |
| 875 | CHECK_EQ(errno, ENOENT); |
| 876 | } |
| 877 | |
| 878 | static void TestOneTruncate(const char *path, uint64 limit, uint64 keep, |
| 879 | size_t dsize, size_t ksize, size_t expect) { |
| 880 | int fd; |
| 881 | CHECK_ERR(fd = open(path, O_RDWR | O_CREAT | O_TRUNC, 0600)); |
| 882 | |
| 883 | const char *discardstr = "DISCARDME!", *keepstr = "KEEPME!"; |
| 884 | const size_t discard_size = strlen(discardstr), keep_size = strlen(keepstr); |
| 885 | |
| 886 | // Fill the file with the requested data; first discard data, then kept data |
| 887 | size_t written = 0; |
| 888 | while (written < dsize) { |
| 889 | size_t bytes = min(dsize - written, discard_size); |
| 890 | CHECK_ERR(write(fd, discardstr, bytes)); |
| 891 | written += bytes; |
| 892 | } |
| 893 | written = 0; |
| 894 | while (written < ksize) { |
| 895 | size_t bytes = min(ksize - written, keep_size); |
| 896 | CHECK_ERR(write(fd, keepstr, bytes)); |
| 897 | written += bytes; |
| 898 | } |
| 899 | |
| 900 | TruncateLogFile(path, limit, keep); |
| 901 | |
| 902 | // File should now be shorter |
| 903 | struct stat statbuf; |
| 904 | CHECK_ERR(fstat(fd, &statbuf)); |
| 905 | CHECK_EQ(static_cast<size_t>(statbuf.st_size), expect); |
| 906 | CHECK_ERR(lseek(fd, 0, SEEK_SET)); |
| 907 | |
| 908 | // File should contain the suffix of the original file |
| 909 | const size_t buf_size = static_cast<size_t>(statbuf.st_size) + 1; |
| 910 | char* buf = new char[buf_size]; |
| 911 | memset(buf, 0, buf_size); |
| 912 | CHECK_ERR(read(fd, buf, buf_size)); |
| 913 | |
| 914 | const char* p = buf; |
| 915 | size_t checked = 0; |
| 916 | while (checked < expect) { |
| 917 | size_t bytes = min(expect - checked, keep_size); |
| 918 | CHECK(!memcmp(p, keepstr, bytes)); |
| 919 | checked += bytes; |
| 920 | } |
| 921 | close(fd); |
| 922 | delete[] buf; |
| 923 | } |
| 924 | |
| 925 | static void TestTruncate() { |
| 926 | #ifdef HAVE_UNISTD_H |
| 927 | fprintf(stderr, "==== Test log truncation\n"); |
| 928 | string path = FLAGS_test_tmpdir + "/truncatefilecustom"; |
| 929 | |
| 930 | // Test on a small file |
| 931 | TestOneTruncate(path.c_str(), 10, 10, 10, 10, 10); |
| 932 | |
| 933 | // And a big file (multiple blocks to copy) |
| 934 | TestOneTruncate(path.c_str(), 2U << 20U, 4U << 10U, 3U << 20U, 4U << 10U, |
| 935 | 4U << 10U); |
| 936 | |
| 937 | // Check edge-case limits |
| 938 | TestOneTruncate(path.c_str(), 10, 20, 0, 20, 20); |
| 939 | TestOneTruncate(path.c_str(), 10, 0, 0, 0, 0); |
| 940 | TestOneTruncate(path.c_str(), 10, 50, 0, 10, 10); |
| 941 | TestOneTruncate(path.c_str(), 50, 100, 0, 30, 30); |
| 942 | |
| 943 | // MacOSX 10.4 doesn't fail in this case. |
| 944 | // Windows doesn't have symlink. |
| 945 | // Let's just ignore this test for these cases. |
| 946 | #if !defined(GLOG_OS_MACOSX) && !defined(GLOG_OS_WINDOWS) |
| 947 | // Through a symlink should fail to truncate |
| 948 | string linkname = path + ".link"; |
| 949 | unlink(linkname.c_str()); |
| 950 | CHECK_ERR(symlink(path.c_str(), linkname.c_str())); |
| 951 | TestOneTruncate(linkname.c_str(), 10, 10, 0, 30, 30); |
| 952 | #endif |
| 953 | |
| 954 | // The /proc/self path makes sense only for linux. |
| 955 | #if defined(GLOG_OS_LINUX) |
| 956 | // Through an open fd symlink should work |
| 957 | int fd; |
| 958 | CHECK_ERR(fd = open(path.c_str(), O_APPEND | O_WRONLY)); |
| 959 | char fdpath[64]; |
| 960 | snprintf(fdpath, sizeof(fdpath), "/proc/self/fd/%d", fd); |
| 961 | TestOneTruncate(fdpath, 10, 10, 10, 10, 10); |
| 962 | #endif |
| 963 | |
| 964 | #endif |
| 965 | } |
| 966 | |
| 967 | struct RecordDeletionLogger : public base::Logger { |
| 968 | RecordDeletionLogger(bool* set_on_destruction, |
| 969 | base::Logger* wrapped_logger) : |
| 970 | set_on_destruction_(set_on_destruction), |
| 971 | wrapped_logger_(wrapped_logger) |
| 972 | { |
| 973 | *set_on_destruction_ = false; |
| 974 | } |
| 975 | virtual ~RecordDeletionLogger() { |
| 976 | *set_on_destruction_ = true; |
| 977 | } |
| 978 | virtual void Write(bool force_flush, |
| 979 | time_t timestamp, |
| 980 | const char* message, |
| 981 | size_t length) { |
| 982 | wrapped_logger_->Write(force_flush, timestamp, message, length); |
| 983 | } |
| 984 | virtual void Flush() { wrapped_logger_->Flush(); } |
| 985 | virtual uint32 LogSize() { return wrapped_logger_->LogSize(); } |
| 986 | private: |
| 987 | bool* set_on_destruction_; |
| 988 | base::Logger* wrapped_logger_; |
| 989 | }; |
| 990 | |
| 991 | static void TestCustomLoggerDeletionOnShutdown() { |
| 992 | bool custom_logger_deleted = false; |
| 993 | base::SetLogger(GLOG_INFO, |
| 994 | new RecordDeletionLogger(&custom_logger_deleted, |
| 995 | base::GetLogger(GLOG_INFO))); |
| 996 | EXPECT_TRUE(IsGoogleLoggingInitialized()); |
| 997 | ShutdownGoogleLogging(); |
| 998 | EXPECT_TRUE(custom_logger_deleted); |
| 999 | EXPECT_FALSE(IsGoogleLoggingInitialized()); |
| 1000 | } |
| 1001 | |
| 1002 | _START_GOOGLE_NAMESPACE_ |
| 1003 | namespace glog_internal_namespace_ { |
| 1004 | extern // in logging.cc |
| 1005 | bool SafeFNMatch_(const char* pattern, size_t patt_len, |
| 1006 | const char* str, size_t str_len); |
| 1007 | } // namespace glog_internal_namespace_ |
| 1008 | using glog_internal_namespace_::SafeFNMatch_; |
| 1009 | _END_GOOGLE_NAMESPACE_ |
| 1010 | |
| 1011 | static bool WrapSafeFNMatch(string pattern, string str) { |
| 1012 | pattern += "abc"; |
| 1013 | str += "defgh"; |
| 1014 | return SafeFNMatch_(pattern.data(), pattern.size() - 3, |
| 1015 | str.data(), str.size() - 5); |
| 1016 | } |
| 1017 | |
| 1018 | TEST(SafeFNMatch, logging) { |
| 1019 | CHECK(WrapSafeFNMatch("foo", "foo")); |
| 1020 | CHECK(!WrapSafeFNMatch("foo", "bar")); |
| 1021 | CHECK(!WrapSafeFNMatch("foo", "fo")); |
| 1022 | CHECK(!WrapSafeFNMatch("foo", "foo2")); |
| 1023 | CHECK(WrapSafeFNMatch("bar/foo.ext", "bar/foo.ext")); |
| 1024 | CHECK(WrapSafeFNMatch("*ba*r/fo*o.ext*", "bar/foo.ext")); |
| 1025 | CHECK(!WrapSafeFNMatch("bar/foo.ext", "bar/baz.ext")); |
| 1026 | CHECK(!WrapSafeFNMatch("bar/foo.ext", "bar/foo")); |
| 1027 | CHECK(!WrapSafeFNMatch("bar/foo.ext", "bar/foo.ext.zip")); |
| 1028 | CHECK(WrapSafeFNMatch("ba?/*.ext", "bar/foo.ext")); |
| 1029 | CHECK(WrapSafeFNMatch("ba?/*.ext", "baZ/FOO.ext")); |
| 1030 | CHECK(!WrapSafeFNMatch("ba?/*.ext", "barr/foo.ext")); |
| 1031 | CHECK(!WrapSafeFNMatch("ba?/*.ext", "bar/foo.ext2")); |
| 1032 | CHECK(WrapSafeFNMatch("ba?/*", "bar/foo.ext2")); |
| 1033 | CHECK(WrapSafeFNMatch("ba?/*", "bar/")); |
| 1034 | CHECK(!WrapSafeFNMatch("ba?/?", "bar/")); |
| 1035 | CHECK(!WrapSafeFNMatch("ba?/*", "bar")); |
| 1036 | } |
| 1037 | |
| 1038 | // TestWaitingLogSink will save messages here |
| 1039 | // No lock: Accessed only by TestLogSinkWriter thread |
| 1040 | // and after its demise by its creator. |
| 1041 | static vector<string> global_messages; |
| 1042 | |
| 1043 | // helper for TestWaitingLogSink below. |
| 1044 | // Thread that does the logic of TestWaitingLogSink |
| 1045 | // It's free to use LOG() itself. |
| 1046 | class TestLogSinkWriter : public Thread { |
| 1047 | public: |
| 1048 | |
| 1049 | TestLogSinkWriter() : should_exit_(false) { |
| 1050 | SetJoinable(true); |
| 1051 | Start(); |
| 1052 | } |
| 1053 | |
| 1054 | // Just buffer it (can't use LOG() here). |
| 1055 | void Buffer(const string& message) { |
| 1056 | mutex_.Lock(); |
| 1057 | RAW_LOG(INFO, "Buffering"); |
| 1058 | messages_.push(message); |
| 1059 | mutex_.Unlock(); |
| 1060 | RAW_LOG(INFO, "Buffered"); |
| 1061 | } |
| 1062 | |
| 1063 | // Wait for the buffer to clear (can't use LOG() here). |
| 1064 | void Wait() { |
| 1065 | RAW_LOG(INFO, "Waiting"); |
| 1066 | mutex_.Lock(); |
| 1067 | while (!NoWork()) { |
| 1068 | mutex_.Unlock(); |
| 1069 | SleepForMilliseconds(1); |
| 1070 | mutex_.Lock(); |
| 1071 | } |
| 1072 | RAW_LOG(INFO, "Waited"); |
| 1073 | mutex_.Unlock(); |
| 1074 | } |
| 1075 | |
| 1076 | // Trigger thread exit. |
| 1077 | void Stop() { |
| 1078 | MutexLock l(&mutex_); |
| 1079 | should_exit_ = true; |
| 1080 | } |
| 1081 | |
| 1082 | private: |
| 1083 | |
| 1084 | // helpers --------------- |
| 1085 | |
| 1086 | // For creating a "Condition". |
| 1087 | bool NoWork() { return messages_.empty(); } |
| 1088 | bool HaveWork() { return !messages_.empty() || should_exit_; } |
| 1089 | |
| 1090 | // Thread body; CAN use LOG() here! |
| 1091 | virtual void Run() { |
| 1092 | while (1) { |
| 1093 | mutex_.Lock(); |
| 1094 | while (!HaveWork()) { |
| 1095 | mutex_.Unlock(); |
| 1096 | SleepForMilliseconds(1); |
| 1097 | mutex_.Lock(); |
| 1098 | } |
| 1099 | if (should_exit_ && messages_.empty()) { |
| 1100 | mutex_.Unlock(); |
| 1101 | break; |
| 1102 | } |
| 1103 | // Give the main thread time to log its message, |
| 1104 | // so that we get a reliable log capture to compare to golden file. |
| 1105 | // Same for the other sleep below. |
| 1106 | SleepForMilliseconds(20); |
| 1107 | RAW_LOG(INFO, "Sink got a messages"); // only RAW_LOG under mutex_ here |
| 1108 | string message = messages_.front(); |
| 1109 | messages_.pop(); |
| 1110 | // Normally this would be some more real/involved logging logic |
| 1111 | // where LOG() usage can't be eliminated, |
| 1112 | // e.g. pushing the message over with an RPC: |
| 1113 | size_t messages_left = messages_.size(); |
| 1114 | mutex_.Unlock(); |
| 1115 | SleepForMilliseconds(20); |
| 1116 | // May not use LOG while holding mutex_, because Buffer() |
| 1117 | // acquires mutex_, and Buffer is called from LOG(), |
| 1118 | // which has its own internal mutex: |
| 1119 | // LOG()->LogToSinks()->TestWaitingLogSink::send()->Buffer() |
| 1120 | LOG(INFO) << "Sink is sending out a message: " << message; |
| 1121 | LOG(INFO) << "Have " << messages_left << " left"; |
| 1122 | global_messages.push_back(message); |
| 1123 | } |
| 1124 | } |
| 1125 | |
| 1126 | // data --------------- |
| 1127 | |
| 1128 | Mutex mutex_; |
| 1129 | bool should_exit_; |
| 1130 | queue<string> messages_; // messages to be logged |
| 1131 | }; |
| 1132 | |
| 1133 | // A log sink that exercises WaitTillSent: |
| 1134 | // it pushes data to a buffer and wakes up another thread to do the logging |
| 1135 | // (that other thread can than use LOG() itself), |
| 1136 | class TestWaitingLogSink : public LogSink { |
| 1137 | public: |
| 1138 | |
| 1139 | TestWaitingLogSink() { |
| 1140 | tid_ = pthread_self(); // for thread-specific behavior |
| 1141 | AddLogSink(this); |
| 1142 | } |
| 1143 | ~TestWaitingLogSink() { |
| 1144 | RemoveLogSink(this); |
| 1145 | writer_.Stop(); |
| 1146 | writer_.Join(); |
| 1147 | } |
| 1148 | |
| 1149 | // (re)define LogSink interface |
| 1150 | |
| 1151 | virtual void send(LogSeverity severity, const char* /* full_filename */, |
| 1152 | const char* base_filename, int line, |
| 1153 | const LogMessageTime &logmsgtime, |
| 1154 | const char* message, size_t message_len) { |
| 1155 | // Push it to Writer thread if we are the original logging thread. |
| 1156 | // Note: Something like ThreadLocalLogSink is a better choice |
| 1157 | // to do thread-specific LogSink logic for real. |
| 1158 | if (pthread_equal(tid_, pthread_self())) { |
| 1159 | writer_.Buffer(ToString(severity, base_filename, line, |
| 1160 | logmsgtime, message, message_len)); |
| 1161 | } |
| 1162 | } |
| 1163 | |
| 1164 | virtual void WaitTillSent() { |
| 1165 | // Wait for Writer thread if we are the original logging thread. |
| 1166 | if (pthread_equal(tid_, pthread_self())) writer_.Wait(); |
| 1167 | } |
| 1168 | |
| 1169 | private: |
| 1170 | |
| 1171 | pthread_t tid_; |
| 1172 | TestLogSinkWriter writer_; |
| 1173 | }; |
| 1174 | |
| 1175 | // Check that LogSink::WaitTillSent can be used in the advertised way. |
| 1176 | // We also do golden-stderr comparison. |
| 1177 | static void TestLogSinkWaitTillSent() { |
| 1178 | { TestWaitingLogSink sink; |
| 1179 | // Sleeps give the sink threads time to do all their work, |
| 1180 | // so that we get a reliable log capture to compare to the golden file. |
| 1181 | LOG(INFO) << "Message 1"; |
| 1182 | SleepForMilliseconds(60); |
| 1183 | LOG(ERROR) << "Message 2"; |
| 1184 | SleepForMilliseconds(60); |
| 1185 | LOG(WARNING) << "Message 3"; |
| 1186 | SleepForMilliseconds(60); |
| 1187 | } |
| 1188 | for (size_t i = 0; i < global_messages.size(); ++i) { |
| 1189 | LOG(INFO) << "Sink capture: " << global_messages[i]; |
| 1190 | } |
| 1191 | CHECK_EQ(global_messages.size(), 3UL); |
| 1192 | } |
| 1193 | |
| 1194 | TEST(Strerror, logging) { |
| 1195 | int errcode = EINTR; |
| 1196 | char *msg = strdup(strerror(errcode)); |
| 1197 | const size_t buf_size = strlen(msg) + 1; |
| 1198 | char *buf = new char[buf_size]; |
| 1199 | CHECK_EQ(posix_strerror_r(errcode, NULL, 0), -1); |
| 1200 | buf[0] = 'A'; |
| 1201 | CHECK_EQ(posix_strerror_r(errcode, buf, 0), -1); |
| 1202 | CHECK_EQ(buf[0], 'A'); |
| 1203 | CHECK_EQ(posix_strerror_r(errcode, NULL, buf_size), -1); |
| 1204 | #if defined(GLOG_OS_MACOSX) || defined(GLOG_OS_FREEBSD) || defined(GLOG_OS_OPENBSD) |
| 1205 | // MacOSX or FreeBSD considers this case is an error since there is |
| 1206 | // no enough space. |
| 1207 | CHECK_EQ(posix_strerror_r(errcode, buf, 1), -1); |
| 1208 | #else |
| 1209 | CHECK_EQ(posix_strerror_r(errcode, buf, 1), 0); |
| 1210 | #endif |
| 1211 | CHECK_STREQ(buf, ""); |
| 1212 | CHECK_EQ(posix_strerror_r(errcode, buf, buf_size), 0); |
| 1213 | CHECK_STREQ(buf, msg); |
| 1214 | delete[] buf; |
| 1215 | CHECK_EQ(msg, StrError(errcode)); |
| 1216 | free(msg); |
| 1217 | } |
| 1218 | |
| 1219 | // Simple routines to look at the sizes of generated code for LOG(FATAL) and |
| 1220 | // CHECK(..) via objdump |
| 1221 | /* |
| 1222 | static void MyFatal() { |
| 1223 | LOG(FATAL) << "Failed"; |
| 1224 | } |
| 1225 | static void MyCheck(bool a, bool b) { |
| 1226 | CHECK_EQ(a, b); |
| 1227 | } |
| 1228 | */ |
| 1229 | #ifdef HAVE_LIB_GMOCK |
| 1230 | |
| 1231 | TEST(DVLog, Basic) { |
| 1232 | ScopedMockLog log; |
| 1233 | |
| 1234 | #if defined(NDEBUG) |
| 1235 | // We are expecting that nothing is logged. |
| 1236 | EXPECT_CALL(log, Log(_, _, _)).Times(0); |
| 1237 | #else |
| 1238 | EXPECT_CALL(log, Log(GLOG_INFO, __FILE__, "debug log")); |
| 1239 | #endif |
| 1240 | |
| 1241 | FLAGS_v = 1; |
| 1242 | DVLOG(1) << "debug log"; |
| 1243 | } |
| 1244 | |
| 1245 | TEST(DVLog, V0) { |
| 1246 | ScopedMockLog log; |
| 1247 | |
| 1248 | // We are expecting that nothing is logged. |
| 1249 | EXPECT_CALL(log, Log(_, _, _)).Times(0); |
| 1250 | |
| 1251 | FLAGS_v = 0; |
| 1252 | DVLOG(1) << "debug log"; |
| 1253 | } |
| 1254 | |
| 1255 | TEST(LogAtLevel, Basic) { |
| 1256 | ScopedMockLog log; |
| 1257 | |
| 1258 | // The function version outputs "logging.h" as a file name. |
| 1259 | EXPECT_CALL(log, Log(GLOG_WARNING, StrNe(__FILE__), "function version")); |
| 1260 | EXPECT_CALL(log, Log(GLOG_INFO, __FILE__, "macro version")); |
| 1261 | |
| 1262 | int severity = GLOG_WARNING; |
| 1263 | LogAtLevel(severity, "function version"); |
| 1264 | |
| 1265 | severity = GLOG_INFO; |
| 1266 | // We can use the macro version as a C++ stream. |
| 1267 | LOG_AT_LEVEL(severity) << "macro" << ' ' << "version"; |
| 1268 | } |
| 1269 | |
| 1270 | TEST(TestExitOnDFatal, ToBeOrNotToBe) { |
| 1271 | // Check the default setting... |
| 1272 | EXPECT_TRUE(base::internal::GetExitOnDFatal()); |
| 1273 | |
| 1274 | // Turn off... |
| 1275 | base::internal::SetExitOnDFatal(false); |
| 1276 | EXPECT_FALSE(base::internal::GetExitOnDFatal()); |
| 1277 | |
| 1278 | // We don't die. |
| 1279 | { |
| 1280 | ScopedMockLog log; |
| 1281 | //EXPECT_CALL(log, Log(_, _, _)).Times(AnyNumber()); |
| 1282 | // LOG(DFATAL) has severity FATAL if debugging, but is |
| 1283 | // downgraded to ERROR if not debugging. |
| 1284 | const LogSeverity severity = |
| 1285 | #if defined(NDEBUG) |
| 1286 | GLOG_ERROR; |
| 1287 | #else |
| 1288 | GLOG_FATAL; |
| 1289 | #endif |
| 1290 | EXPECT_CALL(log, Log(severity, __FILE__, "This should not be fatal")); |
| 1291 | LOG(DFATAL) << "This should not be fatal"; |
| 1292 | } |
| 1293 | |
| 1294 | // Turn back on... |
| 1295 | base::internal::SetExitOnDFatal(true); |
| 1296 | EXPECT_TRUE(base::internal::GetExitOnDFatal()); |
| 1297 | |
| 1298 | #ifdef GTEST_HAS_DEATH_TEST |
| 1299 | // Death comes on little cats' feet. |
| 1300 | EXPECT_DEBUG_DEATH({ |
| 1301 | LOG(DFATAL) << "This should be fatal in debug mode"; |
| 1302 | }, "This should be fatal in debug mode"); |
| 1303 | #endif |
| 1304 | } |
| 1305 | |
| 1306 | #ifdef HAVE_STACKTRACE |
| 1307 | |
| 1308 | static void BacktraceAtHelper() { |
| 1309 | LOG(INFO) << "Not me"; |
| 1310 | |
| 1311 | // The vertical spacing of the next 3 lines is significant. |
| 1312 | LOG(INFO) << "Backtrace me"; |
| 1313 | } |
| 1314 | static int kBacktraceAtLine = __LINE__ - 2; // The line of the LOG(INFO) above |
| 1315 | |
| 1316 | TEST(LogBacktraceAt, DoesNotBacktraceWhenDisabled) { |
| 1317 | StrictMock<ScopedMockLog> log; |
| 1318 | |
| 1319 | FLAGS_log_backtrace_at = ""; |
| 1320 | |
| 1321 | EXPECT_CALL(log, Log(_, _, "Backtrace me")); |
| 1322 | EXPECT_CALL(log, Log(_, _, "Not me")); |
| 1323 | |
| 1324 | BacktraceAtHelper(); |
| 1325 | } |
| 1326 | |
| 1327 | TEST(LogBacktraceAt, DoesBacktraceAtRightLineWhenEnabled) { |
| 1328 | StrictMock<ScopedMockLog> log; |
| 1329 | |
| 1330 | char where[100]; |
| 1331 | snprintf(where, 100, "%s:%d", const_basename(__FILE__), kBacktraceAtLine); |
| 1332 | FLAGS_log_backtrace_at = where; |
| 1333 | |
| 1334 | // The LOG at the specified line should include a stacktrace which includes |
| 1335 | // the name of the containing function, followed by the log message. |
| 1336 | // We use HasSubstr()s instead of ContainsRegex() for environments |
| 1337 | // which don't have regexp. |
| 1338 | EXPECT_CALL(log, Log(_, _, AllOf(HasSubstr("stacktrace:"), |
| 1339 | HasSubstr("BacktraceAtHelper"), |
| 1340 | HasSubstr("main"), |
| 1341 | HasSubstr("Backtrace me")))); |
| 1342 | // Other LOGs should not include a backtrace. |
| 1343 | EXPECT_CALL(log, Log(_, _, "Not me")); |
| 1344 | |
| 1345 | BacktraceAtHelper(); |
| 1346 | } |
| 1347 | |
| 1348 | #endif // HAVE_STACKTRACE |
| 1349 | |
| 1350 | #endif // HAVE_LIB_GMOCK |
| 1351 | |
| 1352 | struct UserDefinedClass { |
| 1353 | bool operator==(const UserDefinedClass&) const { return true; } |
| 1354 | }; |
| 1355 | |
| 1356 | inline ostream& operator<<(ostream& out, const UserDefinedClass&) { |
| 1357 | out << "OK"; |
| 1358 | return out; |
| 1359 | } |
| 1360 | |
| 1361 | TEST(UserDefinedClass, logging) { |
| 1362 | UserDefinedClass u; |
| 1363 | vector<string> buf; |
| 1364 | LOG_STRING(INFO, &buf) << u; |
| 1365 | CHECK_EQ(1UL, buf.size()); |
| 1366 | CHECK(buf[0].find("OK") != string::npos); |
| 1367 | |
| 1368 | // We must be able to compile this. |
| 1369 | CHECK_EQ(u, u); |
| 1370 | } |
| 1371 | |
| 1372 | TEST(LogMsgTime, gmtoff) { |
| 1373 | /* |
| 1374 | * Unit test for GMT offset API |
| 1375 | * TODO: To properly test this API, we need a platform independent way to set time-zone. |
| 1376 | * */ |
| 1377 | google::LogMessage log_obj(__FILE__, __LINE__); |
| 1378 | |
| 1379 | long int nGmtOff = log_obj.getLogMessageTime().gmtoff(); |
| 1380 | // GMT offset ranges from UTC-12:00 to UTC+14:00 |
| 1381 | const long utc_min_offset = -43200; |
| 1382 | const long utc_max_offset = 50400; |
| 1383 | EXPECT_TRUE( (nGmtOff >= utc_min_offset) && (nGmtOff <= utc_max_offset) ); |
| 1384 | } |