Adding extended error codes to SystemSessionAnalyzer

SystemSessionAnalyzerTest.ValidateEvents fails flakily (failing most of
the time) and it is impossible to tell which failure point is being hit.
This change adds recording of extended error codes so that the failure
will be visible so that we can make progress on this old bug.

Some multi-part logical-or statements were broken up to ensure that the
precise failure is found. GetEventInfo was moved to be a member function
so that it has access to the error-setting function.

Test command line is:
components_unittests --gtest_filter=SystemSessionAnalyzerTest.ValidateEvents

Bug: 968440
Change-Id: Ie7b76d6e6607725819244ef22b3a2b1f8ab34d38
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2136061Reviewed-by: Jesse McKenna <jessemckenna@google.com>
Reviewed-by: Ilya Sherman <isherman@chromium.org>
Commit-Queue: Bruce Dawson <brucedawson@chromium.org>
Cr-Commit-Position: refs/heads/master@{#756900}

components/metrics/system_session_analyzer_win.cc

@@ -50,9 +50,28 @@ base::Time ULLFileTimeToTime(ULONGLONG time_ulonglong) {
   return base::Time::FromFileTime(ft);
 }
 
-bool GetEventInfo(EVT_HANDLE context,
-                  EVT_HANDLE event,
-                  SystemSessionAnalyzer::EventInfo* info) {
+}  // namespace
+
+SystemSessionAnalyzer::SystemSessionAnalyzer(uint32_t max_session_cnt)
+    : max_session_cnt_(max_session_cnt), sessions_queried_(0) {}
+
+SystemSessionAnalyzer::~SystemSessionAnalyzer() {}
+
+SystemSessionAnalyzer::ExtendedStatus
+SystemSessionAnalyzer::GetExtendedFailureStatus() const {
+  return extended_status_;
+}
+
+void SystemSessionAnalyzer::SetExtendedFailureStatus(
+    ExtendedStatus new_status) {
+  if (extended_status_ == ExtendedStatus::NO_FAILURE)
+    extended_status_ = new_status;
+}
+
+bool SystemSessionAnalyzer::GetEventInfo(
+    EVT_HANDLE context,
+    EVT_HANDLE event,
+    SystemSessionAnalyzer::EventInfo* info) {
   DCHECK(context);
   DCHECK(event);
   DCHECK(info);
@@ -67,14 +86,22 @@ bool GetEventInfo(EVT_HANDLE context,
   DWORD retrieved_attribute_cnt = 0U;
   if (!::EvtRender(context, event, EvtRenderEventValues, buffer_size,
                    buffer.data(), &buffer_used, &retrieved_attribute_cnt)) {
+    SetExtendedFailureStatus(ExtendedStatus::RENDER_EVENT_FAILURE);
     DLOG(ERROR) << "Failed to render the event.";
     return false;
   }
 
   // Validate the count and types of the retrieved attributes.
-  if ((retrieved_attribute_cnt != kAttributeCnt) ||
-      (buffer[0].Type != EvtVarTypeUInt16) ||
-      (buffer[1].Type != EvtVarTypeFileTime)) {
+  if (retrieved_attribute_cnt != kAttributeCnt) {
+    SetExtendedFailureStatus(ExtendedStatus::ATTRIBUTE_CNT_MISMATCH);
+    return false;
+  }
+  if (buffer[0].Type != EvtVarTypeUInt16) {
+    SetExtendedFailureStatus(ExtendedStatus::EXPECTED_INT16_TYPE);
+    return false;
+  }
+  if (buffer[1].Type != EvtVarTypeFileTime) {
+    SetExtendedFailureStatus(ExtendedStatus::EXPECTED_FILETIME_TYPE);
     return false;
   }
 
@@ -84,13 +111,6 @@ bool GetEventInfo(EVT_HANDLE context,
   return true;
 }
 
-}  // namespace
-
-SystemSessionAnalyzer::SystemSessionAnalyzer(uint32_t max_session_cnt)
-    : max_session_cnt_(max_session_cnt), sessions_queried_(0) {}
-
-SystemSessionAnalyzer::~SystemSessionAnalyzer() {}
-
 SystemSessionAnalyzer::Status SystemSessionAnalyzer::IsSessionUnclean(
     base::Time timestamp) {
   if (!EnsureInitialized())
@@ -146,6 +166,7 @@ bool SystemSessionAnalyzer::FetchEvents(size_t requested_events,
     events[i].reset(events_raw[i]);
 
   if (!success) {
+    SetExtendedFailureStatus(ExtendedStatus::RETRIEVE_EVENTS_FAILURE);
     DLOG(ERROR) << "Failed to retrieve events.";
     return false;
   }
@@ -182,6 +203,7 @@ bool SystemSessionAnalyzer::EnsureHandlesOpened() {
         ::EvtQuery(nullptr, kChannelName, kSessionEventsQuery,
                    EvtQueryChannelPath | EvtQueryReverseDirection));
     if (!query_handle_.get()) {
+      SetExtendedFailureStatus(ExtendedStatus::EVTQUERY_FAILED);
       DLOG(ERROR) << "Event query failed.";
       return false;
     }
@@ -190,8 +212,10 @@ bool SystemSessionAnalyzer::EnsureHandlesOpened() {
   if (!render_context_.get()) {
     // Create the render context for extracting information from the events.
     render_context_ = CreateRenderContext();
-    if (!render_context_.get())
+    if (!render_context_.get()) {
+      SetExtendedFailureStatus(ExtendedStatus::CREATE_RENDER_CONTEXT_FAILURE);
       return false;
+    }
   }
 
   return true;
@@ -203,12 +227,20 @@ bool SystemSessionAnalyzer::Initialize() {
   // Fetch the first (current) session start event and the first session,
   // comprising an end and a start event for a total of 3 events.
   std::vector<EventInfo> events;
-  if (!FetchEvents(3U, &events))
+  if (!FetchEvents(3U, &events)) {
+    SetExtendedFailureStatus(ExtendedStatus::FETCH_EVENTS_FAILURE);
     return false;
+  }
 
   // Validate that the initial event is what we expect.
-  if (events.size() != 3 || events[0].event_id != kIdSessionStart)
+  if (events.size() != 3) {
+    SetExtendedFailureStatus(ExtendedStatus::EVENT_COUNT_MISMATCH);
     return false;
+  }
+  if (events[0].event_id != kIdSessionStart) {
+    SetExtendedFailureStatus(ExtendedStatus::SESSION_START_MISMATCH);
+    return false;
+  }
 
   // Initialize the coverage start to allow detecting event time inversion.
   coverage_start_ = events[0].event_time;
@@ -225,17 +257,25 @@ bool SystemSessionAnalyzer::ProcessSession(const EventInfo& end,
                                            const EventInfo& start) {
   // Validate the ordering of events (newest to oldest). The  expectation is a
   // (start / [unclean]shutdown) pair of events for each session.
-  if (coverage_start_ < end.event_time)
+  if (coverage_start_ < end.event_time) {
+    SetExtendedFailureStatus(ExtendedStatus::COVERAGE_START_ORDER_FAILURE);
     return false;
-  if (end.event_time < start.event_time)
+  }
+  if (end.event_time < start.event_time) {
+    SetExtendedFailureStatus(ExtendedStatus::EVENT_ORDER_FAILURE);
     return false;
+  }
 
   // Process a (start / shutdown) event pair, validating the types of events
   // and recording unclean sessions.
-  if (start.event_id != kIdSessionStart)
+  if (start.event_id != kIdSessionStart) {
+    SetExtendedFailureStatus(ExtendedStatus::UNEXPECTED_START_EVENT_TYPE);
     return false;  // Unexpected event type.
-  if (end.event_id != kIdSessionEnd && end.event_id != kIdSessionEndUnclean)
+  }
+  if (end.event_id != kIdSessionEnd && end.event_id != kIdSessionEndUnclean) {
+    SetExtendedFailureStatus(ExtendedStatus::UNEXPECTED_END_EVENT_TYPE);
     return false;  // Unexpected event type.
+  }
 
   if (end.event_id == kIdSessionEndUnclean) {
     unclean_sessions_.insert(

components/metrics/system_session_analyzer_win.h

@@ -32,6 +32,31 @@ class SystemSessionAnalyzer {
     PROCESS_SESSION_FAILED = 5,
   };
 
+  // Track internal details of what went wrong.
+  enum class ExtendedStatus {
+    NO_FAILURE = 0,
+    RENDER_EVENT_FAILURE = 1,
+    ATTRIBUTE_CNT_MISMATCH = 2,
+    EXPECTED_INT16_TYPE = 3,
+    EXPECTED_FILETIME_TYPE = 4,
+    RETRIEVE_EVENTS_FAILURE = 5,
+    GET_EVENT_INFO_FAILURE = 6,
+    EVTQUERY_FAILED = 7,
+    CREATE_RENDER_CONTEXT_FAILURE = 8,
+    FETCH_EVENTS_FAILURE = 9,
+    EVENT_COUNT_MISMATCH = 10,
+    SESSION_START_MISMATCH = 11,
+    COVERAGE_START_ORDER_FAILURE = 12,
+    EVENT_ORDER_FAILURE = 13,
+    UNEXPECTED_START_EVENT_TYPE = 14,
+    UNEXPECTED_END_EVENT_TYPE = 15,
+  };
+
+  ExtendedStatus GetExtendedFailureStatus() const;
+  // Set an extended failure status code for easier diagnosing of test failures.
+  // The first extended status code is retained.
+  void SetExtendedFailureStatus(ExtendedStatus);
+
   // Minimal information about a log event.
   struct EventInfo {
     uint16_t event_id;
@@ -76,6 +101,9 @@ class SystemSessionAnalyzer {
   // as appropriate.
   bool ProcessSession(const EventInfo& end, const EventInfo& start);
 
+  bool GetEventInfo(EVT_HANDLE context,
+                    EVT_HANDLE event,
+                    SystemSessionAnalyzer::EventInfo* info);
   EvtHandle CreateRenderContext();
 
   // The maximal number of sessions to query events for.
@@ -96,6 +124,9 @@ class SystemSessionAnalyzer {
   // Timestamp of the oldest event.
   base::Time coverage_start_;
 
+  // Track details of what failures occurred.
+  ExtendedStatus extended_status_ = ExtendedStatus::NO_FAILURE;
+
   DISALLOW_COPY_AND_ASSIGN(SystemSessionAnalyzer);
 };
 

components/metrics/system_session_analyzer_win_unittest.cc

@@ -36,7 +36,9 @@ TEST(SystemSessionAnalyzerTest, FetchEvents) {
 TEST(SystemSessionAnalyzerTest, ValidateEvents) {
   SystemSessionAnalyzer analyzer(1U);
   EXPECT_EQ(SystemSessionAnalyzer::CLEAN,
-            analyzer.IsSessionUnclean(base::Time::Now()));
+            analyzer.IsSessionUnclean(base::Time::Now()))
+      << "Extended error code is: "
+      << static_cast<int>(analyzer.GetExtendedFailureStatus());
 }
 
 // Stubs FetchEvents.