Commit 4ab22cfc authored by kkania@chromium.org's avatar kkania@chromium.org

In chromedriver, add /log url to get the contents of the chromedriver log

remotely. Also add a 'chrome.verbose' boolean startup option.
Remove usage of VLOG(1) in chromedriver. We do not need as complicated
logging as in Chrome.
BUG=85241
TEST=none

Review URL: http://codereview.chromium.org/7104085

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@88591 0039d316-1c4b-4281-b951-d872f2087c98
parent 60ad0231
......@@ -847,6 +847,8 @@
'test/webdriver/utility_functions.cc',
'test/webdriver/webdriver_error.h',
'test/webdriver/webdriver_error.cc',
'test/webdriver/webdriver_logging.h',
'test/webdriver/webdriver_logging.cc',
'test/webdriver/webdriver_key_converter.h',
'test/webdriver/webdriver_key_converter.cc',
'test/webdriver/web_element_id.h',
......
......@@ -26,44 +26,30 @@ bool SendAutomationJSONRequest(AutomationMessageSender* sender,
std::string* error_msg) {
std::string request, reply;
base::JSONWriter::Write(&request_dict, false, &request);
bool success = false;
int timeout_ms = TestTimeouts::action_max_timeout_ms();
std::string command;
request_dict.GetString("command", &command);
LOG(INFO) << "Sending '" << command << "' command.";
base::Time before_sending = base::Time::Now();
if (!SendAutomationJSONRequest(
sender, request, timeout_ms, &reply, &success)) {
int64 elapsed_ms = (base::Time::Now() - before_sending).InMilliseconds();
std::string command;
request_dict.GetString("command", &command);
if (elapsed_ms >= timeout_ms) {
*error_msg = base::StringPrintf(
"Chrome did not respond to '%s'. Request may have timed out. "
"Elapsed time was %" PRId64 " ms. Request timeout was %d ms. "
"Request details: (%s).",
command.c_str(),
elapsed_ms,
timeout_ms,
request.c_str());
} else {
*error_msg = base::StringPrintf(
"Chrome did not respond to '%s'. Elapsed time was %" PRId64 " ms. "
"Request details: (%s).",
command.c_str(),
elapsed_ms,
request.c_str());
}
bool success = false;
if (!SendAutomationJSONRequestWithDefaultTimeout(
sender, request, &reply, &success)) {
*error_msg = base::StringPrintf(
"Chrome did not respond to '%s'. Elapsed time was %" PRId64 " ms. "
"Request details: (%s).",
command.c_str(),
(base::Time::Now() - before_sending).InMilliseconds(),
request.c_str());
return false;
}
scoped_ptr<Value> value(base::JSONReader::Read(reply, true));
if (!value.get() || !value->IsType(Value::TYPE_DICTIONARY)) {
std::string command;
request_dict.GetString("command", &command);
LOG(ERROR) << "JSON request did not return dict: " << command << "\n";
return false;
}
DictionaryValue* dict = static_cast<DictionaryValue*>(value.get());
if (!success) {
std::string command, error;
request_dict.GetString("command", &command);
std::string error;
dict->GetString("error", &error);
*error_msg = base::StringPrintf(
"Internal Chrome error during '%s': (%s). Request details: (%s).",
......@@ -100,6 +86,15 @@ bool SendAutomationJSONRequest(AutomationMessageSender* sender,
-1, request, reply, success), timeout_ms);
}
bool SendAutomationJSONRequestWithDefaultTimeout(
AutomationMessageSender* sender,
const std::string& request,
std::string* reply,
bool* success) {
return sender->Send(new AutomationMsg_SendJSONRequest(
-1, request, reply, success));
}
bool SendGetIndicesFromTabIdJSONRequest(
AutomationMessageSender* sender,
int tab_id,
......
......@@ -44,6 +44,14 @@ bool SendAutomationJSONRequest(AutomationMessageSender* sender,
std::string* reply,
bool* success) WARN_UNUSED_RESULT;
// Same as above, but uses the given |AutomationMessageSender|'s default timeout
// value.
bool SendAutomationJSONRequestWithDefaultTimeout(
AutomationMessageSender* sender,
const std::string& request,
std::string* reply,
bool* success);
// Requests the current browser and tab indices for the given tab ID.
// Returns true on success.
bool SendGetIndicesFromTabIdJSONRequest(
......
......@@ -170,7 +170,7 @@ void Automation::InitWithBrowserPath(const FilePath& browser_exe,
std::string chrome_details = base::StringPrintf(
"Using Chrome binary at: %" PRFilePath,
browser_exe.value().c_str());
VLOG(1) << chrome_details;
LOG(INFO) << chrome_details;
if (!launcher_->LaunchBrowserAndServer(launch_props, true)) {
*error = new Error(
......@@ -181,8 +181,8 @@ void Automation::InitWithBrowserPath(const FilePath& browser_exe,
}
launcher_->automation()->set_action_timeout_ms(base::kNoTimeout);
VLOG(1) << "Chrome launched successfully. Version: "
<< automation()->server_version();
LOG(INFO) << "Chrome launched successfully. Version: "
<< automation()->server_version();
bool has_automation_version = false;
*error = CompareVersion(730, 0, &has_automation_version);
......
......@@ -503,6 +503,31 @@ class ElementEqualityTest(unittest.TestCase):
self.assertTrue(result['value'])
class LoggingTest(unittest.TestCase):
def setUp(self):
self._launcher = ChromeDriverLauncher(root_path=os.path.dirname(__file__))
def tearDown(self):
self._launcher.Kill()
def testNoVerboseLogging(self):
self._driver = WebDriver(self._launcher.GetURL(), {})
self._driver.execute_script('console.log("HI")')
request_url = self._launcher.GetURL() + '/log'
req = SendRequest(request_url, method='GET')
log = req.read()
self.assertTrue(':INFO:' not in log, ':INFO: in log: ' + log)
def testVerboseLogging(self):
self._driver = WebDriver(self._launcher.GetURL(), {'chrome.verbose': True})
self._driver.execute_script('console.log("HI")')
request_url = self._launcher.GetURL() + '/log'
req = SendRequest(request_url, method='GET')
log = req.read()
self.assertTrue(':INFO:' in log, ':INFO: not in log: ' + log)
"""Chrome functional test section. All implementation tests of ChromeDriver
should go above.
......
......@@ -9,6 +9,7 @@
#include "base/command_line.h"
#include "base/file_path.h"
#include "base/logging.h"
#include "base/stringprintf.h"
#include "base/values.h"
#include "chrome/app/chrome_command_ids.h"
......@@ -68,6 +69,20 @@ void CreateSession::ExecutePost(Response* const response) {
kBadRequest, "Custom switches must be a list"));
return;
}
Value* verbose_value;
if (capabilities->GetWithoutPathExpansion("chrome.verbose", &verbose_value)) {
bool verbose;
if (verbose_value->GetAsBoolean(&verbose) && verbose) {
// Since logging is shared among sessions, if any session requests verbose
// logging, verbose logging will be enabled for all sessions. It is not
// possible to turn it off.
logging::SetMinLogLevel(logging::LOG_INFO);
} else {
response->SetError(new Error(
kBadRequest, "verbose must be a boolean true or false"));
return;
}
}
FilePath browser_exe;
FilePath::StringType path;
......@@ -96,7 +111,7 @@ void CreateSession::ExecutePost(Response* const response) {
session->set_screenshot_on_error(screenshot_on_error);
}
VLOG(1) << "Created session " << session->id();
LOG(INFO) << "Created session " << session->id();
std::ostringstream stream;
SessionManager* session_manager = SessionManager::GetInstance();
stream << "http://" << session_manager->GetAddress() << "/session/"
......
......@@ -34,7 +34,6 @@ bool WebDriverCommand::Init(Response* const response) {
return false;
}
VLOG(1) << "Fetching session: " << session_id;
session_ = SessionManager::GetInstance()->GetSession(session_id);
if (session_ == NULL) {
response->SetError(
......@@ -42,15 +41,17 @@ bool WebDriverCommand::Init(Response* const response) {
return false;
}
// TODO(kkania): Do not use the standard automation timeout for this,
// and throw an error if it does not succeed.
scoped_ptr<Error> error(session_->WaitForAllTabsToStopLoading());
if (error.get()) {
LOG(WARNING) << error->ToString();
LOG(INFO) << "Waiting for the page to stop loading";
Error* error = session_->WaitForAllTabsToStopLoading();
if (error) {
response->SetError(error);
return false;
}
error.reset(session_->SwitchToTopFrameIfCurrentFrameInvalid());
if (error.get()) {
LOG(WARNING) << error->ToString();
LOG(INFO) << "Done waiting for the page to stop loading";
error = session_->SwitchToTopFrameIfCurrentFrameInvalid();
if (error) {
response->SetError(error);
return false;
}
response->SetField("sessionId", Value::CreateStringValue(session_id));
......
......@@ -9,7 +9,9 @@
#include <vector>
#include "base/format_macros.h"
#include "base/json/json_reader.h"
#include "base/logging.h"
#include "base/memory/scoped_ptr.h"
#include "base/message_loop_proxy.h"
#include "base/string_split.h"
#include "base/string_util.h"
......@@ -20,11 +22,16 @@
#include "chrome/test/webdriver/commands/command.h"
#include "chrome/test/webdriver/session_manager.h"
#include "chrome/test/webdriver/utility_functions.h"
#include "chrome/test/webdriver/webdriver_logging.h"
namespace webdriver {
namespace {
// Maximum safe size of HTTP response message. Any larger than this,
// the message may not be transferred at all.
const size_t kMaxHttpMessageSize = 1024 * 1024 * 16; // 16MB
bool ForbidsMessageBody(const std::string& request_method,
const HttpResponse& response) {
return request_method == "HEAD" ||
......@@ -59,15 +66,40 @@ void Shutdown(struct mg_connection* connection,
shutdown_event->Signal();
}
void SendStatus(struct mg_connection* connection,
const struct mg_request_info* request_info,
void* user_data) {
std::string response = "HTTP/1.1 200 OK\r\n"
"Content-Length:2\r\n\r\n"
"ok";
void SendOkWithBody(struct mg_connection* connection,
const std::string& content) {
const char* response_fmt = "HTTP/1.1 200 OK\r\n"
"Content-Length:%d\r\n\r\n"
"%s";
std::string response = base::StringPrintf(
response_fmt, content.length(), content.c_str());
mg_write(connection, response.data(), response.length());
}
void SendHealthz(struct mg_connection* connection,
const struct mg_request_info* request_info,
void* user_data) {
SendOkWithBody(connection, "ok");
}
void SendLog(struct mg_connection* connection,
const struct mg_request_info* request_info,
void* user_data) {
std::string content, log;
if (GetLogContents(&log)) {
content = "START ChromeDriver log";
const size_t kMaxSizeWithoutHeaders = kMaxHttpMessageSize - 10000;
if (log.size() > kMaxSizeWithoutHeaders) {
log = log.substr(log.size() - kMaxSizeWithoutHeaders);
content += " (only last several MB)";
}
content += ":\n" + log + "END ChromeDriver log";
} else {
content = "No ChromeDriver log found";
}
SendOkWithBody(connection, content);
}
void SendNoContentResponse(struct mg_connection* connection,
const struct mg_request_info* request_info,
void* user_data) {
......@@ -99,7 +131,6 @@ void SendNotImplementedError(struct mg_connection* connection,
"Content-Length:%" PRIuS "\r\n"
"\r\n", body.length());
LOG(ERROR) << header << body;
mg_write(connection, header.data(), header.length());
mg_write(connection, body.data(), body.length());
}
......@@ -225,18 +256,24 @@ bool ParseRequestInfo(const struct mg_request_info* const request_info,
base::SplitString(uri, '/', path_segments);
if (*method == "POST" && request_info->post_data_len > 0) {
VLOG(1) << "...parsing request body";
std::string json(request_info->post_data, request_info->post_data_len);
std::string error;
if (!ParseJSONDictionary(json, parameters, &error)) {
std::string error_msg;
scoped_ptr<Value> params(base::JSONReader::ReadAndReturnError(
json, true, NULL, &error_msg));
if (!params.get()) {
response->SetError(new Error(
kBadRequest,
"Failed to parse command data: " + error + "\n Data: " + json));
"Failed to parse command data: " + error_msg + "\n Data: " + json));
return false;
}
if (!params->IsType(Value::TYPE_DICTIONARY)) {
response->SetError(new Error(
kBadRequest,
"Data passed in URL must be a dictionary. Data: " + json));
return false;
}
*parameters = static_cast<DictionaryValue*>(params.release());
}
VLOG(1) << "Parsed " << method << " " << uri
<< std::string(request_info->post_data, request_info->post_data_len);
return true;
}
......@@ -283,8 +320,12 @@ void Dispatcher::AddShutdown(const std::string& pattern,
shutdown_event);
}
void Dispatcher::AddStatus(const std::string& pattern) {
mg_set_uri_callback(context_, (root_ + pattern).c_str(), &SendStatus, NULL);
void Dispatcher::AddHealthz(const std::string& pattern) {
mg_set_uri_callback(context_, (root_ + pattern).c_str(), &SendHealthz, NULL);
}
void Dispatcher::AddLog(const std::string& pattern) {
mg_set_uri_callback(context_, (root_ + pattern).c_str(), &SendLog, NULL);
}
void Dispatcher::SetNotImplemented(const std::string& pattern) {
......
......@@ -9,6 +9,7 @@
#include <vector>
#include "base/basictypes.h"
#include "base/logging.h"
#include "chrome/test/webdriver/commands/response.h"
#include "third_party/mongoose/mongoose.h"
......@@ -68,15 +69,19 @@ void Dispatch(struct mg_connection* connection,
&path_segments,
&parameters,
&response)) {
std::string post_data(request_info->post_data, request_info->post_data_len);
LOG(INFO) << "Received command, url: " << request_info->uri
<< ", method: " << request_info->request_method
<< ", postd data: " << post_data;
internal::DispatchHelper(
new CommandType(path_segments, parameters),
method,
&response);
}
internal::SendResponse(connection,
request_info->request_method,
response);
LOG(INFO) << "Sent command response, url: " << request_info->uri;
}
class Dispatcher {
......@@ -100,7 +105,11 @@ class Dispatcher {
// Registers a callback for the given pattern that will return a simple
// "HTTP/1.1 200 OK" message with "ok" in the body. Used for checking the
// status of the server.
void AddStatus(const std::string& pattern);
void AddHealthz(const std::string& pattern);
// Registers a callback for the given pattern that will return the current
// WebDriver log contents.
void AddLog(const std::string& pattern);
// Registers a callback that will always respond with a
// "HTTP/1.1 501 Not Implemented" message.
......
......@@ -156,7 +156,7 @@ bool KeyMap::Press(const scoped_refptr<WindowProxy>& window,
modifiers = modifiers | ui::EF_ALT_DOWN;
}
if (command_) {
VLOG(1) << "Pressing command key on linux!!";
LOG(INFO) << "Pressing command key on linux!!";
modifiers = modifiers | ui::EF_COMMAND_DOWN;
}
......
......@@ -27,9 +27,6 @@
#include "base/utf_string_conversions.h"
#include "chrome/common/chrome_paths.h"
#include "chrome/common/chrome_switches.h"
#include "chrome/test/webdriver/dispatch.h"
#include "chrome/test/webdriver/session_manager.h"
#include "chrome/test/webdriver/utility_functions.h"
#include "chrome/test/webdriver/commands/alert_commands.h"
#include "chrome/test/webdriver/commands/cookie_commands.h"
#include "chrome/test/webdriver/commands/create_session.h"
......@@ -46,6 +43,10 @@
#include "chrome/test/webdriver/commands/title_command.h"
#include "chrome/test/webdriver/commands/url_command.h"
#include "chrome/test/webdriver/commands/webelement_commands.h"
#include "chrome/test/webdriver/dispatch.h"
#include "chrome/test/webdriver/session_manager.h"
#include "chrome/test/webdriver/utility_functions.h"
#include "chrome/test/webdriver/webdriver_logging.h"
#include "third_party/mongoose/mongoose.h"
#if defined(OS_WIN)
......@@ -63,7 +64,8 @@ void InitCallbacks(struct mg_context* ctx, Dispatcher* dispatcher,
base::WaitableEvent* shutdown_event,
bool forbid_other_requests) {
dispatcher->AddShutdown("/shutdown", shutdown_event);
dispatcher->AddStatus("/healthz");
dispatcher->AddHealthz("/healthz");
dispatcher->AddLog("/log");
dispatcher->Add<CreateSession>("/session");
......@@ -143,33 +145,6 @@ void InitCallbacks(struct mg_context* ctx, Dispatcher* dispatcher,
} // namespace webdriver
// Initializes logging for ChromeDriver.
void InitChromeDriverLogging(const CommandLine& command_line) {
bool success = InitLogging(
FILE_PATH_LITERAL("chromedriver.log"),
logging::LOG_TO_BOTH_FILE_AND_SYSTEM_DEBUG_LOG,
logging::LOCK_LOG_FILE,
logging::DELETE_OLD_LOG_FILE,
logging::DISABLE_DCHECK_FOR_NON_OFFICIAL_RELEASE_BUILDS);
if (!success) {
PLOG(ERROR) << "Unable to initialize logging";
}
logging::SetLogItems(false, // enable_process_id
false, // enable_thread_id
true, // enable_timestamp
false); // enable_tickcount
if (command_line.HasSwitch(switches::kLoggingLevel)) {
std::string log_level = command_line.GetSwitchValueASCII(
switches::kLoggingLevel);
int level = 0;
if (base::StringToInt(log_level, &level)) {
logging::SetMinLogLevel(level);
} else {
LOG(WARNING) << "Bad log level: " << log_level;
}
}
}
// Configures mongoose according to the given command line flags.
// Returns true on success.
bool SetMongooseOptions(struct mg_context* ctx,
......@@ -209,12 +184,12 @@ int main(int argc, char *argv[]) {
// built Chrome.
chrome::RegisterPathProvider();
TestTimeouts::Initialize();
InitChromeDriverLogging(*cmd_line);
// Parse command line flags.
std::string port = "9515";
std::string root;
std::string url_base;
bool verbose = false;
if (cmd_line->HasSwitch("port"))
port = cmd_line->GetSwitchValueASCII("port");
// The 'root' flag allows the user to specify a location to serve files from.
......@@ -224,6 +199,12 @@ int main(int argc, char *argv[]) {
root = cmd_line->GetSwitchValueASCII("root");
if (cmd_line->HasSwitch("url-base"))
url_base = cmd_line->GetSwitchValueASCII("url-base");
// Whether or not to do verbose logging.
if (cmd_line->HasSwitch("verbose"))
verbose = true;
webdriver::InitWebDriverLogging(
verbose ? logging::LOG_INFO : logging::LOG_WARNING);
webdriver::SessionManager* manager = webdriver::SessionManager::GetInstance();
manager->set_port(port);
......
......@@ -45,10 +45,8 @@ bool SessionManager::Remove(const std::string& id) {
Session* session;
base::AutoLock lock(map_lock_);
it = map_.find(id);
if (it == map_.end()) {
VLOG(1) << "No such session with ID " << id;
if (it == map_.end())
return false;
}
session = it->second;
map_.erase(it);
return true;
......@@ -58,10 +56,8 @@ Session* SessionManager::GetSession(const std::string& id) const {
std::map<std::string, Session*>::const_iterator it;
base::AutoLock lock(map_lock_);
it = map_.find(id);
if (it == map_.end()) {
VLOG(1) << "No such session with ID " << id;
if (it == map_.end())
return NULL;
}
return it->second;
}
......
......@@ -4,76 +4,13 @@
#include "chrome/test/webdriver/utility_functions.h"
#include <string.h>
#include <wchar.h>
#include <algorithm>
#include <sstream>
#include "base/basictypes.h"
#include "base/format_macros.h"
#include "base/json/json_reader.h"
#include "base/logging.h"
#include "base/memory/scoped_ptr.h"
#include "base/rand_util.h"
#include "base/stringprintf.h"
namespace webdriver {
std::string print_valuetype(Value::ValueType e) {
switch (e) {
case Value::TYPE_NULL:
return "NULL ";
case Value::TYPE_BOOLEAN:
return "BOOL";
case Value::TYPE_INTEGER:
return "INT";
case Value::TYPE_DOUBLE:
return "DOUBLE";
case Value::TYPE_STRING:
return "STRING";
case Value::TYPE_BINARY:
return "BIN";
case Value::TYPE_DICTIONARY:
return "DICT";
case Value::TYPE_LIST:
return "LIST";
default:
return "ERROR";
}
}
void CheckValueType(const Value::ValueType expected,
const Value* const actual) {
DCHECK(actual != NULL) << "Expected value to be non-NULL";
DCHECK(expected == actual->GetType())
<< "Expected " << print_valuetype(expected)
<< ", but was " << print_valuetype(actual->GetType());
}
bool ParseJSONDictionary(const std::string& json, DictionaryValue** dict,
std::string* error) {
int error_code = 0;
Value* params =
base::JSONReader::ReadAndReturnError(json, true, &error_code, error);
if (error_code != 0) {
VLOG(1) << "Could not parse JSON object, " << *error;
if (params)
delete params;
return false;
}
if (!params || params->GetType() != Value::TYPE_DICTIONARY) {
*error = "Data passed in URL must be of type dictionary.";
VLOG(1) << "Invalid type to parse";
if (params)
delete params;
return false;
}
*dict = static_cast<DictionaryValue*>(params);
return true;
}
std::string GenerateRandomID() {
uint64 msb = base::RandUint64();
uint64 lsb = base::RandUint64();
......
// Copyright (c) 2010 The Chromium Authors. All rights reserved.
// Copyright (c) 2011 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.
......@@ -7,23 +7,8 @@
#include <string>
#include "base/values.h"
namespace webdriver {
// Converts a value type to a string for logging.
std::string print_valuetype(Value::ValueType e);
// Checks that a value has the expected type.
void CheckValueType(const Value::ValueType expected, const Value* const actual);
// Attempts to parse a |json| string into a valid dictionary. If the parse
// operation fails, the offending |error| will be reported to the user and the
// function will return false. The caller is responsible for the allocated
// memory in |dict|.
bool ParseJSONDictionary(const std::string& json, DictionaryValue** dict,
std::string* error);
// Generates a random, 32-character hexidecimal ID.
std::string GenerateRandomID();
......
// Copyright (c) 2011 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/webdriver/webdriver_logging.h"
#include "base/file_path.h"
#include "base/file_util.h"
#include "base/logging.h"
namespace {
// Path to the WebDriver log file.
const FilePath::CharType kLogPath[] = FILE_PATH_LITERAL("chromedriver.log");
} // namespace
namespace webdriver {
void InitWebDriverLogging(int min_log_level) {
bool success = InitLogging(
kLogPath,
logging::LOG_TO_BOTH_FILE_AND_SYSTEM_DEBUG_LOG,
logging::LOCK_LOG_FILE,
logging::DELETE_OLD_LOG_FILE,
logging::DISABLE_DCHECK_FOR_NON_OFFICIAL_RELEASE_BUILDS);
if (!success) {
PLOG(ERROR) << "Unable to initialize logging";
}
logging::SetLogItems(false, // enable_process_id
false, // enable_thread_id
true, // enable_timestamp
false); // enable_tickcount
logging::SetMinLogLevel(min_log_level);
}
bool GetLogContents(std::string* log_contents) {
return file_util::ReadFileToString(FilePath(kLogPath), log_contents);
}
} // namespace webdriver
// Copyright (c) 2011 The Chromium Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
#ifndef CHROME_TEST_WEBDRIVER_WEBDRIVER_LOGGING_H_
#define CHROME_TEST_WEBDRIVER_WEBDRIVER_LOGGING_H_
#include <string>
namespace webdriver {
// Initializes logging for WebDriver. All logging below the given level
// will be discarded.
void InitWebDriverLogging(int min_log_level);
// Retrieves the current contents of the WebDriver log file.
// Returns true on success.
bool GetLogContents(std::string* log_contents);
} // namespace webdriver
#endif // CHROME_TEST_WEBDRIVER_WEBDRIVER_LOGGING_H_
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment