src/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/performance_logger.h"
  18 #include "chrome/test/chromedriver/chrome/status.h"
  19 #include "chrome/test/chromedriver/session.h"
  20
  21 #if defined(OS_POSIX)
  22 #include <fcntl.h>
  23 #include <unistd.h>
  24 #endif
  25
  26
  27 namespace {
  28
  29 Log::Level g_log_level = Log::kWarning;
  30
  31 int64 g_start_time = 0;
  32
  33 // Array indices are the Log::Level enum values.
  34 const char* kLevelToName[] = {
  35   "ALL",  // kAll
  36   "DEBUG",  // kDebug
  37   "INFO",  // kInfo
  38   "WARNING",  // kWarning
  39   "SEVERE",  // kError
  40   "OFF",  // kOff
  41 };
  42
  43 const char* LevelToName(Log::Level level) {
  44   const int index = level - Log::kAll;
  45   CHECK_GE(index, 0);
  46   CHECK_LT(static_cast<size_t>(index), arraysize(kLevelToName));
  47   return kLevelToName[index];
  48 }
  49
  50 struct LevelPair {
  51   const char* name;
  52   Log::Level level;
  53 };
  54
  55 const LevelPair kNameToLevel[] = {
  56     {"ALL", Log::kAll},
  57     {"DEBUG", Log::kDebug},
  58     {"INFO", Log::kInfo},
  59     {"WARNING", Log::kWarning},
  60     {"SEVERE", Log::kError},
  61     {"OFF", Log::kOff},
  62 };
  63
  64 Log::Level GetLevelFromSeverity(int severity) {
  65   switch (severity) {
  66     case logging::LOG_FATAL:
  67     case logging::LOG_ERROR_REPORT:
  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                   ScopedVector<WebDriverLog>* out_logs,
 243                   ScopedVector<DevToolsEventListener>* out_listeners) {
 244   ScopedVector<WebDriverLog> logs;
 245   ScopedVector<DevToolsEventListener> listeners;
 246   Log::Level browser_log_level = Log::kWarning;
 247   const LoggingPrefs& prefs = capabilities.logging_prefs;
 248
 249   for (LoggingPrefs::const_iterator iter = prefs.begin();
 250        iter != prefs.end();
 251        ++iter) {
 252     std::string type = iter->first;
 253     Log::Level level = iter->second;
 254     if (type == WebDriverLog::kPerformanceType) {
 255       if (level != Log::kOff) {
 256         WebDriverLog* log = new WebDriverLog(type, Log::kAll);
 257         logs.push_back(log);
 258         listeners.push_back(new PerformanceLogger(log));
 259       }
 260     } else if (type == WebDriverLog::kBrowserType) {
 261       browser_log_level = level;
 262     } else if (type != WebDriverLog::kDriverType) {
 263       // Driver "should" ignore unrecognized log types, per Selenium tests.
 264       // For example the Java client passes the "client" log type in the caps,
 265       // which the server should never provide.
 266       LOG(WARNING) << "Ignoring unrecognized log type: " << type;
 267     }
 268   }
 269   // Create "browser" log -- should always exist.
 270   WebDriverLog* browser_log =
 271       new WebDriverLog(WebDriverLog::kBrowserType, browser_log_level);
 272   logs.push_back(browser_log);
 273   // If the level is OFF, don't even bother listening for DevTools events.
 274   if (browser_log_level != Log::kOff)
 275     listeners.push_back(new ConsoleLogger(browser_log));
 276
 277   out_logs->swap(logs);
 278   out_listeners->swap(listeners);
 279   return Status(kOk);
 280 }