[chromedriver] Remove Logger and just use base LOG.

chrome/test/chromedriver/logging.cc

 // 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 <stdio.h>
+
 #include "base/basictypes.h"
+#include "base/command_line.h"
+#include "base/json/json_reader.h"
 #include "base/logging.h"
+#include "base/strings/stringprintf.h"
 #include "base/time/time.h"
 #include "chrome/test/chromedriver/capabilities.h"
 #include "chrome/test/chromedriver/chrome/console_logger.h"
 #include "chrome/test/chromedriver/chrome/performance_logger.h"
 #include "chrome/test/chromedriver/chrome/status.h"
+#include "chrome/test/chromedriver/session.h"
+
+#if defined(OS_POSIX)
+#include <fcntl.h>
+#include <unistd.h>
+#endif
 
 
 namespace {
 
-// Map between WebDriverLog::WebDriverLevel and its name in WD wire protocol.
-// Array indices are the WebDriverLog::WebDriverLevel enum values.
-const char* const kWebDriverLevelNames[] = {
-  "ALL", "DEBUG", "INFO", "WARNING", "SEVERE", "OFF"
+Log::Level g_log_level = Log::kWarning;
+
+int64 g_start_time = 0;
+
+// Array indices are the Log::Level enum values.
+const char* kLevelToName[] = {
+  "ALL",  // kAll
+  "DEBUG",  // kDebug
+  "INFO",  // kInfo
+  "WARNING",  // kWarning
+  "SEVERE",  // kError
+  "OFF",  // kOff
 };
 
-// Map between Log::Level and WebDriverLog::WebDriverLevel.
-// Array indices are the Log::Level enum values.
-WebDriverLog::WebDriverLevel kLogLevelToWebDriverLevels[] = {
-  WebDriverLog::kWdDebug,  // kDebug
-  WebDriverLog::kWdInfo,  // kLog
-  WebDriverLog::kWdWarning,  // kWarning
-  WebDriverLog::kWdSevere  // kError
+const char* LevelToName(Log::Level level) {
+  const int index = level - Log::kAll;
+  CHECK_GE(index, 0);
+  CHECK_LT(static_cast<size_t>(index), arraysize(kLevelToName));
+  return kLevelToName[index];
+}
+
+struct LevelPair {
+  const char* name;
+  Log::Level level;
 };
 
-// Translates Log::Level to WebDriverLog::WebDriverLevel.
-WebDriverLog::WebDriverLevel LogLevelToWebDriverLevel(Log::Level level) {
-  const int index = level - Log::kDebug;
-  CHECK_GE(index, 0);
-  CHECK_LT(static_cast<size_t>(index), arraysize(kLogLevelToWebDriverLevels));
-  return kLogLevelToWebDriverLevels[index];
+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_REPORT:
+    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;
+  }
 }
 
-// Returns WD wire protocol level name for a WebDriverLog::WebDriverLevel.
-std::string GetWebDriverLevelName(
-    const WebDriverLog::WebDriverLevel level) {
-  const int index = level - WebDriverLog::kWdAll;
-  CHECK_GE(index, 0);
-  CHECK_LT(static_cast<size_t>(index), arraysize(kWebDriverLevelNames));
-  return kWebDriverLevelNames[index];
+bool InternalIsVLogOn(int vlog_level) {
+  return GetLevelFromSeverity(vlog_level * -1) >= g_log_level;
+}
+
+std::string ConvertForDisplayInternal(const std::string& input) {
+  size_t left = input.find("{");
+  size_t right = input.rfind("}");
+  if (left == std::string::npos || right == std::string::npos)
+    return input.substr(0, 10 << 10);
+
+  scoped_ptr<base::Value> value(
+      base::JSONReader::Read(input.substr(left, right - left + 1)));
+  if (!value)
+    return input.substr(0, 10 << 10);
+  std::string display = input.substr(0, left) +
+                        PrettyPrintValue(TruncateContainedStrings(value.get()));
+  if (input.length() > right)
+    display += input.substr(right + 1);
+  return display;
+}
+
+// Pretty prints encapsulated JSON and truncates long strings for display.
+std::string ConvertForDisplay(const std::string& input) {
+  std::string display = ConvertForDisplayInternal(input);
+  return display;
+}
+
+bool HandleLogMessage(int severity,
+                      const char* file,
+                      int line,
+                      size_t message_start,
+                      const std::string& str) {
+  Log::Level level = GetLevelFromSeverity(severity);
+  if (level < g_log_level)
+    return true;
+
+  std::string message = str.substr(message_start);
+  const char* level_name = "UNKNOWN";
+  switch (level) {
+    case Log::kDebug:
+      level_name = "DEBUG";
+      break;
+    case Log::kInfo:
+      level_name = "INFO";
+      break;
+    case Log::kWarning:
+      level_name = "WARNING";
+      break;
+    case Log::kError:
+      level_name = "ERROR";
+      break;
+    default:
+      break;
+  }
+  std::string entry = base::StringPrintf(
+      "[%.3lf][%s]: %s",
+      base::TimeDelta(base::TimeTicks::Now() -
+                      base::TimeTicks::FromInternalValue(g_start_time))
+          .InSecondsF(),
+      level_name,
+      ConvertForDisplay(message).c_str());
+  const char* format = "%s\n";
+  if (entry[entry.length() - 1] == '\n')
+    format = "%s";
+
+  fprintf(stderr, format, entry.c_str());
+  fflush(stderr);
+  return true;
 }
 
 }  // namespace
 
-bool WebDriverLog::NameToLevel(
-    const std::string& name, WebDriverLog::WebDriverLevel* out_level) {
-  for (size_t i = 0; i < arraysize(kWebDriverLevelNames); ++i) {
-    if (name == kWebDriverLevelNames[i]) {
-      CHECK_LE(WebDriverLog::kWdAll + i,
-               static_cast<size_t>(WebDriverLog::kWdOff));
-      *out_level =
-          static_cast<WebDriverLog::WebDriverLevel>(WebDriverLog::kWdAll + i);
+bool WebDriverLog::NameToLevel(const std::string& name, Log::Level* out_level) {
+  for (size_t i = 0; i < arraysize(kNameToLevel); ++i) {
+    if (name == kNameToLevel[i].name) {

[chrisgao (Use stgao instead), 2013/09/05 01:20:46]

Can it be case insensitive?

[kkania, 2013/09/05 15:15:11]

the spec isn't clear; i'll leave as is.

+      *out_level = kNameToLevel[i].level;
       return true;
     }
   }
   return false;
 }
 
-WebDriverLog::WebDriverLog(
-    const std::string& type, WebDriverLog::WebDriverLevel min_wd_level)
-    : type_(type),
-      min_wd_level_(min_wd_level),
-      entries_(new base::ListValue()) {
-  VLOG(1) << "Log(" << type_ << ", " << min_wd_level_ << ")";
+WebDriverLog::WebDriverLog(const std::string& type, Log::Level min_level)
+    : type_(type), min_level_(min_level), entries_(new base::ListValue()) {
 }
 
 WebDriverLog::~WebDriverLog() {
   VLOG(1) << "Log type '" << type_ << "' lost "
           << entries_->GetSize() << " entries on destruction";
 }
 
-const std::string& WebDriverLog::GetType() {
-  return type_;
-}
-
-void WebDriverLog::AddEntryTimestamped(const base::Time& timestamp,
-                                       Log::Level level,
-                                       const std::string& message) {
-  const WebDriverLog::WebDriverLevel wd_level = LogLevelToWebDriverLevel(level);
-  if (wd_level < min_wd_level_)
-    return;
-  scoped_ptr<base::DictionaryValue> log_entry_dict(new base::DictionaryValue());
-  log_entry_dict->SetDouble("timestamp",
-                            static_cast<int64>(timestamp.ToJsTime()));
-  log_entry_dict->SetString("level", GetWebDriverLevelName(wd_level));
-  log_entry_dict->SetString("message", message);
-  entries_->Append(log_entry_dict.release());
-}
-
 scoped_ptr<base::ListValue> WebDriverLog::GetAndClearEntries() {
   scoped_ptr<base::ListValue> ret(entries_.release());
   entries_.reset(new base::ListValue());
   return ret.Pass();
 }
 
+void WebDriverLog::AddEntryTimestamped(const base::Time& timestamp,
+                                       Log::Level level,
+                                       const std::string& message) {
+  if (level < min_level_)
+    return;
+
+  scoped_ptr<base::DictionaryValue> log_entry_dict(new base::DictionaryValue());
+  log_entry_dict->SetDouble("timestamp",
+                            static_cast<int64>(timestamp.ToJsTime()));
+  log_entry_dict->SetString("level", LevelToName(level));
+  log_entry_dict->SetString("message", message);
+  entries_->Append(log_entry_dict.release());
+}
+
+const std::string& WebDriverLog::type() const {
+  return type_;
+}
+
+Log::Level WebDriverLog::min_level() const {
+  return min_level_;
+}
+
+bool InitLogging() {
+  InitLogging(&InternalIsVLogOn);
+  g_start_time = base::TimeTicks::Now().ToInternalValue();
+
+  CommandLine* cmd_line = CommandLine::ForCurrentProcess();
+  if (cmd_line->HasSwitch("log-path")) {
+    g_log_level = Log::kInfo;
+    base::FilePath log_path = cmd_line->GetSwitchValuePath("log-path");
+#if defined(OS_WIN)
+    FILE* redir_stderr = _wfreopen(log_path.value().c_str(), L"w", stderr);
+#else
+    FILE* redir_stderr = freopen(log_path.value().c_str(), "w", stderr);
+#endif
+    if (!redir_stderr) {
+      printf("Failed to redirect stderr to log file.\n");
+      return false;
+    }
+  }
+  if (cmd_line->HasSwitch("silent"))
+    g_log_level = Log::kOff;
+
+  if (cmd_line->HasSwitch("verbose")) {
+    g_log_level = Log::kAll;
+  } else {
+#if defined(OS_POSIX)
+    // Close stderr on exec, so that Chrome log spew doesn't confuse users.
+    fcntl(STDERR_FILENO, F_SETFD, FD_CLOEXEC);
+#endif
+  }
+
+  cmd_line->AppendSwitchASCII("vmodule", "*/chrome/test/chromedriver/*=3");

[chrisgao (Use stgao instead), 2013/09/05 01:20:46]

How about adding a comment for this one?

[kkania, 2013/09/05 15:15:11]

Done.

+
+  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;
+  return logging::InitLogging(logging_settings);
+}
+
 Status CreateLogs(const Capabilities& capabilities,
-                  ScopedVector<WebDriverLog>* out_devtools_logs,
+                  ScopedVector<WebDriverLog>* out_logs,
+                  scoped_ptr<WebDriverLog>* out_driver_log,
                   ScopedVector<DevToolsEventListener>* out_listeners) {
-  ScopedVector<WebDriverLog> devtools_logs;
+  ScopedVector<WebDriverLog> logs;
   ScopedVector<DevToolsEventListener> listeners;
-  WebDriverLog::WebDriverLevel browser_log_level = WebDriverLog::kWdInfo;
+  Log::Level browser_log_level = Log::kOff;
+  Log::Level driver_log_level = Log::kWarning;
+  const LoggingPrefs& prefs = capabilities.logging_prefs;
 
-  if (capabilities.logging_prefs) {
-    for (DictionaryValue::Iterator pref(*capabilities.logging_prefs);
-         !pref.IsAtEnd(); pref.Advance()) {
-      const std::string type = pref.key();
-      std::string level_name;
-      if (!pref.value().GetAsString(&level_name)) {
-        return Status(kUnknownError,
-                      "logging level must be a string for log type: " + type);
+  const char kBrowserLogType[] = "browser";
+  const char kDriverLogType[] = "driver";
+  for (LoggingPrefs::const_iterator iter = prefs.begin();
+       iter != prefs.end();
+       ++iter) {
+    std::string type = iter->first;
+    Log::Level level = iter->second;
+    if (type == "performance") {
+      if (level != Log::kOff) {
+        WebDriverLog* log = new WebDriverLog(type, Log::kDebug);

[chrisgao (Use stgao instead), 2013/09/05 01:20:46]

Why not using |level| but Log::kDebug?

[kkania, 2013/09/05 15:15:11]

the thinking was that perf logging doesn't really have levels, so it's just an
on/off switch. I'll change it to All to make it more clear.

+        logs.push_back(log);
+        listeners.push_back(new PerformanceLogger(log));
       }
-      WebDriverLog::WebDriverLevel level = WebDriverLog::kWdOff;
-      if (!WebDriverLog::NameToLevel(level_name, &level)) {
-        return Status(kUnknownError,
-                      "invalid log level \"" + level_name +
-                      "\" for type: " + type);
-      }
-      if ("performance" == type) {
-        if (WebDriverLog::kWdOff != level) {
-          WebDriverLog* log = new WebDriverLog(type, WebDriverLog::kWdAll);
-          devtools_logs.push_back(log);
-          listeners.push_back(new PerformanceLogger(log));
-        }
-      } else if ("browser" == type) {
-        browser_log_level = level;
-      } else {
-        // 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: LoggingPrefs." << type;
-      }
+    } else if (type == kBrowserLogType) {
+      browser_log_level = level;
+    } else if (type == kDriverLogType) {
+      driver_log_level = level;
+    } else {
+      // 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.
-  WebDriverLog* browser_log = new WebDriverLog("browser", browser_log_level);
-  devtools_logs.push_back(browser_log);
+  WebDriverLog* browser_log =
+      new WebDriverLog(kBrowserLogType, browser_log_level);
+  logs.push_back(browser_log);
   // If the level is OFF, don't even bother listening for DevTools events.
-  if (browser_log_level != WebDriverLog::kWdOff)
+  if (browser_log_level != Log::kOff)
     listeners.push_back(new ConsoleLogger(browser_log));
 
-  out_devtools_logs->swap(devtools_logs);
+  // Create "driver" log -- should always exist.
+  scoped_ptr<WebDriverLog> driver_log(
+      new WebDriverLog(kDriverLogType, driver_log_level));
+
+  out_logs->swap(logs);
+  *out_driver_log = driver_log.Pass();

[chrisgao (Use stgao instead), 2013/09/05 01:20:46]

|out_driver_log| is not contained in/owned by |out_logs|.
But the comment in logging.h says it should be.

[kkania, 2013/09/05 15:15:11]

Updated comment.

   out_listeners->swap(listeners);
   return Status(kOk);
 }