blob: 21393d4f2d12bef89d3eda907a3829e49ff04b7d [file] [log] [blame]
// 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);
}