[Windows][Host][Logging] Adding EtwTraceConsumer class

This CL adds the class which consumes the ETW events from
Windows.  The class is fairly straight-forward but there
is one interesting bit as the call to consumer events
blocks us from running tasks on that thread.  In order to
receive events and not block any of the existing threads,
we create a new AutoThread which we use to listen for and
handle events on.  When it is time to clean up, we unblock
the listening thread by stopping the trace session.

Future CLs will add the logic needed to parse the events
and redirect the output to a new location (likely based on
registry settings).  I've kept that out of this CL to keep
its size on the smaller side.

Bug: 1144185
Change-Id: Ibf494251d0929a1741cb2796f26d69d258d96a64
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2515140Reviewed-by: Jamie Walch <jamiewalch@chromium.org>
Commit-Queue: Joe Downing <joedow@chromium.org>
Cr-Commit-Position: refs/heads/master@{#823596}

remoting/host/daemon_process_win.cc

@@ -27,6 +27,7 @@
 #include "ipc/ipc_message.h"
 #include "ipc/ipc_message_macros.h"
 #include "mojo/core/embedder/scoped_ipc_support.h"
+#include "remoting/base/auto_thread.h"
 #include "remoting/base/auto_thread_task_runner.h"
 #include "remoting/base/scoped_sc_handle_win.h"
 #include "remoting/host/branding.h"
@@ -38,6 +39,7 @@
 #include "remoting/host/pairing_registry_delegate_win.h"
 #include "remoting/host/screen_resolution.h"
 #include "remoting/host/switches.h"
+#include "remoting/host/win/etw_trace_consumer.h"
 #include "remoting/host/win/launch_process_with_token.h"
 #include "remoting/host/win/security_descriptor.h"
 #include "remoting/host/win/unprivileged_process_delegate.h"
@@ -48,6 +50,8 @@ using base::TimeDelta;
 
 namespace {
 
+constexpr char kEtwTracingThreadName[] = "ETW Trace Consumer";
+
 // Duplicates |key| and returns the value that can be sent over IPC.
 IPC::PlatformFileForTransit GetRegistryKeyForTransit(
     const base::win::RegKey& key) {
@@ -88,6 +92,10 @@ class DaemonProcessWin : public DaemonProcess {
       int session_id,
       const IPC::ChannelHandle& desktop_pipe) override;
 
+  // Creates an ETW trace consumer which listens for logged events from our
+  // host processes.  Tracing stops when |etw_trace_consumer_| is destroyed.
+  void StartEtwLogging();
+
  protected:
   // DaemonProcess implementation.
   std::unique_ptr<DesktopSession> DoCreateDesktopSession(
@@ -121,6 +129,8 @@ class DaemonProcessWin : public DaemonProcess {
   base::win::RegKey pairing_registry_privileged_key_;
   base::win::RegKey pairing_registry_unprivileged_key_;
 
+  std::unique_ptr<EtwTraceConsumer> etw_trace_consumer_;
+
   DISALLOW_COPY_AND_ASSIGN(DaemonProcessWin);
 };
 
@@ -134,8 +144,7 @@ DaemonProcessWin::DaemonProcessWin(
       ipc_support_(io_task_runner->task_runner(),
                    mojo::core::ScopedIPCSupport::ShutdownPolicy::FAST) {}
 
-DaemonProcessWin::~DaemonProcessWin() {
-}
+DaemonProcessWin::~DaemonProcessWin() = default;
 
 void DaemonProcessWin::OnChannelConnected(int32_t peer_pid) {
   // Obtain the handle of the network process.
@@ -232,9 +241,14 @@ std::unique_ptr<DaemonProcess> DaemonProcess::Create(
     scoped_refptr<AutoThreadTaskRunner> caller_task_runner,
     scoped_refptr<AutoThreadTaskRunner> io_task_runner,
     base::OnceClosure stopped_callback) {
-  std::unique_ptr<DaemonProcessWin> daemon_process(new DaemonProcessWin(
-      caller_task_runner, io_task_runner, std::move(stopped_callback)));
+  auto daemon_process = std::make_unique<DaemonProcessWin>(
+      caller_task_runner, io_task_runner, std::move(stopped_callback));
+
+  // Initialize our ETW logger first so we can capture any subsequent events.
+  daemon_process->StartEtwLogging();
+
   daemon_process->Initialize();
+
   return std::move(daemon_process);
 }
 
@@ -380,4 +394,15 @@ bool DaemonProcessWin::OpenPairingRegistry() {
   return true;
 }
 
+void DaemonProcessWin::StartEtwLogging() {
+  DCHECK(!etw_trace_consumer_);
+
+  // TODO(joedow): Add some registry keys to control the behavior here.
+  // This will most likely include trace levels and output files/locations.
+  etw_trace_consumer_ = EtwTraceConsumer::Create(AutoThread::CreateWithType(
+      kEtwTracingThreadName, caller_task_runner(), base::MessagePumpType::IO));
+
+  LOG_IF(ERROR, !etw_trace_consumer_) << "Failed to create EtwTraceConsumer.";
+}
+
 }  // namespace remoting

remoting/host/win/BUILD.gn

@@ -154,6 +154,8 @@ source_set("unit_tests") {
   sources = [
     "elevated_native_messaging_host.cc",
     "elevated_native_messaging_host.h",
+    "etw_trace_consumer.cc",
+    "etw_trace_consumer.h",
     "etw_trace_controller.cc",
     "etw_trace_controller.h",
     "launch_native_messaging_host_process.cc",
@@ -365,6 +367,8 @@ shared_library("remoting_core") {
     "core_resource.h",
     "elevated_native_messaging_host.cc",
     "elevated_native_messaging_host.h",
+    "etw_trace_consumer.cc",
+    "etw_trace_consumer.h",
     "etw_trace_controller.cc",
     "etw_trace_controller.h",
     "host_service.cc",

remoting/host/win/etw_trace_consumer.cc

+// Copyright 2020 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "remoting/host/win/etw_trace_consumer.h"
+
+#include <stdint.h>
+
+#include <memory>
+
+#include "base/logging.h"
+#include "base/logging_win.h"
+#include "base/macros.h"
+#include "base/threading/thread_checker.h"
+#include "base/win/event_trace_consumer.h"
+#include "base/win/event_trace_controller.h"
+#include "remoting/base/auto_thread_task_runner.h"
+#include "remoting/host/logging.h"
+#include "remoting/host/win/etw_trace_controller.h"
+
+namespace remoting {
+
+namespace {
+
+class EtwTraceConsumerImpl : public EtwTraceConsumer {
+ public:
+  EtwTraceConsumerImpl();
+  EtwTraceConsumerImpl(const EtwTraceConsumerImpl&) = delete;
+  EtwTraceConsumerImpl& operator=(const EtwTraceConsumerImpl&) = delete;
+  ~EtwTraceConsumerImpl() override;
+
+  bool StartLogging(scoped_refptr<AutoThreadTaskRunner> task_runner);
+  void StopLogging();
+
+ private:
+  class Core : public base::win::EtwTraceConsumerBase<Core> {
+   public:
+    Core() = default;
+    Core(const Core&) = delete;
+    Core& operator=(const Core&) = delete;
+    ~Core() = default;
+
+    static VOID WINAPI ProcessEvent(PEVENT_TRACE event);
+
+    bool Start();
+    void Stop();
+
+    // Blocking call to begin receiving ETW events from Windows.  Must be called
+    // on an IO thread which allows blocking.  Call Stop() to unblock the thread
+    // and allow it to be cleaned up.
+    void ConsumeEvents();
+
+   private:
+    // Parses an event and passes it along to the delegate for processing.
+    void DispatchEvent(PEVENT_TRACE event);
+
+    // Handlers which parse and log an ETW event.
+    void HandleFullMessage(PEVENT_TRACE event);
+    void HandleMessage(PEVENT_TRACE event);
+
+    static Core* instance_;
+
+    std::unique_ptr<EtwTraceController> controller_;
+
+    THREAD_CHECKER(thread_checker_);
+  };
+
+  std::unique_ptr<Core> core_;
+  scoped_refptr<AutoThreadTaskRunner> task_runner_;
+};
+
+// static
+EtwTraceConsumerImpl::Core* EtwTraceConsumerImpl::Core::instance_ = nullptr;
+
+// static
+void EtwTraceConsumerImpl::Core::ProcessEvent(PEVENT_TRACE event) {
+  // This method is called on the same thread as Consume().
+  EtwTraceConsumerImpl::Core* instance = instance_;
+  if (instance) {
+    instance->DispatchEvent(event);
+  }
+}
+
+bool EtwTraceConsumerImpl::Core::Start() {
+  DCHECK_CALLED_ON_VALID_THREAD(thread_checker_);
+  DCHECK(!instance_);
+  instance_ = this;
+
+  controller_ = std::make_unique<EtwTraceController>();
+  if (!controller_->Start()) {
+    return false;
+  }
+
+  HRESULT hr = OpenRealtimeSession(controller_->GetActiveSessionName());
+  if (FAILED(hr)) {
+    return false;
+  }
+
+  return true;
+}
+
+void EtwTraceConsumerImpl::Core::Stop() {
+  DCHECK_CALLED_ON_VALID_THREAD(thread_checker_);
+  if (!instance_) {
+    return;
+  }
+
+  DCHECK_EQ(instance_, this);
+  if (controller_) {
+    controller_->Stop();
+    controller_.reset();
+  }
+  instance_ = nullptr;
+}
+
+void EtwTraceConsumerImpl::Core::ConsumeEvents() {
+  // Consume will block the thread until the provider is disabled so make sure
+  // it is not run on the same thread that |core_| was created on.
+  DCHECK(!thread_checker_.CalledOnValidThread());
+  Consume();
+}
+
+void EtwTraceConsumerImpl::Core::DispatchEvent(PEVENT_TRACE event) {
+  // This method is called on the same thread as Consume().
+  DCHECK(!thread_checker_.CalledOnValidThread());
+  if (!event) {
+    return;
+  }
+
+  if (!IsEqualGUID(event->Header.Guid, logging::kLogEventId)) {
+    // Event was not logged from our provider.
+    return;
+  }
+
+  uint8_t event_type = event->Header.Class.Type;
+  if (event_type == logging::LOG_MESSAGE_FULL) {
+    HandleFullMessage(event);
+  } else if (event_type != logging::LOG_MESSAGE) {
+    HandleMessage(event);
+  } else {
+    NOTREACHED() << "Unknown event type.";
+  }
+}
+
+void EtwTraceConsumerImpl::Core::HandleFullMessage(PEVENT_TRACE event) {
+  // TODO(joedow): Implement parsing and logging for this event type.
+  NOTIMPLEMENTED();
+}
+
+void EtwTraceConsumerImpl::Core::HandleMessage(PEVENT_TRACE event) {
+  // TODO(joedow): Implement parsing and logging for this event type.
+  NOTIMPLEMENTED();
+}
+
+EtwTraceConsumerImpl::EtwTraceConsumerImpl() = default;
+
+EtwTraceConsumerImpl::~EtwTraceConsumerImpl() {
+  StopLogging();
+}
+
+bool EtwTraceConsumerImpl::StartLogging(
+    scoped_refptr<AutoThreadTaskRunner> task_runner) {
+  DCHECK(!core_);
+
+  core_ = std::make_unique<Core>();
+  if (!core_->Start()) {
+    core_.reset();
+    return false;
+  }
+
+  task_runner_ = task_runner;
+  // base::Unretained is safe because |core_| is destroyed on |task_runner_|.
+  task_runner_->PostTask(
+      FROM_HERE, base::BindOnce(&EtwTraceConsumerImpl::Core::ConsumeEvents,
+                                base::Unretained(core_.get())));
+  return true;
+}
+
+void EtwTraceConsumerImpl::StopLogging() {
+  if (!core_) {
+    return;
+  }
+
+  // |core_| is consuming trace events on |task_runner_| which is effectively
+  // blocked (Windows is calling it back but we can't schedule work on it).
+  // To unblock that thread, we first need to stop tracing, after that we
+  // schedule a deletion on the tracing thread so it occurs after all of the
+  // pending events have been handled.
+  core_->Stop();
+  task_runner_->DeleteSoon(FROM_HERE, core_.release());
+}
+
+}  // namespace
+
+// static
+std::unique_ptr<EtwTraceConsumer> EtwTraceConsumer::Create(
+    scoped_refptr<AutoThreadTaskRunner> task_runner) {
+  // TODO(joedow): Configure logging destination before returning the instance.
+
+  auto etw_trace_consumer = std::make_unique<EtwTraceConsumerImpl>();
+  if (!etw_trace_consumer->StartLogging(task_runner)) {
+    return nullptr;
+  }
+
+  return etw_trace_consumer;
+}
+
+}  // namespace remoting

remoting/host/win/etw_trace_consumer.h

+// Copyright 2020 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#ifndef REMOTING_HOST_WIN_ETW_TRACE_CONSUMER_H_
+#define REMOTING_HOST_WIN_ETW_TRACE_CONSUMER_H_
+
+#include <memory>
+
+#include "base/memory/ref_counted.h"
+
+namespace remoting {
+
+class AutoThreadTaskRunner;
+
+class EtwTraceConsumer {
+ public:
+  virtual ~EtwTraceConsumer() = default;
+
+  // Creates an ETW Trace Consumer which listens for Host ETW events.
+  // TODO(joedow): Add output functionality (log file / etw file / event log).
+  // Listening starts as soon as an instance is created and stops when the
+  // instance is destroyed.  Only one instance can be active at a time.
+  static std::unique_ptr<EtwTraceConsumer> Create(
+      scoped_refptr<AutoThreadTaskRunner> task_runner);
+};
+
+}  // namespace remoting
+
+#endif  // REMOTING_HOST_WIN_ETW_TRACE_CONSUMER_H_