[Windows][Host][Logging] HostEventFileLogger class

This CL introduces the class which will log events to a file.
The files are placed in the same location as the host binaries
and are cleaned up when the MSI is uninstalled (or reinstalled).
The host log file name includes the date/time so that a new log
is generated each time the host starts.  I added a symlink called
latest.log which points to the newest file.

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

remoting/host/daemon_process_win.cc

@@ -8,6 +8,7 @@
 
 #include <memory>
 #include <utility>
+#include <vector>
 
 #include "base/base_switches.h"
 #include "base/bind.h"
@@ -40,6 +41,7 @@
 #include "remoting/host/screen_resolution.h"
 #include "remoting/host/switches.h"
 #include "remoting/host/win/etw_trace_consumer.h"
+#include "remoting/host/win/host_event_file_logger.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"
@@ -67,7 +69,7 @@ constexpr wchar_t kLoggingRegistryKeyName[] =
 constexpr wchar_t kLoggingRegistryKeyName[] = L"SOFTWARE\\Chromoting\\logging";
 #endif
 
-constexpr wchar_t kLoggingEnabledRegistryValue[] = L"EnableEventLogging";
+constexpr wchar_t kLogToFileRegistryValue[] = L"LogToFile";
 
 }  // namespace
 
@@ -101,9 +103,11 @@ 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();
+  // If event logging has been configured, creates an ETW trace consumer which
+  // listens for logged events from our host processes.  Tracing stops when
+  // |etw_trace_consumer_| is destroyed.  Logging destinations are configured
+  // via the registry.
+  void ConfigureHostLogging();
 
  protected:
   // DaemonProcess implementation.
