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 &gt;={event_id}) and TimeCreated[timediff(@SystemTime) "
77     L"&lt;= 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