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
LevelToName(Log::Level level)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
GetLevelFromSeverity(int severity)64 Log::Level GetLevelFromSeverity(int severity) {
65 switch (severity) {
66 case logging::LOG_FATAL:
67 case logging::LOG_ERROR:
68 return Log::kError;
69 case logging::LOG_WARNING:
70 return Log::kWarning;
71 case logging::LOG_INFO:
72 return Log::kInfo;
73 case logging::LOG_VERBOSE:
74 default:
75 return Log::kDebug;
76 }
77 }
78
GetSessionLog()79 WebDriverLog* GetSessionLog() {
80 Session* session = GetThreadLocalSession();
81 if (!session)
82 return NULL;
83 return session->driver_log.get();
84 }
85
InternalIsVLogOn(int vlog_level)86 bool InternalIsVLogOn(int vlog_level) {
87 WebDriverLog* session_log = GetSessionLog();
88 Log::Level session_level = session_log ? session_log->min_level() : Log::kOff;
89 Log::Level level = g_log_level < session_level ? g_log_level : session_level;
90 return GetLevelFromSeverity(vlog_level * -1) >= level;
91 }
92
HandleLogMessage(int severity,const char * file,int line,size_t message_start,const std::string & str)93 bool HandleLogMessage(int severity,
94 const char* file,
95 int line,
96 size_t message_start,
97 const std::string& str) {
98 Log::Level level = GetLevelFromSeverity(severity);
99 std::string message = str.substr(message_start);
100
101 if (level >= g_log_level) {
102 const char* level_name = LevelToName(level);
103 std::string entry = base::StringPrintf(
104 "[%.3lf][%s]: %s",
105 base::TimeDelta(base::TimeTicks::Now() -
106 base::TimeTicks::FromInternalValue(g_start_time))
107 .InSecondsF(),
108 level_name,
109 message.c_str());
110 fprintf(stderr, "%s", entry.c_str());
111 fflush(stderr);
112 }
113
114 WebDriverLog* session_log = GetSessionLog();
115 if (session_log)
116 session_log->AddEntry(level, message);
117
118 return true;
119 }
120
121 } // namespace
122
123 const char WebDriverLog::kBrowserType[] = "browser";
124 const char WebDriverLog::kDriverType[] = "driver";
125 const char WebDriverLog::kPerformanceType[] = "performance";
126
NameToLevel(const std::string & name,Log::Level * out_level)127 bool WebDriverLog::NameToLevel(const std::string& name, Log::Level* out_level) {
128 for (size_t i = 0; i < arraysize(kNameToLevel); ++i) {
129 if (name == kNameToLevel[i].name) {
130 *out_level = kNameToLevel[i].level;
131 return true;
132 }
133 }
134 return false;
135 }
136
WebDriverLog(const std::string & type,Log::Level min_level)137 WebDriverLog::WebDriverLog(const std::string& type, Log::Level min_level)
138 : type_(type), min_level_(min_level), entries_(new base::ListValue()) {
139 }
140
~WebDriverLog()141 WebDriverLog::~WebDriverLog() {
142 VLOG(1) << "Log type '" << type_ << "' lost "
143 << entries_->GetSize() << " entries on destruction";
144 }
145
GetAndClearEntries()146 scoped_ptr<base::ListValue> WebDriverLog::GetAndClearEntries() {
147 scoped_ptr<base::ListValue> ret(entries_.release());
148 entries_.reset(new base::ListValue());
149 return ret.Pass();
150 }
151
GetFirstErrorMessage() const152 std::string WebDriverLog::GetFirstErrorMessage() const {
153 for (base::ListValue::iterator it = entries_->begin();
154 it != entries_->end();
155 ++it) {
156 base::DictionaryValue* log_entry = NULL;
157 (*it)->GetAsDictionary(&log_entry);
158 if (log_entry != NULL) {
159 std::string level;
160 if (log_entry->GetString("level", &level)) {
161 if (level == kLevelToName[Log::kError]) {
162 std::string message;
163 if (log_entry->GetString("message", &message))
164 return message;
165 }
166 }
167 }
168 }
169 return std::string();
170 }
171
AddEntryTimestamped(const base::Time & timestamp,Log::Level level,const std::string & source,const std::string & message)172 void WebDriverLog::AddEntryTimestamped(const base::Time& timestamp,
173 Log::Level level,
174 const std::string& source,
175 const std::string& message) {
176 if (level < min_level_)
177 return;
178
179 scoped_ptr<base::DictionaryValue> log_entry_dict(new base::DictionaryValue());
180 log_entry_dict->SetDouble("timestamp",
181 static_cast<int64>(timestamp.ToJsTime()));
182 log_entry_dict->SetString("level", LevelToName(level));
183 if (!source.empty())
184 log_entry_dict->SetString("source", source);
185 log_entry_dict->SetString("message", message);
186 entries_->Append(log_entry_dict.release());
187 }
188
type() const189 const std::string& WebDriverLog::type() const {
190 return type_;
191 }
192
set_min_level(Level min_level)193 void WebDriverLog::set_min_level(Level min_level) {
194 min_level_ = min_level;
195 }
196
min_level() const197 Log::Level WebDriverLog::min_level() const {
198 return min_level_;
199 }
200
InitLogging()201 bool InitLogging() {
202 InitLogging(&InternalIsVLogOn);
203 g_start_time = base::TimeTicks::Now().ToInternalValue();
204
205 CommandLine* cmd_line = CommandLine::ForCurrentProcess();
206 if (cmd_line->HasSwitch("log-path")) {
207 g_log_level = Log::kInfo;
208 base::FilePath log_path = cmd_line->GetSwitchValuePath("log-path");
209 #if defined(OS_WIN)
210 FILE* redir_stderr = _wfreopen(log_path.value().c_str(), L"w", stderr);
211 #else
212 FILE* redir_stderr = freopen(log_path.value().c_str(), "w", stderr);
213 #endif
214 if (!redir_stderr) {
215 printf("Failed to redirect stderr to log file.\n");
216 return false;
217 }
218 }
219 if (cmd_line->HasSwitch("silent"))
220 g_log_level = Log::kOff;
221
222 if (cmd_line->HasSwitch("verbose"))
223 g_log_level = Log::kAll;
224
225 // Turn on VLOG for chromedriver. This is parsed during logging::InitLogging.
226 cmd_line->AppendSwitchASCII("vmodule", "*/chrome/test/chromedriver/*=3");
227
228 logging::SetMinLogLevel(logging::LOG_WARNING);
229 logging::SetLogItems(false, // enable_process_id
230 false, // enable_thread_id
231 false, // enable_timestamp
232 false); // enable_tickcount
233 logging::SetLogMessageHandler(&HandleLogMessage);
234
235 logging::LoggingSettings logging_settings;
236 logging_settings.logging_dest = logging::LOG_TO_SYSTEM_DEBUG_LOG;
237 return logging::InitLogging(logging_settings);
238 }
239
CreateLogs(const Capabilities & capabilities,ScopedVector<WebDriverLog> * out_logs,ScopedVector<DevToolsEventListener> * out_listeners)240 Status CreateLogs(const Capabilities& capabilities,
241 ScopedVector<WebDriverLog>* out_logs,
242 ScopedVector<DevToolsEventListener>* out_listeners) {
243 ScopedVector<WebDriverLog> logs;
244 ScopedVector<DevToolsEventListener> listeners;
245 Log::Level browser_log_level = Log::kWarning;
246 const LoggingPrefs& prefs = capabilities.logging_prefs;
247
248 for (LoggingPrefs::const_iterator iter = prefs.begin();
249 iter != prefs.end();
250 ++iter) {
251 std::string type = iter->first;
252 Log::Level level = iter->second;
253 if (type == WebDriverLog::kPerformanceType) {
254 if (level != Log::kOff) {
255 WebDriverLog* log = new WebDriverLog(type, Log::kAll);
256 logs.push_back(log);
257 listeners.push_back(new PerformanceLogger(log));
258 }
259 } else if (type == WebDriverLog::kBrowserType) {
260 browser_log_level = level;
261 } else if (type != WebDriverLog::kDriverType) {
262 // Driver "should" ignore unrecognized log types, per Selenium tests.
263 // For example the Java client passes the "client" log type in the caps,
264 // which the server should never provide.
265 LOG(WARNING) << "Ignoring unrecognized log type: " << type;
266 }
267 }
268 // Create "browser" log -- should always exist.
269 WebDriverLog* browser_log =
270 new WebDriverLog(WebDriverLog::kBrowserType, browser_log_level);
271 logs.push_back(browser_log);
272 // If the level is OFF, don't even bother listening for DevTools events.
273 if (browser_log_level != Log::kOff)
274 listeners.push_back(new ConsoleLogger(browser_log));
275
276 out_logs->swap(logs);
277 out_listeners->swap(listeners);
278 return Status(kOk);
279 }
280