Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 1 | // Copyright (c) 2012 The Chromium OS Authors. All rights reserved. |
| 2 | // Use of this source code is governed by a BSD-style license that can be |
| 3 | // found in the LICENSE file. |
| 4 | |
| 5 | #include <deque> |
| 6 | #include <string> |
| 7 | |
| 8 | #include <base/file_util.h> |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 9 | #include <base/scoped_temp_dir.h> |
| 10 | #include <gmock/gmock.h> |
| 11 | #include <gtest/gtest.h> |
| 12 | |
Christopher Wiley | b691efd | 2012-08-09 13:51:51 -0700 | [diff] [blame] | 13 | #include "shill/logging.h" |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 14 | #include "shill/mock_log.h" |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 15 | |
| 16 | using testing::_; |
| 17 | |
| 18 | namespace { |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 19 | |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 20 | const char kTestStr1[] = "What does Mr Wallace look like?"; |
| 21 | const char kTestStr2[] = "And now little man, I give the watch to you."; |
| 22 | const char kTestStr3[] = "This is a tasty burger!"; |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 23 | |
| 24 | } // namespace |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 25 | |
| 26 | namespace shill { |
| 27 | |
| 28 | class MemoryLogTest : public testing::Test { |
| 29 | protected: |
| 30 | void TearDown() { |
| 31 | // Restore everything to defaults once more. |
| 32 | MemoryLog::GetInstance()->Clear(); |
| 33 | MemoryLog::GetInstance()->SetMaximumSize( |
| 34 | MemoryLog::kDefaultMaximumMemoryLogSizeInBytes); |
| 35 | ScopeLogger::GetInstance()->set_verbose_level(0); |
| 36 | ScopeLogger::GetInstance()->EnableScopesByName(""); |
| 37 | ::logging::SetMinLogLevel(logging::LOG_INFO); |
| 38 | } |
| 39 | }; |
| 40 | |
| 41 | TEST_F(MemoryLogTest, ScopedLoggerStillWorks) { |
| 42 | ScopedMockLog log; |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 43 | EXPECT_CALL(log, Log(_, _, kTestStr1)); |
| 44 | EXPECT_CALL(log, Log(_, _, kTestStr2)); |
Christopher Wiley | b691efd | 2012-08-09 13:51:51 -0700 | [diff] [blame] | 45 | SLOG(WiFi, 2) << "does not get through"; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 46 | ScopeLogger::GetInstance()->EnableScopesByName("+wifi"); |
| 47 | // Verbose levels are inverted. |
| 48 | ScopeLogger::GetInstance()->set_verbose_level(3); |
Christopher Wiley | b691efd | 2012-08-09 13:51:51 -0700 | [diff] [blame] | 49 | SLOG(WiFi, 2) << kTestStr1; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 50 | // It would be nice if the compiler didn't optimize out my conditional check. |
Christopher Wiley | b691efd | 2012-08-09 13:51:51 -0700 | [diff] [blame] | 51 | SLOG_IF(WiFi, 3, strlen("two") == 3) << kTestStr2; |
| 52 | SLOG_IF(WiFi, 3, strlen("one") == 2) << "does not get through again"; |
| 53 | SLOG(WiFi, 4) << "spanish inquisition"; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 54 | } |
| 55 | |
| 56 | TEST_F(MemoryLogTest, NormalLoggingStillWorks) { |
| 57 | ::logging::SetMinLogLevel(logging::LOG_WARNING); |
| 58 | ScopedMockLog log; |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 59 | EXPECT_CALL(log, Log(_, _, kTestStr1)); |
| 60 | EXPECT_CALL(log, Log(_, _, kTestStr2)); |
| 61 | LOG(ERROR) << kTestStr1; |
| 62 | LOG(INFO) << "does not propagate down"; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 63 | // It would be nice if the compiler didn't optimize out my conditional check. |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 64 | LOG_IF(WARNING, strlen("two") == 3) << kTestStr2; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 65 | } |
| 66 | |
| 67 | TEST_F(MemoryLogTest, MemoryLogIsLogging) { |
| 68 | ScopedMockLog log; |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 69 | EXPECT_CALL(log, Log(_, _, kTestStr1)); |
| 70 | EXPECT_CALL(log, Log(_, _, kTestStr2)); |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 71 | ::logging::SetMinLogLevel(logging::LOG_WARNING); |
| 72 | ASSERT_EQ(0, MemoryLog::GetInstance()->current_size_bytes()); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 73 | LOG(WARNING) << kTestStr1; |
| 74 | LOG(WARNING) << kTestStr2; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 75 | // LT because of the prefixes prepended by the logger |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 76 | EXPECT_LT(strlen(kTestStr1) + strlen(kTestStr2), |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 77 | MemoryLog::GetInstance()->current_size_bytes()); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 78 | EXPECT_EQ(2, MemoryLog::GetInstance()->TestGetNumberMessages()); |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 79 | MemoryLog::GetInstance()->Clear(); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 80 | EXPECT_EQ(0, MemoryLog::GetInstance()->current_size_bytes()); |
| 81 | EXPECT_EQ(0, MemoryLog::GetInstance()->TestGetNumberMessages()); |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 82 | } |
| 83 | |
| 84 | TEST_F(MemoryLogTest, MemoryLogLimitingWorks) { |
| 85 | ScopedMockLog log; |
| 86 | ::logging::SetMinLogLevel(logging::LOG_WARNING); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 87 | LOG(INFO) << kTestStr1; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 88 | size_t old_size = MemoryLog::GetInstance()->current_size_bytes(); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 89 | LOG(INFO) << kTestStr2; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 90 | size_t new_size = MemoryLog::GetInstance()->current_size_bytes(); |
| 91 | // Setting the size just above the current size shouldn't affect anything. |
| 92 | MemoryLog::GetInstance()->SetMaximumSize(new_size + 1); |
| 93 | ASSERT_EQ(new_size, MemoryLog::GetInstance()->current_size_bytes()); |
| 94 | // Force MemoryLog to discard the earliest message |
| 95 | MemoryLog::GetInstance()->SetMaximumSize(new_size - 1); |
| 96 | // Should be just last message in the buffer. |
| 97 | ASSERT_EQ(new_size - old_size, |
| 98 | MemoryLog::GetInstance()->current_size_bytes()); |
| 99 | // Now force it to discard the most recent message. |
| 100 | MemoryLog::GetInstance()->SetMaximumSize(0); |
| 101 | ASSERT_EQ(0, MemoryLog::GetInstance()->current_size_bytes()); |
| 102 | // Can't log if we don't have room, but the messages should still get to LOG |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 103 | EXPECT_CALL(log, Log(_, _, kTestStr3)); |
| 104 | LOG(WARNING) << kTestStr3; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 105 | ASSERT_EQ(0, MemoryLog::GetInstance()->current_size_bytes()); |
| 106 | ASSERT_EQ(0, MemoryLog::GetInstance()->TestGetNumberMessages()); |
| 107 | } |
| 108 | |
| 109 | TEST_F(MemoryLogTest, MemoryLogFlushToDiskWorks) { |
| 110 | ScopedTempDir temp_dir; |
| 111 | ASSERT_TRUE(temp_dir.CreateUniqueTempDir()); |
| 112 | FilePath test_path = temp_dir.path().Append("somelogfile"); |
| 113 | ::logging::SetMinLogLevel(logging::LOG_WARNING); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 114 | LOG(INFO) << kTestStr1; |
| 115 | LOG(INFO) << kTestStr2; |
| 116 | LOG(INFO) << kTestStr3; |
| 117 | EXPECT_EQ(3, MemoryLog::GetInstance()->TestGetNumberMessages()); |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 118 | // Because of all the prefixed metadata on each log message, the stuff sent to |
| 119 | // disk should be bigger than the original strings put together. |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 120 | size_t minimal_message_length = strlen(kTestStr1) + strlen(kTestStr2) + |
| 121 | strlen(kTestStr3); |
| 122 | EXPECT_LT(minimal_message_length, |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 123 | MemoryLog::GetInstance()->FlushToDisk(test_path.value().c_str())); |
| 124 | std::string file_contents; |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 125 | EXPECT_TRUE(file_util::ReadFileToString(test_path, &file_contents)); |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 126 | // Log should contain all three messages |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 127 | EXPECT_NE(file_contents.find(kTestStr1), std::string::npos); |
| 128 | EXPECT_NE(file_contents.find(kTestStr2), std::string::npos); |
| 129 | EXPECT_NE(file_contents.find(kTestStr3), std::string::npos); |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 130 | // Preserve message order |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 131 | EXPECT_LT(file_contents.find(kTestStr1), file_contents.find(kTestStr2)); |
| 132 | EXPECT_LT(file_contents.find(kTestStr2), file_contents.find(kTestStr3)); |
| 133 | EXPECT_TRUE(temp_dir.Delete()); |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 134 | } |
| 135 | |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 136 | // Test that messages we're logging that don't go through the MessageLog still |
| 137 | // end up in the message log when we have our handler installed. |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 138 | TEST_F(MemoryLogTest, MemoryLogMessageInterceptorWorks) { |
| 139 | ASSERT_EQ(0, MemoryLog::GetInstance()->TestGetNumberMessages()); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 140 | // Have to use this weird syntax because most normal macros wind up logging |
| 141 | // via LOG, thus getting sent through MemoryLog. |
| 142 | LOG_STREAM(ERROR) << "Doesn't get caught"; |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 143 | ASSERT_EQ(0, MemoryLog::GetInstance()->TestGetNumberMessages()); |
| 144 | MemoryLog::InstallLogInterceptor(); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 145 | LOG_STREAM(ERROR) << "Caught this one!"; |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 146 | ASSERT_EQ(1, MemoryLog::GetInstance()->TestGetNumberMessages()); |
| 147 | // Make sure we're not double logging. |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 148 | LOG(ERROR) << kTestStr1; |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 149 | ASSERT_EQ(2, MemoryLog::GetInstance()->TestGetNumberMessages()); |
Christopher Wiley | b691efd | 2012-08-09 13:51:51 -0700 | [diff] [blame] | 150 | // SLOG_IF works with the intercepting handler. |
| 151 | SLOG_IF(WiFi, 3, strlen("two") == 3) << kTestStr2; |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 152 | ASSERT_EQ(3, MemoryLog::GetInstance()->TestGetNumberMessages()); |
Christopher Wiley | b691efd | 2012-08-09 13:51:51 -0700 | [diff] [blame] | 153 | SLOG_IF(WiFi, 3, strlen("one") == 2) << "does not get through again"; |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 154 | ASSERT_EQ(3, MemoryLog::GetInstance()->TestGetNumberMessages()); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 155 | // Similarly, LOG_IF works with the handler. |
| 156 | LOG_IF(ERROR, strlen("two") == 3) << kTestStr2; |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 157 | ASSERT_EQ(4, MemoryLog::GetInstance()->TestGetNumberMessages()); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 158 | LOG_IF(ERROR, strlen("one") == 2) << "does not get through again"; |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 159 | ASSERT_EQ(4, MemoryLog::GetInstance()->TestGetNumberMessages()); |
| 160 | MemoryLog::UninstallLogInterceptor(); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 161 | LOG_STREAM(ERROR) << "Doesn't get caught"; |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 162 | ASSERT_EQ(4, MemoryLog::GetInstance()->TestGetNumberMessages()); |
| 163 | // Normal log messages still get through. |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame^] | 164 | LOG(ERROR) << kTestStr2; |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 165 | ASSERT_EQ(5, MemoryLog::GetInstance()->TestGetNumberMessages()); |
| 166 | } |
| 167 | |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 168 | } // namespace shill |