base / win / event_trace_consumer_unittest.cc [blame]

// Copyright 2012 The Chromium Authors
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
//
// Unit tests for event trace consumer base class.

#include "base/win/event_trace_consumer.h"

#include <objbase.h>

#include <initguid.h>

#include <iterator>
#include <list>

#include "base/files/file_path.h"
#include "base/files/file_util.h"
#include "base/files/scoped_temp_dir.h"
#include "base/logging.h"
#include "base/process/process_handle.h"
#include "base/strings/string_number_conversions_win.h"
#include "base/strings/string_util.h"
#include "base/win/event_trace_controller.h"
#include "base/win/event_trace_provider.h"
#include "base/win/scoped_handle.h"
#include "testing/gtest/include/gtest/gtest.h"

namespace base {
namespace win {

namespace {

using EventQueue = std::list<EVENT_TRACE>;

class TestConsumer : public EtwTraceConsumerBase<TestConsumer> {
 public:
  TestConsumer() {
    sank_event_.Set(::CreateEvent(nullptr, TRUE, FALSE, nullptr));
    ClearQueue();
  }

  TestConsumer(const TestConsumer&) = delete;
  TestConsumer& operator=(const TestConsumer&) = delete;

  ~TestConsumer() {
    ClearQueue();
    sank_event_.Close();
  }

  void ClearQueue() {
    for (EventQueue::const_iterator it(events_.begin()), end(events_.end());
         it != end; ++it) {
      delete[] reinterpret_cast<char*>(it->MofData);
    }

    events_.clear();
  }

  static void EnqueueEvent(EVENT_TRACE* event) {
    events_.push_back(*event);
    EVENT_TRACE& back = events_.back();

    if (event->MofData != nullptr && event->MofLength != 0) {
      back.MofData = new char[event->MofLength];
      memcpy(back.MofData, event->MofData, event->MofLength);
    }
  }

  static void ProcessEvent(EVENT_TRACE* event) {
    EnqueueEvent(event);
    ::SetEvent(sank_event_.get());
  }

  static ScopedHandle sank_event_;
  static EventQueue events_;
};

ScopedHandle TestConsumer::sank_event_;
EventQueue TestConsumer::events_;

class EtwTraceConsumerBaseTest : public testing::Test {
 public:
  EtwTraceConsumerBaseTest()
      : session_name_(L"TestSession-" + NumberToWString(GetCurrentProcId())) {}

  void SetUp() override {
    // Cleanup any potentially dangling sessions.
    EtwTraceProperties ignore;
    EtwTraceController::Stop(session_name_.c_str(), &ignore);

    // Allocate a new GUID for each provider test.
    ASSERT_HRESULT_SUCCEEDED(::CoCreateGuid(&test_provider_));
  }

  void TearDown() override {
    // Cleanup any potentially dangling sessions.
    EtwTraceProperties ignore;
    EtwTraceController::Stop(session_name_.c_str(), &ignore);
  }

 protected:
  GUID test_provider_;
  std::wstring session_name_;
};

}  // namespace

TEST_F(EtwTraceConsumerBaseTest, Initialize) {
  TestConsumer consumer_;
}

TEST_F(EtwTraceConsumerBaseTest, OpenRealtimeSucceedsWhenNoSession) {
  TestConsumer consumer_;
  ASSERT_HRESULT_SUCCEEDED(
      consumer_.OpenRealtimeSession(session_name_.c_str()));
}

TEST_F(EtwTraceConsumerBaseTest, ConsumerImmediateFailureWhenNoSession) {
  TestConsumer consumer_;
  ASSERT_HRESULT_SUCCEEDED(
      consumer_.OpenRealtimeSession(session_name_.c_str()));
  ASSERT_HRESULT_FAILED(consumer_.Consume());
}

namespace {

class EtwTraceConsumerRealtimeTest : public EtwTraceConsumerBaseTest {
 public:
  void SetUp() override {
    EtwTraceConsumerBaseTest::SetUp();
    ASSERT_HRESULT_SUCCEEDED(
        consumer_.OpenRealtimeSession(session_name_.c_str()));
  }

  void TearDown() override {
    consumer_.Close();
    EtwTraceConsumerBaseTest::TearDown();
  }

  DWORD ConsumerThread() {
    ::SetEvent(consumer_ready_.get());
    return consumer_.Consume();
  }

  static DWORD WINAPI ConsumerThreadMainProc(void* arg) {
    return reinterpret_cast<EtwTraceConsumerRealtimeTest*>(arg)
        ->ConsumerThread();
  }

