// Copyright 2017 The Chromium Authors
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
#include "components/metrics/system_session_analyzer/system_session_analyzer_win.h"
#include "base/logging.h"
#include "base/time/time.h"
namespace metrics {
namespace {
// The name of the log channel to query.
const wchar_t kChannelName[] = L"System";
// Event ids of system startup / shutdown events. These were obtained from
// inspection of the System log in Event Viewer on Windows 10:
// - id 6005: "The Event log service was started."
// - id 6006: "The Event log service was stopped."
// - id 6008: "The previous system shutdown at <time> on <date> was
// unexpected."
const uint16_t kIdSessionStart = 6005U;
const uint16_t kIdSessionEnd = 6006U;
const uint16_t kIdSessionEndUnclean = 6008U;
// An XPATH expression to query for system startup / shutdown events. The query
// is expected to retrieve exactly one event for each startup (kIdSessionStart)
// and one event for each shutdown (either kIdSessionEnd or
// kIdSessionEndUnclean).
const wchar_t kSessionEventsQuery[] =
L"*[System[Provider[@Name='eventlog']"
L" and (EventID=6005 or EventID=6006 or EventID=6008)]]";
// XPath expressions to attributes of interest.
const wchar_t kEventIdPath[] = L"Event/System/EventID";
const wchar_t kEventTimePath[] = L"Event/System/TimeCreated/@SystemTime";
// The timeout to use for calls to ::EvtNext.
const uint32_t kTimeoutMs = 5000;
base::Time ULLFileTimeToTime(ULONGLONG time_ulonglong) {
// Copy low / high parts as FILETIME is not always 64bit aligned.
ULARGE_INTEGER time;
time.QuadPart = time_ulonglong;
FILETIME ft;
ft.dwLowDateTime = time.LowPart;
ft.dwHighDateTime = time.HighPart;
return base::Time::FromFileTime(ft);
}
} // 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);
// Retrieve attributes of interest from the event. We expect the context to
// specify the retrieval of two attributes (event id and event time), each
// with a specific type.
const DWORD kAttributeCnt = 2U;
std::vector<EVT_VARIANT> buffer(kAttributeCnt);
DWORD buffer_size = kAttributeCnt * sizeof(EVT_VARIANT);
DWORD buffer_used = 0U;
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) {
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;
}
info->event_id = buffer[0].UInt16Val;
info->event_time = ULLFileTimeToTime(buffer[1].FileTimeVal);
return true;
}
SystemSessionAnalyzer::Status SystemSessionAnalyzer::IsSessionUnclean(
base::Time timestamp) {
if (!EnsureInitialized()) {
// Insufficient events in the error log is a special-case with its own error
// code so that a truncated system log doesn't cause failures.
if (GetExtendedFailureStatus() == ExtendedStatus::EVENT_COUNT_MISMATCH)
return INSUFFICIENT_DATA;
// Similarly, zero events in the error log is a special-case with its own
// error code so that a severely truncated system log doesn't cause
// failures.
if (GetExtendedFailureStatus() == ExtendedStatus::RETRIEVE_EVENTS_FAILURE)
return INSUFFICIENT_DATA;
return INITIALIZE_FAILED;
}
while (timestamp < coverage_start_ && sessions_queried_ < max_session_cnt_) {
// Fetch the next session start and end events.
std::vector<EventInfo> events;
if (!FetchEvents(2U, &events) || events.size() != 2)
return FETCH_EVENTS_FAILED;
if (!ProcessSession(events[0], events[1]))
return PROCESS_SESSION_FAILED;
++sessions_queried_;
}
if (timestamp < coverage_start_)
return OUTSIDE_RANGE;
// Get the first session starting after the timestamp.
std::map<base::Time, base::TimeDelta>::const_iterator it =
unclean_sessions_.upper_bound(timestamp);
if (it == unclean_sessions_.begin())
return CLEAN; // No prior unclean session.
// Get the previous session and see if it encompasses the timestamp.
--it;
bool is_spanned = (timestamp - it->first) <= it->second;
return is_spanned ? UNCLEAN : CLEAN;
}
bool SystemSessionAnalyzer::FetchEvents(size_t requested_events,
std::vector<EventInfo>* event_infos) {
DCHECK(event_infos);
if (!EnsureHandlesOpened())
return false;
DCHECK(query_handle_.get());
// Retrieve events: 2 events per session, plus the current session's start.
DWORD desired_event_cnt = requested_events;
std::vector<EVT_HANDLE> events_raw(desired_event_cnt, nullptr);
DWORD event_cnt = 0U;
BOOL success = ::EvtNext(query_handle_.get(), desired_event_cnt,
events_raw.data(), kTimeoutMs, 0, &event_cnt);
// Ensure handles get closed. The MSDN sample seems to imply handles may need
// to be closed event in if EvtNext failed.
std::vector<EvtHandle> events(desired_event_cnt);
for (size_t i = 0; i < event_cnt; ++i)
events[i].reset(events_raw[i]);
if (!success) {
SetExtendedFailureStatus(ExtendedStatus::RETRIEVE_EVENTS_FAILURE);
DLOG(ERROR) << "Failed to retrieve events.";
return false;
}
std::vector<EventInfo> event_infos_tmp;
event_infos_tmp.reserve(event_cnt);
EventInfo info = {};
for (size_t i = 0; i < event_cnt; ++i) {
if (!GetEventInfo(render_context_.get(), events[i].get(), &info))
return false;
event_infos_tmp.push_back(info);
}
event_infos->swap(event_infos_tmp);
return true;
}
bool SystemSessionAnalyzer::EnsureInitialized() {
if (!initialized_) {
DCHECK(!init_success_);
init_success_ = Initialize();
initialized_ = true;
}
return init_success_;
}
bool SystemSessionAnalyzer::EnsureHandlesOpened() {
// Create the event query.
// Note: requesting events from newest to oldest.
if (!query_handle_.get()) {
query_handle_.reset(
::EvtQuery(nullptr, kChannelName, kSessionEventsQuery,
EvtQueryChannelPath | EvtQueryReverseDirection));
if (!query_handle_.get()) {
SetExtendedFailureStatus(ExtendedStatus::EVTQUERY_FAILED);
DLOG(ERROR) << "Event query failed.";
return false;
}
}
if (!render_context_.get()) {
// Create the render context for extracting information from the events.
render_context_ = CreateRenderContext();
if (!render_context_.get()) {
SetExtendedFailureStatus(ExtendedStatus::CREATE_RENDER_CONTEXT_FAILURE);
return false;
}
}
return true;
}
bool SystemSessionAnalyzer::Initialize() {
DCHECK(!initialized_);
// 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)) {
SetExtendedFailureStatus(ExtendedStatus::FETCH_EVENTS_FAILURE);
return false;
}
// Validate that the initial event is what we expect.
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;
if (!ProcessSession(events[1], events[2]))
return false;
sessions_queried_ = 1;
return true;
}
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) {
SetExtendedFailureStatus(ExtendedStatus::COVERAGE_START_ORDER_FAILURE);
return false;
}
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) {
SetExtendedFailureStatus(ExtendedStatus::UNEXPECTED_START_EVENT_TYPE);
return false; // Unexpected event type.
}
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(
std::make_pair(start.event_time, end.event_time - start.event_time));
}
coverage_start_ = start.event_time;
return true;
}
SystemSessionAnalyzer::EvtHandle SystemSessionAnalyzer::CreateRenderContext() {
LPCWSTR value_paths[] = {kEventIdPath, kEventTimePath};
const DWORD kValueCnt = std::size(value_paths);
EVT_HANDLE context = nullptr;
context =
::EvtCreateRenderContext(kValueCnt, value_paths, EvtRenderContextValues);
if (!context)
DLOG(ERROR) << "Failed to create render context.";
return EvtHandle(context);
}
} // namespace metrics
Codebase Browser
chromium