1 // Copyright 2017 The Chromium Authors
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
4
5 #include "components/metrics/system_session_analyzer/system_session_analyzer_win.h"
6
7 #include "base/logging.h"
8 #include "base/time/time.h"
9
10 namespace metrics {
11
12 namespace {
13
14 // The name of the log channel to query.
15 const wchar_t kChannelName[] = L"System";
16
17 // Event ids of system startup / shutdown events. These were obtained from
18 // inspection of the System log in Event Viewer on Windows 10:
19 // - id 6005: "The Event log service was started."
20 // - id 6006: "The Event log service was stopped."
21 // - id 6008: "The previous system shutdown at <time> on <date> was
22 // unexpected."
23 const uint16_t kIdSessionStart = 6005U;
24 const uint16_t kIdSessionEnd = 6006U;
25 const uint16_t kIdSessionEndUnclean = 6008U;
26
27 // An XPATH expression to query for system startup / shutdown events. The query
28 // is expected to retrieve exactly one event for each startup (kIdSessionStart)
29 // and one event for each shutdown (either kIdSessionEnd or
30 // kIdSessionEndUnclean).
31 const wchar_t kSessionEventsQuery[] =
32 L"*[System[Provider[@Name='eventlog']"
33 L" and (EventID=6005 or EventID=6006 or EventID=6008)]]";
34
35 // XPath expressions to attributes of interest.
36 const wchar_t kEventIdPath[] = L"Event/System/EventID";
37 const wchar_t kEventTimePath[] = L"Event/System/TimeCreated/@SystemTime";
38
39 // The timeout to use for calls to ::EvtNext.
40 const uint32_t kTimeoutMs = 5000;
41
ULLFileTimeToTime(ULONGLONG time_ulonglong)42 base::Time ULLFileTimeToTime(ULONGLONG time_ulonglong) {
43 // Copy low / high parts as FILETIME is not always 64bit aligned.
44 ULARGE_INTEGER time;
45 time.QuadPart = time_ulonglong;
46 FILETIME ft;
47 ft.dwLowDateTime = time.LowPart;
48 ft.dwHighDateTime = time.HighPart;
49
50 return base::Time::FromFileTime(ft);
51 }
52
53 } // namespace
54
SystemSessionAnalyzer(uint32_t max_session_cnt)55 SystemSessionAnalyzer::SystemSessionAnalyzer(uint32_t max_session_cnt)
56 : max_session_cnt_(max_session_cnt), sessions_queried_(0) {}
57
~SystemSessionAnalyzer()58 SystemSessionAnalyzer::~SystemSessionAnalyzer() {}
59
60 SystemSessionAnalyzer::ExtendedStatus
GetExtendedFailureStatus() const61 SystemSessionAnalyzer::GetExtendedFailureStatus() const {
62 return extended_status_;
63 }
64
SetExtendedFailureStatus(ExtendedStatus new_status)65 void SystemSessionAnalyzer::SetExtendedFailureStatus(
66 ExtendedStatus new_status) {
67 if (extended_status_ == ExtendedStatus::NO_FAILURE)
68 extended_status_ = new_status;
69 }
70
GetEventInfo(EVT_HANDLE context,EVT_HANDLE event,SystemSessionAnalyzer::EventInfo * info)71 bool SystemSessionAnalyzer::GetEventInfo(
72 EVT_HANDLE context,
73 EVT_HANDLE event,
74 SystemSessionAnalyzer::EventInfo* info) {
75 DCHECK(context);
76 DCHECK(event);
77 DCHECK(info);
78
79 // Retrieve attributes of interest from the event. We expect the context to
80 // specify the retrieval of two attributes (event id and event time), each
81 // with a specific type.
82 const DWORD kAttributeCnt = 2U;
83 std::vector<EVT_VARIANT> buffer(kAttributeCnt);
84 DWORD buffer_size = kAttributeCnt * sizeof(EVT_VARIANT);
85 DWORD buffer_used = 0U;
86 DWORD retrieved_attribute_cnt = 0U;
87 if (!::EvtRender(context, event, EvtRenderEventValues, buffer_size,
88 buffer.data(), &buffer_used, &retrieved_attribute_cnt)) {
89 SetExtendedFailureStatus(ExtendedStatus::RENDER_EVENT_FAILURE);
90 DLOG(ERROR) << "Failed to render the event.";
91 return false;
92 }
93
94 // Validate the count and types of the retrieved attributes.
95 if (retrieved_attribute_cnt != kAttributeCnt) {
96 SetExtendedFailureStatus(ExtendedStatus::ATTRIBUTE_CNT_MISMATCH);
97 return false;
98 }
99 if (buffer[0].Type != EvtVarTypeUInt16) {
100 SetExtendedFailureStatus(ExtendedStatus::EXPECTED_INT16_TYPE);
101 return false;
102 }
103 if (buffer[1].Type != EvtVarTypeFileTime) {
104 SetExtendedFailureStatus(ExtendedStatus::EXPECTED_FILETIME_TYPE);
105 return false;
106 }
107
108 info->event_id = buffer[0].UInt16Val;
109 info->event_time = ULLFileTimeToTime(buffer[1].FileTimeVal);
110
111 return true;
112 }
113
IsSessionUnclean(base::Time timestamp)114 SystemSessionAnalyzer::Status SystemSessionAnalyzer::IsSessionUnclean(
115 base::Time timestamp) {
116 if (!EnsureInitialized()) {
117 // Insufficient events in the error log is a special-case with its own error
118 // code so that a truncated system log doesn't cause failures.
119 if (GetExtendedFailureStatus() == ExtendedStatus::EVENT_COUNT_MISMATCH)
120 return INSUFFICIENT_DATA;
121 // Similarly, zero events in the error log is a special-case with its own
122 // error code so that a severely truncated system log doesn't cause
123 // failures.
124 if (GetExtendedFailureStatus() == ExtendedStatus::RETRIEVE_EVENTS_FAILURE)
125 return INSUFFICIENT_DATA;
126 return INITIALIZE_FAILED;
127 }
128
129 while (timestamp < coverage_start_ && sessions_queried_ < max_session_cnt_) {
130 // Fetch the next session start and end events.
131 std::vector<EventInfo> events;
132 if (!FetchEvents(2U, &events) || events.size() != 2)
133 return FETCH_EVENTS_FAILED;
134
135 if (!ProcessSession(events[0], events[1]))
136 return PROCESS_SESSION_FAILED;
137
138 ++sessions_queried_;
139 }
140
141 if (timestamp < coverage_start_)
142 return OUTSIDE_RANGE;
143
144 // Get the first session starting after the timestamp.
145 std::map<base::Time, base::TimeDelta>::const_iterator it =
146 unclean_sessions_.upper_bound(timestamp);
147 if (it == unclean_sessions_.begin())
148 return CLEAN; // No prior unclean session.
149
150 // Get the previous session and see if it encompasses the timestamp.
151 --it;
152 bool is_spanned = (timestamp - it->first) <= it->second;
153 return is_spanned ? UNCLEAN : CLEAN;
154 }
155
FetchEvents(size_t requested_events,std::vector<EventInfo> * event_infos)156 bool SystemSessionAnalyzer::FetchEvents(size_t requested_events,
157 std::vector<EventInfo>* event_infos) {
158 DCHECK(event_infos);
159
160 if (!EnsureHandlesOpened())
161 return false;
162
163 DCHECK(query_handle_.get());
164
165 // Retrieve events: 2 events per session, plus the current session's start.
166 DWORD desired_event_cnt = requested_events;
167 std::vector<EVT_HANDLE> events_raw(desired_event_cnt, nullptr);
168 DWORD event_cnt = 0U;
169 BOOL success = ::EvtNext(query_handle_.get(), desired_event_cnt,
170 events_raw.data(), kTimeoutMs, 0, &event_cnt);
171
172 // Ensure handles get closed. The MSDN sample seems to imply handles may need
173 // to be closed event in if EvtNext failed.
174 std::vector<EvtHandle> events(desired_event_cnt);
175 for (size_t i = 0; i < event_cnt; ++i)
176 events[i].reset(events_raw[i]);
177
178 if (!success) {
179 SetExtendedFailureStatus(ExtendedStatus::RETRIEVE_EVENTS_FAILURE);
180 DLOG(ERROR) << "Failed to retrieve events.";
181 return false;
182 }
183
184 std::vector<EventInfo> event_infos_tmp;
185 event_infos_tmp.reserve(event_cnt);
186
187 EventInfo info = {};
188 for (size_t i = 0; i < event_cnt; ++i) {
189 if (!GetEventInfo(render_context_.get(), events[i].get(), &info))
190 return false;
191 event_infos_tmp.push_back(info);
192 }
193
194 event_infos->swap(event_infos_tmp);
195 return true;
196 }
197
EnsureInitialized()198 bool SystemSessionAnalyzer::EnsureInitialized() {
199 if (!initialized_) {
200 DCHECK(!init_success_);
201 init_success_ = Initialize();
202 initialized_ = true;
203 }
204
205 return init_success_;
206 }
207
EnsureHandlesOpened()208 bool SystemSessionAnalyzer::EnsureHandlesOpened() {
209 // Create the event query.
210 // Note: requesting events from newest to oldest.
211 if (!query_handle_.get()) {
212 query_handle_.reset(
213 ::EvtQuery(nullptr, kChannelName, kSessionEventsQuery,
214 EvtQueryChannelPath | EvtQueryReverseDirection));
215 if (!query_handle_.get()) {
216 SetExtendedFailureStatus(ExtendedStatus::EVTQUERY_FAILED);
217 DLOG(ERROR) << "Event query failed.";
218 return false;
219 }
220 }
221
222 if (!render_context_.get()) {
223 // Create the render context for extracting information from the events.
224 render_context_ = CreateRenderContext();
225 if (!render_context_.get()) {
226 SetExtendedFailureStatus(ExtendedStatus::CREATE_RENDER_CONTEXT_FAILURE);
227 return false;
228 }
229 }
230
231 return true;
232 }
233
Initialize()234 bool SystemSessionAnalyzer::Initialize() {
235 DCHECK(!initialized_);
236
237 // Fetch the first (current) session start event and the first session,
238 // comprising an end and a start event for a total of 3 events.
239 std::vector<EventInfo> events;
240 if (!FetchEvents(3U, &events)) {
241 SetExtendedFailureStatus(ExtendedStatus::FETCH_EVENTS_FAILURE);
242 return false;
243 }
244
245 // Validate that the initial event is what we expect.
246 if (events.size() != 3) {
247 SetExtendedFailureStatus(ExtendedStatus::EVENT_COUNT_MISMATCH);
248 return false;
249 }
250 if (events[0].event_id != kIdSessionStart) {
251 SetExtendedFailureStatus(ExtendedStatus::SESSION_START_MISMATCH);
252 return false;
253 }
254
255 // Initialize the coverage start to allow detecting event time inversion.
256 coverage_start_ = events[0].event_time;
257
258 if (!ProcessSession(events[1], events[2]))
259 return false;
260
261 sessions_queried_ = 1;
262
263 return true;
264 }
265
ProcessSession(const EventInfo & end,const EventInfo & start)266 bool SystemSessionAnalyzer::ProcessSession(const EventInfo& end,
267 const EventInfo& start) {
268 // Validate the ordering of events (newest to oldest). The expectation is a
269 // (start / [unclean]shutdown) pair of events for each session.
270 if (coverage_start_ < end.event_time) {
271 SetExtendedFailureStatus(ExtendedStatus::COVERAGE_START_ORDER_FAILURE);
272 return false;
273 }
274 if (end.event_time < start.event_time) {
275 SetExtendedFailureStatus(ExtendedStatus::EVENT_ORDER_FAILURE);
276 return false;
277 }
278
279 // Process a (start / shutdown) event pair, validating the types of events
280 // and recording unclean sessions.
281 if (start.event_id != kIdSessionStart) {
282 SetExtendedFailureStatus(ExtendedStatus::UNEXPECTED_START_EVENT_TYPE);
283 return false; // Unexpected event type.
284 }
285 if (end.event_id != kIdSessionEnd && end.event_id != kIdSessionEndUnclean) {
286 SetExtendedFailureStatus(ExtendedStatus::UNEXPECTED_END_EVENT_TYPE);
287 return false; // Unexpected event type.
288 }
289
290 if (end.event_id == kIdSessionEndUnclean) {
291 unclean_sessions_.insert(
292 std::make_pair(start.event_time, end.event_time - start.event_time));
293 }
294
295 coverage_start_ = start.event_time;
296
297 return true;
298 }
299
CreateRenderContext()300 SystemSessionAnalyzer::EvtHandle SystemSessionAnalyzer::CreateRenderContext() {
301 LPCWSTR value_paths[] = {kEventIdPath, kEventTimePath};
302 const DWORD kValueCnt = std::size(value_paths);
303
304 EVT_HANDLE context = nullptr;
305 context =
306 ::EvtCreateRenderContext(kValueCnt, value_paths, EvtRenderContextValues);
307 if (!context)
308 DLOG(ERROR) << "Failed to create render context.";
309
310 return EvtHandle(context);
311 }
312
313 } // namespace metrics
314