1 // Copyright 2020 The Chromium Authors. All rights reserved.
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 "chrome/credential_provider/gaiacp/event_logs_upload_manager.h"
6
7 #include <windows.h>
8 #include <winevt.h>
9
10 #include "base/json/json_reader.h"
11 #include "base/json/json_writer.h"
12 #include "base/strings/string_number_conversions.h"
13 #include "base/strings/utf_string_conversions.h"
14 #include "chrome/credential_provider/gaiacp/event_logging_api_manager.h"
15 #include "chrome/credential_provider/gaiacp/gcp_utils.h"
16 #include "chrome/credential_provider/gaiacp/gcpw_strings.h"
17 #include "chrome/credential_provider/gaiacp/logging.h"
18 #include "chrome/credential_provider/gaiacp/reg_utils.h"
19 #include "chrome/credential_provider/gaiacp/win_http_url_fetcher.h"
20
21 namespace credential_provider {
22 namespace {
23
24 // HTTP endpoint on the GCPW service to upload the event viewer logs.
25 const char kGcpwServiceUploadEventLogsPath[] = "/v1/uploadEventViewerLogs";
26
27 // Default timeout when trying to make requests to the GCPW service.
28 const base::TimeDelta kDefaultUploadLogsRequestTimeout =
29 base::TimeDelta::FromMilliseconds(12000);
30
31 // Parameter names that are used in the JSON payload of the requests.
32 const char kRequestSerialNumberParameterName[] = "device_serial_number";
33 const char kRequestMachineGuidParameterName[] = "machine_guid";
34 const char kRequestChunkIdParameterName[] = "chunk_id";
35 const char kRequestLogEntriesParameterName[] = "log_entries";
36 const char kEventLogEventIdParameterName[] = "event_id";
37 const char kEventLogTimeStampParameterName[] = "created_ts";
38 const char kEventLogDataParameterName[] = "data";
39 const char kEventLogSeverityLevelParameterName[] = "severity_level";
40 const char kEventLogTimeStampSecondsParameterName[] = "seconds";
41 const char kEventLogTimeStampNanosParameterName[] = "nanos";
42
43 // Registry key where the the last uploaded event log record id is stored.
44 const wchar_t kEventLogUploadLastUploadedIdRegKey[] = L"last_upload_log_id";
45
46 // Registry key where the highest severity of logs to upload is stored.
47 const wchar_t kEventLogUploadLevelRegKey[] = L"log_upload_level";
48
49 // Default log upload severity level (4=Information).
50 constexpr DWORD kDefaultUploadLogLevel = 4;
51
52 // Number of events to read from event log API at one time.
53 constexpr int kDefaultNumberOfEventsToRead = 10;
54
55 // Maximum number of upload requests to make per upload invocation.
56 constexpr int kMaxAllowedNumberOfUploadRequests = 5;
57
58 // Maximum number of retries if a HTTP call to the backend fails.
59 constexpr unsigned int kMaxNumHttpRetries = 3;
60
61 // Maximum size of the log entries payload in bytes per HTTP request.
62 // TODO (crbug.com/1043195): Change this to use an experiment flag once an
63 // experiment framework for GCPW is available.
64 constexpr size_t kMaxPayloadSizeOfLogEntries = 512 * 1024; // 512 KB.
65
66 // Name that GCPW uses to publish events into the Windows event log.
67 constexpr wchar_t kEventLogPublisherName[] = L"GCPW";
68
69 // XPath query template used to query for GCPW events in the event log created
70 // within the last 30 days (2592000000 milliseconds) with the event logging
71 // API.
72 constexpr wchar_t kEventLogQueryTemplateStr[] =
73 L"<QueryList>"
74 L" <Query Id='0' Path='Application'>"
75 L" <Select Path='Application'>* [System[Provider[@Name='GCPW'] and "
76 L"(EventRecordID >={event_id}) and TimeCreated[timediff(@SystemTime) "
77 L"<= 2592000000]]]</Select>"
78 L" </Query>"
79 L"</QueryList>";
80
81 // List of paths whose values are read from the event log.
82 constexpr const wchar_t* kEventLogValuePaths[] = {
83 L"Event/System/EventRecordID", L"Event/System/TimeCreated/@SystemTime"};
84
85 // Mapping from the string values of log levels to their integral values.
86 const std::unordered_map<base::string16, uint32_t>
87 kEventLogLevelStrToIntValueMap = {{L"Critical", 1},
88 {L"Error", 2},
89 {L"Warning", 3},
90 {L"Information", 4}};
91
92 // Helper class to read event log entries sequentially through the Windows
93 // event logging API.
94 class EventLogReader {
95 public:
EventLogReader()96 EventLogReader()
97 : results_handle_(nullptr),
98 publisher_metadata_(nullptr),
99 render_context_(nullptr),
100 event_handles_(kDefaultNumberOfEventsToRead, nullptr),
101 cur_result_idx_(0),
102 num_results_returned_(0) {}
103
104 // Initialize the reader to read event logs with event record ID's
105 // greater than or equal to the specified value in |first_event_id|.
106 // Returns true if initialization succeeds.
107 bool Initialize(uint64_t first_event_id);
108
109 // Reads the next event log entry and stores it in |log_entry|. The log
110 // entries are returned in an increasing order of their event record ids.
111 // Returns true if |log_entry| was read successfully.
112 bool GetNextEventLogEntry(EventLogsUploadManager::EventLogEntry* log_entry);
113
114 // Close the reader and free internal resources.
115 void Close();
116
~EventLogReader()117 ~EventLogReader() { Close(); }
118
119 private:
120 bool HasValidQueryResults();
121 bool GetQueryInfo(EVT_QUERY_PROPERTY_ID property_id,
122 std::vector<EVT_VARIANT>* value_buffer);
123 bool ReadEventLogEntryFromEvent(
124 EVT_HANDLE event_handle,
125 EventLogsUploadManager::EventLogEntry* log_entry);
126 bool GetFormattedMessage(EVT_HANDLE event_handle,
127 EVT_FORMAT_MESSAGE_FLAGS message_flag,
128 base::string16* message);
129
130 EVT_HANDLE results_handle_;
131 EVT_HANDLE publisher_metadata_;
132 EVT_HANDLE render_context_;
133 std::vector<EVT_HANDLE> event_handles_;
134 DWORD cur_result_idx_;
135 DWORD num_results_returned_;
136 };
137
Initialize(uint64_t first_event_id)138 bool EventLogReader::Initialize(uint64_t first_event_id) {
139 base::string16 query(kEventLogQueryTemplateStr);
140 base::string16 pattern(L"{event_id}");
141 query.replace(query.find(pattern), pattern.size(),
142 base::NumberToString16(first_event_id));
143
144 // If in an initialized state, close and re-initialize.
145 if (results_handle_) {
146 Close();
147 }
148
149 results_handle_ = EventLoggingApiManager::Get()->EvtQuery(
150 nullptr, nullptr, query.c_str(),
151 EvtQueryChannelPath | EvtQueryTolerateQueryErrors);
152
153 if (results_handle_ == nullptr) {
154 LOGFN(ERROR) << "EvtQuery failed! Error="
155 << EventLoggingApiManager::Get()->GetLastErrorAsString();
156 return false;
157 }
158
159 if (!HasValidQueryResults()) {
160 Close();
161 LOGFN(WARNING) << "Could not find any valid logs!";
162 return false;
163 }
164
165 publisher_metadata_ = EventLoggingApiManager::Get()->EvtOpenPublisherMetadata(
166 nullptr, kEventLogPublisherName, nullptr, 0, 0);
167 if (publisher_metadata_ == nullptr) {
168 Close();
169 LOGFN(ERROR) << "EvtOpenPublisherMetadata failed. Error="
170 << EventLoggingApiManager::Get()->GetLastErrorAsString();
171 return false;
172 }
173
174 const DWORD paths_count =
175 sizeof(kEventLogValuePaths) / sizeof(const wchar_t*);
176 render_context_ = EventLoggingApiManager::Get()->EvtCreateRenderContext(
177 paths_count, (LPCWSTR*)kEventLogValuePaths, EvtRenderContextValues);
178
179 if (render_context_ == nullptr) {
180 Close();
181 LOGFN(ERROR) << "EvtCreateRenderContext failed. Error="
182 << EventLoggingApiManager::Get()->GetLastErrorAsString();
183 return false;
184 }
185
186 return true;
187 }
188
GetNextEventLogEntry(EventLogsUploadManager::EventLogEntry * log_entry)189 bool EventLogReader::GetNextEventLogEntry(
190 EventLogsUploadManager::EventLogEntry* log_entry) {
191 DCHECK(results_handle_);
192 DCHECK(log_entry);
193
194 if (cur_result_idx_ >= num_results_returned_) {
195 // Read the next block of events from the result set.
196 if (!EventLoggingApiManager::Get()->EvtNext(
197 results_handle_, event_handles_.size(), &event_handles_[0],
198 INFINITE, 0, &num_results_returned_)) {
199 DWORD last_error = EventLoggingApiManager::Get()->GetLastError();
200 num_results_returned_ = 0;
201 if (last_error != ERROR_NO_MORE_ITEMS) {
202 LOGFN(ERROR) << "EvtNext failed with error: "
203 << EventLoggingApiManager::Get()->GetLastErrorAsString();
204 }
205 return false;
206 }
207 cur_result_idx_ = 0;
208 }
209
210 bool status =
211 ReadEventLogEntryFromEvent(event_handles_[cur_result_idx_], log_entry);
212 EventLoggingApiManager::Get()->EvtClose(event_handles_[cur_result_idx_]);
213 event_handles_[cur_result_idx_] = nullptr;
214 ++cur_result_idx_;
215 return status;
216 }
217
218 // Returns true if the query resulted in valid results found.
HasValidQueryResults()219 bool EventLogReader::HasValidQueryResults() {
220 std::vector<EVT_VARIANT> names_buffer, status_buffer;
221
222 if (GetQueryInfo(EvtQueryNames, &names_buffer) &&
223 GetQueryInfo(EvtQueryStatuses, &status_buffer)) {
224 PEVT_VARIANT query_names = &names_buffer[0];
225 PEVT_VARIANT query_statuses = &status_buffer[0];
226
227 for (DWORD i = 0; i < query_names->Count; ++i) {
228 if (query_statuses->UInt32Arr[i] != ERROR_SUCCESS) {
229 LOGFN(ERROR) << "Query path " << query_names->StringArr[0]
230 << " has error status " << query_statuses->UInt32Arr[i];
231 return false;
232 }
233 }
234 } else {
235 return false;
236 }
237
238 return true;
239 }
240
241 // Gets the requested property of the query and stores in the buffer.
GetQueryInfo(EVT_QUERY_PROPERTY_ID property_id,std::vector<EVT_VARIANT> * value_buffer)242 bool EventLogReader::GetQueryInfo(EVT_QUERY_PROPERTY_ID property_id,
243 std::vector<EVT_VARIANT>* value_buffer) {
244 DCHECK(value_buffer);
245
246 DWORD buffer_used = 0;
247 if (!EventLoggingApiManager::Get()->EvtGetQueryInfo(
248 results_handle_, property_id, 0, nullptr, &buffer_used)) {
249 DWORD last_error = EventLoggingApiManager::Get()->GetLastError();
250 if (last_error == ERROR_INSUFFICIENT_BUFFER) {
251 value_buffer->resize(buffer_used / sizeof(EVT_VARIANT) + 1);
252 DWORD buffer_size = value_buffer->size() * sizeof(EVT_VARIANT);
253 if (EventLoggingApiManager::Get()->EvtGetQueryInfo(
254 results_handle_, property_id, buffer_size, value_buffer->data(),
255 &buffer_used)) {
256 return true;
257 }
258 }
259 }
260 LOGFN(ERROR) << "EvtGetQueryInfo failed with error: "
261 << EventLoggingApiManager::Get()->GetLastErrorAsString();
262 return false;
263 }
264
265 // Reads the event log info from the specified handle.
ReadEventLogEntryFromEvent(EVT_HANDLE event_handle,EventLogsUploadManager::EventLogEntry * log_entry)266 bool EventLogReader::ReadEventLogEntryFromEvent(
267 EVT_HANDLE event_handle,
268 EventLogsUploadManager::EventLogEntry* log_entry) {
269 DCHECK(log_entry);
270
271 DWORD buffer_used = 0;
272 DWORD property_count = 0;
273 std::vector<EVT_VARIANT> buffer;
274 bool render_done = false;
275
276 if (!EventLoggingApiManager::Get()->EvtRender(
277 render_context_, event_handle, EvtRenderEventValues, 0, nullptr,
278 &buffer_used, &property_count)) {
279 DWORD last_error = EventLoggingApiManager::Get()->GetLastError();
280 if (last_error == ERROR_INSUFFICIENT_BUFFER) {
281 buffer.resize(buffer_used / sizeof(EVT_VARIANT) + 1);
282 DWORD buffer_size = buffer.size() * sizeof(EVT_VARIANT);
283 if (EventLoggingApiManager::Get()->EvtRender(
284 render_context_, event_handle, EvtRenderEventValues, buffer_size,
285 &buffer[0], &buffer_used, &property_count)) {
286 render_done = true;
287 }
288 }
289 }
290
291 if (render_done) {
292 log_entry->event_id = buffer[0].UInt64Val;
293 UINT64 ticks = buffer[1].FileTimeVal;
294 // Convert from Windows epoch to Unix epoch.
295 log_entry->created_ts.seconds = (INT64)((ticks / 10000000) - 11644473600LL);
296 log_entry->created_ts.nanos = (INT32)((ticks % 10000000) * 100);
297 } else {
298 LOGFN(ERROR) << "EvtRender failed with error: "
299 << EventLoggingApiManager::Get()->GetLastErrorAsString();
300 return false;
301 }
302
303 if (!GetFormattedMessage(event_handle, EvtFormatMessageEvent,
304 &log_entry->data)) {
305 return false;
306 }
307
308 base::string16 level_str;
309 if (!GetFormattedMessage(event_handle, EvtFormatMessageLevel, &level_str))
310 return false;
311
312 if (kEventLogLevelStrToIntValueMap.find(level_str) !=
313 kEventLogLevelStrToIntValueMap.end()) {
314 log_entry->severity_level = kEventLogLevelStrToIntValueMap.at(level_str);
315 } else {
316 log_entry->severity_level = 0;
317 }
318
319 return true;
320 }
321
322 // Read the requested formatted message from the event handle.
GetFormattedMessage(EVT_HANDLE event_handle,EVT_FORMAT_MESSAGE_FLAGS message_flag,base::string16 * message)323 bool EventLogReader::GetFormattedMessage(EVT_HANDLE event_handle,
324 EVT_FORMAT_MESSAGE_FLAGS message_flag,
325 base::string16* message) {
326 DCHECK(message);
327
328 DWORD buffer_used = 0;
329 if (!EventLoggingApiManager::Get()->EvtFormatMessage(
330 publisher_metadata_, event_handle, 0, 0, nullptr, message_flag, 0,
331 nullptr, &buffer_used)) {
332 DWORD last_error = EventLoggingApiManager::Get()->GetLastError();
333 if (last_error == ERROR_INSUFFICIENT_BUFFER) {
334 std::vector<WCHAR> buffer(buffer_used);
335 if (EventLoggingApiManager::Get()->EvtFormatMessage(
336 publisher_metadata_, event_handle, 0, 0, nullptr, message_flag,
337 buffer.size(), &buffer[0], &buffer_used)) {
338 message->assign(&buffer[0]);
339 return true;
340 }
341 }
342 }
343 LOGFN(ERROR) << "EvtFormatMessage failed with error: "
344 << EventLoggingApiManager::Get()->GetLastErrorAsString();
345 return false;
346 }
347
348 // Close all open handles.
Close()349 void EventLogReader::Close() {
350 for (size_t i = 0; i < event_handles_.size(); ++i) {
351 if (event_handles_[i]) {
352 EventLoggingApiManager::Get()->EvtClose(event_handles_[i]);
353 event_handles_[i] = nullptr;
354 }
355 }
356
357 if (render_context_) {
358 EventLoggingApiManager::Get()->EvtClose(render_context_);
359 render_context_ = nullptr;
360 }
361
362 if (publisher_metadata_) {
363 EventLoggingApiManager::Get()->EvtClose(publisher_metadata_);
364 publisher_metadata_ = nullptr;
365 }
366
367 if (results_handle_) {
368 EventLoggingApiManager::Get()->EvtClose(results_handle_);
369 results_handle_ = nullptr;
370 }
371 }
372
373 } // namespace
374
375 // static
Get()376 EventLogsUploadManager* EventLogsUploadManager::Get() {
377 return *GetInstanceStorage();
378 }
379
380 // static
GetInstanceStorage()381 EventLogsUploadManager** EventLogsUploadManager::GetInstanceStorage() {
382 static EventLogsUploadManager instance;
383 static EventLogsUploadManager* instance_storage = &instance;
384 return &instance_storage;
385 }
386
EventLogsUploadManager()387 EventLogsUploadManager::EventLogsUploadManager()
388 : upload_status_(S_OK), num_event_logs_uploaded_(0) {}
389
390 EventLogsUploadManager::~EventLogsUploadManager() = default;
391
GetGcpwServiceUploadEventViewerLogsUrl()392 GURL EventLogsUploadManager::GetGcpwServiceUploadEventViewerLogsUrl() {
393 GURL gcpw_service_url = GetGcpwServiceUrl();
394
395 return gcpw_service_url.Resolve(kGcpwServiceUploadEventLogsPath);
396 }
397
UploadEventViewerLogs(const std::string & access_token)398 HRESULT EventLogsUploadManager::UploadEventViewerLogs(
399 const std::string& access_token) {
400 LOGFN(VERBOSE);
401
402 DWORD log_upload_level = GetGlobalFlagOrDefault(kEventLogUploadLevelRegKey,
403 kDefaultUploadLogLevel);
404
405 EventLogReader event_log_reader;
406
407 DWORD first_event_log_id_to_upload =
408 1 + GetGlobalFlagOrDefault(kEventLogUploadLastUploadedIdRegKey, 0);
409 if (!event_log_reader.Initialize(first_event_log_id_to_upload)) {
410 LOGFN(ERROR) << "Failed to initialize event log reader!";
411 upload_status_ = E_FAIL;
412 return upload_status_;
413 }
414
415 uint64_t chunk_id = 0;
416 size_t log_entries_payload_size = 0;
417 int num_upload_requests_made = 0;
418 std::unique_ptr<base::Value> log_entry_value_list;
419 EventLogEntry log_entry;
420
421 while (event_log_reader.GetNextEventLogEntry(&log_entry) &&
422 num_upload_requests_made < kMaxAllowedNumberOfUploadRequests) {
423 if (log_entry.severity_level > log_upload_level)
424 continue;
425
426 chunk_id = std::max(chunk_id, log_entry.event_id);
427
428 base::Value log_entry_value(base::Value::Type::DICTIONARY);
429 log_entry.ToValue(log_entry_value);
430
431 // Get the JSON for the log to keep track of payload size.
432 std::string log_entry_json;
433 if (!base::JSONWriter::Write(log_entry_value, &log_entry_json)) {
434 LOGFN(ERROR) << "base::JSONWriter::Write failed";
435 upload_status_ = E_FAIL;
436 return upload_status_;
437 }
438
439 if (!log_entry_value_list) {
440 log_entry_value_list.reset(new base::Value(base::Value::Type::LIST));
441 }
442 log_entry_value_list->Append(std::move(log_entry_value));
443
444 log_entries_payload_size += log_entry_json.size();
445 if (log_entries_payload_size >= kMaxPayloadSizeOfLogEntries) {
446 upload_status_ = MakeUploadLogChunkRequest(
447 access_token, chunk_id, std::move(log_entry_value_list));
448 if (FAILED(upload_status_)) {
449 return upload_status_;
450 }
451 ++num_upload_requests_made;
452 chunk_id = 0;
453 log_entries_payload_size = 0;
454 }
455 }
456
457 if (log_entry_value_list && log_entry_value_list->GetList().size() > 0) {
458 upload_status_ = MakeUploadLogChunkRequest(access_token, chunk_id,
459 std::move(log_entry_value_list));
460 if (FAILED(upload_status_)) {
461 return upload_status_;
462 }
463 ++num_upload_requests_made;
464 }
465
466 LOGFN(VERBOSE) << num_event_logs_uploaded_ << " events uploaded with "
467 << num_upload_requests_made << " requests.";
468 upload_status_ = S_OK;
469 return upload_status_;
470 }
471
MakeUploadLogChunkRequest(const std::string & access_token,uint64_t chunk_id,std::unique_ptr<base::Value> log_entries_value_list)472 HRESULT EventLogsUploadManager::MakeUploadLogChunkRequest(
473 const std::string& access_token,
474 uint64_t chunk_id,
475 std::unique_ptr<base::Value> log_entries_value_list) {
476 // The GCPW service uses serial number and machine GUID for identifying
477 // the device entry.
478 base::string16 serial_number = GetSerialNumber();
479 base::string16 machine_guid;
480 HRESULT hr = GetMachineGuid(&machine_guid);
481 if (FAILED(hr)) {
482 LOGFN(ERROR) << "Could not get Machine GUID. Error:" << putHR(hr);
483 return hr;
484 }
485
486 size_t num_events_to_upload = log_entries_value_list->GetList().size();
487
488 base::Value request_dict(base::Value::Type::DICTIONARY);
489 request_dict.SetStringKey(kRequestSerialNumberParameterName,
490 base::UTF16ToUTF8(serial_number));
491 request_dict.SetStringKey(kRequestMachineGuidParameterName,
492 base::UTF16ToUTF8(machine_guid));
493 request_dict.SetIntKey(kRequestChunkIdParameterName, chunk_id);
494 base::Value log_entries =
495 base::Value::FromUniquePtrValue(std::move(log_entries_value_list));
496 request_dict.SetKey(kRequestLogEntriesParameterName, std::move(log_entries));
497 base::Optional<base::Value> request_result;
498
499 // Make the upload HTTP request.
500 hr = WinHttpUrlFetcher::BuildRequestAndFetchResultFromHttpService(
501 EventLogsUploadManager::Get()->GetGcpwServiceUploadEventViewerLogsUrl(),
502 access_token, {}, request_dict, kDefaultUploadLogsRequestTimeout,
503 kMaxNumHttpRetries, &request_result);
504
505 if (FAILED(hr)) {
506 LOGFN(ERROR) << "BuildRequestAndFetchResultFromHttpService hr="
507 << putHR(hr);
508 return hr;
509 }
510
511 // Store the chunk id which is the last uploaded event log id
512 // in registry so we know where to start next time.
513 SetGlobalFlag(kEventLogUploadLastUploadedIdRegKey, chunk_id);
514 num_event_logs_uploaded_ += num_events_to_upload;
515 return S_OK;
516 }
517
ToValue(base::Value & dict) const518 void EventLogsUploadManager::EventLogEntry::ToValue(base::Value& dict) const {
519 base::Value timestamp(base::Value::Type::DICTIONARY);
520 timestamp.SetIntKey(kEventLogTimeStampSecondsParameterName,
521 created_ts.seconds);
522 timestamp.SetIntKey(kEventLogTimeStampNanosParameterName, created_ts.nanos);
523
524 dict.SetStringKey(kEventLogDataParameterName, base::UTF16ToUTF8(data));
525 dict.SetIntKey(kEventLogEventIdParameterName, event_id);
526 dict.SetIntKey(kEventLogSeverityLevelParameterName, severity_level);
527 dict.SetKey(kEventLogTimeStampParameterName, std::move(timestamp));
528 }
529
530 } // namespace credential_provider
531