diff options
-rw-r--r-- | base/base.gyp | 12 | ||||
-rw-r--r-- | base/event_trace_consumer_win.h | 143 | ||||
-rw-r--r-- | base/event_trace_consumer_win_unittest.cc | 337 | ||||
-rw-r--r-- | base/event_trace_controller_win.cc | 130 | ||||
-rw-r--r-- | base/event_trace_controller_win.h | 168 | ||||
-rw-r--r-- | base/event_trace_controller_win_unittest.cc | 203 | ||||
-rw-r--r-- | base/event_trace_provider_win.cc | 126 | ||||
-rw-r--r-- | base/event_trace_provider_win.h | 155 | ||||
-rw-r--r-- | base/event_trace_provider_win_unittest.cc | 107 | ||||
-rw-r--r-- | base/logging.cc | 10 | ||||
-rw-r--r-- | base/logging.h | 7 | ||||
-rw-r--r-- | base/logging_win.cc | 152 | ||||
-rw-r--r-- | base/logging_win.h | 60 | ||||
-rw-r--r-- | chrome/common/env_vars.cc | 4 | ||||
-rw-r--r-- | chrome/common/env_vars.h | 1 | ||||
-rw-r--r-- | chrome/common/logging_chrome.cc | 16 |
16 files changed, 1631 insertions, 0 deletions
diff --git a/base/base.gyp b/base/base.gyp index f5b9b36..cce3f07 100644 --- a/base/base.gyp +++ b/base/base.gyp @@ -119,6 +119,11 @@ 'event_recorder.cc', 'event_recorder.h', 'event_recorder_stubs.cc', + 'event_trace_consumer_win.h', + 'event_trace_controller_win.cc', + 'event_trace_controller_win.h', + 'event_trace_provider_win.cc', + 'event_trace_provider_win.h', 'field_trial.cc', 'field_trial.h', 'file_descriptor_shuffle.cc', @@ -182,6 +187,7 @@ 'lock_impl_posix.cc', 'lock_impl_win.cc', 'logging.cc', + 'logging_win.cc', 'logging.h', 'mac_util.h', 'mac_util.mm', @@ -604,6 +610,9 @@ 'data_pack_unittest.cc', 'debug_util_unittest.cc', 'directory_watcher_unittest.cc', + 'event_trace_consumer_win_unittest.cc', + 'event_trace_controller_win_unittest.cc', + 'event_trace_provider_win_unittest.cc', 'field_trial_unittest.cc', 'file_descriptor_shuffle_unittest.cc', 'file_path_unittest.cc', @@ -725,6 +734,9 @@ ], }, { # OS != "win" 'sources!': [ + 'event_trace_consumer_win_unittest.cc', + 'event_trace_controller_win_unittest.cc', + 'event_trace_provider_win_unittest.cc', 'object_watcher_unittest.cc', 'pe_image_unittest.cc', 'scoped_bstr_win_unittest.cc', diff --git a/base/event_trace_consumer_win.h b/base/event_trace_consumer_win.h new file mode 100644 index 0000000..03db96f --- /dev/null +++ b/base/event_trace_consumer_win.h @@ -0,0 +1,143 @@ +// Copyright (c) 2009 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. +// +// Declaration of a Windows event trace consumer base class. +#ifndef BASE_EVENT_TRACE_CONSUMER_WIN_H_ +#define BASE_EVENT_TRACE_CONSUMER_WIN_H_ + +#include <windows.h> +#include <wmistr.h> +#include <evntrace.h> +#include <vector> +#include "base/basictypes.h" + +// This class is a base class that makes it easier to consume events +// from realtime or file sessions. Concrete consumers need to sublass +// a specialization of this class and override the ProcessEvent and/or +// the ProcessBuffer methods to implement the event consumption logic. +// Usage might look like: +// class MyConsumer: public EtwTraceConsumerBase<MyConsumer, 1> { +// protected: +// static VOID WINAPI ProcessEvent(PEVENT_TRACE event); +// }; +// +// MyConsumer consumer; +// consumer.OpenFileSession(file_path); +// consumer.Consume(); +template <class ImplClass> +class EtwTraceConsumerBase { + public: + // Constructs a closed consumer. + EtwTraceConsumerBase() { + } + + ~EtwTraceConsumerBase() { + Close(); + } + + // Opens the named realtime session, which must be existent. + // Note: You can use OpenRealtimeSession or OpenFileSession + // to open as many as MAXIMUM_WAIT_OBJECTS (63) sessions at + // any one time, though only one of them may be a realtime + // session. + HRESULT OpenRealtimeSession(const wchar_t* session_name); + + // Opens the event trace log in "file_name", which must be a full or + // relative path to an existing event trace log file. + // Note: You can use OpenRealtimeSession or OpenFileSession + // to open as many as kNumSessions at any one time. + HRESULT OpenFileSession(const wchar_t* file_name); + + // Consume all open sessions from beginning to end. + HRESULT Consume(); + + // Close all open sessions. + HRESULT Close(); + + protected: + // Override in subclasses to handle events. + static void ProcessEvent(EVENT_TRACE* event) { + } + // Override in subclasses to handle buffers. + static bool ProcessBuffer(EVENT_TRACE_LOGFILE* buffer) { + return true; // keep going + } + + protected: + // Currently open sessions. + std::vector<TRACEHANDLE> trace_handles_; + + private: + // These delegate to ImplClass callbacks with saner signatures. + static void WINAPI ProcessEventCallback(EVENT_TRACE* event) { + ImplClass::ProcessEvent(event); + } + static ULONG WINAPI ProcessBufferCallback(PEVENT_TRACE_LOGFILE buffer) { + return ImplClass::ProcessBuffer(buffer); + } + + DISALLOW_COPY_AND_ASSIGN(EtwTraceConsumerBase); +}; + +template <class ImplClass> inline +HRESULT EtwTraceConsumerBase<ImplClass>::OpenRealtimeSession( + const wchar_t* session_name) { + EVENT_TRACE_LOGFILE logfile = {}; + logfile.LoggerName = const_cast<wchar_t*>(session_name); + logfile.LogFileMode = EVENT_TRACE_REAL_TIME_MODE; + logfile.BufferCallback = &ProcessBufferCallback; + logfile.EventCallback = &ProcessEventCallback; + logfile.Context = this; + TRACEHANDLE trace_handle = ::OpenTrace(&logfile); + if (reinterpret_cast<TRACEHANDLE>(INVALID_HANDLE_VALUE) == trace_handle) + return HRESULT_FROM_WIN32(::GetLastError()); + + trace_handles_.push_back(trace_handle); + return S_OK; +} + +template <class ImplClass> inline +HRESULT EtwTraceConsumerBase<ImplClass>::OpenFileSession( + const wchar_t* file_name) { + EVENT_TRACE_LOGFILE logfile = {}; + logfile.LogFileName = const_cast<wchar_t*>(file_name); + logfile.BufferCallback = &ProcessBufferCallback; + logfile.EventCallback = &ProcessEventCallback; + logfile.Context = this; + TRACEHANDLE trace_handle = ::OpenTrace(&logfile); + if (reinterpret_cast<TRACEHANDLE>(INVALID_HANDLE_VALUE) == trace_handle) + return HRESULT_FROM_WIN32(::GetLastError()); + + trace_handles_.push_back(trace_handle); + return S_OK; +} + +template <class ImplClass> inline +HRESULT EtwTraceConsumerBase<ImplClass>::Consume() { + ULONG err = ::ProcessTrace(&trace_handles_[0], + trace_handles_.size(), + NULL, + NULL); + return HRESULT_FROM_WIN32(err); +} + +template <class ImplClass> inline +HRESULT EtwTraceConsumerBase<ImplClass>::Close() { + HRESULT hr = S_OK; + for (size_t i = 0; i < trace_handles_.size(); ++i) { + if (NULL != trace_handles_[i]) { + ULONG ret = ::CloseTrace(trace_handles_[i]); + trace_handles_[i] = NULL; + + if (FAILED(HRESULT_FROM_WIN32(ret))) + hr = HRESULT_FROM_WIN32(ret); + } + + trace_handles_.clear(); + } + + return hr; +} + +#endif // BASE_EVENT_TRACE_CONSUMER_WIN_H_ diff --git a/base/event_trace_consumer_win_unittest.cc b/base/event_trace_consumer_win_unittest.cc new file mode 100644 index 0000000..9fcc4a6 --- /dev/null +++ b/base/event_trace_consumer_win_unittest.cc @@ -0,0 +1,337 @@ +// Copyright (c) 2009 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. +// +// Unit tests for event trace consumer_ base class. +#include "base/event_trace_consumer_win.h" +#include <list> +#include "base/basictypes.h" +#include "base/event_trace_controller_win.h" +#include "base/event_trace_provider_win.h" +#include "base/file_path.h" +#include "base/file_util.h" +#include "base/logging.h" +#include "base/scoped_handle.h" +#include "testing/gtest/include/gtest/gtest.h" + +#include <initguid.h> // NOLINT - has to be last + +namespace { + +typedef std::list<EVENT_TRACE> EventQueue; + +class TestConsumer: public EtwTraceConsumerBase<TestConsumer> { + public: + TestConsumer() { + sank_event_.Set(::CreateEvent(NULL, TRUE, FALSE, NULL)); + ClearQueue(); + } + + ~TestConsumer() { + ClearQueue(); + sank_event_.Close(); + } + + void ClearQueue() { + EventQueue::const_iterator it(events_.begin()), end(events_.end()); + + for (; it != end; ++it) { + delete [] it->MofData; + } + + events_.clear(); + } + + static void EnqueueEvent(EVENT_TRACE* event) { + events_.push_back(*event); + EVENT_TRACE& back = events_.back(); + + if (NULL != event->MofData && 0 != event->MofLength) { + 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_; + + private: + DISALLOW_COPY_AND_ASSIGN(TestConsumer); +}; + +ScopedHandle TestConsumer::sank_event_; +EventQueue TestConsumer::events_; + +const wchar_t* const kTestSessionName = L"TestLogSession"; + +class EtwTraceConsumerBaseTest: public testing::Test { + public: + virtual void SetUp() { + EtwTraceController::Stop(kTestSessionName, NULL); + } +}; + +} // namespace + +TEST_F(EtwTraceConsumerBaseTest, Initialize) { + TestConsumer consumer_; +} + +TEST_F(EtwTraceConsumerBaseTest, OpenRealtimeSucceedsWhenNoSession) { + TestConsumer consumer_; + + ASSERT_HRESULT_SUCCEEDED(consumer_.OpenRealtimeSession(kTestSessionName)); +} + +TEST_F(EtwTraceConsumerBaseTest, ConsumerImmediateFailureWhenNoSession) { + TestConsumer consumer_; + + ASSERT_HRESULT_SUCCEEDED(consumer_.OpenRealtimeSession(kTestSessionName)); + ASSERT_HRESULT_FAILED(consumer_.Consume()); +} + +namespace { + +class EtwTraceConsumerRealtimeTest: public testing::Test { + public: + virtual void SetUp() { + ASSERT_HRESULT_SUCCEEDED(consumer_.OpenRealtimeSession(kTestSessionName)); + } + + virtual void TearDown() { + consumer_.Close(); + } + + DWORD ConsumerThread() { + ::SetEvent(consumer_ready_.Get()); + + HRESULT hr = consumer_.Consume(); + return hr; + } + + static DWORD WINAPI ConsumerThreadMainProc(void* arg) { + return reinterpret_cast<EtwTraceConsumerRealtimeTest*>(arg)-> + ConsumerThread(); + } + + HRESULT StartConsumerThread() { + consumer_ready_.Set(::CreateEvent(NULL, TRUE, FALSE, NULL)); + EXPECT_TRUE(consumer_ready_ != NULL); + consumer_thread_.Set(::CreateThread(NULL, 0, ConsumerThreadMainProc, + this, 0, NULL)); + if (NULL == consumer_thread_.Get()) + return HRESULT_FROM_WIN32(::GetLastError()); + + HRESULT hr = S_OK; + HANDLE events[] = { consumer_ready_, consumer_thread_ }; + DWORD result = ::WaitForMultipleObjects(arraysize(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 (WAIT_OBJECT_0 == ::WaitForSingleObject(consumer_ready_, 0)) + return S_OK; + DWORD exit_code = 0; + if (::GetExitCodeThread(consumer_thread_, &exit_code)) + return exit_code; + else + return HRESULT_FROM_WIN32(::GetLastError()); + break; + } + default: + return E_UNEXPECTED; + break; + } + + return hr; + } + + // Waits for consumer_ thread to exit, and returns its exit code. + HRESULT JoinConsumerThread() { + if (WAIT_OBJECT_0 != ::WaitForSingleObject(consumer_thread_, INFINITE)) + return HRESULT_FROM_WIN32(::GetLastError()); + + DWORD exit_code = 0; + if (::GetExitCodeThread(consumer_thread_, &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; + + HRESULT hr = controller.StartRealtimeSession(kTestSessionName, 100 * 1024); + if (hr == E_ACCESSDENIED) { + LOG(INFO) << "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. + ASSERT_EQ(WAIT_TIMEOUT, ::WaitForSingleObject(consumer_thread_, 50)); + + ASSERT_HRESULT_SUCCEEDED(controller.Stop(NULL)); + + // The consumer_ returns success on session stop. + ASSERT_HRESULT_SUCCEEDED(JoinConsumerThread()); +} + +namespace { + +// {036B8F65-8DF3-46e4-ABFC-6985C43D59BA} +DEFINE_GUID(kTestProvider, + 0x36b8f65, 0x8df3, 0x46e4, 0xab, 0xfc, 0x69, 0x85, 0xc4, 0x3d, 0x59, 0xba); + +// {57E47923-A549-476f-86CA-503D57F59E62} +DEFINE_GUID(kTestEventType, + 0x57e47923, 0xa549, 0x476f, 0x86, 0xca, 0x50, 0x3d, 0x57, 0xf5, 0x9e, 0x62); + +} // namespace + +TEST_F(EtwTraceConsumerRealtimeTest, ConsumeEvent) { + EtwTraceController controller; + HRESULT hr = controller.StartRealtimeSession(kTestSessionName, 100 * 1024); + if (hr == E_ACCESSDENIED) { + LOG(INFO) << "You must be an administrator to run this test on Vista"; + return; + } + + ASSERT_HRESULT_SUCCEEDED(controller.EnableProvider(kTestProvider, + TRACE_LEVEL_VERBOSE, 0xFFFFFFFF)); + + EtwTraceProvider provider(kTestProvider); + ASSERT_EQ(ERROR_SUCCESS, provider.Register()); + + // Start the consumer_. + ASSERT_HRESULT_SUCCEEDED(StartConsumerThread()); + + ASSERT_EQ(0, TestConsumer::events_.size()); + + EtwMofEvent<1> event(kTestEventType, 1, TRACE_LEVEL_ERROR); + EXPECT_EQ(ERROR_SUCCESS, provider.Log(&event.header)); + + EXPECT_EQ(WAIT_OBJECT_0, ::WaitForSingleObject(TestConsumer::sank_event_, + INFINITE)); + ASSERT_HRESULT_SUCCEEDED(controller.Stop(NULL)); + ASSERT_HRESULT_SUCCEEDED(JoinConsumerThread()); + ASSERT_NE(0, TestConsumer::events_.size()); +} + +namespace { + +// We run events through a file session to assert that +// the content comes through. +class EtwTraceConsumerDataTest: public testing::Test { + public: + EtwTraceConsumerDataTest() { + } + + virtual void SetUp() { + EtwTraceController::Stop(kTestSessionName, NULL); + // Construct a temp file name. + ASSERT_TRUE(file_util::CreateTemporaryFile(&temp_file_)); + } + + virtual void TearDown() { + EXPECT_TRUE(file_util::Delete(temp_file_, false)); + EtwTraceController::Stop(kTestSessionName, NULL); + } + + HRESULT LogEventToTempSession(PEVENT_TRACE_HEADER header) { + EtwTraceController controller; + + // Set up a file session. + HRESULT hr = controller.StartFileSession(kTestSessionName, + temp_file_.value().c_str()); + if (FAILED(hr)) + return hr; + + // Enable our provider. + EXPECT_HRESULT_SUCCEEDED(controller.EnableProvider(kTestProvider, + TRACE_LEVEL_VERBOSE, 0xFFFFFFFF)); + + EtwTraceProvider provider(kTestProvider); + // Then register our provider, means we get a session handle immediately. + EXPECT_EQ(ERROR_SUCCESS, provider.Register()); + // Trace the event, it goes to the temp file. + EXPECT_EQ(ERROR_SUCCESS, provider.Log(header)); + EXPECT_HRESULT_SUCCEEDED(controller.DisableProvider(kTestProvider)); + EXPECT_HRESULT_SUCCEEDED(provider.Unregister()); + EXPECT_HRESULT_SUCCEEDED(controller.Flush(NULL)); + EXPECT_HRESULT_SUCCEEDED(controller.Stop(NULL)); + + 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) { + file_util::Delete(temp_file_, false); + + 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_; + 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 = NULL; + HRESULT hr = RoundTripEvent(&event.header, &trace); + if (hr == E_ACCESSDENIED) { + LOG(INFO) << "You must be an administrator to run this test on Vista"; + return; + } + ASSERT_TRUE(NULL != trace); + ASSERT_EQ(sizeof(kData), trace->MofLength); + ASSERT_STREQ(kData, reinterpret_cast<const char*>(trace->MofData)); +} diff --git a/base/event_trace_controller_win.cc b/base/event_trace_controller_win.cc new file mode 100644 index 0000000..cb15150 --- /dev/null +++ b/base/event_trace_controller_win.cc @@ -0,0 +1,130 @@ +// Copyright (c) 2009 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. +// +// Implementation of a Windows event trace controller class. +#include "base/event_trace_controller_win.h" +#include "base/logging.h" + +EtwTraceController::EtwTraceController() : session_(NULL) { +} + +EtwTraceController::~EtwTraceController() { + Stop(NULL); +} + +HRESULT EtwTraceController::Start(const wchar_t* session_name, + EtwTraceProperties* prop) { + DCHECK(NULL == session_ && session_name_.empty()); + EtwTraceProperties ignore; + if (prop == NULL) + prop = &ignore; + + HRESULT hr = Start(session_name, prop, &session_); + if (SUCCEEDED(hr)) + session_name_ = session_name; + + return hr; +} + +HRESULT EtwTraceController::StartFileSession(const wchar_t* session_name, + const wchar_t* logfile_path, bool realtime) { + DCHECK(NULL == session_ && session_name_.empty()); + + EtwTraceProperties prop; + prop.SetLoggerFileName(logfile_path); + EVENT_TRACE_PROPERTIES& p = *prop.get(); + p.Wnode.ClientContext = 1; // QPC timer accuracy. + p.LogFileMode = EVENT_TRACE_FILE_MODE_SEQUENTIAL; // Sequential log. + if (realtime) + p.LogFileMode |= EVENT_TRACE_REAL_TIME_MODE; + + p.MaximumFileSize = 100; // 100M file size. + p.FlushTimer = 30; // 30 seconds flush lag. + return Start(session_name, &prop); +} + +HRESULT EtwTraceController::StartRealtimeSession(const wchar_t* session_name, + size_t buffer_size) { + DCHECK(NULL == session_ && session_name_.empty()); + EtwTraceProperties prop; + EVENT_TRACE_PROPERTIES& p = *prop.get(); + p.LogFileMode = EVENT_TRACE_REAL_TIME_MODE | EVENT_TRACE_USE_PAGED_MEMORY; + p.FlushTimer = 1; // flush every second. + p.BufferSize = 16; // 16 K buffers. + p.LogFileNameOffset = 0; + return Start(session_name, &prop); +} + +HRESULT EtwTraceController::EnableProvider(REFGUID provider, UCHAR level, + ULONG flags) { + ULONG error = ::EnableTrace(TRUE, flags, level, &provider, session_); + return HRESULT_FROM_WIN32(error); +} + +HRESULT EtwTraceController::DisableProvider(REFGUID provider) { + ULONG error = ::EnableTrace(FALSE, 0, 0, &provider, session_); + return HRESULT_FROM_WIN32(error); +} + +HRESULT EtwTraceController::Stop(EtwTraceProperties* properties) { + EtwTraceProperties ignore; + if (properties == NULL) + properties = &ignore; + + ULONG error = ::ControlTrace(session_, NULL, properties->get(), + EVENT_TRACE_CONTROL_STOP); + if (ERROR_SUCCESS != error) + return HRESULT_FROM_WIN32(error); + + session_ = NULL; + session_name_.clear(); + return S_OK; +} + +HRESULT EtwTraceController::Flush(EtwTraceProperties* properties) { + EtwTraceProperties ignore; + if (properties == NULL) + properties = &ignore; + + ULONG error = ::ControlTrace(session_, NULL, properties->get(), + EVENT_TRACE_CONTROL_FLUSH); + if (ERROR_SUCCESS != error) + return HRESULT_FROM_WIN32(error); + + return S_OK; +} + +HRESULT EtwTraceController::Start(const wchar_t* session_name, + EtwTraceProperties* properties, TRACEHANDLE* session_handle) { + ULONG err = ::StartTrace(session_handle, session_name, properties->get()); + return HRESULT_FROM_WIN32(err); +} + +HRESULT EtwTraceController::Query(const wchar_t* session_name, + EtwTraceProperties* properties) { + ULONG err = ::ControlTrace(NULL, session_name, properties->get(), + EVENT_TRACE_CONTROL_QUERY); + return HRESULT_FROM_WIN32(err); +}; + +HRESULT EtwTraceController::Update(const wchar_t* session_name, + EtwTraceProperties* properties) { + ULONG err = ::ControlTrace(NULL, session_name, properties->get(), + EVENT_TRACE_CONTROL_UPDATE); + return HRESULT_FROM_WIN32(err); +} + +HRESULT EtwTraceController::Stop(const wchar_t* session_name, + EtwTraceProperties* properties) { + ULONG err = ::ControlTrace(NULL, session_name, properties->get(), + EVENT_TRACE_CONTROL_STOP); + return HRESULT_FROM_WIN32(err); +} + +HRESULT EtwTraceController::Flush(const wchar_t* session_name, + EtwTraceProperties* properties) { + ULONG err = ::ControlTrace(NULL, session_name, properties->get(), + EVENT_TRACE_CONTROL_FLUSH); + return HRESULT_FROM_WIN32(err); +} diff --git a/base/event_trace_controller_win.h b/base/event_trace_controller_win.h new file mode 100644 index 0000000..5267c86 --- /dev/null +++ b/base/event_trace_controller_win.h @@ -0,0 +1,168 @@ +// Copyright (c) 2009 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. +// +// Declaration of a Windows event trace controller class. +// The controller takes care of creating and manipulating event trace +// sessions. +// +// Event tracing for Windows is a system-provided service that provides +// logging control and high-performance transport for generic, binary trace +// events. Event trace providers register with the system by their name, +// which is a GUID, and can from that point forward receive callbacks that +// start or end tracing and that change their trace level and enable mask. +// +// A trace controller can create an event tracing session, which either +// sends events to a binary file, or to a realtime consumer, or both. +// +// A trace consumer consumes events from zero or one realtime session, +// as well as potentially from multiple binary trace files. +#ifndef BASE_EVENT_TRACE_CONTROLLER_WIN_H_ +#define BASE_EVENT_TRACE_CONTROLLER_WIN_H_ + +#include <windows.h> +#include <wmistr.h> +#include <evntrace.h> +#include <string> +#include "base/basictypes.h" + +// Utility class to make it easier to work with EVENT_TRACE_PROPERTIES. +// The EVENT_TRACE_PROPERTIES structure contains information about an +// event tracing session. +class EtwTraceProperties { + public: + EtwTraceProperties() { + memset(buffer_, 0, sizeof(buffer_)); + EVENT_TRACE_PROPERTIES* prop = get(); + + prop->Wnode.BufferSize = sizeof(buffer_); + prop->Wnode.Flags = WNODE_FLAG_TRACED_GUID; + prop->LoggerNameOffset = sizeof(EVENT_TRACE_PROPERTIES); + prop->LogFileNameOffset = sizeof(EVENT_TRACE_PROPERTIES) + + sizeof(wchar_t) * kMaxStringLen; + } + + EVENT_TRACE_PROPERTIES* get() { + return &properties_; + } + const EVENT_TRACE_PROPERTIES* get() const { + return reinterpret_cast<const EVENT_TRACE_PROPERTIES*>(&properties_); + } + + const wchar_t* GetLoggerName() const { + return reinterpret_cast<const wchar_t *>(buffer_ + get()->LoggerNameOffset); + } + + HRESULT SetLoggerName(const wchar_t* logger_name) { + size_t len = wcslen(logger_name) + 1; + if (kMaxStringLen < len) + return E_INVALIDARG; + + memcpy(buffer_ + get()->LoggerNameOffset, + logger_name, + sizeof(wchar_t) * len); + return S_OK; + } + + const wchar_t* GetLoggerFileName() const { + return reinterpret_cast<const wchar_t*>(buffer_ + get()->LogFileNameOffset); + } + + HRESULT SetLoggerFileName(const wchar_t* logger_file_name) { + size_t len = wcslen(logger_file_name) + 1; + if (kMaxStringLen < len) + return E_INVALIDARG; + + memcpy(buffer_ + get()->LogFileNameOffset, + logger_file_name, + sizeof(wchar_t) * len); + return S_OK; + } + + // Max string len for name and session name is 1024 per documentation. + static const size_t kMaxStringLen = 1024; + // Properties buffer allocates space for header and for + // max length for name and session name. + static const size_t kBufSize = sizeof(EVENT_TRACE_PROPERTIES) + + 2 * sizeof(wchar_t) * (kMaxStringLen); + + private: + // The EVENT_TRACE_PROPERTIES structure needs to be overlaid on a + // larger buffer to allow storing the logger name and logger file + // name contiguously with the structure. + union { + public: + // Our properties header. + EVENT_TRACE_PROPERTIES properties_; + // The actual size of the buffer is forced by this member. + char buffer_[kBufSize]; + }; + + DISALLOW_COPY_AND_ASSIGN(EtwTraceProperties); +}; + +// This class implements an ETW controller, which knows how to start and +// stop event tracing sessions, as well as controlling ETW provider +// log levels and enable bit masks under the session. +class EtwTraceController { + public: + EtwTraceController(); + ~EtwTraceController(); + + // Start a session with given name and properties. + HRESULT Start(const wchar_t* session_name, EtwTraceProperties* prop); + + // Starts a session tracing to a file with some default properties. + HRESULT StartFileSession(const wchar_t* session_name, + const wchar_t* logfile_path, + bool realtime = false); + + // Starts a realtime session with some default properties. + HRESULT StartRealtimeSession(const wchar_t* session_name, + size_t buffer_size); + + // Enables "provider" at "level" for this session. + // This will cause all providers registered with the GUID + // "provider" to start tracing at the new level, systemwide. + HRESULT EnableProvider(const GUID& provider, UCHAR level, + ULONG flags = 0xFFFFFFFF); + // Disables "provider". + HRESULT DisableProvider(const GUID& provider); + + // Stops our session and retrieve the new properties of the session, + // properties may be NULL. + HRESULT Stop(EtwTraceProperties* properties); + + // Flushes our session and retrieve the current properties, + // properties may be NULL. + HRESULT Flush(EtwTraceProperties* properties); + + // Static utility functions for controlling + // sessions we don't necessarily own. + static HRESULT Start(const wchar_t* session_name, + EtwTraceProperties* properties, + TRACEHANDLE* session_handle); + + static HRESULT Query(const wchar_t* session_name, + EtwTraceProperties* properties); + + static HRESULT Update(const wchar_t* session_name, + EtwTraceProperties* properties); + + static HRESULT Stop(const wchar_t* session_name, + EtwTraceProperties* properties); + static HRESULT Flush(const wchar_t* session_name, + EtwTraceProperties* properties); + + // Accessors. + TRACEHANDLE session() const { return session_; } + const wchar_t* session_name() const { return session_name_.c_str(); } + + private: + std::wstring session_name_; + TRACEHANDLE session_; + + DISALLOW_COPY_AND_ASSIGN(EtwTraceController); +}; + +#endif // BASE_EVENT_TRACE_CONTROLLER_WIN_H_ diff --git a/base/event_trace_controller_win_unittest.cc b/base/event_trace_controller_win_unittest.cc new file mode 100644 index 0000000..f688d48 --- /dev/null +++ b/base/event_trace_controller_win_unittest.cc @@ -0,0 +1,203 @@ +// Copyright (c) 2009 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. +// +// Unit tests for event trace controller. +#include "base/event_trace_controller_win.h" +#include "base/event_trace_provider_win.h" +#include "base/file_path.h" +#include "base/file_util.h" +#include "base/logging.h" +#include "base/scoped_handle.h" +#include "base/sys_info.h" +#include "testing/gtest/include/gtest/gtest.h" +#include <initguid.h> // NOLINT - must be last. + +namespace { + +const wchar_t kTestSessionName[] = L"TestLogSession"; + +// {0D236A42-CD18-4e3d-9975-DCEEA2106E05} +DEFINE_GUID(kTestProvider, + 0xd236a42, 0xcd18, 0x4e3d, 0x99, 0x75, 0xdc, 0xee, 0xa2, 0x10, 0x6e, 0x5); + +DEFINE_GUID(kGuidNull, + 0x0000000, 0x0000, 0x0000, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x0); + +const ULONG kTestProviderFlags = 0xCAFEBABE; + +class TestingProvider: public EtwTraceProvider { + public: + explicit TestingProvider(const GUID& provider_name) + : EtwTraceProvider(provider_name) { + callback_event_.Set(::CreateEvent(NULL, TRUE, FALSE, NULL)); + } + + void WaitForCallback() { + ::WaitForSingleObject(callback_event_.Get(), INFINITE); + ::ResetEvent(callback_event_.Get()); + } + + private: + virtual void OnEventsEnabled() { + ::SetEvent(callback_event_.Get()); + } + virtual void OnEventsDisabled() { + ::SetEvent(callback_event_.Get()); + } + + ScopedHandle callback_event_; + + DISALLOW_COPY_AND_ASSIGN(TestingProvider); +}; + +} // namespace + +TEST(EtwTraceTest, Cleanup) { + // Clean up potential leftover sessions from previous unsuccessful runs. + EtwTraceController::Stop(kTestSessionName, NULL); +} + +TEST(EtwTracePropertiesTest, Initialization) { + EtwTraceProperties prop; + + EVENT_TRACE_PROPERTIES* p = prop.get(); + EXPECT_NE(0, p->Wnode.BufferSize); + EXPECT_EQ(0, p->Wnode.ProviderId); + EXPECT_EQ(0, p->Wnode.HistoricalContext); + + EXPECT_TRUE(kGuidNull == p->Wnode.Guid); + EXPECT_EQ(0, p->Wnode.ClientContext); + EXPECT_EQ(WNODE_FLAG_TRACED_GUID, p->Wnode.Flags); + + EXPECT_EQ(0, p->BufferSize); + EXPECT_EQ(0, p->MinimumBuffers); + EXPECT_EQ(0, p->MaximumBuffers); + EXPECT_EQ(0, p->MaximumFileSize); + EXPECT_EQ(0, p->LogFileMode); + EXPECT_EQ(0, p->FlushTimer); + EXPECT_EQ(0, p->EnableFlags); + EXPECT_EQ(0, p->AgeLimit); + + EXPECT_EQ(0, p->NumberOfBuffers); + EXPECT_EQ(0, p->FreeBuffers); + EXPECT_EQ(0, p->EventsLost); + EXPECT_EQ(0, p->BuffersWritten); + EXPECT_EQ(0, p->LogBuffersLost); + EXPECT_EQ(0, p->RealTimeBuffersLost); + EXPECT_EQ(0, p->LoggerThreadId); + EXPECT_NE(0, p->LogFileNameOffset); + EXPECT_NE(0, p->LoggerNameOffset); +} + +TEST(EtwTracePropertiesTest, Strings) { + EtwTraceProperties prop; + + ASSERT_STREQ(L"", prop.GetLoggerFileName()); + ASSERT_STREQ(L"", prop.GetLoggerName()); + + std::wstring name(1023, L'A'); + ASSERT_HRESULT_SUCCEEDED(prop.SetLoggerFileName(name.c_str())); + ASSERT_HRESULT_SUCCEEDED(prop.SetLoggerName(name.c_str())); + ASSERT_STREQ(name.c_str(), prop.GetLoggerFileName()); + ASSERT_STREQ(name.c_str(), prop.GetLoggerName()); + + std::wstring name2(1024, L'A'); + ASSERT_HRESULT_FAILED(prop.SetLoggerFileName(name2.c_str())); + ASSERT_HRESULT_FAILED(prop.SetLoggerName(name2.c_str())); +} + +TEST(EtwTraceControllerTest, Initialize) { + EtwTraceController controller; + + EXPECT_EQ(NULL, controller.session()); + EXPECT_STREQ(L"", controller.session_name()); +} + +TEST(EtwTraceControllerTest, StartRealTimeSession) { + EtwTraceController controller; + + HRESULT hr = controller.StartRealtimeSession(kTestSessionName, 100 * 1024); + if (hr == E_ACCESSDENIED) { + LOG(INFO) << "You must be an administrator to run this test on Vista"; + return; + } + + EXPECT_TRUE(NULL != controller.session()); + EXPECT_STREQ(kTestSessionName, controller.session_name()); + + EXPECT_HRESULT_SUCCEEDED(controller.Stop(NULL)); + EXPECT_EQ(NULL, controller.session()); + EXPECT_STREQ(L"", controller.session_name()); +} + +TEST(EtwTraceControllerTest, StartFileSession) { + FilePath temp; + + ASSERT_HRESULT_SUCCEEDED(file_util::CreateTemporaryFile(&temp)); + + EtwTraceController controller; + HRESULT hr = controller.StartFileSession(kTestSessionName, + temp.value().c_str()); + if (hr == E_ACCESSDENIED) { + LOG(INFO) << "You must be an administrator to run this test on Vista"; + return; + } + + EXPECT_TRUE(NULL != controller.session()); + EXPECT_STREQ(kTestSessionName, controller.session_name()); + + EXPECT_HRESULT_SUCCEEDED(controller.Stop(NULL)); + EXPECT_EQ(NULL, controller.session()); + EXPECT_STREQ(L"", controller.session_name()); +} + +TEST(EtwTraceControllerTest, EnableDisable) { + TestingProvider provider(kTestProvider); + + EXPECT_EQ(ERROR_SUCCESS, provider.Register()); + EXPECT_EQ(NULL, provider.session_handle()); + + EtwTraceController controller; + HRESULT hr = controller.StartRealtimeSession(kTestSessionName, 100 * 1024); + if (hr == E_ACCESSDENIED) { + LOG(INFO) << "You must be an administrator to run this test on Vista"; + return; + } + + EXPECT_HRESULT_SUCCEEDED(controller.EnableProvider(kTestProvider, + TRACE_LEVEL_VERBOSE, kTestProviderFlags)); + + provider.WaitForCallback(); + + EXPECT_EQ(TRACE_LEVEL_VERBOSE, provider.enable_level()); + EXPECT_EQ(kTestProviderFlags, provider.enable_flags()); + + EXPECT_HRESULT_SUCCEEDED(controller.DisableProvider(kTestProvider)); + + provider.WaitForCallback(); + + EXPECT_EQ(0, provider.enable_level()); + EXPECT_EQ(0, provider.enable_flags()); + + EXPECT_EQ(ERROR_SUCCESS, provider.Unregister()); + + // Enable the provider again, before registering. + EXPECT_HRESULT_SUCCEEDED(controller.EnableProvider(kTestProvider, + TRACE_LEVEL_VERBOSE, kTestProviderFlags)); + + // Register the provider again, the settings above + // should take immediate effect. + EXPECT_EQ(ERROR_SUCCESS, provider.Register()); + + EXPECT_EQ(TRACE_LEVEL_VERBOSE, provider.enable_level()); + EXPECT_EQ(kTestProviderFlags, provider.enable_flags()); + + EXPECT_HRESULT_SUCCEEDED(controller.Stop(NULL)); + + provider.WaitForCallback(); + + // Session should have wound down. + EXPECT_EQ(0, provider.enable_level()); + EXPECT_EQ(0, provider.enable_flags()); +} diff --git a/base/event_trace_provider_win.cc b/base/event_trace_provider_win.cc new file mode 100644 index 0000000..69fcd57 --- /dev/null +++ b/base/event_trace_provider_win.cc @@ -0,0 +1,126 @@ +// Copyright (c) 2009 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/event_trace_provider_win.h" +#include <windows.h> +#include <cguid.h> + +TRACE_GUID_REGISTRATION EtwTraceProvider::obligatory_guid_registration_ = { + &GUID_NULL, + NULL +}; + +EtwTraceProvider::EtwTraceProvider(const GUID& provider_name) + : provider_name_(provider_name), registration_handle_(NULL), + session_handle_(NULL), enable_flags_(0), enable_level_(0) { +} + +EtwTraceProvider::EtwTraceProvider() + : provider_name_(GUID_NULL), registration_handle_(NULL), + session_handle_(NULL), enable_flags_(0), enable_level_(0) { +} + +EtwTraceProvider::~EtwTraceProvider() { + Unregister(); +} + +ULONG EtwTraceProvider::EnableEvents(void* buffer) { + session_handle_ = ::GetTraceLoggerHandle(buffer); + if (NULL == session_handle_) { + return ::GetLastError(); + } + + enable_flags_ = ::GetTraceEnableFlags(session_handle_); + enable_level_ = ::GetTraceEnableLevel(session_handle_); + + // Give subclasses a chance to digest the state change. + OnEventsEnabled(); + + return ERROR_SUCCESS; +} + +ULONG EtwTraceProvider::DisableEvents() { + enable_level_ = 0; + enable_flags_ = 0; + session_handle_ = NULL; + + // Give subclasses a chance to digest the state change. + OnEventsDisabled(); + + return ERROR_SUCCESS; +} + +ULONG EtwTraceProvider::Callback(WMIDPREQUESTCODE request, void* buffer) { + switch (request) { + case WMI_ENABLE_EVENTS: + return EnableEvents(buffer); + case WMI_DISABLE_EVENTS: + return DisableEvents(); + default: + return ERROR_INVALID_PARAMETER; + } + // Not reached. +} + +ULONG WINAPI EtwTraceProvider::ControlCallback(WMIDPREQUESTCODE request, + void* context, ULONG *reserved, void* buffer) { + EtwTraceProvider *provider = reinterpret_cast<EtwTraceProvider*>(context); + + return provider->Callback(request, buffer); +} + +ULONG EtwTraceProvider::Register() { + if (provider_name_ == GUID_NULL) + return ERROR_INVALID_NAME; + + return ::RegisterTraceGuids(ControlCallback, this, &provider_name_, + 1, &obligatory_guid_registration_, NULL, NULL, ®istration_handle_); +} + +ULONG EtwTraceProvider::Unregister() { + ULONG ret = ::UnregisterTraceGuids(registration_handle_); + + // Make sure we don't log anything from here on. + enable_level_ = 0; + enable_flags_ = 0; + session_handle_ = NULL; + registration_handle_ = NULL; + + return ret; +} + +ULONG EtwTraceProvider::Log(const EtwEventClass& event_class, + EtwEventType type, EtwEventLevel level, const char *message) { + if (NULL == session_handle_ || enable_level_ < level) + return ERROR_SUCCESS; // No one listening. + + EtwMofEvent<1> event(event_class, type, level); + + event.fields[0].DataPtr = reinterpret_cast<ULONG64>(message); + event.fields[0].Length = message ? + sizeof(message[0]) * (1 + strlen(message)) : 0; + + return ::TraceEvent(session_handle_, &event.header); +} + +ULONG EtwTraceProvider::Log(const EtwEventClass& event_class, + EtwEventType type, EtwEventLevel level, const wchar_t *message) { + if (NULL == session_handle_ || enable_level_ < level) + return ERROR_SUCCESS; // No one listening. + + EtwMofEvent<1> event(event_class, type, level); + + event.fields[0].DataPtr = reinterpret_cast<ULONG64>(message); + event.fields[0].Length = message ? + sizeof(message[0]) * (1 + wcslen(message)) : 0; + + return ::TraceEvent(session_handle_, &event.header); +} + +ULONG EtwTraceProvider::Log(EVENT_TRACE_HEADER* event) { + if (enable_level_ < event->Class.Level) + return ERROR_SUCCESS; + + return ::TraceEvent(session_handle_, event); +} diff --git a/base/event_trace_provider_win.h b/base/event_trace_provider_win.h new file mode 100644 index 0000000..bf186ee --- /dev/null +++ b/base/event_trace_provider_win.h @@ -0,0 +1,155 @@ +// Copyright (c) 2009 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. +// +// Declaration of a Windows event trace provider class, to allow using +// Windows Event Tracing for logging transport and control. +#ifndef BASE_EVENT_TRACE_PROVIDER_WIN_H_ +#define BASE_EVENT_TRACE_PROVIDER_WIN_H_ + +#include <windows.h> +#include <wmistr.h> +#include <evntrace.h> +#include "base/basictypes.h" + +typedef GUID EtwEventClass; +typedef UCHAR EtwEventType; +typedef UCHAR EtwEventLevel; +typedef USHORT EtwEventVersion; +typedef ULONG EtwEventFlags; + +// Base class is a POD for correctness. +template <size_t N> struct EtwMofEventBase { + EVENT_TRACE_HEADER header; + MOF_FIELD fields[N]; +}; + +// Utility class to auto-initialize event trace header structures. +template <size_t N> class EtwMofEvent: public EtwMofEventBase<N> { + public: + typedef EtwMofEventBase<N> Super; + + EtwMofEvent() { + memset(static_cast<Super*>(this), 0, sizeof(Super)); + } + + EtwMofEvent(const EtwEventClass& event_class, EtwEventType type, + EtwEventLevel level) { + memset(static_cast<Super*>(this), 0, sizeof(Super)); + header.Size = sizeof(Super); + header.Guid = event_class; + header.Class.Type = type; + header.Class.Level = level; + header.Flags = WNODE_FLAG_TRACED_GUID | WNODE_FLAG_USE_MOF_PTR; + } + + EtwMofEvent(const EtwEventClass& event_class, EtwEventType type, + EtwEventVersion version, EtwEventLevel level) { + memset(static_cast<Super*>(this), 0, sizeof(Super)); + header.Size = sizeof(Super); + header.Guid = event_class; + header.Class.Type = type; + header.Class.Version = version; + header.Class.Level = level; + header.Flags = WNODE_FLAG_TRACED_GUID | WNODE_FLAG_USE_MOF_PTR; + } + + void SetField(int field, size_t size, const void *data) { + // DCHECK(field < N); + if (field < N) { + fields[field].DataPtr = reinterpret_cast<ULONG64>(data); + fields[field].Length = size; + } + } + + EVENT_TRACE_HEADER* get() { return& header; } + + private: + DISALLOW_COPY_AND_ASSIGN(EtwMofEvent); +}; + +// Trace provider with Event Tracing for Windows. The trace provider +// registers with ETW by its name which is a GUID. ETW calls back to +// the object whenever the trace level or enable flags for this provider +// name changes. +// Users of this class can test whether logging is currently enabled at +// a particular trace level, and whether particular enable flags are set, +// before other resources are consumed to generate and issue the log +// messages themselves. +class EtwTraceProvider { + public: + // Creates an event trace provider identified by provider_name, which + // will be the name registered with Event Tracing for Windows (ETW). + explicit EtwTraceProvider(const GUID& provider_name); + + // Creates an unnamed event trace provider, the provider must be given + // a name before registration. + EtwTraceProvider(); + virtual ~EtwTraceProvider(); + + // Registers the trace provider with Event Tracing for Windows. + // Note: from this point forward ETW may call the provider's control + // callback. If the provider's name is enabled in some trace session + // already, the callback may occur recursively from this call, so + // call this only when you're ready to handle callbacks. + ULONG Register(); + // Unregisters the trace provider with ETW. + ULONG Unregister(); + + // Accessors. + void set_provider_name(const GUID& provider_name) { + provider_name_ = provider_name; + } + const GUID& provider_name() const { return provider_name_; } + TRACEHANDLE registration_handle() const { return registration_handle_; } + TRACEHANDLE session_handle() const { return session_handle_; } + EtwEventFlags enable_flags() const { return enable_flags_; } + EtwEventLevel enable_level() const { return enable_level_; } + + // Returns true iff logging should be performed for "level" and "flags". + // Note: flags is treated as a bitmask, and should normally have a single + // bit set, to test whether to log for a particular sub "facility". + bool ShouldLog(EtwEventLevel level, EtwEventFlags flags) { + return NULL != session_handle_ && level >= enable_level_ && + (0 != (flags & enable_flags_)); + } + + // Simple wrappers to log Unicode and ANSI strings. + // Do nothing if !ShouldLog(level, 0xFFFFFFFF). + ULONG Log(const EtwEventClass& event_class, EtwEventType type, + EtwEventLevel level, const char *message); + ULONG Log(const EtwEventClass& event_class, EtwEventType type, + EtwEventLevel level, const wchar_t *message); + + // Log the provided event. + ULONG Log(EVENT_TRACE_HEADER* event); + + protected: + // These are called after events have been enabled or disabled. + // Override them if you want to do processing at the start or + // end of collection. + // Note: These may be called ETW's thread and they may be racy. + virtual void OnEventsEnabled() {} + virtual void OnEventsDisabled() {} + + private: + ULONG EnableEvents(PVOID buffer); + ULONG DisableEvents(); + ULONG Callback(WMIDPREQUESTCODE request, PVOID buffer); + static ULONG WINAPI ControlCallback(WMIDPREQUESTCODE request, PVOID context, + ULONG *reserved, PVOID buffer); + + GUID provider_name_; + TRACEHANDLE registration_handle_; + TRACEHANDLE session_handle_; + EtwEventFlags enable_flags_; + EtwEventLevel enable_level_; + + // We don't use this, but on XP we're obliged to pass one in to + // RegisterTraceGuids. Non-const, because that's how the API needs it. + static TRACE_GUID_REGISTRATION obligatory_guid_registration_; + + DISALLOW_COPY_AND_ASSIGN(EtwTraceProvider); +}; + +#endif // BASE_EVENT_TRACE_PROVIDER_WIN_H_ diff --git a/base/event_trace_provider_win_unittest.cc b/base/event_trace_provider_win_unittest.cc new file mode 100644 index 0000000..2ffae82 --- /dev/null +++ b/base/event_trace_provider_win_unittest.cc @@ -0,0 +1,107 @@ +// Copyright (c) 2009 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. +// +// Unit tests for event trace provider. +#include "base/event_trace_provider_win.h" +#include <new> +#include "testing/gtest/include/gtest/gtest.h" +#include <initguid.h> // NOLINT - has to be last + +namespace { + +// {7F0FD37F-FA3C-4cd6-9242-DF60967A2CB2} +DEFINE_GUID(kTestProvider, + 0x7f0fd37f, 0xfa3c, 0x4cd6, 0x92, 0x42, 0xdf, 0x60, 0x96, 0x7a, 0x2c, 0xb2); + +// {7F0FD37F-FA3C-4cd6-9242-DF60967A2CB2} +DEFINE_GUID(kTestEventClass, + 0x7f0fd37f, 0xfa3c, 0x4cd6, 0x92, 0x42, 0xdf, 0x60, 0x96, 0x7a, 0x2c, 0xb2); + +} // namespace + +TEST(EtwTraceProviderTest, ToleratesPreCreateInvocations) { + // Because the trace provider is used in logging, it's important that + // it be possible to use static provider instances without regard to + // whether they've been constructed or destructed. + // The interface of the class is designed to tolerate this usage. + char buf[sizeof(EtwTraceProvider)] = {0}; + EtwTraceProvider& provider = reinterpret_cast<EtwTraceProvider&>(buf); + + EXPECT_EQ(NULL, provider.registration_handle()); + EXPECT_EQ(NULL, provider.session_handle()); + EXPECT_EQ(0, provider.enable_flags()); + EXPECT_EQ(0, provider.enable_level()); + + EXPECT_FALSE(provider.ShouldLog(TRACE_LEVEL_FATAL, 0xfffffff)); + + // We expect these not to crash. + provider.Log(kTestEventClass, 0, TRACE_LEVEL_FATAL, "foo"); + provider.Log(kTestEventClass, 0, TRACE_LEVEL_FATAL, L"foo"); + + EtwMofEvent<1> dummy(kTestEventClass, 0, TRACE_LEVEL_FATAL); + DWORD data = 0; + dummy.SetField(0, sizeof(data), &data); + provider.Log(dummy.get()); + + // Placement-new the provider into our buffer. + new (buf) EtwTraceProvider(kTestProvider); + + // Registration is now safe. + EXPECT_EQ(ERROR_SUCCESS, provider.Register()); + + // Destruct the instance, this should unregister it. + provider.EtwTraceProvider::~EtwTraceProvider(); + + // And post-destruction, all of the above should still be safe. + EXPECT_EQ(NULL, provider.registration_handle()); + EXPECT_EQ(NULL, provider.session_handle()); + EXPECT_EQ(0, provider.enable_flags()); + EXPECT_EQ(0, provider.enable_level()); + + EXPECT_FALSE(provider.ShouldLog(TRACE_LEVEL_FATAL, 0xfffffff)); + + // We expect these not to crash. + provider.Log(kTestEventClass, 0, TRACE_LEVEL_FATAL, "foo"); + provider.Log(kTestEventClass, 0, TRACE_LEVEL_FATAL, L"foo"); + provider.Log(dummy.get()); +} + +TEST(EtwTraceProviderTest, Initialize) { + EtwTraceProvider provider(kTestProvider); + + EXPECT_EQ(NULL, provider.registration_handle()); + EXPECT_EQ(NULL, provider.session_handle()); + EXPECT_EQ(0, provider.enable_flags()); + EXPECT_EQ(0, provider.enable_level()); +} + +TEST(EtwTraceProviderTest, Register) { + EtwTraceProvider provider(kTestProvider); + + ASSERT_EQ(ERROR_SUCCESS, provider.Register()); + EXPECT_NE(NULL, provider.registration_handle()); + ASSERT_EQ(ERROR_SUCCESS, provider.Unregister()); + EXPECT_EQ(NULL, provider.registration_handle()); +} + +TEST(EtwTraceProviderTest, RegisterWithNoNameFails) { + EtwTraceProvider provider; + + EXPECT_NE(ERROR_SUCCESS, provider.Register()); +} + +TEST(EtwTraceProviderTest, Enable) { + EtwTraceProvider provider(kTestProvider); + + ASSERT_EQ(ERROR_SUCCESS, provider.Register()); + EXPECT_NE(NULL, provider.registration_handle()); + + // No session so far. + EXPECT_EQ(NULL, provider.session_handle()); + EXPECT_EQ(0, provider.enable_flags()); + EXPECT_EQ(0, provider.enable_level()); + + ASSERT_EQ(ERROR_SUCCESS, provider.Unregister()); + EXPECT_EQ(NULL, provider.registration_handle()); +} diff --git a/base/logging.cc b/base/logging.cc index b59e3fb..e9cfc7a 100644 --- a/base/logging.cc +++ b/base/logging.cc @@ -98,6 +98,8 @@ LogAssertHandlerFunction log_assert_handler = NULL; // An report handler override specified by the client to be called instead of // the debug message dialog. LogReportHandlerFunction log_report_handler = NULL; +// A log message handler that gets notified of every log message we process. +LogMessageHandlerFunction log_message_handler = NULL; // The lock is used if log file locking is false. It helps us avoid problems // with multiple threads writing to the log file at the same time. Use @@ -312,6 +314,11 @@ void SetLogReportHandler(LogReportHandlerFunction handler) { log_report_handler = handler; } +void SetLogMessageHandler(LogMessageHandlerFunction handler) { + log_message_handler = handler; +} + + // Displays a message box to the user with the error message in it. For // Windows programs, it's possible that the message loop is messed up on // a fatal error, and creating a MessageBox will cause that message loop @@ -446,6 +453,9 @@ LogMessage::~LogMessage() { #else str_newline.append("\n"); #endif + // Give any log message handler first dibs on the message. + if (log_message_handler && log_message_handler(severity_, str_newline)) + return; if (log_filter_prefix && severity_ <= kMaxFilteredLogLevel && str_newline.compare(message_start_, log_filter_prefix->size(), diff --git a/base/logging.h b/base/logging.h index de8de71..4fbe483 100644 --- a/base/logging.h +++ b/base/logging.h @@ -186,6 +186,13 @@ void SetLogAssertHandler(LogAssertHandlerFunction handler); typedef void (*LogReportHandlerFunction)(const std::string& str); void SetLogReportHandler(LogReportHandlerFunction handler); +// Sets the Log Message Handler that gets passed every log message before +// it's sent to other log destinations (if any). +// Returns true to signal that it handled the message and the message +// should not be sent to other log destinations. +typedef bool (*LogMessageHandlerFunction)(int severity, const std::string& str); +void SetLogMessageHandler(LogMessageHandlerFunction handler); + typedef int LogSeverity; const LogSeverity LOG_INFO = 0; const LogSeverity LOG_WARNING = 1; diff --git a/base/logging_win.cc b/base/logging_win.cc new file mode 100644 index 0000000..b3702aa --- /dev/null +++ b/base/logging_win.cc @@ -0,0 +1,152 @@ +// Copyright (c) 2009 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/logging_win.h" +#include "base/atomicops.h" +#include "base/singleton.h" +#include <initguid.h> // NOLINT + +namespace { + +struct LogEventProviderTraits { + // WARNING: User has to deal with get() returning NULL. + static logging::LogEventProvider* New() { + if (base::subtle::NoBarrier_AtomicExchange(&dead_, 1)) + return NULL; + logging::LogEventProvider* ptr = + reinterpret_cast<logging::LogEventProvider*>(buffer_); + // We are protected by a memory barrier. + new (ptr) logging::LogEventProvider(); + return ptr; + } + + static void Delete(logging::LogEventProvider* p) { + base::subtle::NoBarrier_Store(&dead_, 1); + MemoryBarrier(); + p->logging::LogEventProvider::~LogEventProvider(); + } + + static const bool kRegisterAtExit = true; + + private: + static const size_t kBufferSize = (sizeof(logging::LogEventProvider) + + sizeof(intptr_t) - 1) / sizeof(intptr_t); + static intptr_t buffer_[kBufferSize]; + + // Signal the object was already deleted, so it is not revived. + static base::subtle::Atomic32 dead_; +}; + +intptr_t LogEventProviderTraits::buffer_[kBufferSize]; +base::subtle::Atomic32 LogEventProviderTraits::dead_ = 0; + +Singleton<logging::LogEventProvider, LogEventProviderTraits> log_provider; + +} // namespace + +namespace logging { + +DEFINE_GUID(kLogEventId, + 0x7fe69228, 0x633e, 0x4f06, 0x80, 0xc1, 0x52, 0x7f, 0xea, 0x23, 0xe3, 0xa7); + +LogEventProvider::LogEventProvider() : old_log_level_(LOG_NONE) { +} + +bool LogEventProvider::LogMessage(int severity, const std::string& message) { + EtwEventLevel level = TRACE_LEVEL_NONE; + + // Convert the log severity to the most appropriate ETW trace level. + switch (severity) { + case LOG_INFO: + level = TRACE_LEVEL_INFORMATION; + break; + case LOG_WARNING: + level = TRACE_LEVEL_WARNING; + break; + case LOG_ERROR: + case LOG_ERROR_REPORT: + level = TRACE_LEVEL_ERROR; + break; + case LOG_FATAL: + level = TRACE_LEVEL_FATAL; + break; + }; + + // Bail if we're not logging, not at that level, + // or if we're post-atexit handling. + LogEventProvider* provider = log_provider.get(); + if (provider == NULL || level > provider->enable_level()) + return false; + + // And now log the event, with stack trace if one is + // requested per our enable flags. + if (provider->enable_flags() & ENABLE_STACK_TRACE_CAPTURE) { + const size_t kMaxBacktraceDepth = 32; + void* backtrace[kMaxBacktraceDepth]; + DWORD depth = CaptureStackBackTrace(2, kMaxBacktraceDepth, backtrace, NULL); + EtwMofEvent<3> event(kLogEventId, LOG_MESSAGE_WITH_STACKTRACE, level); + + event.SetField(0, sizeof(depth), &depth); + event.SetField(1, sizeof(backtrace[0]) * depth, &backtrace); + event.SetField(2, message.length() + 1, message.c_str()); + + provider->Log(event.get()); + } else { + EtwMofEvent<1> event(kLogEventId, LOG_MESSAGE, level); + event.SetField(0, message.length() + 1, message.c_str()); + provider->Log(event.get()); + } + + // Don't increase verbosity in other log destinations. + if (severity >= provider->old_log_level_) + return true; + + return false; +} + +void LogEventProvider::Initialize(const GUID& provider_name) { + LogEventProvider* provider = log_provider.get(); + + provider->set_provider_name(provider_name); + provider->Register(); + + // Register our message handler with logging. + SetLogMessageHandler(LogMessage); +} + +void LogEventProvider::Uninitialize() { + log_provider.get()->Unregister(); +} + +void LogEventProvider::OnEventsEnabled() { + // Grab the old log level so we can restore it later. + old_log_level_ = GetMinLogLevel(); + + // Convert the new trace level to a logging severity + // and enable logging at that level. + EtwEventLevel level = enable_level(); + switch (level) { + case TRACE_LEVEL_NONE: + case TRACE_LEVEL_FATAL: + SetMinLogLevel(LOG_FATAL); + break; + case TRACE_LEVEL_ERROR: + SetMinLogLevel(LOG_ERROR); + break; + case TRACE_LEVEL_WARNING: + SetMinLogLevel(LOG_WARNING); + break; + case TRACE_LEVEL_INFORMATION: + case TRACE_LEVEL_VERBOSE: + SetMinLogLevel(LOG_INFO); + break; + } +} + +void LogEventProvider::OnEventsDisabled() { + // Restore the old log level. + SetMinLogLevel(old_log_level_); +} + +} // namespace logging diff --git a/base/logging_win.h b/base/logging_win.h new file mode 100644 index 0000000..42b02fe --- /dev/null +++ b/base/logging_win.h @@ -0,0 +1,60 @@ +// Copyright (c) 2009 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. + +#ifndef BASE_LOGGING_WIN_H_ +#define BASE_LOGGING_WIN_H_ + +#include <string> +#include "base/basictypes.h" +#include "base/event_trace_provider_win.h" +#include "base/logging.h" + +namespace logging { + +// Event ID for the log messages we generate. +extern const GUID kLogEventId; + +// Feature enable mask for LogEventProvider. +enum LogEnableMask { + // If this bit is set in our provider enable mask, we will include + // a stack trace with every log message. + ENABLE_STACK_TRACE_CAPTURE = 0x0001, +}; + +// The message types our log event provider generates. +// ETW likes user message types to start at 10. +enum LogMessageTypes { + // A textual only log message, contains a zero-terminated string. + LOG_MESSAGE = 10, + // A message with a stack trace, followed by the zero-terminated + // message text. + LOG_MESSAGE_WITH_STACKTRACE = 11, +}; + +// Trace provider class to drive log control and transport +// with Event Tracing for Windows. +class LogEventProvider : public EtwTraceProvider { + public: + LogEventProvider(); + + static bool LogMessage(int severity, const std::string& message); + static void Initialize(const GUID& provider_name); + static void Uninitialize(); + + protected: + // Overridden to manipulate the log level on ETW control callbacks. + virtual void OnEventsEnabled(); + virtual void OnEventsDisabled(); + + private: + // The log severity prior to OnEventsEnabled, + // restored in OnEventsDisabled. + logging::LogSeverity old_log_level_; + + DISALLOW_COPY_AND_ASSIGN(LogEventProvider); +}; + +} // namespace logging + +#endif // BASE_LOGGING_WIN_H_ diff --git a/chrome/common/env_vars.cc b/chrome/common/env_vars.cc index 120b846..c838ca4 100644 --- a/chrome/common/env_vars.cc +++ b/chrome/common/env_vars.cc @@ -14,6 +14,10 @@ const wchar_t kHeadless[] = L"CHROME_HEADLESS"; // The name of the log file. const wchar_t kLogFileName[] = L"CHROME_LOG_FILE"; +// If this environment variable is set, Chrome on Windows will log +// to Event Tracing for Windows. +const wchar_t kEtwLogging[] = L"CHROME_ETW_LOGGING"; + // CHROME_CRASHED exists if a previous instance of chrome has crashed. This // triggers the 'restart chrome' dialog. CHROME_RESTART contains the strings // that are needed to show the dialog. diff --git a/chrome/common/env_vars.h b/chrome/common/env_vars.h index 080afd3..21dde5e 100644 --- a/chrome/common/env_vars.h +++ b/chrome/common/env_vars.h @@ -11,6 +11,7 @@ namespace env_vars { extern const wchar_t kHeadless[]; extern const wchar_t kLogFileName[]; +extern const wchar_t kEtwLogging[]; extern const wchar_t kShowRestart[]; extern const wchar_t kRestartInfo[]; extern const wchar_t kRtlLocale[]; diff --git a/chrome/common/logging_chrome.cc b/chrome/common/logging_chrome.cc index c8580be..c957782 100644 --- a/chrome/common/logging_chrome.cc +++ b/chrome/common/logging_chrome.cc @@ -45,6 +45,10 @@ #include "chrome/common/env_vars.h" #include "ipc/ipc_logging.h" #include "ipc/ipc_message.h" +#if defined(OS_WIN) +#include "base/logging_win.h" +#include <initguid.h> +#endif // When true, this means that error dialogs should not be shown. static bool dialogs_are_suppressed_ = false; @@ -53,6 +57,12 @@ static bool dialogs_are_suppressed_ = false; // InitChromeLogging() and the beginning of CleanupChromeLogging(). static bool chrome_logging_initialized_ = false; +#if defined(OS_WIN) +// {7FE69228-633E-4f06-80C1-527FEA23E3A7} +DEFINE_GUID(kChromeTraceProviderName, + 0x7fe69228, 0x633e, 0x4f06, 0x80, 0xc1, 0x52, 0x7f, 0xea, 0x23, 0xe3, 0xa7); +#endif + // Assertion handler for logging errors that occur when dialogs are // silenced. To record a new error, pass the log string associated // with that error in the str parameter. @@ -157,6 +167,12 @@ void InitChromeLogging(const CommandLine& command_line, logging::SetMinLogLevel(LOG_WARNING); } +#if defined(OS_WIN) + // Enable trace control and transport through event tracing for Windows. + if (base::SysInfo::HasEnvVar(env_vars::kEtwLogging)) + logging::LogEventProvider::Initialize(kChromeTraceProviderName); +#endif + chrome_logging_initialized_ = true; } |