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 void WebDriverLog::AddEntryTimestamped(const base::Time& timestamp,
 154                                        Log::Level level,
 155                                        const std::string& source,
 156                                        const std::string& message) {
 157   if (level < min_level_)
 158     return;
 159
 160   scoped_ptr<base::DictionaryValue> log_entry_dict(new base::DictionaryValue());
 161   log_entry_dict->SetDouble("timestamp",
 162                             static_cast<int64>(timestamp.ToJsTime()));
 163   log_entry_dict->SetString("level", LevelToName(level));
 164   if (!source.empty())
 165     log_entry_dict->SetString("source", source);
 166   log_entry_dict->SetString("message", message);
 167   entries_->Append(log_entry_dict.release());
 168 }
 169
 170 const std::string& WebDriverLog::type() const {
 171   return type_;
 172 }
 173
 174 void WebDriverLog::set_min_level(Level min_level) {
 175   min_level_ = min_level;
 176 }
 177
 178 Log::Level WebDriverLog::min_level() const {
 179   return min_level_;
 180 }
 181
 182 bool InitLogging() {
 183   InitLogging(&InternalIsVLogOn);
 184   g_start_time = base::TimeTicks::Now().ToInternalValue();
 185
 186   CommandLine* cmd_line = CommandLine::ForCurrentProcess();
 187   if (cmd_line->HasSwitch("log-path")) {
 188     g_log_level = Log::kInfo;
 189     base::FilePath log_path = cmd_line->GetSwitchValuePath("log-path");
 190 #if defined(OS_WIN)
 191     FILE* redir_stderr = _wfreopen(log_path.value().c_str(), L"w", stderr);
 192 #else
 193     FILE* redir_stderr = freopen(log_path.value().c_str(), "w", stderr);
 194 #endif
 195     if (!redir_stderr) {
 196       printf("Failed to redirect stderr to log file.\n");
 197       return false;
 198     }
 199   }
 200   if (cmd_line->HasSwitch("silent"))
 201     g_log_level = Log::kOff;
 202
 203   if (cmd_line->HasSwitch("verbose"))
 204     g_log_level = Log::kAll;
 205
 206   // Turn on VLOG for chromedriver. This is parsed during logging::InitLogging.
 207   cmd_line->AppendSwitchASCII("vmodule", "*/chrome/test/chromedriver/*=3");
 208
 209   logging::SetMinLogLevel(logging::LOG_WARNING);
 210   logging::SetLogItems(false,   // enable_process_id
 211                        false,   // enable_thread_id
 212                        false,   // enable_timestamp
 213                        false);  // enable_tickcount
 214   logging::SetLogMessageHandler(&HandleLogMessage);
 215
 216   logging::LoggingSettings logging_settings;
 217   logging_settings.logging_dest = logging::LOG_TO_SYSTEM_DEBUG_LOG;
 218   return logging::InitLogging(logging_settings);
 219 }
 220
 221 Status CreateLogs(const Capabilities& capabilities,
 222                   ScopedVector<WebDriverLog>* out_logs,
 223                   ScopedVector<DevToolsEventListener>* out_listeners) {
 224   ScopedVector<WebDriverLog> logs;
 225   ScopedVector<DevToolsEventListener> listeners;
 226   Log::Level browser_log_level = Log::kWarning;
 227   const LoggingPrefs& prefs = capabilities.logging_prefs;
 228
 229   for (LoggingPrefs::const_iterator iter = prefs.begin();
 230        iter != prefs.end();
 231        ++iter) {
 232     std::string type = iter->first;
 233     Log::Level level = iter->second;
 234     if (type == WebDriverLog::kPerformanceType) {
 235       if (level != Log::kOff) {
 236         WebDriverLog* log = new WebDriverLog(type, Log::kAll);
 237         logs.push_back(log);
 238         listeners.push_back(new PerformanceLogger(log));
 239       }
 240     } else if (type == WebDriverLog::kBrowserType) {
 241       browser_log_level = level;
 242     } else if (type != WebDriverLog::kDriverType) {
 243       // Driver "should" ignore unrecognized log types, per Selenium tests.
 244       // For example the Java client passes the "client" log type in the caps,
 245       // which the server should never provide.
 246       LOG(WARNING) << "Ignoring unrecognized log type: " << type;
 247     }
 248   }
 249   // Create "browser" log -- should always exist.
 250   WebDriverLog* browser_log =
 251       new WebDriverLog(WebDriverLog::kBrowserType, browser_log_level);
 252   logs.push_back(browser_log);
 253   // If the level is OFF, don't even bother listening for DevTools events.
 254   if (browser_log_level != Log::kOff)
 255     listeners.push_back(new ConsoleLogger(browser_log));
 256
 257   out_logs->swap(logs);
 258   out_listeners->swap(listeners);
 259   return Status(kOk);
 260 }