123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425 |
- // Copyright (c) 2011 The Chromium Authors. All rights reserved.
- // Use of this source code is governed by a BSD-style license that can be
- // found in the LICENSE file.
- #include "butil/basictypes.h"
- #include "butil/logging.h"
- #include <gtest/gtest.h>
- #include <gflags/gflags.h>
- #if !BRPC_WITH_GLOG
- namespace logging {
- DECLARE_bool(crash_on_fatal_log);
- DECLARE_int32(v);
- namespace {
- // Needs to be global since log assert handlers can't maintain state.
- int log_sink_call_count = 0;
- #if !defined(OFFICIAL_BUILD) || defined(DCHECK_ALWAYS_ON) || !defined(NDEBUG)
- void LogSink(const std::string& str) {
- ++log_sink_call_count;
- }
- #endif
- // Class to make sure any manipulations we do to the min log level are
- // contained (i.e., do not affect other unit tests).
- class LogStateSaver {
- public:
- LogStateSaver() : old_min_log_level_(GetMinLogLevel()) {}
- ~LogStateSaver() {
- SetMinLogLevel(old_min_log_level_);
- SetLogAssertHandler(NULL);
- log_sink_call_count = 0;
- }
- private:
- int old_min_log_level_;
- DISALLOW_COPY_AND_ASSIGN(LogStateSaver);
- };
- class LoggingTest : public testing::Test {
- public:
- virtual void SetUp() {
- _old_crash_on_fatal_log = ::logging::FLAGS_crash_on_fatal_log;
- ::logging::FLAGS_crash_on_fatal_log = true;
- }
- virtual void TearDown() {
- ::logging::FLAGS_crash_on_fatal_log = _old_crash_on_fatal_log;
- if (::logging::FLAGS_v != 0) {
- // Clear -verbose to avoid affecting other tests.
- ASSERT_FALSE(GFLAGS_NS::SetCommandLineOption("v", "0").empty());
- ASSERT_FALSE(GFLAGS_NS::SetCommandLineOption("vmodule", "").empty());
- }
- }
- private:
- bool _old_crash_on_fatal_log;
- LogStateSaver log_state_saver_;
- };
- TEST_F(LoggingTest, LogIsOn) {
- #if defined(NDEBUG)
- const bool kDfatalIsFatal = false;
- #else // defined(NDEBUG)
- const bool kDfatalIsFatal = true;
- #endif // defined(NDEBUG)
- SetMinLogLevel(BLOG_INFO);
- EXPECT_TRUE(LOG_IS_ON(INFO));
- EXPECT_TRUE(LOG_IS_ON(WARNING));
- EXPECT_TRUE(LOG_IS_ON(ERROR));
- EXPECT_TRUE(LOG_IS_ON(FATAL));
- EXPECT_TRUE(LOG_IS_ON(DFATAL));
- SetMinLogLevel(BLOG_WARNING);
- EXPECT_FALSE(LOG_IS_ON(INFO));
- EXPECT_TRUE(LOG_IS_ON(WARNING));
- EXPECT_TRUE(LOG_IS_ON(ERROR));
- EXPECT_TRUE(LOG_IS_ON(FATAL));
- EXPECT_TRUE(LOG_IS_ON(DFATAL));
- SetMinLogLevel(BLOG_ERROR);
- EXPECT_FALSE(LOG_IS_ON(INFO));
- EXPECT_FALSE(LOG_IS_ON(WARNING));
- EXPECT_TRUE(LOG_IS_ON(ERROR));
- EXPECT_TRUE(LOG_IS_ON(FATAL));
- EXPECT_TRUE(LOG_IS_ON(DFATAL));
- // LOG_IS_ON(FATAL) should always be true.
- SetMinLogLevel(BLOG_FATAL + 1);
- EXPECT_FALSE(LOG_IS_ON(INFO));
- EXPECT_FALSE(LOG_IS_ON(WARNING));
- EXPECT_FALSE(LOG_IS_ON(ERROR));
- EXPECT_TRUE(LOG_IS_ON(FATAL));
- EXPECT_TRUE(kDfatalIsFatal == LOG_IS_ON(DFATAL));
- }
- TEST_F(LoggingTest, DebugLoggingReleaseBehavior) {
- #if !defined(NDEBUG)
- int debug_only_variable = 1;
- #endif
- // These should avoid emitting references to |debug_only_variable|
- // in release mode.
- DLOG_IF(INFO, debug_only_variable) << "test";
- DLOG_ASSERT(debug_only_variable) << "test";
- DPLOG_IF(INFO, debug_only_variable) << "test";
- DVLOG_IF(1, debug_only_variable) << "test";
- }
- TEST_F(LoggingTest, Dcheck) {
- #if defined(NDEBUG) && !defined(DCHECK_ALWAYS_ON)
- // Release build.
- EXPECT_FALSE(DCHECK_IS_ON());
- EXPECT_FALSE(DLOG_IS_ON(DCHECK));
- #elif defined(NDEBUG) && defined(DCHECK_ALWAYS_ON)
- // Release build with real DCHECKS.
- SetLogAssertHandler(&LogSink);
- EXPECT_TRUE(DCHECK_IS_ON());
- EXPECT_FALSE(DLOG_IS_ON(DCHECK));
- #else
- // Debug build.
- SetLogAssertHandler(&LogSink);
- EXPECT_TRUE(DCHECK_IS_ON());
- EXPECT_TRUE(DLOG_IS_ON(DCHECK));
- #endif
- EXPECT_EQ(0, log_sink_call_count);
- DCHECK(false);
- EXPECT_EQ(DCHECK_IS_ON() ? 1 : 0, log_sink_call_count);
- DPCHECK(false);
- EXPECT_EQ(DCHECK_IS_ON() ? 2 : 0, log_sink_call_count);
- DCHECK_EQ(0, 1);
- EXPECT_EQ(DCHECK_IS_ON() ? 3 : 0, log_sink_call_count);
- }
- TEST_F(LoggingTest, DcheckReleaseBehavior) {
- int some_variable = 1;
- // These should still reference |some_variable| so we don't get
- // unused variable warnings.
- DCHECK(some_variable) << "test";
- DPCHECK(some_variable) << "test";
- DCHECK_EQ(some_variable, 1) << "test";
- }
- TEST_F(LoggingTest, streaming_log_sanity) {
- ::logging::FLAGS_crash_on_fatal_log = false;
- LOG(WARNING) << 1 << 1.1f << 2l << "apple" << noflush;
- LOG(WARNING) << " orange" << noflush;
- ASSERT_EQ("11.12apple orange", LOG_STREAM(WARNING).content_str());
- ASSERT_EQ("", LOG_STREAM(WARNING).content_str());
-
- LOG(FATAL) << 1 << 1.1f << 2l << "apple" << noflush;
- LOG(FATAL) << " orange" << noflush;
- ASSERT_EQ("11.12apple orange", LOG_STREAM(FATAL).content_str());
- ASSERT_EQ("", LOG_STREAM(FATAL).content_str());
- LOG(TRACE) << 1 << 1.1f << 2l << "apple" << noflush;
- LOG(TRACE) << " orange" << noflush;
- ASSERT_EQ("11.12apple orange", LOG_STREAM(TRACE).content_str());
- ASSERT_EQ("", LOG_STREAM(TRACE).content_str());
-
- LOG(NOTICE) << 1 << 1.1f << 2l << "apple" << noflush;
- LOG(DEBUG) << 1 << 1.1f << 2l << "apple" << noflush;
- LOG(FATAL) << 1 << 1.1f << 2l << "apple";
- LOG(ERROR) << 1 << 1.1f << 2l << "apple";
- LOG(WARNING) << 1 << 1.1f << 2l << "apple";
- LOG(INFO) << 1 << 1.1f << 2l << "apple";
- LOG(TRACE) << 1 << 1.1f << 2l << "apple";
- LOG(NOTICE) << 2 << 2.2f << 3l << "orange" << noflush;
- ASSERT_EQ("11.12apple22.23orange", LOG_STREAM(NOTICE).content_str());
- LOG(DEBUG) << 1 << 1.1f << 2l << "apple";
- errno = EINVAL;
- PLOG(FATAL) << "Error occurred" << noflush;
- ASSERT_EQ("Error occurred: Invalid argument", PLOG_STREAM(FATAL).content_str());
-
- errno = 0;
- PLOG(FATAL) << "Error occurred" << noflush;
- #if defined(OS_LINUX)
- ASSERT_EQ("Error occurred: Success", PLOG_STREAM(FATAL).content_str());
- #else
- ASSERT_EQ("Error occurred: Undefined error: 0", PLOG_STREAM(FATAL).content_str());
- #endif
- errno = EINTR;
- PLOG(FATAL) << "Error occurred" << noflush;
- ASSERT_EQ("Error occurred: Interrupted system call",
- PLOG_STREAM(FATAL).content_str());
- }
- TEST_F(LoggingTest, log_at) {
- ::logging::StringSink log_str;
- ::logging::LogSink* old_sink = ::logging::SetLogSink(&log_str);
- LOG_AT(WARNING, "specified_file.cc", 12345) << "file/line is specified";
- // the file:line part should be using the argument given by us.
- ASSERT_NE(std::string::npos, log_str.find("specified_file.cc:12345"));
- // restore the old sink.
- ::logging::SetLogSink(old_sink);
- }
- #define VLOG_NE(verbose_level) VLOG(verbose_level) << noflush
- #define VLOG2_NE(virtual_path, verbose_level) \
- VLOG2(virtual_path, verbose_level) << noflush
- TEST_F(LoggingTest, vlog_sanity) {
- ::logging::FLAGS_crash_on_fatal_log = false;
- EXPECT_FALSE(GFLAGS_NS::SetCommandLineOption("v", "1").empty());
-
- EXPECT_FALSE(GFLAGS_NS::SetCommandLineOption("vmodule",
- "logging_unittest=1").empty());
- EXPECT_FALSE(GFLAGS_NS::SetCommandLineOption("vmodule",
- "logging_UNITTEST=2").empty());
- for (int i = 0; i < 10; ++i) {
- VLOG_NE(i) << "vlog " << i;
- }
- EXPECT_EQ("vlog 1vlog 2", LOG_STREAM(VERBOSE).content_str());
- EXPECT_EQ("vlog 0", LOG_STREAM(INFO).content_str());
-
- VLOG_NE(-1) << "nothing";
- EXPECT_EQ("", LOG_STREAM(VERBOSE).content_str());
- // VLOG(0) is LOG(INFO)
- VLOG_NE(0) << "always on";
- EXPECT_EQ("always on", LOG_STREAM(INFO).content_str());
- EXPECT_FALSE(GFLAGS_NS::SetCommandLineOption("vmodule",
- "logging_unittest=0").empty());
- for (int i = 0; i < 10; ++i) {
- VLOG_NE(i) << "vlog " << i;
- }
- EXPECT_EQ("", LOG_STREAM(VERBOSE).content_str());
- EXPECT_EQ("vlog 0", LOG_STREAM(INFO).content_str());
- EXPECT_FALSE(GFLAGS_NS::SetCommandLineOption("vmodule",
- "logging_unittest=0,logging_unittest=1").empty());
- for (int i = 0; i < 10; ++i) {
- VLOG_NE(i) << "vlog " << i;
- }
- EXPECT_EQ("vlog 1", LOG_STREAM(VERBOSE).content_str());
- EXPECT_EQ("vlog 0", LOG_STREAM(INFO).content_str());
- EXPECT_FALSE(GFLAGS_NS::SetCommandLineOption("vmodule",
- "logging_unittest=1,logging_unittest=0").empty());
- for (int i = 0; i < 10; ++i) {
- VLOG_NE(i) << "vlog " << i;
- }
- EXPECT_EQ("", LOG_STREAM(VERBOSE).content_str());
- EXPECT_EQ("vlog 0", LOG_STREAM(INFO).content_str());
- EXPECT_FALSE(GFLAGS_NS::SetCommandLineOption("vmodule", "").empty());
- for (int i = 0; i < 10; ++i) {
- VLOG_NE(i) << "vlog " << i;
- }
- EXPECT_EQ("vlog 1", LOG_STREAM(VERBOSE).content_str());
- EXPECT_EQ("vlog 0", LOG_STREAM(INFO).content_str());
- EXPECT_FALSE(GFLAGS_NS::SetCommandLineOption("vmodule",
- "logg?ng_*=2").empty());
- for (int i = 0; i < 10; ++i) {
- VLOG_NE(i) << "vlog " << i;
- }
- EXPECT_EQ("vlog 1vlog 2", LOG_STREAM(VERBOSE).content_str());
- EXPECT_EQ("vlog 0", LOG_STREAM(INFO).content_str());
- EXPECT_FALSE(GFLAGS_NS::SetCommandLineOption("vmodule",
- "foo=3,logging_unittest=3, logg?ng_*=2 , logging_*=1 ").empty());
- for (int i = 0; i < 10; ++i) {
- VLOG_NE(i) << "vlog " << i;
- }
- EXPECT_EQ("vlog 1vlog 2vlog 3", LOG_STREAM(VERBOSE).content_str());
- EXPECT_EQ("vlog 0", LOG_STREAM(INFO).content_str());
- for (int i = 0; i < 10; ++i) {
- VLOG_IF(i, i % 2 == 1) << "vlog " << i << noflush;
- }
- EXPECT_EQ("vlog 1vlog 3", LOG_STREAM(VERBOSE).content_str());
- EXPECT_FALSE(GFLAGS_NS::SetCommandLineOption(
- "vmodule",
- "foo/bar0/0=2,foo/bar/1=3, 2=4, foo/*/3=5, */ba?/4=6,"
- "/5=7,/foo/bar/6=8,foo2/bar/7=9,foo/bar/8=9").empty());
- VLOG2_NE("foo/bar/0", 2) << " vlog0";
- VLOG2_NE("foo/bar0/0", 2) << " vlog0.0";
- VLOG2_NE("foo/bar/1", 3) << " vlog1";
- VLOG2_NE("foo/bar/2", 4) << " vlog2";
- VLOG2_NE("foo/bar2/2", 4) << " vlog2.2";
- VLOG2_NE("foo/bar/3", 5) << " vlog3";
- VLOG2_NE("foo/bar/4", 6) << " vlog4";
- VLOG2_NE("foo/bar/5", 7) << " vlog5";
- VLOG2_NE("foo/bar/6", 8) << " vlog6";
- VLOG2_NE("foo/bar/7", 9) << " vlog7";
- VLOG2_NE("foo/bar/8", 10) << " vlog8";
- VLOG2_NE("foo/bar/9", 11) << " vlog9";
- EXPECT_EQ(" vlog0.0 vlog1 vlog2 vlog2.2 vlog3 vlog4",
- LOG_STREAM(VERBOSE).content_str());
- // Make sure verbose log is not flushed to other levels.
- ASSERT_TRUE(LOG_STREAM(FATAL).content_str().empty());
- ASSERT_TRUE(LOG_STREAM(ERROR).content_str().empty());
- ASSERT_TRUE(LOG_STREAM(WARNING).content_str().empty());
- ASSERT_TRUE(LOG_STREAM(NOTICE).content_str().empty());
- ASSERT_TRUE(LOG_STREAM(INFO).content_str().empty());
- }
- TEST_F(LoggingTest, check) {
- ::logging::FLAGS_crash_on_fatal_log = false;
- CHECK(1 < 2);
- CHECK(1 > 2);
- int a = 1;
- int b = 2;
- CHECK(a > b) << "bad! a=" << a << " b=" << b;
- CHECK_EQ(a, b) << "a=" << a << " b=" << b;
- CHECK_EQ(1, 1) << "a=" << a << " b=" << b;
- CHECK_NE(2, 1);
- CHECK_NE(1, 2) << "blah0";
- CHECK_NE(2, 2) << "blah1";
-
- CHECK_LT(2, 3);
- CHECK_LT(3, 2) << "blah2";
- CHECK_LT(3, 3) << "blah3";
- CHECK_LE(2, 3);
- CHECK_LE(3, 2) << "blah4";
- CHECK_LE(3, 3);
- CHECK_GT(3, 2);
- CHECK_GT(1, 2) << "1 can't be greater than 2";
- CHECK_GT(3, 3) << "blah5";
- CHECK_GE(3, 2);
- CHECK_GE(2, 3) << "blah6";
- CHECK_GE(3, 3);
- }
- int foo(int* p) {
- return ++*p;
- }
- TEST_F(LoggingTest, debug_level) {
- ::logging::FLAGS_crash_on_fatal_log = false;
- int run_foo = 0;
- LOG(DEBUG) << foo(&run_foo) << noflush;
- LOG(DEBUG) << foo(&run_foo);
-
- DLOG(FATAL) << foo(&run_foo);
- DLOG(WARNING) << foo(&run_foo);
- DLOG(TRACE) << foo(&run_foo);
- DLOG(NOTICE) << foo(&run_foo);
- DLOG(DEBUG) << foo(&run_foo);
- EXPECT_FALSE(GFLAGS_NS::SetCommandLineOption("vmodule", "").empty());
- EXPECT_FALSE(GFLAGS_NS::SetCommandLineOption("v", "1").empty());
- DVLOG(1) << foo(&run_foo);
- DVLOG2("a/b/c", 1) << foo(&run_foo);
- #ifdef NDEBUG
- ASSERT_EQ(0, run_foo);
- #else
- ASSERT_EQ(9, run_foo);
- #endif
- }
- static void need_ostream(std::ostream& os, const char* s) {
- os << s;
- }
- TEST_F(LoggingTest, as_ostream) {
- ::logging::FLAGS_crash_on_fatal_log = false;
- need_ostream(LOG_STREAM(WARNING) << noflush, "hello");
- ASSERT_EQ("hello", LOG_STREAM(WARNING).content_str());
- need_ostream(LOG_STREAM(WARNING), "hello");
- ASSERT_EQ("", LOG_STREAM(WARNING).content_str());
- need_ostream(LOG_STREAM(INFO) << noflush, "world");
- ASSERT_EQ("world", LOG_STREAM(INFO).content_str());
- need_ostream(LOG_STREAM(INFO), "world");
- ASSERT_EQ("", LOG_STREAM(INFO).content_str());
- LOG(WARNING) << 1.123456789;
- const std::streamsize saved_prec = LOG_STREAM(WARNING).precision(2);
- LOG(WARNING) << 1.123456789;
- LOG_STREAM(WARNING).precision(saved_prec);
- LOG(WARNING) << 1.123456789;
- }
- TEST_F(LoggingTest, limited_logging) {
- for (int i = 0; i < 100000; ++i) {
- LOG_ONCE(INFO) << "HEHE1";
- LOG_ONCE(INFO) << "HEHE2";
- VLOG_ONCE(1) << "VHEHE3";
- VLOG_ONCE(1) << "VHEHE4";
- LOG_EVERY_N(INFO, 10000) << "i1=" << i;
- LOG_EVERY_N(INFO, 5000) << "i2=" << i;
- VLOG_EVERY_N(1, 10000) << "vi3=" << i;
- VLOG_EVERY_N(1, 5000) << "vi4=" << i;
- }
- for (int i = 0; i < 300; ++i) {
- LOG_EVERY_SECOND(INFO) << "i1=" << i;
- LOG_EVERY_SECOND(INFO) << "i2=" << i;
- VLOG_EVERY_SECOND(1) << "vi3=" << i;
- VLOG_EVERY_SECOND(1) << "vi4=" << i;
- usleep(10000);
- }
- }
- } // namespace
- } // namespace logging
- #endif
|