Fix event tracing for windows test flakyness.

Assert on non-null properties to the static members of the trace controller.
Fix usage of same.
Add a PostEventsDisabled method to trace producer to which allows for a non-racy enable/disable test.
Fix a race in the trace event unittest by normalizing the state of the singleton ETW provider to dead, dead, and stone cold dead with an at exit manager.

BUG=52388
BUG=59328
TEST=Unittests in the change.

Review URL: http://codereview.chromium.org/3777007

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@62834 0039d316-1c4b-4281-b951-d872f2087c98

7 files changed, 91 insertions, 47 deletions

diff --git a/base/event_trace_consumer_win_unittest.cc b/base/event_trace_consumer_win_unittest.cc
index 6c0a740..c964412 100644
--- a/base/event_trace_consumer_win_unittest.cc
+++ b/base/event_trace_consumer_win_unittest.cc
@@ -72,7 +72,8 @@ const wchar_t* const kTestSessionName = L"TestLogSession";
 class EtwTraceConsumerBaseTest: public testing::Test {
  public:
   virtual void SetUp() {
-    EtwTraceController::Stop(kTestSessionName, NULL);
+    EtwTraceProperties ignore;
+    EtwTraceController::Stop(kTestSessionName, &ignore);
   }
 };
 
@@ -245,14 +246,16 @@ class EtwTraceConsumerDataTest: public testing::Test {
   }
 
   virtual void SetUp() {
-    EtwTraceController::Stop(kTestSessionName, NULL);
+    EtwTraceProperties prop;
+    EtwTraceController::Stop(kTestSessionName, &prop);
     // 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);
+    EtwTraceProperties ignore;
+    EtwTraceController::Stop(kTestSessionName, &ignore);
   }
 
   HRESULT LogEventToTempSession(PEVENT_TRACE_HEADER header) {
diff --git a/base/event_trace_controller_win.cc b/base/event_trace_controller_win.cc
index cb15150..0e11d8a 100644
--- a/base/event_trace_controller_win.cc
+++ b/base/event_trace_controller_win.cc
@@ -6,6 +6,39 @@
 #include "base/event_trace_controller_win.h"
 #include "base/logging.h"
 
+EtwTraceProperties::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;
+}
+
+HRESULT EtwTraceProperties::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;
+}
+
+HRESULT EtwTraceProperties::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;
+}
+
 EtwTraceController::EtwTraceController() : session_(NULL) {
 }
 
