| // Copyright (c) 2012 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 "chrome/test/chromedriver/logging.h" |
| |
| #include <stddef.h> |
| #include <stdint.h> |
| #include <stdio.h> |
| |
| #include <memory> |
| #include <utility> |
| |
| #include "base/command_line.h" |
| #include "base/json/json_reader.h" |
| #include "base/logging.h" |
| #include "base/stl_util.h" |
| #include "base/strings/stringprintf.h" |
| #include "base/time/time.h" |
| #include "build/build_config.h" |
| #include "chrome/test/chromedriver/capabilities.h" |
| #include "chrome/test/chromedriver/chrome/console_logger.h" |
| #include "chrome/test/chromedriver/chrome/status.h" |
| #include "chrome/test/chromedriver/command_listener_proxy.h" |
| #include "chrome/test/chromedriver/devtools_events_logger.h" |
| #include "chrome/test/chromedriver/performance_logger.h" |
| #include "chrome/test/chromedriver/session.h" |
| #include "chrome/test/chromedriver/version.h" |
| |
| #if defined(OS_POSIX) |
| #include <fcntl.h> |
| #include <unistd.h> |
| #endif |
| |
| |
| namespace { |
| |
| Log::Level g_log_level = Log::kWarning; |
| |
| int64_t g_start_time = 0; |
| |
| bool readable_timestamp; |
| |
| // Array indices are the Log::Level enum values. |
| const char* const kLevelToName[] = { |
| "ALL", // kAll |
| "DEBUG", // kDebug |
| "INFO", // kInfo |
| "WARNING", // kWarning |
| "SEVERE", // kError |
| "OFF", // kOff |
| }; |
| |
| const char* LevelToName(Log::Level level) { |
| const int index = level - Log::kAll; |
| CHECK_GE(index, 0); |
| CHECK_LT(static_cast<size_t>(index), base::size(kLevelToName)); |
| return kLevelToName[index]; |
| } |
| |
| struct LevelPair { |
| const char* name; |
| Log::Level level; |
| }; |
| |
| const LevelPair kNameToLevel[] = { |
| {"ALL", Log::kAll}, |
| {"DEBUG", Log::kDebug}, |
| {"INFO", Log::kInfo}, |
| {"WARNING", Log::kWarning}, |
| {"SEVERE", Log::kError}, |
| {"OFF", Log::kOff}, |
| }; |
| |
| Log::Level GetLevelFromSeverity(int severity) { |
| switch (severity) { |
| case logging::LOG_FATAL: |
| case logging::LOG_ERROR: |
| return Log::kError; |
| case logging::LOG_WARNING: |
| return Log::kWarning; |
| case logging::LOG_INFO: |
| return Log::kInfo; |
| case logging::LOG_VERBOSE: |
| default: |
| return Log::kDebug; |
| } |
| } |
| |
| WebDriverLog* GetSessionLog() { |
| Session* session = GetThreadLocalSession(); |
| if (!session) |
| return NULL; |
| return session->driver_log.get(); |
| } |
| |
| bool InternalIsVLogOn(int vlog_level) { |
| WebDriverLog* session_log = GetSessionLog(); |
| Log::Level session_level = session_log ? session_log->min_level() : Log::kOff; |
| Log::Level level = g_log_level < session_level ? g_log_level : session_level; |
| return GetLevelFromSeverity(vlog_level * -1) >= level; |
| } |
| |
| bool HandleLogMessage(int severity, |
| const char* file, |
| int line, |
| size_t message_start, |
| const std::string& str) { |
| Log::Level level = GetLevelFromSeverity(severity); |
| std::string message = str.substr(message_start); |
| |
| if (level >= g_log_level) { |
| const char* level_name = LevelToName(level); |
| std::string entry; |
| |
| if (readable_timestamp) { |
| #if defined(OS_WIN) |
| SYSTEMTIME local_time; |
| GetLocalTime(&local_time); |
| |
| entry = base::StringPrintf( |
| "[%02d-%02d-%04d %02d:%02d:%02d.%03d][%s]: %s", |
| local_time.wMonth, local_time.wDay, local_time.wYear, |
| local_time.wHour, local_time.wMinute, local_time.wSecond, |
| local_time.wMilliseconds, |
| level_name, |
| message.c_str()); |
| #elif defined(OS_POSIX) || defined(OS_FUCHSIA) |
| timeval tv; |
| gettimeofday(&tv, nullptr); |
| time_t t = tv.tv_sec; |
| struct tm local_time; |
| localtime_r(&t, &local_time); |
| struct tm* tm_time = &local_time; |
| |
| entry = base::StringPrintf( |
| "[%02d-%02d-%04d %02d:%02d:%02d.%06ld][%s]: %s", |
| 1 + tm_time->tm_mon, tm_time->tm_mday, 1900 + tm_time->tm_year, |
| tm_time->tm_hour, tm_time->tm_min, tm_time->tm_sec, |
| static_cast<long>(tv.tv_usec), |
| level_name, |
| message.c_str()); |
| #else |
| #error Unsupported platform |
| #endif |
| } else { |
| entry = base::StringPrintf( |
| "[%.3lf][%s]: %s", |
| base::TimeDelta(base::TimeTicks::Now() - |
| base::TimeTicks::UnixEpoch()) |
| .InSecondsF(), |
| level_name, |
| message.c_str()); |
| } |
| fprintf(stderr, "%s", entry.c_str()); |
| fflush(stderr); |
| } |
| |
| WebDriverLog* session_log = GetSessionLog(); |
| if (session_log) |
| session_log->AddEntry(level, message); |
| |
| return true; |
| } |
| |
| } // namespace |
| |
| const char WebDriverLog::kBrowserType[] = "browser"; |
| const char WebDriverLog::kDriverType[] = "driver"; |
| const char WebDriverLog::kPerformanceType[] = "performance"; |
| const char WebDriverLog::kDevToolsType[] = "devtools"; |
| |
| bool WebDriverLog::NameToLevel(const std::string& name, Log::Level* out_level) { |
| for (size_t i = 0; i < base::size(kNameToLevel); ++i) { |
| if (name == kNameToLevel[i].name) { |
| *out_level = kNameToLevel[i].level; |
| return true; |
| } |
| } |
| return false; |
| } |
| |
| WebDriverLog::WebDriverLog(const std::string& type, Log::Level min_level) |
| : type_(type), min_level_(min_level), emptied_(true) {} |
| |
| WebDriverLog::~WebDriverLog() { |
| size_t sum = 0; |
| for (const std::unique_ptr<base::ListValue>& batch : batches_of_entries_) |
| sum += batch->GetSize(); |
| VLOG(1) << "Log type '" << type_ << "' lost " << sum |
| << " entries on destruction"; |
| } |
| |
| std::unique_ptr<base::ListValue> WebDriverLog::GetAndClearEntries() { |
| std::unique_ptr<base::ListValue> ret; |
| if (batches_of_entries_.empty()) { |
| ret.reset(new base::ListValue()); |
| emptied_ = true; |
| } else { |
| ret = std::move(batches_of_entries_.front()); |
| batches_of_entries_.pop_front(); |
| emptied_ = false; |
| } |
| return ret; |
| } |
| |
| bool GetFirstErrorMessageFromList(const base::ListValue* list, |
| std::string* message) { |
| for (auto it = list->begin(); it != list->end(); ++it) { |
| const base::DictionaryValue* log_entry = NULL; |
| it->GetAsDictionary(&log_entry); |
| if (log_entry != NULL) { |
| std::string level; |
| if (log_entry->GetString("level", &level)) |
| if (level == kLevelToName[Log::kError]) |
| if (log_entry->GetString("message", message)) |
| return true; |
| } |
| } |
| return false; |
| } |
| |
| std::string WebDriverLog::GetFirstErrorMessage() const { |
| std::string message; |
| for (const std::unique_ptr<base::ListValue>& list : batches_of_entries_) |
| if (GetFirstErrorMessageFromList(list.get(), &message)) |
| break; |
| return message; |
| } |
| |
| void WebDriverLog::AddEntryTimestamped(const base::Time& timestamp, |
| Log::Level level, |
| const std::string& source, |
| const std::string& message) { |
| if (level < min_level_) |
| return; |
| |
| std::unique_ptr<base::DictionaryValue> log_entry_dict( |
| new base::DictionaryValue()); |
| log_entry_dict->SetDouble("timestamp", |
| static_cast<int64_t>(timestamp.ToJsTime())); |
| log_entry_dict->SetString("level", LevelToName(level)); |
| if (!source.empty()) |
| log_entry_dict->SetString("source", source); |
| log_entry_dict->SetString("message", message); |
| if (batches_of_entries_.empty() || |
| batches_of_entries_.back()->GetSize() >= internal::kMaxReturnedEntries) { |
| std::unique_ptr<base::ListValue> list(new base::ListValue()); |
| list->Append(std::move(log_entry_dict)); |
| batches_of_entries_.push_back(std::move(list)); |
| } else { |
| batches_of_entries_.back()->Append(std::move(log_entry_dict)); |
| } |
| } |
| |
| bool WebDriverLog::Emptied() const { |
| return emptied_; |
| } |
| |
| const std::string& WebDriverLog::type() const { |
| return type_; |
| } |
| |
| void WebDriverLog::set_min_level(Level min_level) { |
| min_level_ = min_level; |
| } |
| |
| Log::Level WebDriverLog::min_level() const { |
| return min_level_; |
| } |
| |
| bool InitLogging() { |
| g_start_time = base::TimeTicks::Now().ToInternalValue(); |
| base::CommandLine* cmd_line = base::CommandLine::ForCurrentProcess(); |
| |
| if (cmd_line->HasSwitch("log-path")) { |
| g_log_level = Log::kInfo; |
| base::FilePath log_path = cmd_line->GetSwitchValuePath("log-path"); |
| |
| const base::FilePath::CharType* logMode = FILE_PATH_LITERAL("w"); |
| if (cmd_line->HasSwitch("append-log")) { |
| logMode = FILE_PATH_LITERAL("a"); |
| } |
| if (cmd_line->HasSwitch("readable-timestamp")) { |
| readable_timestamp = true; |
| } |
| #if defined(OS_WIN) |
| FILE* redir_stderr = _wfreopen(log_path.value().c_str(), logMode, stderr); |
| #else |
| FILE* redir_stderr = freopen(log_path.value().c_str(), logMode, stderr); |
| #endif |
| if (!redir_stderr) { |
| printf("Failed to redirect stderr to log file.\n"); |
| return false; |
| } |
| } |
| |
| Log::truncate_logged_params = !cmd_line->HasSwitch("replayable"); |
| Log::is_vlog_on_func = &InternalIsVLogOn; |
| |
| int num_level_switches = 0; |
| |
| if (cmd_line->HasSwitch("silent")) { |
| g_log_level = Log::kOff; |
| num_level_switches++; |
| } |
| |
| if (cmd_line->HasSwitch("verbose")) { |
| g_log_level = Log::kAll; |
| num_level_switches++; |
| } |
| |
| if (cmd_line->HasSwitch("log-level")) { |
| if (!WebDriverLog::NameToLevel(cmd_line->GetSwitchValueASCII("log-level"), |
| &g_log_level)) { |
| printf("Invalid --log-level value.\n"); |
| return false; |
| } |
| num_level_switches++; |
| } |
| |
| if (num_level_switches > 1) { |
| printf("Only one of --log-level, --verbose, or --silent is allowed.\n"); |
| return false; |
| } |
| |
| // Turn on VLOG for chromedriver. This is parsed during logging::InitLogging. |
| if (!cmd_line->HasSwitch("vmodule")) |
| cmd_line->AppendSwitchASCII("vmodule", "*/chrome/test/chromedriver/*=3"); |
| |
| logging::SetMinLogLevel(logging::LOG_WARNING); |
| logging::SetLogItems(false, // enable_process_id |
| false, // enable_thread_id |
| false, // enable_timestamp |
| false); // enable_tickcount |
| logging::SetLogMessageHandler(&HandleLogMessage); |
| |
| logging::LoggingSettings logging_settings; |
| logging_settings.logging_dest = |
| logging::LOG_TO_SYSTEM_DEBUG_LOG | logging::LOG_TO_STDERR; |
| bool res = logging::InitLogging(logging_settings); |
| if (cmd_line->HasSwitch("log-path") && res) { |
| VLOG(0) << "Starting ChromeDriver " << kChromeDriverVersion; |
| VLOG(0) << kPortProtectionMessage; |
| } |
| return res; |
| } |
| |
| Status CreateLogs( |
| const Capabilities& capabilities, |
| const Session* session, |
| std::vector<std::unique_ptr<WebDriverLog>>* out_logs, |
| std::vector<std::unique_ptr<DevToolsEventListener>>* out_devtools_listeners, |
| std::vector<std::unique_ptr<CommandListener>>* out_command_listeners) { |
| std::vector<std::unique_ptr<WebDriverLog>> logs; |
| std::vector<std::unique_ptr<DevToolsEventListener>> devtools_listeners; |
| std::vector<std::unique_ptr<CommandListener>> command_listeners; |
| Log::Level browser_log_level = Log::kWarning; |
| const LoggingPrefs& prefs = capabilities.logging_prefs; |
| |
| for (auto iter = prefs.begin(); iter != prefs.end(); ++iter) { |
| std::string type = iter->first; |
| Log::Level level = iter->second; |
| if (type == WebDriverLog::kPerformanceType) { |
| if (level != Log::kOff) { |
| logs.push_back(std::make_unique<WebDriverLog>(type, Log::kAll)); |
| devtools_listeners.push_back(std::make_unique<PerformanceLogger>( |
| logs.back().get(), session, capabilities.perf_logging_prefs)); |
| PerformanceLogger* perf_log = |
| static_cast<PerformanceLogger*>(devtools_listeners.back().get()); |
| // We use a proxy for |perf_log|'s |CommandListener| interface. |
| // Otherwise, |perf_log| would be owned by both session->chrome and |
| // |session|, which would lead to memory errors on destruction. |
| // session->chrome will own |perf_log|, and |session| will own |proxy|. |
| // session->command_listeners (the proxy) will be destroyed first. |
| command_listeners.push_back( |
| std::make_unique<CommandListenerProxy>(perf_log)); |
| } |
| } else if (type == WebDriverLog::kDevToolsType) { |
| logs.push_back(std::make_unique<WebDriverLog>(type, Log::kAll)); |
| devtools_listeners.push_back( |
| std::make_unique<DevToolsEventsLogger>( |
| logs.back().get(), |
| capabilities.devtools_events_logging_prefs.get())); |
| } else if (type == WebDriverLog::kBrowserType) { |
| browser_log_level = level; |
| } else if (type != WebDriverLog::kDriverType) { |
| // Driver "should" ignore unrecognized log types, per Selenium tests. |
| // For example the Java client passes the "client" log type in the caps, |
| // which the server should never provide. |
| LOG(WARNING) << "Ignoring unrecognized log type: " << type; |
| } |
| } |
| // Create "browser" log -- should always exist. |
| logs.push_back(std::make_unique<WebDriverLog>(WebDriverLog::kBrowserType, |
| browser_log_level)); |
| // If the level is OFF, don't even bother listening for DevTools events. |
| if (browser_log_level != Log::kOff) |
| devtools_listeners.push_back( |
| std::make_unique<ConsoleLogger>(logs.back().get())); |
| |
| out_logs->swap(logs); |
| out_devtools_listeners->swap(devtools_listeners); |
| out_command_listeners->swap(command_listeners); |
| return Status(kOk); |
| } |