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 } 261
