chrome/test/chromedriver/logging.cc

   1 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "chrome/test/chromedriver/logging.h"
   6
   7 #include <stdio.h>
   8
   9 #include "base/basictypes.h"
  10 #include "base/command_line.h"
  11 #include "base/json/json_reader.h"
  12 #include "base/logging.h"
  13 #include "base/strings/stringprintf.h"
  14 #include "base/time/time.h"
  15 #include "chrome/test/chromedriver/capabilities.h"
  16 #include "chrome/test/chromedriver/chrome/console_logger.h"
  17 #include "chrome/test/chromedriver/chrome/status.h"
  18 #include "chrome/test/chromedriver/command_listener_proxy.h"
  19 #include "chrome/test/chromedriver/performance_logger.h"
  20 #include "chrome/test/chromedriver/session.h"
  21
  22 #if defined(OS_POSIX)
  23 #include <fcntl.h>
  24 #include <unistd.h>
  25 #endif
  26
  27
  28 namespace {
  29
  30 Log::Level g_log_level = Log::kWarning;
  31
  32 int64 g_start_time = 0;
  33
  34 // Array indices are the Log::Level enum values.
  35 const char* const kLevelToName[] = {
  36   "ALL",  // kAll
  37   "DEBUG",  // kDebug
  38   "INFO",  // kInfo
  39   "WARNING",  // kWarning
  40   "SEVERE",  // kError
  41   "OFF",  // kOff
  42 };
  43
  44 const char* LevelToName(Log::Level level) {
  45   const int index = level - Log::kAll;
  46   CHECK_GE(index, 0);
  47   CHECK_LT(static_cast<size_t>(index), arraysize(kLevelToName));
  48   return kLevelToName[index];
  49 }
  50
  51 struct LevelPair {
  52   const char* name;
  53   Log::Level level;
  54 };
  55
  56 const LevelPair kNameToLevel[] = {
  57     {"ALL", Log::kAll},
  58     {"DEBUG", Log::kDebug},
  59     {"INFO", Log::kInfo},
  60     {"WARNING", Log::kWarning},
  61     {"SEVERE", Log::kError},
  62     {"OFF", Log::kOff},
  63 };
  64
  65 Log::Level GetLevelFromSeverity(int severity) {
  66   switch (severity) {
  67     case logging::LOG_FATAL:
  68     case logging::LOG_ERROR:
  69       return Log::kError;
  70     case logging::LOG_WARNING:
  71       return Log::kWarning;
  72     case logging::LOG_INFO:
  73       return Log::kInfo;
  74     case logging::LOG_VERBOSE:
  75     default:
  76       return Log::kDebug;
  77   }
  78 }
  79
  80 WebDriverLog* GetSessionLog() {
  81   Session* session = GetThreadLocalSession();
  82   if (!session)
  83     return NULL;
  84   return session->driver_log.get();
  85 }
  86
  87 bool InternalIsVLogOn(int vlog_level) {
  88   WebDriverLog* session_log = GetSessionLog();
  89   Log::Level session_level = session_log ? session_log->min_level() : Log::kOff;
  90   Log::Level level = g_log_level < session_level ? g_log_level : session_level;
  91   return GetLevelFromSeverity(vlog_level * -1) >= level;
  92 }
  93
  94 bool HandleLogMessage(int severity,
  95                       const char* file,
  96                       int line,
  97                       size_t message_start,
  98                       const std::string& str) {
  99   Log::Level level = GetLevelFromSeverity(severity);
 100   std::string message = str.substr(message_start);
 101
 102   if (level >= g_log_level) {
 103     const char* level_name = LevelToName(level);
 104     std::string entry = base::StringPrintf(
 105         "[%.3lf][%s]: %s",
 106         base::TimeDelta(base::TimeTicks::Now() -
 107                         base::TimeTicks::FromInternalValue(g_start_time))
 108             .InSecondsF(),
 109         level_name,
 110         message.c_str());
 111     fprintf(stderr, "%s", entry.c_str());
 112     fflush(stderr);
 113   }
 114
 115   WebDriverLog* session_log = GetSessionLog();
 116   if (session_log)
 117     session_log->AddEntry(level, message);
 118
 119   return true;
 120 }
 121
 122 }  // namespace
 123
 124 const char WebDriverLog::kBrowserType[] = "browser";
 125 const char WebDriverLog::kDriverType[] = "driver";
 126 const char WebDriverLog::kPerformanceType[] = "performance";
 127
 128 bool WebDriverLog::NameToLevel(const std::string& name, Log::Level* out_level) {
 129   for (size_t i = 0; i < arraysize(kNameToLevel); ++i) {
 130     if (name == kNameToLevel[i].name) {
 131       *out_level = kNameToLevel[i].level;
 132       return true;
 133     }
 134   }
 135   return false;
 136 }
 137
 138 WebDriverLog::WebDriverLog(const std::string& type, Log::Level min_level)
 139     : type_(type), min_level_(min_level), entries_(new base::ListValue()) {
 140 }
 141
 142 WebDriverLog::~WebDriverLog() {
 143   VLOG(1) << "Log type '" << type_ << "' lost "
 144           << entries_->GetSize() << " entries on destruction";
 145 }
 146
 147 scoped_ptr<base::ListValue> WebDriverLog::GetAndClearEntries() {
 148   scoped_ptr<base::ListValue> ret(entries_.release());
 149   entries_.reset(new base::ListValue());
 150   return ret.Pass();
 151 }
 152
 153 std::string WebDriverLog::GetFirstErrorMessage() const {
 154   for (base::ListValue::iterator it = entries_->begin();
 155        it != entries_->end();
 156        ++it) {
 157     base::DictionaryValue* log_entry = NULL;
 158     (*it)->GetAsDictionary(&log_entry);
 159     if (log_entry != NULL) {
 160       std::string level;
 161       if (log_entry->GetString("level", &level)) {
 162         if (level == kLevelToName[Log::kError]) {
 163           std::string message;
 164           if (log_entry->GetString("message", &message))
 165             return message;
 166         }
 167       }
 168     }
 169   }
 170   return std::string();
 171 }
 172
 173 void WebDriverLog::AddEntryTimestamped(const base::Time& timestamp,
 174                                        Log::Level level,
 175                                        const std::string& source,
 176                                        const std::string& message) {
 177   if (level < min_level_)
 178     return;
 179
 180   scoped_ptr<base::DictionaryValue> log_entry_dict(new base::DictionaryValue());
 181   log_entry_dict->SetDouble("timestamp",
 182                             static_cast<int64>(timestamp.ToJsTime()));
 183   log_entry_dict->SetString("level", LevelToName(level));
 184   if (!source.empty())
 185     log_entry_dict->SetString("source", source);
 186   log_entry_dict->SetString("message", message);
 187   entries_->Append(log_entry_dict.release());
 188 }
 189
 190 const std::string& WebDriverLog::type() const {
 191   return type_;
 192 }
 193
 194 void WebDriverLog::set_min_level(Level min_level) {
 195   min_level_ = min_level;
 196 }
 197
 198 Log::Level WebDriverLog::min_level() const {
 199   return min_level_;
 200 }
 201
 202 bool InitLogging() {
 203   InitLogging(&InternalIsVLogOn);
 204   g_start_time = base::TimeTicks::Now().ToInternalValue();
 205
 206   CommandLine* cmd_line = CommandLine::ForCurrentProcess();
 207   if (cmd_line->HasSwitch("log-path")) {
 208     g_log_level = Log::kInfo;
 209     base::FilePath log_path = cmd_line->GetSwitchValuePath("log-path");
 210 #if defined(OS_WIN)
 211     FILE* redir_stderr = _wfreopen(log_path.value().c_str(), L"w", stderr);
 212 #else
 213     FILE* redir_stderr = freopen(log_path.value().c_str(), "w", stderr);
 214 #endif
 215     if (!redir_stderr) {
 216       printf("Failed to redirect stderr to log file.\n");
 217       return false;
 218     }
 219   }
 220   if (cmd_line->HasSwitch("silent"))
 221     g_log_level = Log::kOff;
 222
 223   if (cmd_line->HasSwitch("verbose"))
 224     g_log_level = Log::kAll;
 225
 226   // Turn on VLOG for chromedriver. This is parsed during logging::InitLogging.
 227   cmd_line->AppendSwitchASCII("vmodule", "*/chrome/test/chromedriver/*=3");
 228
 229   logging::SetMinLogLevel(logging::LOG_WARNING);
 230   logging::SetLogItems(false,   // enable_process_id
 231                        false,   // enable_thread_id
 232                        false,   // enable_timestamp
 233                        false);  // enable_tickcount
 234   logging::SetLogMessageHandler(&HandleLogMessage);
 235
 236   logging::LoggingSettings logging_settings;
 237   logging_settings.logging_dest = logging::LOG_TO_SYSTEM_DEBUG_LOG;
 238   return logging::InitLogging(logging_settings);
 239 }
 240
 241 Status CreateLogs(const Capabilities& capabilities,
 242                   const Session* session,
 243                   ScopedVector<WebDriverLog>* out_logs,
 244                   ScopedVector<DevToolsEventListener>* out_devtools_listeners,
 245                   ScopedVector<CommandListener>* out_command_listeners) {
 246   ScopedVector<WebDriverLog> logs;
 247   ScopedVector<DevToolsEventListener> devtools_listeners;
 248   ScopedVector<CommandListener> command_listeners;
 249   Log::Level browser_log_level = Log::kWarning;
 250   const LoggingPrefs& prefs = capabilities.logging_prefs;
 251
 252   for (LoggingPrefs::const_iterator iter = prefs.begin();
 253        iter != prefs.end();
 254        ++iter) {
 255     std::string type = iter->first;
 256     Log::Level level = iter->second;
 257     if (type == WebDriverLog::kPerformanceType) {
 258       if (level != Log::kOff) {
 259         WebDriverLog* log = new WebDriverLog(type, Log::kAll);
 260         logs.push_back(log);
 261         PerformanceLogger* perf_log =
 262             new PerformanceLogger(log, session,
 263                                   capabilities.perf_logging_prefs);
 264         // We use a proxy for |perf_log|'s |CommandListener| interface.
 265         // Otherwise, |perf_log| would be owned by both session->chrome and
 266         // |session|, which would lead to memory errors on destruction.
 267         // session->chrome will own |perf_log|, and |session| will own |proxy|.
 268         // session->command_listeners (the proxy) will be destroyed first.
 269         CommandListenerProxy* proxy = new CommandListenerProxy(perf_log);
 270         devtools_listeners.push_back(perf_log);
 271         command_listeners.push_back(proxy);
 272       }
 273     } else if (type == WebDriverLog::kBrowserType) {
 274       browser_log_level = level;
 275     } else if (type != WebDriverLog::kDriverType) {
 276       // Driver "should" ignore unrecognized log types, per Selenium tests.
 277       // For example the Java client passes the "client" log type in the caps,
 278       // which the server should never provide.
 279       LOG(WARNING) << "Ignoring unrecognized log type: " << type;
 280     }
 281   }
 282   // Create "browser" log -- should always exist.
 283   WebDriverLog* browser_log =
 284       new WebDriverLog(WebDriverLog::kBrowserType, browser_log_level);
 285   logs.push_back(browser_log);
 286   // If the level is OFF, don't even bother listening for DevTools events.
 287   if (browser_log_level != Log::kOff)
 288     devtools_listeners.push_back(new ConsoleLogger(browser_log));
 289
 290   out_logs->swap(logs);
 291   out_devtools_listeners->swap(devtools_listeners);
 292   out_command_listeners->swap(command_listeners);
 293   return Status(kOk);
 294 }