// Copyright (c) 2010 The Chromium 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 "base/debug/trace_event.h"
#include <strstream>
#include "base/at_exit.h"
#include "base/basictypes.h"
#include "base/file_util.h"
#include "base/win/event_trace_consumer.h"
#include "base/win/event_trace_controller.h"
#include "base/win/windows_version.h"
#include "testing/gmock/include/gmock/gmock.h"
#include "testing/gtest/include/gtest/gtest.h"
#include <initguid.h> // NOLINT - must be last include.
namespace base {
namespace debug {
namespace {
using testing::_;
using testing::AnyNumber;
using testing::InSequence;
using testing::Ge;
using testing::Le;
using testing::NotNull;
using base::win::EtwEventType;
using base::win::EtwTraceConsumerBase;
using base::win::EtwTraceController;
using base::win::EtwTraceProperties;
// Data for unittests traces.
const char kEmpty[] = "";
const char kName[] = "unittest.trace_name";
const char kExtra[] = "UnittestDummyExtraString";
const void* kId = kName;
const wchar_t kTestSessionName[] = L"TraceEvent unittest session";
MATCHER_P(BufferStartsWith, str, "Buffer starts with") {
return memcmp(arg, str.c_str(), str.length()) == 0;
}
// Duplicated from <evntrace.h> to fix link problems.
DEFINE_GUID( /* 68fdd900-4a3e-11d1-84f4-0000f80464e3 */
kEventTraceGuid,
0x68fdd900,
0x4a3e,
0x11d1,
0x84, 0xf4, 0x00, 0x00, 0xf8, 0x04, 0x64, 0xe3);
class TestEventConsumer: public EtwTraceConsumerBase<TestEventConsumer> {
public:
TestEventConsumer() {
EXPECT_TRUE(current_ == NULL);
current_ = this;
}
~TestEventConsumer() {
EXPECT_TRUE(current_ == this);
current_ = NULL;
}
MOCK_METHOD4(Event, void(REFGUID event_class,
EtwEventType event_type,
size_t buf_len,
const void* buf));
static void ProcessEvent(EVENT_TRACE* event) {
ASSERT_TRUE(current_ != NULL);
current_->Event(event->Header.Guid,
event->Header.Class.Type,
event->MofLength,
event->MofData);
}
private:
static TestEventConsumer* current_;
};
TestEventConsumer* TestEventConsumer::current_ = NULL;
class TraceEventTest: public testing::Test {
public:
TraceEventTest() {
}
void SetUp() {
bool is_xp = win::GetVersion() < base::win::VERSION_VISTA;
if (is_xp) {
// Tear down any dangling session from an earlier failing test.
EtwTraceProperties ignore;
EtwTraceController::Stop(kTestSessionName, &ignore);
}
// Resurrect and initialize the TraceLog singleton instance.
// On Vista and better, we need the provider registered before we
// start the private, in-proc session, but on XP we need the global
// session created and the provider enabled before we register our
// provider.
TraceLog* tracelog = NULL;
if (!is_xp) {
TraceLog::Resurrect();
tracelog = TraceLog::GetInstance();
ASSERT_TRUE(tracelog != NULL);
ASSERT_FALSE(tracelog->IsTracing());
}
// Create the log file.
ASSERT_TRUE(file_util::CreateTemporaryFile(&log_file_));
// Create a private log session on the file.
EtwTraceProperties prop;
ASSERT_HRESULT_SUCCEEDED(prop.SetLoggerFileName(log_file_.value().c_str()));
EVENT_TRACE_PROPERTIES& p = *prop.get();
p.Wnode.ClientContext = 1; // QPC timer accuracy.
p.LogFileMode = EVENT_TRACE_FILE_MODE_SEQUENTIAL; // Sequential log.
// On Vista and later, we create a private in-process log session, because
// otherwise we'd need administrator privileges. Unfortunately we can't
// do the same on XP and better, because the semantics of a private
// logger session are different, and the IN_PROC flag is not supported.
if (!is_xp) {
p.LogFileMode |= EVENT_TRACE_PRIVATE_IN_PROC | // In-proc for non-admin.
EVENT_TRACE_PRIVATE_LOGGER_MODE; // Process-private log.
}
p.MaximumFileSize = 100; // 100M file size.
p.FlushTimer = 1; // 1 second flush lag.
ASSERT_HRESULT_SUCCEEDED(controller_.Start(kTestSessionName, &prop));
// Enable the TraceLog provider GUID.
ASSERT_HRESULT_SUCCEEDED(
controller_.EnableProvider(kChromeTraceProviderName,
TRACE_LEVEL_INFORMATION,
0));
if (is_xp) {
TraceLog::Resurrect();
tracelog = TraceLog::GetInstance();
}
ASSERT_TRUE(tracelog != NULL);
EXPECT_TRUE(tracelog->IsTracing());
}
void TearDown() {
EtwTraceProperties prop;
if (controller_.session() != 0)
EXPECT_HRESULT_SUCCEEDED(controller_.Stop(&prop));
if (!log_file_.value().empty())
file_util::Delete(log_file_, false);
}
void ExpectEvent(REFGUID guid,
EtwEventType type,
const char* name,
size_t name_len,
const void* id,
const char* extra,
size_t extra_len) {
// Build the trace event buffer we expect will result from this.
std::stringbuf str;
str.sputn(name, name_len + 1);
str.sputn(reinterpret_cast<const char*>(&id), sizeof(id));
str.sputn(extra, extra_len + 1);
// And set up the expectation for the event callback.
EXPECT_CALL(consumer_, Event(guid,
type,
testing::Ge(str.str().length()),
BufferStartsWith(str.str())));
}
void ExpectPlayLog() {
// Ignore EventTraceGuid events.
EXPECT_CALL(consumer_, Event(kEventTraceGuid, _, _, _))
.Times(AnyNumber());
}
void PlayLog() {
EtwTraceProperties prop;
EXPECT_HRESULT_SUCCEEDED(controller_.Flush(&prop));
EXPECT_HRESULT_SUCCEEDED(controller_.Stop(&prop));
ASSERT_HRESULT_SUCCEEDED(
consumer_.OpenFileSession(log_file_.value().c_str()));
ASSERT_HRESULT_SUCCEEDED(consumer_.Consume());
}
private:
// We want our singleton torn down after each test.
ShadowingAtExitManager at_exit_manager_;
EtwTraceController controller_;
FilePath log_file_;
TestEventConsumer consumer_;
};
} // namespace
TEST_F(TraceEventTest, TraceLog) {
ExpectPlayLog();
// The events should arrive in the same sequence as the expects.
InSequence in_sequence;
// Full argument version, passing lengths explicitly.
TraceLog::Trace(kName,
strlen(kName),
TraceLog::EVENT_BEGIN,
kId,
kExtra,
strlen(kExtra));
ExpectEvent(kTraceEventClass32,
kTraceEventTypeBegin,
kName, strlen(kName),
kId,
kExtra, strlen(kExtra));
// Const char* version.
TraceLog::Trace(static_cast<const char*>(kName),
TraceLog::EVENT_END,
kId,
static_cast<const char*>(kExtra));
ExpectEvent(kTraceEventClass32,
kTraceEventTypeEnd,
kName, strlen(kName),
kId,
kExtra, strlen(kExtra));
// std::string extra version.
TraceLog::Trace(static_cast<const char*>(kName),
TraceLog::EVENT_INSTANT,
kId,
std::string(kExtra));
ExpectEvent(kTraceEventClass32,
kTraceEventTypeInstant,
kName, strlen(kName),
kId,
kExtra, strlen(kExtra));
// Test for sanity on NULL inputs.
TraceLog::Trace(NULL,
0,
TraceLog::EVENT_BEGIN,
kId,
NULL,
0);
ExpectEvent(kTraceEventClass32,
kTraceEventTypeBegin,
kEmpty, 0,
kId,
kEmpty, 0);
TraceLog::Trace(NULL,
-1,
TraceLog::EVENT_END,
kId,
NULL,
-1);
ExpectEvent(kTraceEventClass32,
kTraceEventTypeEnd,
kEmpty, 0,
kId,
kEmpty, 0);
PlayLog();
}
TEST_F(TraceEventTest, Macros) {
ExpectPlayLog();
// The events should arrive in the same sequence as the expects.
InSequence in_sequence;
TRACE_EVENT_BEGIN(kName, kId, kExtra);
ExpectEvent(kTraceEventClass32,
kTraceEventTypeBegin,
kName, strlen(kName),
kId,
kExtra, strlen(kExtra));
TRACE_EVENT_END(kName, kId, kExtra);
ExpectEvent(kTraceEventClass32,
kTraceEventTypeEnd,
kName, strlen(kName),
kId,
kExtra, strlen(kExtra));
TRACE_EVENT_INSTANT(kName, kId, kExtra);
ExpectEvent(kTraceEventClass32,
kTraceEventTypeInstant,
kName, strlen(kName),
kId,
kExtra, strlen(kExtra));
PlayLog();
}
} // namespace debug
} // namespace base