@@ -97,6 +130,7 @@ HRESULT EtwTraceController::Flush(EtwTraceProperties* properties) {
 
 HRESULT EtwTraceController::Start(const wchar_t* session_name,
     EtwTraceProperties* properties, TRACEHANDLE* session_handle) {
+  DCHECK(properties != NULL);
   ULONG err = ::StartTrace(session_handle, session_name, properties->get());
   return HRESULT_FROM_WIN32(err);
 }
@@ -110,6 +144,7 @@ HRESULT EtwTraceController::Query(const wchar_t* session_name,
 
 HRESULT EtwTraceController::Update(const wchar_t* session_name,
     EtwTraceProperties* properties) {
+  DCHECK(properties != NULL);
   ULONG err = ::ControlTrace(NULL, session_name, properties->get(),
                              EVENT_TRACE_CONTROL_UPDATE);
   return HRESULT_FROM_WIN32(err);
@@ -117,6 +152,7 @@ HRESULT EtwTraceController::Update(const wchar_t* session_name,
 
 HRESULT EtwTraceController::Stop(const wchar_t* session_name,
     EtwTraceProperties* properties) {
+  DCHECK(properties != NULL);
   ULONG err = ::ControlTrace(NULL, session_name, properties->get(),
                              EVENT_TRACE_CONTROL_STOP);
   return HRESULT_FROM_WIN32(err);
@@ -124,6 +160,7 @@ HRESULT EtwTraceController::Stop(const wchar_t* session_name,
 
 HRESULT EtwTraceController::Flush(const wchar_t* session_name,
     EtwTraceProperties* properties) {
+  DCHECK(properties != NULL);
   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
index 5f66b97..bf44fa9 100644
--- a/base/event_trace_controller_win.h
+++ b/base/event_trace_controller_win.h
@@ -32,20 +32,12 @@
 // 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;
-  }
+  EtwTraceProperties();
 
   EVENT_TRACE_PROPERTIES* get() {
     return &properties_;
   }
+
   const EVENT_TRACE_PROPERTIES* get() const {
     return reinterpret_cast<const EVENT_TRACE_PROPERTIES*>(&properties_);
   }
@@ -54,31 +46,14 @@ class EtwTraceProperties {
     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;
-  }
-
+  // Copies logger_name to the properties structure.
+  HRESULT SetLoggerName(const wchar_t* logger_name);
   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;
-  }
+  // Copies logger_file_name to the properties structure.
+  HRESULT SetLoggerFileName(const wchar_t* logger_file_name);
 
   // Max string len for name and session name is 1024 per documentation.
   static const size_t kMaxStringLen = 1024;
diff --git a/base/event_trace_controller_win_unittest.cc b/base/event_trace_controller_win_unittest.cc
index 55222a6..5777e58 100644
--- a/base/event_trace_controller_win_unittest.cc
+++ b/base/event_trace_controller_win_unittest.cc
@@ -42,7 +42,7 @@ class TestingProvider: public EtwTraceProvider {
   virtual void OnEventsEnabled() {
     ::SetEvent(callback_event_.Get());
   }
-  virtual void OnEventsDisabled() {
+  virtual void PostEventsDisabled() {
     ::SetEvent(callback_event_.Get());
   }
 
@@ -55,7 +55,8 @@ class TestingProvider: public EtwTraceProvider {
 
 TEST(EtwTraceTest, Cleanup) {
   // Clean up potential leftover sessions from previous unsuccessful runs.
-  EtwTraceController::Stop(kTestSessionName, NULL);
+  EtwTraceProperties ignore;
+  EtwTraceController::Stop(kTestSessionName, &ignore);
 }
 
 TEST(EtwTracePropertiesTest, Initialization) {
@@ -152,8 +153,7 @@ TEST(EtwTraceControllerTest, StartFileSession) {
   EXPECT_STREQ(L"", controller.session_name());
 }
 
-// Flaky, http://crbug.com/59328.
-TEST(EtwTraceControllerTest, FLAKY_EnableDisable) {
+TEST(EtwTraceControllerTest, EnableDisable) {
   TestingProvider provider(kTestProvider);
 
   EXPECT_EQ(ERROR_SUCCESS, provider.Register());
diff --git a/base/event_trace_provider_win.cc b/base/event_trace_provider_win.cc
index c7f5001..826a4bf 100644
--- a/base/event_trace_provider_win.cc
+++ b/base/event_trace_provider_win.cc
@@ -48,6 +48,8 @@ ULONG EtwTraceProvider::DisableEvents() {
   enable_flags_ = 0;
   session_handle_ = NULL;
 
+  PostEventsDisabled();
+
   return ERROR_SUCCESS;
 }
 
diff --git a/base/event_trace_provider_win.h b/base/event_trace_provider_win.h
index b0526b1..5c89d1a 100644
--- a/base/event_trace_provider_win.h
+++ b/base/event_trace_provider_win.h
@@ -126,13 +126,25 @@ class EtwTraceProvider {
   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.
+  // Called after events have been enabled, override in subclasses
+  // to set up state or log at the start of a session.
+  // Note: This function may be called ETW's thread and may be racy,
+  //    bring your own locking if needed.
   virtual void OnEventsEnabled() {}
+
+  // Called just before events are disabled, override in subclasses
+  // to tear down state or log at the end of a session.
+  // Note: This function may be called ETW's thread and may be racy,
+  //    bring your own locking if needed.
   virtual void OnEventsDisabled() {}
 
+  // Called just after events have been disabled, override in subclasses
+  // to tear down state at the end of a session. At this point it's
+  // to late to log anything to the session.
+  // Note: This function may be called ETW's thread and may be racy,
+  //    bring your own locking if needed.
+  virtual void PostEventsDisabled() {}
+
  private:
   ULONG EnableEvents(PVOID buffer);
   ULONG DisableEvents();
diff --git a/base/trace_event_win_unittest.cc b/base/trace_event_win_unittest.cc
index a142af1..79a48e3 100644
--- a/base/trace_event_win_unittest.cc
+++ b/base/trace_event_win_unittest.cc
@@ -6,6 +6,7 @@
 
 #include <strstream>
 
+#include "base/at_exit.h"
 #include "base/basictypes.h"
 #include "base/file_util.h"
 #include "base/event_trace_consumer_win.h"
@@ -76,18 +77,29 @@ TestEventConsumer* TestEventConsumer::current_ = NULL;
 
 class TraceEventTest: public testing::Test {
  public:
+  TraceEventTest() {
+  }
+
   void SetUp() {
     bool is_xp = base::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.
+    base::TraceLog* tracelog = NULL;
     if (!is_xp) {
       base::TraceLog::Resurrect();
-      base::TraceLog* tracelog = base::TraceLog::Get();
+      tracelog = base::TraceLog::Get();
       ASSERT_TRUE(tracelog != NULL);
+      ASSERT_FALSE(tracelog->IsTracing());
     }
 
     // Create the log file.
@@ -121,9 +133,10 @@ class TraceEventTest: public testing::Test {
 
     if (is_xp) {
       base::TraceLog::Resurrect();
-      base::TraceLog* tracelog = base::TraceLog::Get();
-      ASSERT_TRUE(tracelog != NULL);
+      tracelog = base::TraceLog::Get();
     }
+    ASSERT_TRUE(tracelog != NULL);
+    EXPECT_TRUE(tracelog->IsTracing());
   }
 
   void TearDown() {
@@ -163,6 +176,7 @@ class TraceEventTest: public testing::Test {
 
   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()));
@@ -171,6 +185,8 @@ class TraceEventTest: public testing::Test {
   }
 
  private:
+  // We want our singleton torn down after each test.
+  base::ShadowingAtExitManager at_exit_manager_;
   EtwTraceController controller_;
   FilePath log_file_;
   TestEventConsumer consumer_;
@@ -254,8 +270,7 @@ TEST_F(TraceEventTest, TraceLog) {
   PlayLog();
 }
 
-// Marked flaky per http://crbug.com/52388
-TEST_F(TraceEventTest, FLAKY_Macros) {
+TEST_F(TraceEventTest, Macros) {
   ExpectPlayLog();
 
   // The events should arrive in the same sequence as the expects.