  HRESULT StartConsumerThread() {
    consumer_ready_.Set(::CreateEvent(nullptr, TRUE, FALSE, nullptr));
    EXPECT_TRUE(consumer_ready_.is_valid());
    consumer_thread_.Set(
        ::CreateThread(nullptr, 0, ConsumerThreadMainProc, this, 0, nullptr));
    if (consumer_thread_.get() == nullptr)
      return HRESULT_FROM_WIN32(::GetLastError());

    HANDLE events[] = {consumer_ready_.get(), consumer_thread_.get()};
    DWORD result =
        ::WaitForMultipleObjects(std::size(events), events, FALSE, INFINITE);
    switch (result) {
      case WAIT_OBJECT_0:
        // The event was set, the consumer_ is ready.
        return S_OK;
      case WAIT_OBJECT_0 + 1: {
        // The thread finished. This may race with the event, so check
        // explicitly for the event here, before concluding there's trouble.
        if (::WaitForSingleObject(consumer_ready_.get(), 0) == WAIT_OBJECT_0)
          return S_OK;
        DWORD exit_code = 0;
        if (::GetExitCodeThread(consumer_thread_.get(), &exit_code))
          return exit_code;
        return HRESULT_FROM_WIN32(::GetLastError());
      }
      default:
        return E_UNEXPECTED;
    }
  }

  // Waits for consumer_ thread to exit, and returns its exit code.
  HRESULT JoinConsumerThread() {
    if (::WaitForSingleObject(consumer_thread_.get(), INFINITE) !=
        WAIT_OBJECT_0) {
      return HRESULT_FROM_WIN32(::GetLastError());
    }

    DWORD exit_code = 0;
    if (::GetExitCodeThread(consumer_thread_.get(), &exit_code))
      return exit_code;

    return HRESULT_FROM_WIN32(::GetLastError());
  }

  TestConsumer consumer_;
  ScopedHandle consumer_ready_;
  ScopedHandle consumer_thread_;
};

}  // namespace

TEST_F(EtwTraceConsumerRealtimeTest, ConsumerReturnsWhenSessionClosed) {
  EtwTraceController controller;
  if (controller.StartRealtimeSession(session_name_.c_str(), 1024) ==
      E_ACCESSDENIED) {
    VLOG(1) << "You must be an administrator to run this test on Vista";
    return;
  }

  // Start the consumer_.
  ASSERT_HRESULT_SUCCEEDED(StartConsumerThread());

  // Wait around for the consumer_ thread a bit. This is inherently racy because
  // the consumer thread says that it is ready and then calls Consume() which
  // calls ::ProcessTrace. We need to call WaitForSingleObject after the call to
  // ::ProcessTrace but there is no way to know when that call has been made.
  // With a timeout of 50 ms this test was failing frequently when the system
  // was under load. It is hoped that 500 ms will be enough.
  ASSERT_EQ(static_cast<DWORD>(WAIT_TIMEOUT),
            ::WaitForSingleObject(consumer_thread_.get(), 500));
  ASSERT_HRESULT_SUCCEEDED(controller.Stop(nullptr));

  // The consumer_ returns success on session stop.
  ASSERT_HRESULT_SUCCEEDED(JoinConsumerThread());
}

namespace {

// clang-format off
// {57E47923-A549-476f-86CA-503D57F59E62}
DEFINE_GUID(
    kTestEventType,
    0x57e47923, 0xa549, 0x476f, 0x86, 0xca, 0x50, 0x3d, 0x57, 0xf5, 0x9e, 0x62);
// clang-format on

}  // namespace

TEST_F(EtwTraceConsumerRealtimeTest, ConsumeEvent) {
  EtwTraceController controller;
  if (controller.StartRealtimeSession(session_name_.c_str(), 1024) ==
      E_ACCESSDENIED) {
    VLOG(1) << "You must be an administrator to run this test on Vista";
    return;
  }

  ASSERT_HRESULT_SUCCEEDED(controller.EnableProvider(
      test_provider_, TRACE_LEVEL_VERBOSE, 0xFFFFFFFF));

  EtwTraceProvider provider(test_provider_);
  ASSERT_EQ(static_cast<DWORD>(ERROR_SUCCESS), provider.Register());

  // Start the consumer_.
  ASSERT_HRESULT_SUCCEEDED(StartConsumerThread());
  ASSERT_EQ(0u, TestConsumer::events_.size());

  EtwMofEvent<1> event(kTestEventType, 1, TRACE_LEVEL_ERROR);
  EXPECT_EQ(static_cast<DWORD>(ERROR_SUCCESS), provider.Log(&event.header));
  EXPECT_EQ(WAIT_OBJECT_0,
            ::WaitForSingleObject(TestConsumer::sank_event_.get(), INFINITE));
  ASSERT_HRESULT_SUCCEEDED(controller.Stop(nullptr));
  ASSERT_HRESULT_SUCCEEDED(JoinConsumerThread());
  ASSERT_NE(0u, TestConsumer::events_.size());
}

namespace {

// We run events through a file session to assert that
// the content comes through.
class EtwTraceConsumerDataTest : public EtwTraceConsumerBaseTest {
 public:
  EtwTraceConsumerDataTest() = default;