@@ -253,8 +257,8 @@ std::unique_ptr<DaemonProcess> DaemonProcess::Create(
   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();
+  // Configure host logging first so we can capture subsequent events.
+  daemon_process->ConfigureHostLogging();
 
   daemon_process->Initialize();
 
@@ -403,7 +407,7 @@ bool DaemonProcessWin::OpenPairingRegistry() {
   return true;
 }
 
-void DaemonProcessWin::StartEtwLogging() {
+void DaemonProcessWin::ConfigureHostLogging() {
   DCHECK(!etw_trace_consumer_);
 
   base::win::RegKey logging_reg_key;
@@ -415,28 +419,35 @@ void DaemonProcessWin::StartEtwLogging() {
     return;
   }
 
-  if (!logging_reg_key.HasValue(kLoggingEnabledRegistryValue)) {
-    VLOG(1) << "Event logging registry value does not exist. EtwTraceConsumer "
-            << "not created.";
-    return;
+  std::vector<std::unique_ptr<HostEventLogger>> loggers;
+
+  // Check to see if file logging has been enabled.
+  if (logging_reg_key.HasValue(kLogToFileRegistryValue)) {
+    DWORD enabled = 0;
+    result = logging_reg_key.ReadValueDW(kLogToFileRegistryValue, &enabled);
+    if (result == ERROR_SUCCESS) {
+      auto file_logger = HostEventFileLogger::Create();
+      if (file_logger) {
+        loggers.push_back(std::move(file_logger));
+      }
+    } else {
+      ::SetLastError(result);
+      PLOG(ERROR) << "Failed to read HKLM\\" << kLoggingRegistryKeyName << "\\"
+                  << kLogToFileRegistryValue;
+    }
   }
 
-  DWORD enabled = 0;
-  result = logging_reg_key.ReadValueDW(kLoggingEnabledRegistryValue, &enabled);
-  if (result != ERROR_SUCCESS) {
-    ::SetLastError(result);
-    PLOG(ERROR) << "Failed to read HKLM\\" << kLoggingRegistryKeyName << "\\"
-                << kLoggingEnabledRegistryValue;
-    return;
-  }
+  // TODO(joedow): Hook up a Windows Event Logger here.
 
-  if (!enabled) {
-    VLOG(1) << "Event logging is not enabled.  EtwTraceConsumer not created.";
+  if (loggers.empty()) {
+    VLOG(1) << "No host event loggers have been configured.";
     return;
   }
 
-  etw_trace_consumer_ = EtwTraceConsumer::Create(AutoThread::CreateWithType(
-      kEtwTracingThreadName, caller_task_runner(), base::MessagePumpType::IO));
+  etw_trace_consumer_ = EtwTraceConsumer::Create(
+      AutoThread::CreateWithType(kEtwTracingThreadName, caller_task_runner(),
+                                 base::MessagePumpType::IO),
+      std::move(loggers));
 }
 
 }  // namespace remoting

remoting/host/installer/win/chromoting.wxs

@@ -660,16 +660,6 @@
       </Component>
     </DirectoryRef>
 
-    <DirectoryRef Id="config_files">
-      <!-- Delete debug.log from previous versions -->
-      <Component Id="delete_debug_log"
-                 Guid="b309082a-e6fa-4dc7-98e4-3d83c896561d">
-        <RemoveFile Id="debug.log"
-                    Name="debug.log"
-                    On="both" />
-      </Component>
-    </DirectoryRef>
-
     <!-- The service is always installed in the stopped state with start type
          set to 'manual'. This becomes a problem when upgrading an existing
          installation that is configured to start the service automatically.
@@ -715,7 +705,6 @@
 
     <Feature Id="chromoting_host" Level="1" Title="$(var.ChromotingHost)">
       <ComponentRef Id="credits"/>
-      <ComponentRef Id="delete_debug_log"/>
       <ComponentRef Id="delete_usagestats"/>
       <?if $(var.OfficialBuild) != 0 ?>
         <ComponentRef Id="omaha_registration"/>
@@ -776,9 +765,9 @@
        Impersonate="no"
        Return="ignore"/>
 
-    <CustomAction Id="remove_debug_log"
+    <CustomAction Id="remove_logs"
       Directory="binaries"
-      ExeCommand='cmd /c del /f debug.log'
+      ExeCommand='cmd /c del /f *.log'
       Execute="deferred"
       Impersonate="no"
       Return="ignore"/>
@@ -810,7 +799,7 @@
            See http://msdn.microsoft.com/en-us/library/aa371197.aspx. -->
       <RemoveExistingProducts After="InstallInitialize" />
 
-      <Custom Action="remove_debug_log" Before="RemoveFiles">
+      <Custom Action="remove_logs" Before="RemoveFiles">
         Installed AND (NOT MAINTENANCE)
       </Custom>
       <Custom Action="remove_symbolic_link" Before="RemoveFiles">

remoting/host/win/BUILD.gn

@@ -154,10 +154,6 @@ 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",
     "event_trace_data.cc",
     "event_trace_data.h",
     "event_trace_data_unittest.cc",
@@ -376,6 +372,9 @@ shared_library("remoting_core") {
     "etw_trace_controller.h",
     "event_trace_data.cc",
     "event_trace_data.h",
+    "host_event_file_logger.cc",
+    "host_event_file_logger.h",
+    "host_event_logger.h",
     "host_service.cc",
     "host_service.h",
     "launch_native_messaging_host_process.cc",

remoting/host/win/etw_trace_consumer.cc

@@ -18,6 +18,7 @@
 #include "remoting/host/logging.h"
 #include "remoting/host/win/etw_trace_controller.h"
 #include "remoting/host/win/event_trace_data.h"
+#include "remoting/host/win/host_event_logger.h"
 
 namespace remoting {
 
@@ -30,7 +31,8 @@ class EtwTraceConsumerImpl : public EtwTraceConsumer {
   EtwTraceConsumerImpl& operator=(const EtwTraceConsumerImpl&) = delete;
   ~EtwTraceConsumerImpl() override;
 
-  bool StartLogging(scoped_refptr<AutoThreadTaskRunner> task_runner);
+  bool StartLogging(scoped_refptr<AutoThreadTaskRunner> task_runner,
+                    std::vector<std::unique_ptr<HostEventLogger>> loggers);
   void StopLogging();
 
  private:
@@ -43,7 +45,7 @@ class EtwTraceConsumerImpl : public EtwTraceConsumer {
 
     static VOID WINAPI ProcessEvent(EVENT_TRACE* event);
 
-    bool Start();
+    bool Start(std::vector<std::unique_ptr<HostEventLogger>> loggers);
     void Stop();
 
     // Blocking call to begin receiving ETW events from Windows.  Must be called
@@ -55,14 +57,12 @@ class EtwTraceConsumerImpl : public EtwTraceConsumer {
     // Parses an event and passes it along to the delegate for processing.
     void DispatchEvent(EVENT_TRACE* event);
 
-    // Handlers which parse and log an ETW event.
-    void HandleFullMessage(const EventTraceData& data);
-    void HandleMessage(const EventTraceData& data);
-
     static Core* instance_;
 
     std::unique_ptr<EtwTraceController> controller_;
 
+    std::vector<std::unique_ptr<HostEventLogger>> loggers_;
+
     THREAD_CHECKER(main_thread_checker_);
     THREAD_CHECKER(consume_thread_checker_);
   };
@@ -91,7 +91,8 @@ EtwTraceConsumerImpl::Core::~Core() {
   DCHECK_CALLED_ON_VALID_THREAD(consume_thread_checker_);
 }
 
-bool EtwTraceConsumerImpl::Core::Start() {
+bool EtwTraceConsumerImpl::Core::Start(
+    std::vector<std::unique_ptr<HostEventLogger>> loggers) {
   DCHECK_CALLED_ON_VALID_THREAD(main_thread_checker_);
   DCHECK(!instance_);
   instance_ = this;
@@ -106,6 +107,8 @@ bool EtwTraceConsumerImpl::Core::Start() {
     return false;
   }
 
+  loggers_ = std::move(loggers);
+
   return true;
 }
 
@@ -143,23 +146,14 @@ void EtwTraceConsumerImpl::Core::DispatchEvent(EVENT_TRACE* event) {
   }
 
   EventTraceData data = EventTraceData::Create(event);
-  if (data.event_type == logging::LOG_MESSAGE_FULL) {
-    HandleFullMessage(data);
-  } else if (data.event_type == logging::LOG_MESSAGE) {
-    HandleMessage(data);
+  if (data.event_type == logging::LOG_MESSAGE_FULL ||
+      data.event_type == logging::LOG_MESSAGE) {
+    for (const auto& logger : loggers_) {
+      logger->LogEvent(data);
+    }
   }
 }
 
-void EtwTraceConsumerImpl::Core::HandleFullMessage(const EventTraceData& data) {
-  // TODO(joedow): Implement logging for this event type.
-  NOTIMPLEMENTED();
-}
-
-void EtwTraceConsumerImpl::Core::HandleMessage(const EventTraceData& data) {
-  // TODO(joedow): Implement logging for this event type.
-  NOTIMPLEMENTED();
-}
-
 EtwTraceConsumerImpl::EtwTraceConsumerImpl() = default;
 
 EtwTraceConsumerImpl::~EtwTraceConsumerImpl() {
@@ -167,11 +161,12 @@ EtwTraceConsumerImpl::~EtwTraceConsumerImpl() {
 }
 
 bool EtwTraceConsumerImpl::StartLogging(
-    scoped_refptr<AutoThreadTaskRunner> task_runner) {
+    scoped_refptr<AutoThreadTaskRunner> task_runner,
+    std::vector<std::unique_ptr<HostEventLogger>> loggers) {
   DCHECK(!core_);
 
   core_ = std::make_unique<Core>();
-  if (!core_->Start()) {
+  if (!core_->Start(std::move(loggers))) {
     core_.reset();
     return false;
   }
@@ -202,11 +197,12 @@ void EtwTraceConsumerImpl::StopLogging() {
 
 // static
 std::unique_ptr<EtwTraceConsumer> EtwTraceConsumer::Create(
-    scoped_refptr<AutoThreadTaskRunner> task_runner) {
-  // TODO(joedow): Configure logging destination before returning the instance.
+    scoped_refptr<AutoThreadTaskRunner> task_runner,
+    std::vector<std::unique_ptr<HostEventLogger>> loggers) {
+  DCHECK(!loggers.empty());
 
   auto etw_trace_consumer = std::make_unique<EtwTraceConsumerImpl>();
-  if (!etw_trace_consumer->StartLogging(task_runner)) {
+  if (!etw_trace_consumer->StartLogging(task_runner, std::move(loggers))) {
     LOG(ERROR) << "Failed to start EtwTraceConsumer instance.";
     return nullptr;
   }

remoting/host/win/etw_trace_consumer.h

@@ -6,23 +6,25 @@
 #define REMOTING_HOST_WIN_ETW_TRACE_CONSUMER_H_
 
 #include <memory>
+#include <vector>
 
 #include "base/memory/ref_counted.h"
 
 namespace remoting {
 
 class AutoThreadTaskRunner;
+class HostEventLogger;
 
 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);
+      scoped_refptr<AutoThreadTaskRunner> task_runner,
+      std::vector<std::unique_ptr<HostEventLogger>> loggers);
 };
 
 }  // namespace remoting

remoting/host/win/event_trace_data.cc

@@ -58,7 +58,7 @@ EventTraceData EventTraceData::Create(EVENT_TRACE* event) {
 
   // Parse the MofData.  The structure is defined in //base/logging_win.cc.
   // - For LOG_MESSAGE events, the MofData buffer just contains the message.
-  // - For LOG_FULL_MESSAGE events, the MofData buffer is comprised of 5 fields
+  // - For LOG_MESSAGE_FULL events, the MofData buffer is comprised of 5 fields
   //   which must be parsed (or skipped) in sequence.
   if (data.event_type == logging::LOG_MESSAGE) {
     data.message.assign(reinterpret_cast<const char*>(event->MofData),

remoting/host/win/host_event_file_logger.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/host_event_file_logger.h"
+
+#include <utility>
+
+#include "base/base_paths.h"
+#include "base/check.h"
+#include "base/files/file_util.h"
+#include "base/logging.h"
+#include "base/notreached.h"
+#include "base/path_service.h"
+#include "base/strings/stringprintf.h"
+#include "remoting/host/win/event_trace_data.h"
+
+namespace remoting {
+
+namespace {
+
+constexpr wchar_t kLatestLogSymbolicLinkName[] = L"latest.log";
+
+constexpr char kInfoSeverity[] = "INFO";
+constexpr char kWarningSeverity[] = "WARNING";
+constexpr char kErrorSeverity[] = "ERROR";
+constexpr char kFatalSeverity[] = "FATAL";
+constexpr char kVerboseSeverity[] = "VERBOSE";
+constexpr char kUnknownSeverity[] = "UNKNOWN";
+
+std::string SeverityToString(logging::LogSeverity severity) {
+  switch (severity) {
+    case logging::LOG_INFO:
+      return kInfoSeverity;
+    case logging::LOG_WARNING:
+      return kWarningSeverity;
+    case logging::LOG_ERROR:
+      return kErrorSeverity;
+    case logging::LOG_FATAL:
+      return kFatalSeverity;
+    default:
+      if (severity < 0) {
+        return kVerboseSeverity;
+      }
+      NOTREACHED();
+      return kUnknownSeverity;
+  }
+}
+
+}  // namespace
+
+HostEventFileLogger::HostEventFileLogger(base::File log_file)
+    : log_file_(std::move(log_file)) {}
+
+HostEventFileLogger::~HostEventFileLogger() = default;
+
+std::unique_ptr<HostEventLogger> HostEventFileLogger::Create() {
+  base::FilePath directory;
+  bool result = base::PathService::Get(base::DIR_EXE, &directory);
+  DCHECK(result);
+
+  if (!base::DirectoryExists(directory)) {
+    LOG(ERROR) << "PathService returned an invalid DIR_EXE directory: "
+               << directory;
+    return nullptr;
+  }
+
+  base::Time::Exploded exploded;
+  base::Time::Now().LocalExplode(&exploded);
+  base::FilePath log_file_path = directory.Append(base::StringPrintf(
+      L"chrome_remote_desktop_%4d%02d%02d_%02d%02d%02d_%03d.log", exploded.year,
+      exploded.month, exploded.day_of_month, exploded.hour, exploded.minute,
+      exploded.second, exploded.millisecond));
+
+  // Create the log_file and set the write mode to append.
+  base::File log_file(log_file_path, base::File::Flags::FLAG_APPEND |
+                                         base::File::Flags::FLAG_CREATE);
+
+  if (!log_file.IsValid()) {
+    LOG(ERROR) << "Failed to create the output log file at: " << log_file_path;
+    return nullptr;
+  }
+
+  base::FilePath sym_link_path = directory.Append(kLatestLogSymbolicLinkName);
+  if (!::CreateSymbolicLink(sym_link_path.value().c_str(),
+                            log_file_path.value().c_str(),
+                            /*file*/ 0)) {
+    LOG(WARNING) << "Failed to create symbolic link for latest log file.";
+  }
+
+  return std::make_unique<HostEventFileLogger>(std::move(log_file));
+}
+
+void HostEventFileLogger::LogEvent(const EventTraceData& data) {
+  std::size_t pos = data.file.rfind("/");
+  std::string file_name =
+      pos != std::string::npos ? data.file.substr(pos + 1) : data.file;
+  std::string severity(SeverityToString(data.severity));
+
+  // Log format is: [YYYYMMDD/HHMMSS.sss:severity:file_name(line)] <message>
+  std::string message(base::StringPrintf(
+      "[%4d%02d%02d/%02d%02d%02d.%03d:%s:%s(%d)] %s", data.time_stamp.year,
+      data.time_stamp.month, data.time_stamp.day_of_month, data.time_stamp.hour,
+      data.time_stamp.minute, data.time_stamp.second,
+      data.time_stamp.millisecond, severity.c_str(), file_name.c_str(),
+      data.line, data.message.c_str()));
+
+  log_file_.Write(/*unused*/ 0, message.c_str(), message.size());
+}
+
+}  // namespace remoting

remoting/host/win/host_event_file_logger.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_HOST_EVENT_FILE_LOGGER_H_
+#define REMOTING_HOST_WIN_HOST_EVENT_FILE_LOGGER_H_
+
+#include <memory>
+
+#include "base/files/file.h"
+#include "remoting/host/win/host_event_logger.h"
+
+namespace remoting {
+
+// Logs ETW event trace data to a file.
+class HostEventFileLogger : public HostEventLogger {
+ public:
+  // Helper function which creates a HostEventLogger instance which will log
+  // to a unique file located in the same directory as current executable.
+  // Returns nullptr if an error occurs in configuring the logger.
+  static std::unique_ptr<HostEventLogger> Create();
+
+  explicit HostEventFileLogger(base::File log_file);
+  HostEventFileLogger(const HostEventFileLogger&) = delete;
+  HostEventFileLogger& operator=(const HostEventFileLogger&) = delete;
+  ~HostEventFileLogger() override;
+
+  void LogEvent(const EventTraceData& data) override;
+
+ private:
+  base::File log_file_;
+};
+
+}  // namespace remoting
+
+#endif  // REMOTING_HOST_WIN_HOST_EVENT_FILE_LOGGER_H_

remoting/host/win/host_event_logger.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_HOST_EVENT_LOGGER_H_
+#define REMOTING_HOST_WIN_HOST_EVENT_LOGGER_H_
+
+namespace remoting {
+
+struct EventTraceData;
+
+class HostEventLogger {
+ public:
+  virtual ~HostEventLogger() = default;
+
+  // Logs |data| to the destination defined in the implementation class.
+  virtual void LogEvent(const EventTraceData& data) = 0;
+};
+
+}  // namespace remoting
+
+#endif  // REMOTING_HOST_WIN_HOST_EVENT_LOGGER_H_