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* 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 } 295
