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 | |
Christopher Wiley | 3e7635e | 2012-08-15 09:46:17 -0700 | [diff] [blame] | 8 | #include <base/file_path.h> |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 9 | #include <base/file_util.h> |
Paul Stewart | 5ad1606 | 2013-02-21 18:10:48 -0800 | [diff] [blame] | 10 | #include <base/files/scoped_temp_dir.h> |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 11 | #include <gmock/gmock.h> |
| 12 | #include <gtest/gtest.h> |
| 13 | |
Christopher Wiley | b691efd | 2012-08-09 13:51:51 -0700 | [diff] [blame] | 14 | #include "shill/logging.h" |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 15 | #include "shill/mock_log.h" |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 16 | |
Albert Chaulk | 0e1cdea | 2013-02-27 15:32:55 -0800 | [diff] [blame] | 17 | using base::FilePath; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 18 | using testing::_; |
| 19 | |
| 20 | namespace { |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 21 | |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 22 | const char kTestStr1[] = "What does Mr Wallace look like?"; |
| 23 | const char kTestStr2[] = "And now little man, I give the watch to you."; |
| 24 | const char kTestStr3[] = "This is a tasty burger!"; |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 25 | |
| 26 | } // namespace |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 27 | |
| 28 | namespace shill { |
| 29 | |
| 30 | class MemoryLogTest : public testing::Test { |
| 31 | protected: |
| 32 | void TearDown() { |
| 33 | // Restore everything to defaults once more. |
| 34 | MemoryLog::GetInstance()->Clear(); |
| 35 | MemoryLog::GetInstance()->SetMaximumSize( |
| 36 | MemoryLog::kDefaultMaximumMemoryLogSizeInBytes); |
| 37 | ScopeLogger::GetInstance()->set_verbose_level(0); |
| 38 | ScopeLogger::GetInstance()->EnableScopesByName(""); |
| 39 | ::logging::SetMinLogLevel(logging::LOG_INFO); |
| 40 | } |
| 41 | }; |
| 42 | |
Christopher Wiley | 6e8c54b | 2012-08-15 16:12:30 -0700 | [diff] [blame] | 43 | class MemoryLogDeathTest : public testing::Test { }; |
| 44 | |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 45 | TEST_F(MemoryLogTest, ScopedLoggerStillWorks) { |
| 46 | ScopedMockLog log; |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame] | 47 | EXPECT_CALL(log, Log(_, _, kTestStr1)); |
| 48 | EXPECT_CALL(log, Log(_, _, kTestStr2)); |
Christopher Wiley | b691efd | 2012-08-09 13:51:51 -0700 | [diff] [blame] | 49 | SLOG(WiFi, 2) << "does not get through"; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 50 | ScopeLogger::GetInstance()->EnableScopesByName("+wifi"); |
| 51 | // Verbose levels are inverted. |
| 52 | ScopeLogger::GetInstance()->set_verbose_level(3); |
Christopher Wiley | b691efd | 2012-08-09 13:51:51 -0700 | [diff] [blame] | 53 | SLOG(WiFi, 2) << kTestStr1; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 54 | // 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] | 55 | SLOG_IF(WiFi, 3, strlen("two") == 3) << kTestStr2; |
| 56 | SLOG_IF(WiFi, 3, strlen("one") == 2) << "does not get through again"; |
| 57 | SLOG(WiFi, 4) << "spanish inquisition"; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 58 | } |
| 59 | |
| 60 | TEST_F(MemoryLogTest, NormalLoggingStillWorks) { |
| 61 | ::logging::SetMinLogLevel(logging::LOG_WARNING); |
| 62 | ScopedMockLog log; |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame] | 63 | EXPECT_CALL(log, Log(_, _, kTestStr1)); |
| 64 | EXPECT_CALL(log, Log(_, _, kTestStr2)); |
| 65 | LOG(ERROR) << kTestStr1; |
| 66 | LOG(INFO) << "does not propagate down"; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 67 | // 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] | 68 | LOG_IF(WARNING, strlen("two") == 3) << kTestStr2; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 69 | } |
| 70 | |
Christopher Wiley | 6e8c54b | 2012-08-15 16:12:30 -0700 | [diff] [blame] | 71 | // Test that no matter what we did, CHECK still kills the process. |
| 72 | TEST_F(MemoryLogDeathTest, CheckLogsStillWork) { |
| 73 | EXPECT_DEATH( { CHECK(false) << "diediedie"; }, |
| 74 | "Check failed: false. diediedie"); |
| 75 | } |
| 76 | |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 77 | TEST_F(MemoryLogTest, MemoryLogIsLogging) { |
| 78 | ScopedMockLog log; |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame] | 79 | EXPECT_CALL(log, Log(_, _, kTestStr1)); |
| 80 | EXPECT_CALL(log, Log(_, _, kTestStr2)); |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 81 | ::logging::SetMinLogLevel(logging::LOG_WARNING); |
| 82 | ASSERT_EQ(0, MemoryLog::GetInstance()->current_size_bytes()); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame] | 83 | LOG(WARNING) << kTestStr1; |
| 84 | LOG(WARNING) << kTestStr2; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 85 | // LT because of the prefixes prepended by the logger |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame] | 86 | EXPECT_LT(strlen(kTestStr1) + strlen(kTestStr2), |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 87 | MemoryLog::GetInstance()->current_size_bytes()); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame] | 88 | EXPECT_EQ(2, MemoryLog::GetInstance()->TestGetNumberMessages()); |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 89 | MemoryLog::GetInstance()->Clear(); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame] | 90 | EXPECT_EQ(0, MemoryLog::GetInstance()->current_size_bytes()); |
| 91 | EXPECT_EQ(0, MemoryLog::GetInstance()->TestGetNumberMessages()); |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 92 | } |
| 93 | |
| 94 | TEST_F(MemoryLogTest, MemoryLogLimitingWorks) { |
| 95 | ScopedMockLog log; |
| 96 | ::logging::SetMinLogLevel(logging::LOG_WARNING); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame] | 97 | LOG(INFO) << kTestStr1; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 98 | size_t old_size = MemoryLog::GetInstance()->current_size_bytes(); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame] | 99 | LOG(INFO) << kTestStr2; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 100 | size_t new_size = MemoryLog::GetInstance()->current_size_bytes(); |
| 101 | // Setting the size just above the current size shouldn't affect anything. |
| 102 | MemoryLog::GetInstance()->SetMaximumSize(new_size + 1); |
| 103 | ASSERT_EQ(new_size, MemoryLog::GetInstance()->current_size_bytes()); |
| 104 | // Force MemoryLog to discard the earliest message |
| 105 | MemoryLog::GetInstance()->SetMaximumSize(new_size - 1); |
| 106 | // Should be just last message in the buffer. |
| 107 | ASSERT_EQ(new_size - old_size, |
| 108 | MemoryLog::GetInstance()->current_size_bytes()); |
| 109 | // Now force it to discard the most recent message. |
| 110 | MemoryLog::GetInstance()->SetMaximumSize(0); |
| 111 | ASSERT_EQ(0, MemoryLog::GetInstance()->current_size_bytes()); |
| 112 | // 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] | 113 | EXPECT_CALL(log, Log(_, _, kTestStr3)); |
| 114 | LOG(WARNING) << kTestStr3; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 115 | ASSERT_EQ(0, MemoryLog::GetInstance()->current_size_bytes()); |
| 116 | ASSERT_EQ(0, MemoryLog::GetInstance()->TestGetNumberMessages()); |
| 117 | } |
| 118 | |
Christopher Wiley | 3e7635e | 2012-08-15 09:46:17 -0700 | [diff] [blame] | 119 | TEST_F(MemoryLogTest, MemoryLogFlushToFileWorks) { |
Paul Stewart | 5ad1606 | 2013-02-21 18:10:48 -0800 | [diff] [blame] | 120 | base::ScopedTempDir temp_dir; |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 121 | ASSERT_TRUE(temp_dir.CreateUniqueTempDir()); |
| 122 | FilePath test_path = temp_dir.path().Append("somelogfile"); |
| 123 | ::logging::SetMinLogLevel(logging::LOG_WARNING); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame] | 124 | LOG(INFO) << kTestStr1; |
| 125 | LOG(INFO) << kTestStr2; |
| 126 | LOG(INFO) << kTestStr3; |
| 127 | EXPECT_EQ(3, MemoryLog::GetInstance()->TestGetNumberMessages()); |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 128 | // Because of all the prefixed metadata on each log message, the stuff sent to |
| 129 | // disk should be bigger than the original strings put together. |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame] | 130 | size_t minimal_message_length = strlen(kTestStr1) + strlen(kTestStr2) + |
| 131 | strlen(kTestStr3); |
| 132 | EXPECT_LT(minimal_message_length, |
Christopher Wiley | 3e7635e | 2012-08-15 09:46:17 -0700 | [diff] [blame] | 133 | MemoryLog::GetInstance()->FlushToFile(test_path)); |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 134 | std::string file_contents; |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame] | 135 | EXPECT_TRUE(file_util::ReadFileToString(test_path, &file_contents)); |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 136 | // Log should contain all three messages |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame] | 137 | EXPECT_NE(file_contents.find(kTestStr1), std::string::npos); |
| 138 | EXPECT_NE(file_contents.find(kTestStr2), std::string::npos); |
| 139 | EXPECT_NE(file_contents.find(kTestStr3), std::string::npos); |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 140 | // Preserve message order |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame] | 141 | EXPECT_LT(file_contents.find(kTestStr1), file_contents.find(kTestStr2)); |
| 142 | EXPECT_LT(file_contents.find(kTestStr2), file_contents.find(kTestStr3)); |
| 143 | EXPECT_TRUE(temp_dir.Delete()); |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 144 | } |
| 145 | |
Christopher Wiley | 3e7635e | 2012-08-15 09:46:17 -0700 | [diff] [blame] | 146 | TEST_F(MemoryLogTest, MemoryLogFlushToDiskCannotCreateFile) { |
| 147 | ScopedMockLog log; |
mukesh agrawal | 910d0d6 | 2012-12-06 14:35:40 -0800 | [diff] [blame] | 148 | FilePath tmp_path; |
| 149 | EXPECT_CALL(log, Log(_, _, ::testing::EndsWith(tmp_path.AsUTF8Unsafe()))); |
Christopher Wiley | 3e7635e | 2012-08-15 09:46:17 -0700 | [diff] [blame] | 150 | EXPECT_CALL(log, Log(_, |
| 151 | _, |
| 152 | "Failed to open file for dumping memory log to disk.")); |
| 153 | EXPECT_CALL(log, Log(_, _, "Failed to flush memory log to disk")); |
Christopher Wiley | 3e7635e | 2012-08-15 09:46:17 -0700 | [diff] [blame] | 154 | file_util::CreateTemporaryFile(&tmp_path); |
| 155 | // Flushing fails because a directory already exists with the same name as |
| 156 | // our log file. |
| 157 | MemoryLog::GetInstance()->FlushToDiskImpl( |
| 158 | tmp_path.Append("cannot_be_created")); |
| 159 | } |
| 160 | |
| 161 | TEST_F(MemoryLogTest, MemoryLogFlushToDiskRotateWorks) { |
| 162 | FilePath tmp_dir; |
| 163 | file_util::CreateNewTempDirectory(std::string("/"), &tmp_dir); |
| 164 | FilePath log_path = tmp_dir.Append("connectivity.log"); |
| 165 | FilePath log_path_backup = tmp_dir.Append("connectivity.bak"); |
| 166 | LOG(INFO) << kTestStr1; |
| 167 | LOG(INFO) << kTestStr2; |
| 168 | // Populate a dump file with some messages. |
| 169 | MemoryLog::GetInstance()->FlushToDiskImpl(log_path); |
| 170 | // There should be no rotated file at this point, we've only done one dump. |
| 171 | EXPECT_FALSE(file_util::PathExists(log_path_backup)); |
| 172 | // Tell MemoryLog it should rotate at a really small size threshhold. |
| 173 | MemoryLog::GetInstance()->TestSetMaxDiskLogSize(1); |
| 174 | LOG(INFO) << kTestStr3; |
| 175 | // Flush to disk, which should cause a log rotate, since the old log file had |
| 176 | // more than a byte in it. |
| 177 | MemoryLog::GetInstance()->FlushToDiskImpl(log_path); |
| 178 | MemoryLog::GetInstance()->TestSetMaxDiskLogSize( |
| 179 | MemoryLog::kDefaultMaxDiskLogSizeInBytes); |
| 180 | std::string file_contents; |
| 181 | EXPECT_TRUE(file_util::ReadFileToString(log_path_backup, &file_contents)); |
| 182 | // Rotated log should contain the first two messages. |
| 183 | EXPECT_NE(file_contents.find(kTestStr1), std::string::npos); |
| 184 | EXPECT_NE(file_contents.find(kTestStr2), std::string::npos); |
| 185 | EXPECT_TRUE(file_util::Delete(tmp_dir, true)); |
| 186 | } |
| 187 | |
| 188 | TEST_F(MemoryLogTest, MemoryLogFlushToDiskWorks) { |
mukesh agrawal | 910d0d6 | 2012-12-06 14:35:40 -0800 | [diff] [blame] | 189 | ScopedMockLog log; |
Christopher Wiley | 3e7635e | 2012-08-15 09:46:17 -0700 | [diff] [blame] | 190 | FilePath tmp_path; |
| 191 | file_util::CreateTemporaryFile(&tmp_path); |
| 192 | LOG(INFO) << kTestStr1; |
| 193 | LOG(INFO) << kTestStr2; |
| 194 | LOG(INFO) << kTestStr3; |
mukesh agrawal | 910d0d6 | 2012-12-06 14:35:40 -0800 | [diff] [blame] | 195 | EXPECT_CALL(log, Log(_, _, _)); |
| 196 | EXPECT_CALL(log, Log(_, _, ::testing::EndsWith(tmp_path.AsUTF8Unsafe()))); |
Christopher Wiley | 3e7635e | 2012-08-15 09:46:17 -0700 | [diff] [blame] | 197 | MemoryLog::GetInstance()->FlushToDiskImpl(tmp_path); |
| 198 | // No rotation should have happened. |
| 199 | EXPECT_FALSE(file_util::PathExists(tmp_path.Append(".bak"))); |
| 200 | // But we should have a dump file now. |
| 201 | std::string file_contents; |
| 202 | EXPECT_TRUE(file_util::ReadFileToString(tmp_path, &file_contents)); |
| 203 | // Dump file should contain everything we logged. |
| 204 | EXPECT_NE(file_contents.find(kTestStr1), std::string::npos); |
| 205 | EXPECT_NE(file_contents.find(kTestStr2), std::string::npos); |
| 206 | EXPECT_NE(file_contents.find(kTestStr3), std::string::npos); |
| 207 | EXPECT_TRUE(file_util::Delete(tmp_path, false)); |
| 208 | } |
| 209 | |
Christopher Wiley | 6e8c54b | 2012-08-15 16:12:30 -0700 | [diff] [blame] | 210 | // Test that most messages go through MemoryLog |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 211 | TEST_F(MemoryLogTest, MemoryLogMessageInterceptorWorks) { |
| 212 | ASSERT_EQ(0, MemoryLog::GetInstance()->TestGetNumberMessages()); |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 213 | // Make sure we're not double logging. |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame] | 214 | LOG(ERROR) << kTestStr1; |
Christopher Wiley | 6e8c54b | 2012-08-15 16:12:30 -0700 | [diff] [blame] | 215 | ASSERT_EQ(1, MemoryLog::GetInstance()->TestGetNumberMessages()); |
Christopher Wiley | b691efd | 2012-08-09 13:51:51 -0700 | [diff] [blame] | 216 | SLOG_IF(WiFi, 3, strlen("two") == 3) << kTestStr2; |
Christopher Wiley | 6e8c54b | 2012-08-15 16:12:30 -0700 | [diff] [blame] | 217 | ASSERT_EQ(2, MemoryLog::GetInstance()->TestGetNumberMessages()); |
Christopher Wiley | b691efd | 2012-08-09 13:51:51 -0700 | [diff] [blame] | 218 | SLOG_IF(WiFi, 3, strlen("one") == 2) << "does not get through again"; |
Christopher Wiley | 6e8c54b | 2012-08-15 16:12:30 -0700 | [diff] [blame] | 219 | ASSERT_EQ(2, MemoryLog::GetInstance()->TestGetNumberMessages()); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame] | 220 | LOG_IF(ERROR, strlen("two") == 3) << kTestStr2; |
Christopher Wiley | 6e8c54b | 2012-08-15 16:12:30 -0700 | [diff] [blame] | 221 | ASSERT_EQ(3, MemoryLog::GetInstance()->TestGetNumberMessages()); |
Christopher Wiley | d778352 | 2012-08-10 14:21:47 -0700 | [diff] [blame] | 222 | LOG_IF(ERROR, strlen("one") == 2) << "does not get through again"; |
Christopher Wiley | 6e8c54b | 2012-08-15 16:12:30 -0700 | [diff] [blame] | 223 | ASSERT_EQ(3, MemoryLog::GetInstance()->TestGetNumberMessages()); |
| 224 | NOTIMPLEMENTED(); |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 225 | ASSERT_EQ(4, MemoryLog::GetInstance()->TestGetNumberMessages()); |
Christopher Wiley | 6e8c54b | 2012-08-15 16:12:30 -0700 | [diff] [blame] | 226 | |
Christopher Wiley | f11cebb | 2012-08-08 12:22:20 -0700 | [diff] [blame] | 227 | } |
| 228 | |
Christopher Wiley | 5781aa4 | 2012-07-30 14:42:23 -0700 | [diff] [blame] | 229 | } // namespace shill |