memory_log_unittest.cc

// Copyright (c) 2012 The Chromium OS 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 <deque>
#include <string>

#include <base/file_util.h>
#include <base/scoped_temp_dir.h>
#include <gmock/gmock.h>
#include <gtest/gtest.h>

#include "shill/logging.h"
#include "shill/mock_log.h"

using testing::_;

namespace {

const char kTestStr1[] = "What does Mr Wallace look like?";
const char kTestStr2[] = "And now little man, I give the watch to you.";
const char kTestStr3[] = "This is a tasty burger!";
const char kTestStr1WithPrefix[] = "memlog: What does Mr Wallace look like?";
const char kTestStr2WithPrefix[] =
    "memlog: And now little man, I give the watch to you.";
const char kTestStr3WithPrefix[] = "memlog: This is a tasty burger!";

}  // namespace

namespace shill {

class MemoryLogTest : public testing::Test {
 protected:
  void TearDown() {
    // Restore everything to defaults once more.
    MemoryLog::GetInstance()->Clear();
    MemoryLog::GetInstance()->SetMaximumSize(
        MemoryLog::kDefaultMaximumMemoryLogSizeInBytes);
    ScopeLogger::GetInstance()->set_verbose_level(0);
    ScopeLogger::GetInstance()->EnableScopesByName("");
    ::logging::SetMinLogLevel(logging::LOG_INFO);
  }
};

TEST_F(MemoryLogTest, ScopedLoggerStillWorks) {
  ScopedMockLog log;
  EXPECT_CALL(log, Log(_, _, kTestStr1WithPrefix));
  EXPECT_CALL(log, Log(_, _, kTestStr2WithPrefix));
  SLOG(WiFi, 2) << "does not get through";
  ScopeLogger::GetInstance()->EnableScopesByName("+wifi");
  // Verbose levels are inverted.
  ScopeLogger::GetInstance()->set_verbose_level(3);
  SLOG(WiFi, 2) << kTestStr1;
  // It would be nice if the compiler didn't optimize out my conditional check.
  SLOG_IF(WiFi, 3, strlen("two") == 3) << kTestStr2;
  SLOG_IF(WiFi, 3, strlen("one") == 2) << "does not get through again";
  SLOG(WiFi, 4) << "spanish inquisition";
}

TEST_F(MemoryLogTest, NormalLoggingStillWorks) {
  ::logging::SetMinLogLevel(logging::LOG_WARNING);
  ScopedMockLog log;
  EXPECT_CALL(log, Log(_, _, kTestStr1WithPrefix));
  EXPECT_CALL(log, Log(_, _, kTestStr2WithPrefix));
  MLOG(ERROR) << kTestStr1;
  MLOG(INFO) << "does not propagate down";
  // It would be nice if the compiler didn't optimize out my conditional check.
  MLOG_IF(WARNING, strlen("two") == 3) << kTestStr2;
}

TEST_F(MemoryLogTest, MemoryLogIsLogging) {
  ScopedMockLog log;
  EXPECT_CALL(log, Log(_, _, kTestStr1WithPrefix));
  EXPECT_CALL(log, Log(_, _, kTestStr2WithPrefix));
  ::logging::SetMinLogLevel(logging::LOG_WARNING);
  ASSERT_EQ(0, MemoryLog::GetInstance()->current_size_bytes());
  MLOG(WARNING) << kTestStr1;
  MLOG(WARNING) << kTestStr2;
  // LT because of the prefixes prepended by the logger
  ASSERT_LT(strlen(kTestStr1WithPrefix) + strlen(kTestStr2WithPrefix),
            MemoryLog::GetInstance()->current_size_bytes());
  ASSERT_EQ(2, MemoryLog::GetInstance()->TestGetNumberMessages());
  MemoryLog::GetInstance()->Clear();
  ASSERT_EQ(0, MemoryLog::GetInstance()->current_size_bytes());
  ASSERT_EQ(0, MemoryLog::GetInstance()->TestGetNumberMessages());
}

TEST_F(MemoryLogTest, MemoryLogLimitingWorks) {
  ScopedMockLog log;
  ::logging::SetMinLogLevel(logging::LOG_WARNING);
  MLOG(INFO) << kTestStr1;
  size_t old_size = MemoryLog::GetInstance()->current_size_bytes();
  MLOG(INFO) << kTestStr2;
  size_t new_size = MemoryLog::GetInstance()->current_size_bytes();
  // Setting the size just above the current size shouldn't affect anything.
  MemoryLog::GetInstance()->SetMaximumSize(new_size + 1);
  ASSERT_EQ(new_size, MemoryLog::GetInstance()->current_size_bytes());
  // Force MemoryLog to discard the earliest message
  MemoryLog::GetInstance()->SetMaximumSize(new_size - 1);
  // Should be just last message in the buffer.
  ASSERT_EQ(new_size - old_size,
            MemoryLog::GetInstance()->current_size_bytes());
  // Now force it to discard the most recent message.
  MemoryLog::GetInstance()->SetMaximumSize(0);
  ASSERT_EQ(0, MemoryLog::GetInstance()->current_size_bytes());
  // Can't log if we don't have room, but the messages should still get to LOG
  EXPECT_CALL(log, Log(_, _, kTestStr3WithPrefix));
  MLOG(WARNING) << kTestStr3;
  ASSERT_EQ(0, MemoryLog::GetInstance()->current_size_bytes());
  ASSERT_EQ(0, MemoryLog::GetInstance()->TestGetNumberMessages());
}

TEST_F(MemoryLogTest, MemoryLogFlushToDiskWorks) {
  ScopedTempDir temp_dir;
  ASSERT_TRUE(temp_dir.CreateUniqueTempDir());
  FilePath test_path = temp_dir.path().Append("somelogfile");
  ::logging::SetMinLogLevel(logging::LOG_WARNING);
  MLOG(INFO) << kTestStr1;
  MLOG(INFO) << kTestStr2;
  MLOG(INFO) << kTestStr3;
  ASSERT_EQ(3, MemoryLog::GetInstance()->TestGetNumberMessages());
  // Because of all the prefixed metadata on each log message, the stuff sent to
  // disk should be bigger than the original strings put together.
  size_t minimal_message_length = strlen(kTestStr1WithPrefix) +
      strlen(kTestStr2WithPrefix) + strlen(kTestStr3WithPrefix);
  ASSERT_LT(minimal_message_length,
            MemoryLog::GetInstance()->FlushToDisk(test_path.value().c_str()));
  std::string file_contents;
  ASSERT_TRUE(file_util::ReadFileToString(test_path, &file_contents));
  // Log should contain all three messages
  ASSERT_NE(file_contents.find(kTestStr1WithPrefix), std::string::npos);
  ASSERT_NE(file_contents.find(kTestStr2WithPrefix), std::string::npos);
  ASSERT_NE(file_contents.find(kTestStr3WithPrefix), std::string::npos);
  // Preserve message order
  ASSERT_LT(file_contents.find(kTestStr1WithPrefix),
            file_contents.find(kTestStr2WithPrefix));
  ASSERT_LT(file_contents.find(kTestStr2WithPrefix),
            file_contents.find(kTestStr3WithPrefix));
  ASSERT_TRUE(temp_dir.Delete());
}

TEST_F(MemoryLogTest, MemoryLogMessageInterceptorWorks) {
  ASSERT_EQ(0, MemoryLog::GetInstance()->TestGetNumberMessages());
  NOTIMPLEMENTED();
  ASSERT_EQ(0, MemoryLog::GetInstance()->TestGetNumberMessages());
  MemoryLog::InstallLogInterceptor();
  NOTIMPLEMENTED();
  ASSERT_EQ(1, MemoryLog::GetInstance()->TestGetNumberMessages());
  // Make sure we're not double logging.
  MLOG(ERROR) << kTestStr1;
  ASSERT_EQ(2, MemoryLog::GetInstance()->TestGetNumberMessages());
  // SLOG_IF works with the intercepting handler.
  SLOG_IF(WiFi, 3, strlen("two") == 3) << kTestStr2;
  ASSERT_EQ(3, MemoryLog::GetInstance()->TestGetNumberMessages());
  SLOG_IF(WiFi, 3, strlen("one") == 2) << "does not get through again";
  ASSERT_EQ(3, MemoryLog::GetInstance()->TestGetNumberMessages());
  // Similarly, MLOG_IF works with the handler.
  MLOG_IF(ERROR, strlen("two") == 3) << kTestStr2;
  ASSERT_EQ(4, MemoryLog::GetInstance()->TestGetNumberMessages());
  MLOG_IF(ERROR, strlen("one") == 2) << "does not get through again";
  ASSERT_EQ(4, MemoryLog::GetInstance()->TestGetNumberMessages());
  MemoryLog::UninstallLogInterceptor();
  NOTIMPLEMENTED();
  ASSERT_EQ(4, MemoryLog::GetInstance()->TestGetNumberMessages());
  // Normal log messages still get through.
  MLOG(ERROR) << kTestStr2;
  ASSERT_EQ(5, MemoryLog::GetInstance()->TestGetNumberMessages());
}

}  // namespace shill