From 8ccab4ce91b74252b7c83c1e4ae2969ed06ae2f8 Mon Sep 17 00:00:00 2001 From: Charles Kerr Date: Thu, 17 Jun 2021 16:17:25 -0500 Subject: [PATCH] feat: bring --enable-logging functionality in line with Chromium (#25089) Co-authored-by: Jeremy Rose --- docs/api/command-line-switches.md | 54 +++++- docs/api/environment-variables.md | 17 +- docs/tutorial/application-debugging.md | 2 +- filenames.gni | 3 + shell/app/electron_main_delegate.cc | 57 +++--- shell/app/electron_main_delegate.h | 1 + shell/browser/electron_browser_client.cc | 15 ++ shell/browser/electron_browser_client.h | 1 + shell/browser/electron_browser_context.cc | 1 + shell/browser/electron_browser_main_parts.cc | 6 + shell/common/api/electron_api_testing.cc | 48 +++++ shell/common/logging.cc | 141 ++++++++++++++ shell/common/logging.h | 22 +++ shell/common/node_bindings.cc | 8 + spec-main/api-session-spec.ts | 39 ++-- .../fixtures/apps/remote-control/main.js | 5 + spec-main/logging-spec.ts | 183 ++++++++++++++++++ spec-main/spec-helpers.ts | 4 +- 18 files changed, 553 insertions(+), 54 deletions(-) create mode 100644 shell/common/api/electron_api_testing.cc create mode 100644 shell/common/logging.cc create mode 100644 shell/common/logging.h create mode 100644 spec-main/logging-spec.ts diff --git a/docs/api/command-line-switches.md b/docs/api/command-line-switches.md index b125f128c63..353abf12e0c 100644 --- a/docs/api/command-line-switches.md +++ b/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 diff --git a/docs/api/environment-variables.md b/docs/api/environment-variables.md index aa0111c87a2..cf3adfc846b 100644 --- a/docs/api/environment-variables.md +++ b/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: diff --git a/docs/tutorial/application-debugging.md b/docs/tutorial/application-debugging.md index c9619e37779..a89b0ea4b07 100644 --- a/docs/tutorial/application-debugging.md +++ b/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). diff --git a/filenames.gni b/filenames.gni index 90da20719ff..ce70e310412 100644 --- a/filenames.gni +++ b/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", diff --git a/shell/app/electron_main_delegate.cc b/shell/app/electron_main_delegate.cc index cd243b59f2e..e65333bc65f 100644 --- a/shell/app/electron_main_delegate.cc +++ b/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 diff --git a/shell/app/electron_main_delegate.h b/shell/app/electron_main_delegate.h index c0e1e4d9b38..ce75b0abd0f 100644 --- a/shell/app/electron_main_delegate.h +++ b/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; diff --git a/shell/browser/electron_browser_client.cc b/shell/browser/electron_browser_client.cc index a66747ce292..42399914dd7 100644 --- a/shell/browser/electron_browser_client.cc +++ b/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) diff --git a/shell/browser/electron_browser_client.h b/shell/browser/electron_browser_client.h index 6e4c8c8db40..682ed5630e3 100644 --- a/shell/browser/electron_browser_client.h +++ b/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& top_frame_origin) override; + base::FilePath GetLoggingFileName(const base::CommandLine& cmd_line) override; // content::RenderProcessHostObserver: void RenderProcessHostDestroyed(content::RenderProcessHost* host) override; diff --git a/shell/browser/electron_browser_context.cc b/shell/browser/electron_browser_context.cc index da6254a6db2..47af4b70f1e 100644 --- a/shell/browser/electron_browser_context.cc +++ b/shell/browser/electron_browser_context.cc @@ -9,6 +9,7 @@ #include #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" diff --git a/shell/browser/electron_browser_main_parts.cc b/shell/browser/electron_browser_main_parts.cc index fa2ede47634..8b4cc4cdac9 100644 --- a/shell/browser/electron_browser_main_parts.cc +++ b/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(); } diff --git a/shell/common/api/electron_api_testing.cc b/shell/common/api/electron_api_testing.cc new file mode 100644 index 00000000000..818ca4f9702 --- /dev/null +++ b/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 exports, + v8::Local unused, + v8::Local 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 diff --git a/shell/common/logging.cc b/shell/common/logging.cc new file mode 100644 index 00000000000..d69c4a77feb --- /dev/null +++ b/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 + +#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 diff --git a/shell/common/logging.h b/shell/common/logging.h new file mode 100644 index 00000000000..d7b9e209710 --- /dev/null +++ b/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_ diff --git a/shell/common/node_bindings.cc b/shell/common/node_bindings.cc index a0ea8bae645..a1e46fd9a3e 100644 --- a/shell/common/node_bindings.cc +++ b/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_ // 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 } diff --git a/spec-main/api-session-spec.ts b/spec-main/api-session-spec.ts index 9ffce8e1946..746121164f3 100644 --- a/spec-main/api-session-spec.ts +++ b/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 () => { diff --git a/spec-main/fixtures/apps/remote-control/main.js b/spec-main/fixtures/apps/remote-control/main.js index 05d7e609a5f..b8d89ff7248 100644 --- a/spec-main/fixtures/apps/remote-control/main.js +++ b/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 = []; diff --git a/spec-main/logging-spec.ts b/spec-main/logging-spec.ts new file mode 100644 index 00000000000..b3414279761 --- /dev/null +++ b/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(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(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(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(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(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/); + }); +}); diff --git a/spec-main/spec-helpers.ts b/spec-main/spec-helpers.ts index 6bcf0949066..c644f402b53 100644 --- a/spec-main/spec-helpers.ts +++ b/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); });