Browse Source

feat: bring --enable-logging functionality in line with Chromium (#25089)

Co-authored-by: Jeremy Rose <[email protected]>
Charles Kerr 3 years ago
parent
commit
8ccab4ce91

+ 49 - 5
docs/api/command-line-switches.md

@@ -67,13 +67,22 @@ Enables caller stack logging for the following APIs (filtering events):
 
 * `desktopCapturer.getSources()` / `desktop-capturer-get-sources`
 
-### --enable-logging
+### --enable-logging[=file]
 
-Prints Chromium's logging into console.
+Prints Chromium's logging to stderr (or a log file).
 
-This switch can not be used in `app.commandLine.appendSwitch` since it is parsed
-earlier than user's app is loaded, but you can set the `ELECTRON_ENABLE_LOGGING`
-environment variable to achieve the same effect.
+The `ELECTRON_ENABLE_LOGGING` environment variable has the same effect as
+passing `--enable-logging`.
+
+Passing `--enable-logging` will result in logs being printed on stderr.
+Passing `--enable-logging=file` will result in logs being saved to the file
+specified by `--log-file=...`, or to `electron_debug.log` in the user-data
+directory if `--log-file` is not specified.
+
+> **Note:** On Windows, logs from child processes cannot be sent to stderr.
+> Logging to a file is the most reliable way to collect logs on Windows.
+
+See also `--log-file`, `--log-level`, `--v`, and `--vmodule`.
 
 ### --force-fieldtrials=`trials`
 
@@ -126,10 +135,37 @@ See the [Node.js documentation][node-cli] or run `node --help` in your terminal
 
 Set a custom locale.
 
+### --log-file=`path`
+
+If `--enable-logging` is specified, logs will be written to the given path. The
+parent directory must exist.
+
+Setting the `ELECTRON_LOG_FILE` environment variable is equivalent to passing
+this flag. If both are present, the command-line switch takes precedence.
+
 ### --log-net-log=`path`
 
 Enables net log events to be saved and writes them to `path`.
 
+### --log-level=`N`
+
+Sets the verbosity of logging when used together with `--enable-logging`.
+`N` should be one of [Chrome's LogSeverities][severities].
+
+Note that two complimentary logging mechanisms in Chromium -- `LOG()`
+and `VLOG()` -- are controlled by different switches. `--log-level`
+controls `LOG()` messages, while `--v` and `--vmodule` control `VLOG()`
+messages. So you may want to use a combination of these three switches
+depending on the granularity you want and what logging calls are made
+by the code you're trying to watch.
+
+See [Chromium Logging source][logging] for more information on how
+`LOG()` and `VLOG()` interact. Loosely speaking, `VLOG()` can be thought
+of as sub-levels / per-module levels inside `LOG(INFO)` to control the
+firehose of `LOG(INFO)` data.
+
+See also `--enable-logging`, `--log-level`, `--v`, and `--vmodule`.
+
 ### --no-proxy-server
 
 Don't use a proxy server and always make direct connections. Overrides any other
@@ -181,6 +217,8 @@ positive values are used for V-logging levels.
 
 This switch only works when `--enable-logging` is also passed.
 
+See also `--enable-logging`, `--log-level`, and `--vmodule`.
+
 ### --vmodule=`pattern`
 
 Gives the per-module maximal V-logging levels to override the value given by
@@ -193,6 +231,8 @@ logging level for all code in the source files under a `foo/bar` directory.
 
 This switch only works when `--enable-logging` is also passed.
 
+See also `--enable-logging`, `--log-level`, and `--v`.
+
 ### --force_high_performance_gpu
 
 Force using discrete GPU when there are multiple GPUs available.
@@ -240,4 +280,8 @@ By default inspector websocket url is available in stderr and under /json/list e
 [ready]: app.md#event-ready
 [play-silent-audio]: https://github.com/atom/atom/pull/9485/files
 [debugging-main-process]: ../tutorial/debugging-main-process.md
+[logging]: https://source.chromium.org/chromium/chromium/src/+/master:base/logging.h
 [node-cli]: https://nodejs.org/api/cli.html
+[play-silent-audio]: https://github.com/atom/atom/pull/9485/files
+[ready]: app.md#event-ready
+[severities]: https://source.chromium.org/chromium/chromium/src/+/master:base/logging.h?q=logging::LogSeverity&ss=chromium

+ 15 - 2
docs/api/environment-variables.md

@@ -118,7 +118,19 @@ debugging purposes.
 
 ### `ELECTRON_ENABLE_LOGGING`
 
-Prints Chrome's internal logging to the console.
+Prints Chromium's internal logging to the console.
+
+Setting this variable is the same as passing `--enable-logging`
+on the command line. For more info, see `--enable-logging` in [command-line
+switches](./command-line-switches.md#enable-loggingfile).
+
+### `ELECTRON_LOG_FILE`
+
+Sets the file destination for Chromium's internal logging.
+
+Setting this variable is the same as passing `--log-file`
+on the command line. For more info, see `--log-file` in [command-line
+switches](./command-line-switches.md#log-filepath).
 
 ### `ELECTRON_DEBUG_DRAG_REGIONS`
 
@@ -127,7 +139,8 @@ green and non-draggable regions will be colored red to aid debugging.
 
 ### `ELECTRON_DEBUG_NOTIFICATIONS`
 
-Adds extra logs to [`Notification`](./notification.md) lifecycles on macOS to aid in debugging. Extra logging will be displayed when new Notifications are created or activated. They will also be displayed when common actions are taken: a notification is shown, dismissed, its button is clicked, or it is replied to.
+Adds extra logs to [`Notification`](./notification.md) lifecycles on macOS to aid in debugging. Extra logging will be displayed when new Notifications are created or activated. They will also be displayed when common a
+tions are taken: a notification is shown, dismissed, its button is clicked, or it is replied to.
 
 Sample output:
 

+ 1 - 1
docs/tutorial/application-debugging.md

@@ -45,4 +45,4 @@ If the V8 context crashes, the DevTools will display this message.
 
 Chromium logs can be enabled via the `ELECTRON_ENABLE_LOGGING` environment variable. For more information, see the [environment variables documentation](../api/environment-variables.md#electron_enable_logging).
 
-Alternatively, the command line argument `--enable-logging` can be passed. More information is available in the [command line switches documentation](../api/command-line-switches.md#--enable-logging).
+Alternatively, the command line argument `--enable-logging` can be passed. More information is available in the [command line switches documentation](../api/command-line-switches.md#--enable-loggingfile).

+ 3 - 0
filenames.gni

@@ -510,6 +510,7 @@ filenames = {
     "shell/common/api/electron_api_native_image.cc",
     "shell/common/api/electron_api_native_image.h",
     "shell/common/api/electron_api_shell.cc",
+    "shell/common/api/electron_api_testing.cc",
     "shell/common/api/electron_api_v8_util.cc",
     "shell/common/api/electron_bindings.cc",
     "shell/common/api/electron_bindings.h",
@@ -604,6 +605,8 @@ filenames = {
     "shell/common/keyboard_util.cc",
     "shell/common/keyboard_util.h",
     "shell/common/language_util.h",
+    "shell/common/logging.cc",
+    "shell/common/logging.h",
     "shell/common/mouse_util.cc",
     "shell/common/mouse_util.h",
     "shell/common/node_bindings.cc",

+ 27 - 30
shell/app/electron_main_delegate.cc

@@ -32,6 +32,7 @@
 #include "shell/browser/relauncher.h"
 #include "shell/common/application_info.h"
 #include "shell/common/electron_paths.h"
+#include "shell/common/logging.h"
 #include "shell/common/options_switches.h"
 #include "shell/common/platform_util.h"
 #include "shell/renderer/electron_renderer_client.h"
@@ -71,6 +72,10 @@ namespace {
 
 const char* kRelauncherProcess = "relauncher";
 
+constexpr base::StringPiece kElectronDisableSandbox("ELECTRON_DISABLE_SANDBOX");
+constexpr base::StringPiece kElectronEnableStackDumping(
+    "ELECTRON_ENABLE_STACK_DUMPING");
+
 bool IsBrowserProcess(base::CommandLine* cmd) {
   std::string process_type = cmd->GetSwitchValueASCII(::switches::kProcessType);
   return process_type.empty();
@@ -236,7 +241,6 @@ const size_t ElectronMainDelegate::kNonWildcardDomainNonPortSchemesSize =
 bool ElectronMainDelegate::BasicStartupComplete(int* exit_code) {
   auto* command_line = base::CommandLine::ForCurrentProcess();
 
-  logging::LoggingSettings settings;
 #if defined(OS_WIN)
   v8_crashpad_support::SetUp();
 
@@ -244,43 +248,16 @@ bool ElectronMainDelegate::BasicStartupComplete(int* exit_code) {
   // prevent output in the same line as the prompt.
   if (IsBrowserProcess(command_line))
     std::wcout << std::endl;
-#if defined(DEBUG)
-  // Print logging to debug.log on Windows
-  settings.logging_dest = logging::LOG_TO_ALL;
-  base::FilePath log_filename;
-  base::PathService::Get(base::DIR_EXE, &log_filename);
-  log_filename = log_filename.AppendASCII("debug.log");
-  settings.log_file_path = log_filename.value().c_str();
-  settings.lock_log = logging::LOCK_LOG_FILE;
-  settings.delete_old = logging::DELETE_OLD_LOG_FILE;
-#else
-  settings.logging_dest =
-      logging::LOG_TO_SYSTEM_DEBUG_LOG | logging::LOG_TO_STDERR;
-#endif  // defined(DEBUG)
-#else   // defined(OS_WIN)
-  settings.logging_dest =
-      logging::LOG_TO_SYSTEM_DEBUG_LOG | logging::LOG_TO_STDERR;
 #endif  // !defined(OS_WIN)
 
-  // Only enable logging when --enable-logging is specified.
   auto env = base::Environment::Create();
-  if (!command_line->HasSwitch(::switches::kEnableLogging) &&
-      !env->HasVar("ELECTRON_ENABLE_LOGGING")) {
-    settings.logging_dest = logging::LOG_NONE;
-    logging::SetMinLogLevel(logging::LOGGING_NUM_SEVERITIES);
-  }
-
-  logging::InitLogging(settings);
-
-  // Logging with pid and timestamp.
-  logging::SetLogItems(true, false, true, false);
 
   // Enable convenient stack printing. This is enabled by default in
   // non-official builds.
-  if (env->HasVar("ELECTRON_ENABLE_STACK_DUMPING"))
+  if (env->HasVar(kElectronEnableStackDumping))
     base::debug::EnableInProcessStackDumping();
 
-  if (env->HasVar("ELECTRON_DISABLE_SANDBOX"))
+  if (env->HasVar(kElectronDisableSandbox))
     command_line->AppendSwitch(sandbox::policy::switches::kNoSandbox);
 
   tracing_sampler_profiler_ =
@@ -353,6 +330,19 @@ void ElectronMainDelegate::PreSandboxStartup() {
                                                  user_data_dir, false, true);
   }
 
+#if !defined(OS_WIN)
+  // For windows we call InitLogging later, after the sandbox is initialized.
+  //
+  // On Linux, we force a "preinit" in the zygote (i.e. never log to a default
+  // log file), because the zygote is booted prior to JS running, so it can't
+  // know the correct user-data directory. (And, further, accessing the
+  // application name on Linux can cause glib calls that end up spawning
+  // threads, which if done before the zygote is booted, causes a CHECK().)
+  logging::InitElectronLogging(*command_line,
+                               /* is_preinit = */ process_type.empty() ||
+                                   process_type == ::switches::kZygoteProcess);
+#endif
+
 #if !defined(MAS_BUILD)
   crash_reporter::InitializeCrashKeys();
 #endif
@@ -400,6 +390,13 @@ void ElectronMainDelegate::PreSandboxStartup() {
   }
 }
 
+void ElectronMainDelegate::SandboxInitialized(const std::string& process_type) {
+#if defined(OS_WIN)
+  logging::InitElectronLogging(*base::CommandLine::ForCurrentProcess(),
+                               /* is_preinit = */ process_type.empty());
+#endif
+}
+
 void ElectronMainDelegate::PreBrowserMain() {
   // This is initialized early because the service manager reads some feature
   // flags and we need to make sure the feature list is initialized before the

+ 1 - 0
shell/app/electron_main_delegate.h

@@ -30,6 +30,7 @@ class ElectronMainDelegate : public content::ContentMainDelegate {
   // content::ContentMainDelegate:
   bool BasicStartupComplete(int* exit_code) override;
   void PreSandboxStartup() override;
+  void SandboxInitialized(const std::string& process_type) override;
   void PreBrowserMain() override;
   content::ContentBrowserClient* CreateContentBrowserClient() override;
   content::ContentGpuClient* CreateContentGpuClient() override;

+ 15 - 0
shell/browser/electron_browser_client.cc

@@ -100,6 +100,7 @@
 #include "shell/common/api/api.mojom.h"
 #include "shell/common/application_info.h"
 #include "shell/common/electron_paths.h"
+#include "shell/common/logging.h"
 #include "shell/common/options_switches.h"
 #include "shell/common/platform_util.h"
 #include "third_party/blink/public/common/loader/url_loader_throttle.h"
@@ -542,6 +543,15 @@ void ElectronBrowserClient::AppendExtraCommandLineSwitches(
   }
 #endif
 
+  // The zygote process is booted before JS runs, so DIR_USER_DATA isn't usable
+  // at that time. It doesn't need --user-data-dir to be correct anyway, since
+  // the zygote itself doesn't access anything in that directory.
+  if (process_type != ::switches::kZygoteProcess) {
+    base::FilePath user_data_dir;
+    if (base::PathService::Get(chrome::DIR_USER_DATA, &user_data_dir))
+      command_line->AppendSwitchPath(::switches::kUserDataDir, user_data_dir);
+  }
+
   if (process_type == ::switches::kUtilityProcess ||
       process_type == ::switches::kRendererProcess) {
     // Copy following switches to child process.
@@ -794,6 +804,11 @@ bool ElectronBrowserClient::ArePersistentMediaDeviceIDsAllowed(
   return true;
 }
 
+base::FilePath ElectronBrowserClient::GetLoggingFileName(
+    const base::CommandLine& cmd_line) {
+  return logging::GetLogFileName(cmd_line);
+}
+
 void ElectronBrowserClient::SiteInstanceDeleting(
     content::SiteInstance* site_instance) {
 #if BUILDFLAG(ENABLE_ELECTRON_EXTENSIONS)

+ 1 - 0
shell/browser/electron_browser_client.h

@@ -263,6 +263,7 @@ class ElectronBrowserClient : public content::ContentBrowserClient,
       const GURL& scope,
       const GURL& site_for_cookies,
       const absl::optional<url::Origin>& top_frame_origin) override;
+  base::FilePath GetLoggingFileName(const base::CommandLine& cmd_line) override;
 
   // content::RenderProcessHostObserver:
   void RenderProcessHostDestroyed(content::RenderProcessHost* host) override;

+ 1 - 0
shell/browser/electron_browser_context.cc

@@ -9,6 +9,7 @@
 #include <utility>
 
 #include "base/barrier_closure.h"
+#include "base/base_paths.h"
 #include "base/command_line.h"
 #include "base/files/file_path.h"
 #include "base/no_destructor.h"

+ 6 - 0
shell/browser/electron_browser_main_parts.cc

@@ -45,6 +45,7 @@
 #include "shell/common/application_info.h"
 #include "shell/common/electron_paths.h"
 #include "shell/common/gin_helper/trackable_object.h"
+#include "shell/common/logging.h"
 #include "shell/common/node_bindings.h"
 #include "shell/common/node_includes.h"
 #include "third_party/abseil-cpp/absl/types/optional.h"
@@ -269,6 +270,11 @@ void ElectronBrowserMainParts::PostEarlyInitialization() {
   // Initialize field trials.
   InitializeFieldTrials();
 
+  // Reinitialize logging now that the app has had a chance to set the app name
+  // and/or user data directory.
+  logging::InitElectronLogging(*base::CommandLine::ForCurrentProcess(),
+                               /* is_preinit = */ false);
+
   // Initialize after user script environment creation.
   fake_browser_process_->PostEarlyInitialization();
 }

+ 48 - 0
shell/common/api/electron_api_testing.cc

@@ -0,0 +1,48 @@
+// Copyright (c) 2021 Slack Technologies, Inc.
+// Use of this source code is governed by the MIT license that can be
+// found in the LICENSE file.
+
+#include "base/dcheck_is_on.h"
+#include "base/logging.h"
+#include "shell/common/gin_helper/dictionary.h"
+#include "shell/common/node_includes.h"
+#include "v8/include/v8.h"
+
+#if DCHECK_IS_ON()
+namespace {
+
+void Log(int severity, std::string text) {
+  switch (severity) {
+    case logging::LOGGING_VERBOSE:
+      VLOG(1) << text;
+      break;
+    case logging::LOGGING_INFO:
+      LOG(INFO) << text;
+      break;
+    case logging::LOGGING_WARNING:
+      LOG(WARNING) << text;
+      break;
+    case logging::LOGGING_ERROR:
+      LOG(ERROR) << text;
+      break;
+    case logging::LOGGING_FATAL:
+      LOG(FATAL) << text;
+      break;
+    default:
+      LOG(ERROR) << "Unrecognized severity: " << severity;
+      break;
+  }
+}
+
+void Initialize(v8::Local<v8::Object> exports,
+                v8::Local<v8::Value> unused,
+                v8::Local<v8::Context> context,
+                void* priv) {
+  gin_helper::Dictionary dict(context->GetIsolate(), exports);
+  dict.SetMethod("log", &Log);
+}
+
+}  // namespace
+
+NODE_LINKED_MODULE_CONTEXT_AWARE(electron_common_testing, Initialize)
+#endif

+ 141 - 0
shell/common/logging.cc

@@ -0,0 +1,141 @@
+// Copyright (c) 2021 Slack Technologies, Inc.
+// Use of this source code is governed by the MIT license that can be
+// found in the LICENSE file.
+
+#include "shell/common/logging.h"
+
+#include <string>
+
+#include "base/base_switches.h"
+#include "base/command_line.h"
+#include "base/environment.h"
+#include "base/files/file_path.h"
+#include "base/logging.h"
+#include "base/path_service.h"
+#include "base/strings/string_number_conversions.h"
+#include "chrome/common/chrome_paths.h"
+#include "content/public/common/content_switches.h"
+#include "shell/common/electron_paths.h"
+
+namespace logging {
+
+constexpr base::StringPiece kLogFileName("ELECTRON_LOG_FILE");
+constexpr base::StringPiece kElectronEnableLogging("ELECTRON_ENABLE_LOGGING");
+
+base::FilePath GetLogFileName(const base::CommandLine& command_line) {
+  std::string filename = command_line.GetSwitchValueASCII(switches::kLogFile);
+  if (filename.empty())
+    base::Environment::Create()->GetVar(kLogFileName, &filename);
+  if (!filename.empty())
+    return base::FilePath::FromUTF8Unsafe(filename);
+
+  const base::FilePath log_filename(FILE_PATH_LITERAL("electron_debug.log"));
+  base::FilePath log_path;
+
+  if (base::PathService::Get(chrome::DIR_LOGS, &log_path)) {
+    log_path = log_path.Append(log_filename);
+    return log_path;
+  } else {
+    // error with path service, just use some default file somewhere
+    return log_filename;
+  }
+}
+
+bool HasExplicitLogFile(const base::CommandLine& command_line) {
+  std::string filename = command_line.GetSwitchValueASCII(switches::kLogFile);
+  if (filename.empty())
+    base::Environment::Create()->GetVar(kLogFileName, &filename);
+  return !filename.empty();
+}
+
+LoggingDestination DetermineLoggingDestination(
+    const base::CommandLine& command_line,
+    bool is_preinit) {
+  bool enable_logging = false;
+  std::string logging_destination;
+  if (command_line.HasSwitch(::switches::kEnableLogging)) {
+    enable_logging = true;
+    logging_destination =
+        command_line.GetSwitchValueASCII(switches::kEnableLogging);
+  } else {
+    auto env = base::Environment::Create();
+    if (env->HasVar(kElectronEnableLogging)) {
+      enable_logging = true;
+      env->GetVar(kElectronEnableLogging, &logging_destination);
+    }
+  }
+  if (!enable_logging)
+    return LOG_NONE;
+
+  // --enable-logging logs to stderr, --enable-logging=file logs to a file.
+  // NB. this differs from Chromium, in which --enable-logging logs to a file
+  // and --enable-logging=stderr logs to stderr, because that's how Electron
+  // used to work, so in order to not break anyone who was depending on
+  // --enable-logging logging to stderr, we preserve the old behavior by
+  // default.
+  // If --log-file or ELECTRON_LOG_FILE is specified along with
+  // --enable-logging, return LOG_TO_FILE.
+  // If we're in the pre-init phase, before JS has run, we want to avoid
+  // logging to the default log file, which is inside the user data directory,
+  // because we aren't able to accurately determine the user data directory
+  // before JS runs. Instead, log to stderr unless there's an explicit filename
+  // given.
+  if (HasExplicitLogFile(command_line) ||
+      (logging_destination == "file" && !is_preinit))
+    return LOG_TO_FILE;
+  return LOG_TO_SYSTEM_DEBUG_LOG | LOG_TO_STDERR;
+}
+
+void InitElectronLogging(const base::CommandLine& command_line,
+                         bool is_preinit) {
+  const std::string process_type =
+      command_line.GetSwitchValueASCII(::switches::kProcessType);
+  LoggingDestination logging_dest =
+      DetermineLoggingDestination(command_line, is_preinit);
+  LogLockingState log_locking_state = LOCK_LOG_FILE;
+  base::FilePath log_path;
+
+  if (command_line.HasSwitch(::switches::kLoggingLevel) &&
+      GetMinLogLevel() >= 0) {
+    std::string log_level =
+        command_line.GetSwitchValueASCII(::switches::kLoggingLevel);
+    int level = 0;
+    if (base::StringToInt(log_level, &level) && level >= 0 &&
+        level < LOGGING_NUM_SEVERITIES) {
+      SetMinLogLevel(level);
+    } else {
+      DLOG(WARNING) << "Bad log level: " << log_level;
+    }
+  }
+
+  // Don't resolve the log path unless we need to. Otherwise we leave an open
+  // ALPC handle after sandbox lockdown on Windows.
+  if ((logging_dest & LOG_TO_FILE) != 0) {
+    log_path = GetLogFileName(command_line);
+  } else {
+    log_locking_state = DONT_LOCK_LOG_FILE;
+  }
+
+  // On Windows, having non canonical forward slashes in log file name causes
+  // problems with sandbox filters, see https://crbug.com/859676
+  log_path = log_path.NormalizePathSeparators();
+
+  LoggingSettings settings;
+  settings.logging_dest = logging_dest;
+  settings.log_file_path = log_path.value().c_str();
+  settings.lock_log = log_locking_state;
+  // If we're logging to an explicit file passed with --log-file, we don't want
+  // to delete the log file on our second initialization.
+  settings.delete_old =
+      process_type.empty() && (is_preinit || !HasExplicitLogFile(command_line))
+          ? DELETE_OLD_LOG_FILE
+          : APPEND_TO_OLD_LOG_FILE;
+  bool success = InitLogging(settings);
+  if (!success) {
+    PLOG(FATAL) << "Failed to init logging";
+  }
+
+  SetLogItems(true /* pid */, false, true /* timestamp */, false);
+}
+
+}  // namespace logging

+ 22 - 0
shell/common/logging.h

@@ -0,0 +1,22 @@
+// Copyright (c) 2021 Slack Technologies, Inc.
+// Use of this source code is governed by the MIT license that can be
+// found in the LICENSE file.
+
+#ifndef SHELL_COMMON_LOGGING_H_
+#define SHELL_COMMON_LOGGING_H_
+
+namespace base {
+class CommandLine;
+class FilePath;
+}  // namespace base
+
+namespace logging {
+
+void InitElectronLogging(const base::CommandLine& command_line,
+                         bool is_preinit);
+
+base::FilePath GetLogFileName(const base::CommandLine& command_line);
+
+}  // namespace logging
+
+#endif  // SHELL_COMMON_LOGGING_H_

+ 8 - 0
shell/common/node_bindings.cc

@@ -88,6 +88,8 @@
 
 #define ELECTRON_DESKTOP_CAPTURER_MODULE(V) V(electron_browser_desktop_capturer)
 
+#define ELECTRON_TESTING_MODULE(V) V(electron_common_testing)
+
 // This is used to load built-in modules. Instead of using
 // __attribute__((constructor)), we call the _register_<modname>
 // function for each built-in modules explicitly. This is only
@@ -101,6 +103,9 @@ ELECTRON_VIEWS_MODULES(V)
 #if BUILDFLAG(ENABLE_DESKTOP_CAPTURER)
 ELECTRON_DESKTOP_CAPTURER_MODULE(V)
 #endif
+#if DCHECK_IS_ON()
+ELECTRON_TESTING_MODULE(V)
+#endif
 #undef V
 
 namespace {
@@ -329,6 +334,9 @@ void NodeBindings::RegisterBuiltinModules() {
 #if BUILDFLAG(ENABLE_DESKTOP_CAPTURER)
   ELECTRON_DESKTOP_CAPTURER_MODULE(V)
 #endif
+#if DCHECK_IS_ON()
+  ELECTRON_TESTING_MODULE(V)
+#endif
 #undef V
 }
 

+ 25 - 14
spec-main/api-session-spec.ts

@@ -557,31 +557,40 @@ describe('session module', () => {
 
     it('accepts the request when the callback is called with 0', async () => {
       const ses = session.fromPartition(`${Math.random()}`);
-      ses.setCertificateVerifyProc(({ verificationResult, errorCode }, callback) => {
-        expect(['net::ERR_CERT_AUTHORITY_INVALID', 'net::ERR_CERT_COMMON_NAME_INVALID'].includes(verificationResult)).to.be.true();
-        expect([-202, -200].includes(errorCode)).to.be.true();
+      let validate: () => void;
+      ses.setCertificateVerifyProc(({ hostname, verificationResult, errorCode }, callback) => {
+        validate = () => {
+          expect(hostname).to.equal('127.0.0.1');
+          expect(verificationResult).to.be.oneOf(['net::ERR_CERT_AUTHORITY_INVALID', 'net::ERR_CERT_COMMON_NAME_INVALID']);
+          expect(errorCode).to.be.oneOf([-202, -200]);
+        };
         callback(0);
       });
 
       const w = new BrowserWindow({ show: false, webPreferences: { session: ses } });
       await w.loadURL(`https://127.0.0.1:${(server.address() as AddressInfo).port}`);
       expect(w.webContents.getTitle()).to.equal('hello');
+      expect(validate!).not.to.be.undefined();
+      validate!();
     });
 
     it('rejects the request when the callback is called with -2', async () => {
       const ses = session.fromPartition(`${Math.random()}`);
+      let validate: () => void;
       ses.setCertificateVerifyProc(({ hostname, certificate, verificationResult }, callback) => {
-        expect(hostname).to.equal('127.0.0.1');
-        expect(certificate.issuerName).to.equal('Intermediate CA');
-        expect(certificate.subjectName).to.equal('localhost');
-        expect(certificate.issuer.commonName).to.equal('Intermediate CA');
-        expect(certificate.subject.commonName).to.equal('localhost');
-        expect(certificate.issuerCert.issuer.commonName).to.equal('Root CA');
-        expect(certificate.issuerCert.subject.commonName).to.equal('Intermediate CA');
-        expect(certificate.issuerCert.issuerCert.issuer.commonName).to.equal('Root CA');
-        expect(certificate.issuerCert.issuerCert.subject.commonName).to.equal('Root CA');
-        expect(certificate.issuerCert.issuerCert.issuerCert).to.equal(undefined);
-        expect(['net::ERR_CERT_AUTHORITY_INVALID', 'net::ERR_CERT_COMMON_NAME_INVALID'].includes(verificationResult)).to.be.true();
+        validate = () => {
+          expect(hostname).to.equal('127.0.0.1');
+          expect(certificate.issuerName).to.equal('Intermediate CA');
+          expect(certificate.subjectName).to.equal('localhost');
+          expect(certificate.issuer.commonName).to.equal('Intermediate CA');
+          expect(certificate.subject.commonName).to.equal('localhost');
+          expect(certificate.issuerCert.issuer.commonName).to.equal('Root CA');
+          expect(certificate.issuerCert.subject.commonName).to.equal('Intermediate CA');
+          expect(certificate.issuerCert.issuerCert.issuer.commonName).to.equal('Root CA');
+          expect(certificate.issuerCert.issuerCert.subject.commonName).to.equal('Root CA');
+          expect(certificate.issuerCert.issuerCert.issuerCert).to.equal(undefined);
+          expect(verificationResult).to.be.oneOf(['net::ERR_CERT_AUTHORITY_INVALID', 'net::ERR_CERT_COMMON_NAME_INVALID']);
+        };
         callback(-2);
       });
 
@@ -589,6 +598,8 @@ describe('session module', () => {
       const w = new BrowserWindow({ show: false, webPreferences: { session: ses } });
       await expect(w.loadURL(url)).to.eventually.be.rejectedWith(/ERR_FAILED/);
       expect(w.webContents.getTitle()).to.equal(url);
+      expect(validate!).not.to.be.undefined();
+      validate!();
     });
 
     it('saves cached results', async () => {

+ 5 - 0
spec-main/fixtures/apps/remote-control/main.js

@@ -2,6 +2,11 @@ const { app } = require('electron');
 const http = require('http');
 const v8 = require('v8');
 
+if (app.commandLine.hasSwitch('boot-eval')) {
+  // eslint-disable-next-line no-eval
+  eval(app.commandLine.getSwitchValue('boot-eval'));
+}
+
 app.whenReady().then(() => {
   const server = http.createServer((req, res) => {
     const chunks = [];

+ 183 - 0
spec-main/logging-spec.ts

@@ -0,0 +1,183 @@
+import { app } from 'electron';
+import { expect } from 'chai';
+import { emittedOnce } from './events-helpers';
+import { startRemoteControlApp, ifdescribe } from './spec-helpers';
+
+import * as fs from 'fs/promises';
+import * as path from 'path';
+import * as uuid from 'uuid';
+
+// This test depends on functions that are only available when DCHECK_IS_ON.
+ifdescribe(process._linkedBinding('electron_common_testing'))('logging', () => {
+  it('does not log by default', async () => {
+    // ELECTRON_ENABLE_LOGGING is turned on in the appveyor config.
+    const { ELECTRON_ENABLE_LOGGING: _, ...envWithoutEnableLogging } = process.env;
+    const rc = await startRemoteControlApp([], { env: envWithoutEnableLogging });
+    const stderrComplete = new Promise<string>(resolve => {
+      let stderr = '';
+      rc.process.stderr!.on('data', function listener (chunk) {
+        stderr += chunk.toString('utf8');
+      });
+      rc.process.on('close', () => { resolve(stderr); });
+    });
+    const [hasLoggingSwitch, hasLoggingVar] = await rc.remotely(() => {
+      // Make sure we're actually capturing stderr by logging a known value to
+      // stderr.
+      console.error('SENTINEL');
+      process._linkedBinding('electron_common_testing').log(0, 'TEST_LOG');
+      setTimeout(() => { process.exit(0); });
+      return [require('electron').app.commandLine.hasSwitch('enable-logging'), !!process.env.ELECTRON_ENABLE_LOGGING];
+    });
+    expect(hasLoggingSwitch).to.be.false();
+    expect(hasLoggingVar).to.be.false();
+    const stderr = await stderrComplete;
+    // stderr should include the sentinel but not the LOG() message.
+    expect(stderr).to.match(/SENTINEL/);
+    expect(stderr).not.to.match(/TEST_LOG/);
+  });
+
+  it('logs to stderr when --enable-logging is passed', async () => {
+    const rc = await startRemoteControlApp(['--enable-logging']);
+    const stderrComplete = new Promise<string>(resolve => {
+      let stderr = '';
+      rc.process.stderr!.on('data', function listener (chunk) {
+        stderr += chunk.toString('utf8');
+      });
+      rc.process.on('close', () => { resolve(stderr); });
+    });
+    rc.remotely(() => {
+      process._linkedBinding('electron_common_testing').log(0, 'TEST_LOG');
+      setTimeout(() => { require('electron').app.quit(); });
+    });
+    const stderr = await stderrComplete;
+    expect(stderr).to.match(/TEST_LOG/);
+  });
+
+  it('logs to stderr when ELECTRON_ENABLE_LOGGING is set', async () => {
+    const rc = await startRemoteControlApp([], { env: { ...process.env, ELECTRON_ENABLE_LOGGING: '1' } });
+    const stderrComplete = new Promise<string>(resolve => {
+      let stderr = '';
+      rc.process.stderr!.on('data', function listener (chunk) {
+        stderr += chunk.toString('utf8');
+      });
+      rc.process.on('close', () => { resolve(stderr); });
+    });
+    rc.remotely(() => {
+      process._linkedBinding('electron_common_testing').log(0, 'TEST_LOG');
+      setTimeout(() => { require('electron').app.quit(); });
+    });
+    const stderr = await stderrComplete;
+    expect(stderr).to.match(/TEST_LOG/);
+  });
+
+  it('logs to a file in the user data dir when --enable-logging=file is passed', async () => {
+    const rc = await startRemoteControlApp(['--enable-logging=file']);
+    const userDataDir = await rc.remotely(() => {
+      const { app } = require('electron');
+      process._linkedBinding('electron_common_testing').log(0, 'TEST_LOG');
+      setTimeout(() => { app.quit(); });
+      return app.getPath('userData');
+    });
+    await emittedOnce(rc.process, 'exit');
+    const logFilePath = path.join(userDataDir, 'electron_debug.log');
+    const stat = await fs.stat(logFilePath);
+    expect(stat.isFile()).to.be.true();
+    const contents = await fs.readFile(logFilePath, 'utf8');
+    expect(contents).to.match(/TEST_LOG/);
+  });
+
+  it('logs to a file in the user data dir when ELECTRON_ENABLE_LOGGING=file is set', async () => {
+    const rc = await startRemoteControlApp([], { env: { ...process.env, ELECTRON_ENABLE_LOGGING: 'file' } });
+    const userDataDir = await rc.remotely(() => {
+      const { app } = require('electron');
+      process._linkedBinding('electron_common_testing').log(0, 'TEST_LOG');
+      setTimeout(() => { app.quit(); });
+      return app.getPath('userData');
+    });
+    await emittedOnce(rc.process, 'exit');
+    const logFilePath = path.join(userDataDir, 'electron_debug.log');
+    const stat = await fs.stat(logFilePath);
+    expect(stat.isFile()).to.be.true();
+    const contents = await fs.readFile(logFilePath, 'utf8');
+    expect(contents).to.match(/TEST_LOG/);
+  });
+
+  it('logs to the given file when --log-file is passed', async () => {
+    const logFilePath = path.join(app.getPath('temp'), 'test-log-file-' + uuid.v4());
+    const rc = await startRemoteControlApp(['--enable-logging', '--log-file=' + logFilePath]);
+    rc.remotely(() => {
+      process._linkedBinding('electron_common_testing').log(0, 'TEST_LOG');
+      setTimeout(() => { require('electron').app.quit(); });
+    });
+    await emittedOnce(rc.process, 'exit');
+    const stat = await fs.stat(logFilePath);
+    expect(stat.isFile()).to.be.true();
+    const contents = await fs.readFile(logFilePath, 'utf8');
+    expect(contents).to.match(/TEST_LOG/);
+  });
+
+  it('logs to the given file when ELECTRON_LOG_FILE is set', async () => {
+    const logFilePath = path.join(app.getPath('temp'), 'test-log-file-' + uuid.v4());
+    const rc = await startRemoteControlApp([], { env: { ...process.env, ELECTRON_ENABLE_LOGGING: '1', ELECTRON_LOG_FILE: logFilePath } });
+    rc.remotely(() => {
+      process._linkedBinding('electron_common_testing').log(0, 'TEST_LOG');
+      setTimeout(() => { require('electron').app.quit(); });
+    });
+    await emittedOnce(rc.process, 'exit');
+    const stat = await fs.stat(logFilePath);
+    expect(stat.isFile()).to.be.true();
+    const contents = await fs.readFile(logFilePath, 'utf8');
+    expect(contents).to.match(/TEST_LOG/);
+  });
+
+  it('does not lose early log messages when logging to a given file with --log-file', async () => {
+    const logFilePath = path.join(app.getPath('temp'), 'test-log-file-' + uuid.v4());
+    const rc = await startRemoteControlApp(['--enable-logging', '--log-file=' + logFilePath, '--boot-eval=process._linkedBinding(\'electron_common_testing\').log(0, \'EARLY_LOG\')']);
+    rc.remotely(() => {
+      process._linkedBinding('electron_common_testing').log(0, 'LATER_LOG');
+      setTimeout(() => { require('electron').app.quit(); });
+    });
+    await emittedOnce(rc.process, 'exit');
+    const stat = await fs.stat(logFilePath);
+    expect(stat.isFile()).to.be.true();
+    const contents = await fs.readFile(logFilePath, 'utf8');
+    expect(contents).to.match(/EARLY_LOG/);
+    expect(contents).to.match(/LATER_LOG/);
+  });
+
+  it('enables logging when switch is appended during first tick', async () => {
+    const rc = await startRemoteControlApp(['--boot-eval=require(\'electron\').app.commandLine.appendSwitch(\'--enable-logging\')']);
+    const stderrComplete = new Promise<string>(resolve => {
+      let stderr = '';
+      rc.process.stderr!.on('data', function listener (chunk) {
+        stderr += chunk.toString('utf8');
+      });
+      rc.process.on('close', () => { resolve(stderr); });
+    });
+    rc.remotely(() => {
+      process._linkedBinding('electron_common_testing').log(0, 'TEST_LOG');
+      setTimeout(() => { require('electron').app.quit(); });
+    });
+    const stderr = await stderrComplete;
+    expect(stderr).to.match(/TEST_LOG/);
+  });
+
+  it('respects --log-level', async () => {
+    const rc = await startRemoteControlApp(['--enable-logging', '--log-level=1']);
+    const stderrComplete = new Promise<string>(resolve => {
+      let stderr = '';
+      rc.process.stderr!.on('data', function listener (chunk) {
+        stderr += chunk.toString('utf8');
+      });
+      rc.process.on('close', () => { resolve(stderr); });
+    });
+    rc.remotely(() => {
+      process._linkedBinding('electron_common_testing').log(0, 'TEST_INFO_LOG');
+      process._linkedBinding('electron_common_testing').log(1, 'TEST_WARNING_LOG');
+      setTimeout(() => { require('electron').app.quit(); });
+    });
+    const stderr = await stderrComplete;
+    expect(stderr).to.match(/TEST_WARNING_LOG/);
+    expect(stderr).not.to.match(/TEST_INFO_LOG/);
+  });
+});

+ 2 - 2
spec-main/spec-helpers.ts

@@ -69,9 +69,9 @@ class RemoteControlApp {
   }
 }
 
-export async function startRemoteControlApp () {
+export async function startRemoteControlApp (extraArgs: string[] = [], options?: childProcess.SpawnOptionsWithoutStdio) {
   const appPath = path.join(__dirname, 'fixtures', 'apps', 'remote-control');
-  const appProcess = childProcess.spawn(process.execPath, [appPath]);
+  const appProcess = childProcess.spawn(process.execPath, [appPath, ...extraArgs], options);
   appProcess.stderr.on('data', d => {
     process.stderr.write(d);
   });