  void SetUp() override {
    EtwTraceConsumerBaseTest::SetUp();

    EtwTraceProperties prop;
    EtwTraceController::Stop(session_name_.c_str(), &prop);

    // Create a temp dir for this test.
    ASSERT_TRUE(temp_dir_.CreateUniqueTempDir());
    // Construct a temp file name in our dir.
    temp_file_ = temp_dir_.GetPath().Append(FILE_PATH_LITERAL("test.etl"));
  }

  void TearDown() override {
    EXPECT_TRUE(DeleteFile(temp_file_));

    EtwTraceConsumerBaseTest::TearDown();
  }

  HRESULT LogEventToTempSession(PEVENT_TRACE_HEADER header) {
    EtwTraceController controller;

    // Set up a file session.
    HRESULT hr = controller.StartFileSession(session_name_.c_str(),
                                             temp_file_.value().c_str());
    if (FAILED(hr))
      return hr;

    // Enable our provider.
    EXPECT_HRESULT_SUCCEEDED(controller.EnableProvider(
        test_provider_, TRACE_LEVEL_VERBOSE, 0xFFFFFFFF));

    EtwTraceProvider provider(test_provider_);
    // Then register our provider, means we get a session handle immediately.
    EXPECT_EQ(static_cast<DWORD>(ERROR_SUCCESS), provider.Register());
    // Trace the event, it goes to the temp file.
    EXPECT_EQ(static_cast<DWORD>(ERROR_SUCCESS), provider.Log(header));
    EXPECT_HRESULT_SUCCEEDED(controller.DisableProvider(test_provider_));
    EXPECT_HRESULT_SUCCEEDED(provider.Unregister());
    EXPECT_HRESULT_SUCCEEDED(controller.Flush(nullptr));
    EXPECT_HRESULT_SUCCEEDED(controller.Stop(nullptr));

    return S_OK;
  }

  HRESULT ConsumeEventFromTempSession() {
    // Now consume the event(s).
    TestConsumer consumer_;
    HRESULT hr = consumer_.OpenFileSession(temp_file_.value().c_str());
    if (SUCCEEDED(hr))
      hr = consumer_.Consume();
    consumer_.Close();
    // And nab the result.
    events_.swap(TestConsumer::events_);
    return hr;
  }

  HRESULT RoundTripEvent(PEVENT_TRACE_HEADER header, PEVENT_TRACE* trace) {
    DeleteFile(temp_file_);

    HRESULT hr = LogEventToTempSession(header);
    if (SUCCEEDED(hr))
      hr = ConsumeEventFromTempSession();

    if (FAILED(hr))
      return hr;

    // We should now have the event in the queue.
    if (events_.empty())
      return E_FAIL;

    *trace = &events_.back();
    return S_OK;
  }

  EventQueue events_;
  ScopedTempDir temp_dir_;
  FilePath temp_file_;
};

}  // namespace

TEST_F(EtwTraceConsumerDataTest, RoundTrip) {
  EtwMofEvent<1> event(kTestEventType, 1, TRACE_LEVEL_ERROR);

  static const char kData[] = "This is but test data";
  event.fields[0].DataPtr = reinterpret_cast<ULONG64>(kData);
  event.fields[0].Length = sizeof(kData);

  PEVENT_TRACE trace = nullptr;
  HRESULT hr = RoundTripEvent(&event.header, &trace);
  if (hr == E_ACCESSDENIED) {
    VLOG(1) << "You must be an administrator to run this test on Vista";
    return;
  }
  ASSERT_HRESULT_SUCCEEDED(hr) << "RoundTripEvent failed";
  ASSERT_TRUE(trace != nullptr);
  ASSERT_EQ(sizeof(kData), trace->MofLength);
  ASSERT_STREQ(kData, reinterpret_cast<const char*>(trace->MofData));
}

}  // namespace win
}  // namespace base