rtc_base/logging_unittest.cc - src - Git at Google

 /*
  *  Copyright 2004 The WebRTC Project Authors. All rights reserved.
  *
  *  Use of this source code is governed by a BSD-style license
  *  that can be found in the LICENSE file in the root of the source
  *  tree. An additional intellectual property rights grant can be found
  *  in the file PATENTS.  All contributing project authors may
  *  be found in the AUTHORS file in the root of the source tree.
  */

 #include "rtc_base/logging.h"
 #include "rtc_base/arraysize.h"
 #include "rtc_base/checks.h"
 #include "rtc_base/event.h"
 #include "rtc_base/gunit.h"
 #include "rtc_base/platform_thread.h"
 #include "rtc_base/stream.h"
 #include "test/testsupport/fileutils.h"

 namespace rtc {

 template <typename Base>
 class LogSinkImpl
     : public LogSink,
       public Base {
  public:
   LogSinkImpl() {}

   template<typename P>
   explicit LogSinkImpl(P* p) : Base(p) {}

  private:
   void OnLogMessage(const std::string& message) override {
     static_cast<Base*>(this)->WriteAll(
         message.data(), message.size(), nullptr, nullptr);
   }
 };

 class LogMessageForTesting : public LogMessage {
  public:
   LogMessageForTesting(const char* file,
                        int line,
                        LoggingSeverity sev,
                        LogErrorContext err_ctx = ERRCTX_NONE,
                        int err = 0)
       : LogMessage(file, line, sev, err_ctx, err) {}

   const std::string& get_extra() const { return extra_; }
   bool is_noop() const { return is_noop_; }

   // Returns the contents of the internal log stream.
   // Note that parts of the stream won't (as is) be available until *after* the
   // dtor of the parent class has run. So, as is, this only represents a
   // partially built stream.
   std::string GetPrintStream() {
     RTC_DCHECK(!is_finished_);
     is_finished_ = true;
     FinishPrintStream();
     std::string ret = print_stream_.str();
     // Just to make an error even more clear if the stream gets used after this.
     print_stream_.clear();
     return ret;
   }

  private:
   bool is_finished_ = false;
 };

 // Test basic logging operation. We should get the INFO log but not the VERBOSE.
 // We should restore the correct global state at the end.
 TEST(LogTest, SingleStream) {
   int sev = LogMessage::GetLogToStream(nullptr);

   std::string str;
   LogSinkImpl<StringStream> stream(&str);
   LogMessage::AddLogToStream(&stream, LS_INFO);
   EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream));

   RTC_LOG(LS_INFO) << "INFO";
   RTC_LOG(LS_VERBOSE) << "VERBOSE";
   EXPECT_NE(std::string::npos, str.find("INFO"));
   EXPECT_EQ(std::string::npos, str.find("VERBOSE"));

   LogMessage::RemoveLogToStream(&stream);
   EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream));

   EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
 }

 #if GTEST_HAS_DEATH_TEST && !defined(WEBRTC_ANDROID)
 TEST(LogTest, Checks) {
   EXPECT_DEATH(FATAL() << "message",
                "\n\n#\n"
                "# Fatal error in: \\S+, line \\d+\n"
                "# last system error: \\d+\n"
                "# Check failed: FATAL\\(\\)\n"
                "# message"
                );

   int a = 1, b = 2;
   EXPECT_DEATH(RTC_CHECK_EQ(a, b) << 1 << 2u,
                "\n\n#\n"
                "# Fatal error in: \\S+, line \\d+\n"
                "# last system error: \\d+\n"
                "# Check failed: a == b \\(1 vs. 2\\)\n"
                "# 12"
                );
   RTC_CHECK_EQ(5, 5);

   RTC_CHECK(true) << "Shouldn't crash" << 1;
   EXPECT_DEATH(RTC_CHECK(false) << "Hi there!",
                "\n\n#\n"
                "# Fatal error in: \\S+, line \\d+\n"
                "# last system error: \\d+\n"
                "# Check failed: false\n"
                "# Hi there!"
                );
 }
 #endif

 // Test using multiple log streams. The INFO stream should get the INFO message,
 // the VERBOSE stream should get the INFO and the VERBOSE.
 // We should restore the correct global state at the end.
 TEST(LogTest, MultipleStreams) {
   int sev = LogMessage::GetLogToStream(nullptr);

   std::string str1, str2;
   LogSinkImpl<StringStream> stream1(&str1), stream2(&str2);
   LogMessage::AddLogToStream(&stream1, LS_INFO);
   LogMessage::AddLogToStream(&stream2, LS_VERBOSE);
   EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream1));
   EXPECT_EQ(LS_VERBOSE, LogMessage::GetLogToStream(&stream2));

   RTC_LOG(LS_INFO) << "INFO";
   RTC_LOG(LS_VERBOSE) << "VERBOSE";

   EXPECT_NE(std::string::npos, str1.find("INFO"));
   EXPECT_EQ(std::string::npos, str1.find("VERBOSE"));
   EXPECT_NE(std::string::npos, str2.find("INFO"));
   EXPECT_NE(std::string::npos, str2.find("VERBOSE"));

   LogMessage::RemoveLogToStream(&stream2);
   LogMessage::RemoveLogToStream(&stream1);
   EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream2));
   EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream1));

   EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
 }

 class LogThread {
  public:
   LogThread() : thread_(&ThreadEntry, this, "LogThread") {}
   ~LogThread() { thread_.Stop(); }

   void Start() { thread_.Start(); }

  private:
   void Run() {
     // LS_SENSITIVE by default to avoid cluttering up any real logging going on.
     RTC_LOG(LS_SENSITIVE) << "RTC_LOG";
   }

   static void ThreadEntry(void* p) { static_cast<LogThread*>(p)->Run(); }

   PlatformThread thread_;
   Event event_{false, false};
 };

 // Ensure we don't crash when adding/removing streams while threads are going.
 // We should restore the correct global state at the end.
 // This test also makes sure that the 'noop' stream() singleton object, can be
 // safely used from mutiple threads since the threads log at LS_SENSITIVE
 // (by default 'noop' entries).
 TEST(LogTest, MultipleThreads) {
   int sev = LogMessage::GetLogToStream(nullptr);

   LogThread thread1, thread2, thread3;
   thread1.Start();
   thread2.Start();
   thread3.Start();

   LogSinkImpl<NullStream> stream1, stream2, stream3;
   for (int i = 0; i < 1000; ++i) {
     LogMessage::AddLogToStream(&stream1, LS_INFO);
     LogMessage::AddLogToStream(&stream2, LS_VERBOSE);
     LogMessage::AddLogToStream(&stream3, LS_SENSITIVE);
     LogMessage::RemoveLogToStream(&stream1);
     LogMessage::RemoveLogToStream(&stream2);
     LogMessage::RemoveLogToStream(&stream3);
   }

   EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
 }


 TEST(LogTest, WallClockStartTime) {
   uint32_t time = LogMessage::WallClockStartTime();
   // Expect the time to be in a sensible range, e.g. > 2012-01-01.
   EXPECT_GT(time, 1325376000u);
 }

 TEST(LogTest, CheckExtraErrorField) {
   LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_WARNING,
                                ERRCTX_ERRNO, 0xD);
   ASSERT_FALSE(log_msg.is_noop());
   log_msg.stream() << "This gets added at dtor time";

   const std::string& extra = log_msg.get_extra();
   const size_t length_to_check = arraysize("[0x12345678]") - 1;
   ASSERT_GE(extra.length(), length_to_check);
   EXPECT_EQ(std::string("[0x0000000D]"), extra.substr(0, length_to_check));
 }

 TEST(LogTest, CheckFilePathParsed) {
   LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_INFO);
   ASSERT_FALSE(log_msg.is_noop());
   log_msg.stream() << "<- Does this look right?";

   const std::string stream = log_msg.GetPrintStream();
   EXPECT_NE(std::string::npos, stream.find("(myfile.cc:100)"));
 }

 TEST(LogTest, CheckNoopLogEntry) {
   if (LogMessage::GetLogToDebug() <= LS_SENSITIVE) {
     printf("CheckNoopLogEntry: skipping. Global severity is being overridden.");
     return;
   }

   // Logging at LS_SENSITIVE severity, is by default turned off, so this should
   // be treated as a noop message.
   LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_SENSITIVE);
   log_msg.stream() << "Should be logged to nowhere.";
   EXPECT_TRUE(log_msg.is_noop());
   const std::string stream = log_msg.GetPrintStream();
   EXPECT_TRUE(stream.empty());
 }

 // Test the time required to write 1000 80-character logs to a string.
 TEST(LogTest, Perf) {
   std::string str;
   LogSinkImpl<StringStream> stream(&str);
   LogMessage::AddLogToStream(&stream, LS_SENSITIVE);

   const std::string message(80, 'X');
   {
     // Just to be sure that we're not measuring the performance of logging
     // noop log messages.
     LogMessageForTesting sanity_check_msg(__FILE__, __LINE__, LS_SENSITIVE);
     ASSERT_FALSE(sanity_check_msg.is_noop());
   }

   // We now know how many bytes the logging framework will tag onto every msg.
   const size_t logging_overhead = str.size();
   // Reset the stream to 0 size.
   str.clear();
   str.reserve(120000);
   static const int kRepetitions = 1000;

   int64_t start = TimeMillis(), finish;
   for (int i = 0; i < kRepetitions; ++i) {
     LogMessageForTesting(__FILE__, __LINE__, LS_SENSITIVE).stream() << message;
   }
   finish = TimeMillis();

   LogMessage::RemoveLogToStream(&stream);
   stream.Close();

   EXPECT_EQ(str.size(), (message.size() + logging_overhead) * kRepetitions);
   RTC_LOG(LS_INFO) << "Total log time: " << TimeDiff(finish, start) << " ms "
                    << " total bytes logged: " << str.size();
 }

 }  // namespace rtc
	/*
	* Copyright 2004 The WebRTC Project Authors. All rights reserved.
	*
	* Use of this source code is governed by a BSD-style license
	* that can be found in the LICENSE file in the root of the source
	* tree. An additional intellectual property rights grant can be found
	* in the file PATENTS. All contributing project authors may
	* be found in the AUTHORS file in the root of the source tree.
	*/

	#include "rtc_base/logging.h"
	#include "rtc_base/arraysize.h"
	#include "rtc_base/checks.h"
	#include "rtc_base/event.h"
	#include "rtc_base/gunit.h"
	#include "rtc_base/platform_thread.h"
	#include "rtc_base/stream.h"
	#include "test/testsupport/fileutils.h"

	namespace rtc {

	template <typename Base>
	class LogSinkImpl
	: public LogSink,
	public Base {
	public:
	LogSinkImpl() {}

	template<typename P>
	explicit LogSinkImpl(P* p) : Base(p) {}

	private:
	void OnLogMessage(const std::string& message) override {
	static_cast<Base*>(this)->WriteAll(
	message.data(), message.size(), nullptr, nullptr);
	}
	};

	class LogMessageForTesting : public LogMessage {
	public:
	LogMessageForTesting(const char* file,
	int line,
	LoggingSeverity sev,
	LogErrorContext err_ctx = ERRCTX_NONE,
	int err = 0)
	: LogMessage(file, line, sev, err_ctx, err) {}

	const std::string& get_extra() const { return extra_; }
	bool is_noop() const { return is_noop_; }

	// Returns the contents of the internal log stream.
	// Note that parts of the stream won't (as is) be available until after the
	// dtor of the parent class has run. So, as is, this only represents a
	// partially built stream.
	std::string GetPrintStream() {
	RTC_DCHECK(!is_finished_);
	is_finished_ = true;
	FinishPrintStream();
	std::string ret = print_stream_.str();
	// Just to make an error even more clear if the stream gets used after this.
	print_stream_.clear();
	return ret;
	}

	private:
	bool is_finished_ = false;
	};

	// Test basic logging operation. We should get the INFO log but not the VERBOSE.
	// We should restore the correct global state at the end.
	TEST(LogTest, SingleStream) {
	int sev = LogMessage::GetLogToStream(nullptr);

	std::string str;
	LogSinkImpl<StringStream> stream(&str);
	LogMessage::AddLogToStream(&stream, LS_INFO);
	EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream));

	RTC_LOG(LS_INFO) << "INFO";
	RTC_LOG(LS_VERBOSE) << "VERBOSE";
	EXPECT_NE(std::string::npos, str.find("INFO"));
	EXPECT_EQ(std::string::npos, str.find("VERBOSE"));

	LogMessage::RemoveLogToStream(&stream);
	EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream));

	EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
	}

	#if GTEST_HAS_DEATH_TEST && !defined(WEBRTC_ANDROID)
	TEST(LogTest, Checks) {
	EXPECT_DEATH(FATAL() << "message",
	"\n\n#\n"
	"# Fatal error in: \\S+, line \\d+\n"
	"# last system error: \\d+\n"
	"# Check failed: FATAL\\(\\)\n"
	"# message"
	);

	int a = 1, b = 2;
	EXPECT_DEATH(RTC_CHECK_EQ(a, b) << 1 << 2u,
	"\n\n#\n"
	"# Fatal error in: \\S+, line \\d+\n"
	"# last system error: \\d+\n"
	"# Check failed: a == b \\(1 vs. 2\\)\n"
	"# 12"
	);
	RTC_CHECK_EQ(5, 5);

	RTC_CHECK(true) << "Shouldn't crash" << 1;
	EXPECT_DEATH(RTC_CHECK(false) << "Hi there!",
	"\n\n#\n"
	"# Fatal error in: \\S+, line \\d+\n"
	"# last system error: \\d+\n"
	"# Check failed: false\n"
	"# Hi there!"
	);
	}
	#endif

	// Test using multiple log streams. The INFO stream should get the INFO message,
	// the VERBOSE stream should get the INFO and the VERBOSE.
	// We should restore the correct global state at the end.
	TEST(LogTest, MultipleStreams) {
	int sev = LogMessage::GetLogToStream(nullptr);

	std::string str1, str2;
	LogSinkImpl<StringStream> stream1(&str1), stream2(&str2);
	LogMessage::AddLogToStream(&stream1, LS_INFO);
	LogMessage::AddLogToStream(&stream2, LS_VERBOSE);
	EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream1));
	EXPECT_EQ(LS_VERBOSE, LogMessage::GetLogToStream(&stream2));

	RTC_LOG(LS_INFO) << "INFO";
	RTC_LOG(LS_VERBOSE) << "VERBOSE";

	EXPECT_NE(std::string::npos, str1.find("INFO"));
	EXPECT_EQ(std::string::npos, str1.find("VERBOSE"));
	EXPECT_NE(std::string::npos, str2.find("INFO"));
	EXPECT_NE(std::string::npos, str2.find("VERBOSE"));

	LogMessage::RemoveLogToStream(&stream2);
	LogMessage::RemoveLogToStream(&stream1);
	EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream2));
	EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream1));

	EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
	}

	class LogThread {
	public:
	LogThread() : thread_(&ThreadEntry, this, "LogThread") {}
	~LogThread() { thread_.Stop(); }

	void Start() { thread_.Start(); }

	private:
	void Run() {
	// LS_SENSITIVE by default to avoid cluttering up any real logging going on.
	RTC_LOG(LS_SENSITIVE) << "RTC_LOG";
	}

	static void ThreadEntry(void* p) { static_cast<LogThread*>(p)->Run(); }

	PlatformThread thread_;
	Event event_{false, false};
	};

	// Ensure we don't crash when adding/removing streams while threads are going.
	// We should restore the correct global state at the end.
	// This test also makes sure that the 'noop' stream() singleton object, can be
	// safely used from mutiple threads since the threads log at LS_SENSITIVE
	// (by default 'noop' entries).
	TEST(LogTest, MultipleThreads) {
	int sev = LogMessage::GetLogToStream(nullptr);

	LogThread thread1, thread2, thread3;
	thread1.Start();
	thread2.Start();
	thread3.Start();

	LogSinkImpl<NullStream> stream1, stream2, stream3;
	for (int i = 0; i < 1000; ++i) {
	LogMessage::AddLogToStream(&stream1, LS_INFO);
	LogMessage::AddLogToStream(&stream2, LS_VERBOSE);
	LogMessage::AddLogToStream(&stream3, LS_SENSITIVE);
	LogMessage::RemoveLogToStream(&stream1);
	LogMessage::RemoveLogToStream(&stream2);
	LogMessage::RemoveLogToStream(&stream3);
	}

	EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
	}


	TEST(LogTest, WallClockStartTime) {
	uint32_t time = LogMessage::WallClockStartTime();
	// Expect the time to be in a sensible range, e.g. > 2012-01-01.
	EXPECT_GT(time, 1325376000u);
	}

	TEST(LogTest, CheckExtraErrorField) {
	LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_WARNING,
	ERRCTX_ERRNO, 0xD);
	ASSERT_FALSE(log_msg.is_noop());
	log_msg.stream() << "This gets added at dtor time";

	const std::string& extra = log_msg.get_extra();
	const size_t length_to_check = arraysize("[0x12345678]") - 1;
	ASSERT_GE(extra.length(), length_to_check);
	EXPECT_EQ(std::string("[0x0000000D]"), extra.substr(0, length_to_check));
	}

	TEST(LogTest, CheckFilePathParsed) {
	LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_INFO);
	ASSERT_FALSE(log_msg.is_noop());
	log_msg.stream() << "<- Does this look right?";

	const std::string stream = log_msg.GetPrintStream();
	EXPECT_NE(std::string::npos, stream.find("(myfile.cc:100)"));
	}

	TEST(LogTest, CheckNoopLogEntry) {
	if (LogMessage::GetLogToDebug() <= LS_SENSITIVE) {
	printf("CheckNoopLogEntry: skipping. Global severity is being overridden.");
	return;
	}

	// Logging at LS_SENSITIVE severity, is by default turned off, so this should
	// be treated as a noop message.
	LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_SENSITIVE);
	log_msg.stream() << "Should be logged to nowhere.";
	EXPECT_TRUE(log_msg.is_noop());
	const std::string stream = log_msg.GetPrintStream();
	EXPECT_TRUE(stream.empty());
	}

	// Test the time required to write 1000 80-character logs to a string.
	TEST(LogTest, Perf) {
	std::string str;
	LogSinkImpl<StringStream> stream(&str);
	LogMessage::AddLogToStream(&stream, LS_SENSITIVE);

	const std::string message(80, 'X');
	{
	// Just to be sure that we're not measuring the performance of logging
	// noop log messages.
	LogMessageForTesting sanity_check_msg(__FILE__, __LINE__, LS_SENSITIVE);
	ASSERT_FALSE(sanity_check_msg.is_noop());
	}

	// We now know how many bytes the logging framework will tag onto every msg.
	const size_t logging_overhead = str.size();
	// Reset the stream to 0 size.
	str.clear();
	str.reserve(120000);
	static const int kRepetitions = 1000;

	int64_t start = TimeMillis(), finish;
	for (int i = 0; i < kRepetitions; ++i) {
	LogMessageForTesting(__FILE__, __LINE__, LS_SENSITIVE).stream() << message;
	}
	finish = TimeMillis();

	LogMessage::RemoveLogToStream(&stream);
	stream.Close();

	EXPECT_EQ(str.size(), (message.size() + logging_overhead) * kRepetitions);
	RTC_LOG(LS_INFO) << "Total log time: " << TimeDiff(finish, start) << " ms "
	<< " total bytes logged: " << str.size();
	}

	} // namespace rtc