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_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
GetSessionLog()80 WebDriverLog* GetSessionLog() {
81 Session* session = GetThreadLocalSession();
82 if (!session)
83 return NULL;
84 return session->driver_log.get();
85 }
86
InternalIsVLogOn(int vlog_level)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
HandleLogMessage(int severity,const char * file,int line,size_t message_start,const std::string & str)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
NameToLevel(const std::string & name,Log::Level * out_level)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
WebDriverLog(const std::string & type,Log::Level min_level)138 WebDriverLog::WebDriverLog(const std::string& type, Log::Level min_level)
139 : type_(type), min_level_(min_level), entries_(new base::ListValue()) {
140 }
141
~WebDriverLog()142 WebDriverLog::~WebDriverLog() {
143 VLOG(1) << "Log type '" << type_ << "' lost "
144 << entries_->GetSize() << " entries on destruction";
145 }
146
GetAndClearEntries()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
AddEntryTimestamped(const base::Time & timestamp,Log::Level level,const std::string & source,const std::string & message)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
type() const170 const std::string& WebDriverLog::type() const {
171 return type_;
172 }
173
set_min_level(Level min_level)174 void WebDriverLog::set_min_level(Level min_level) {
175 min_level_ = min_level;
176 }
177
min_level() const178 Log::Level WebDriverLog::min_level() const {
179 return min_level_;
180 }
181
InitLogging()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
CreateLogs(const Capabilities & capabilities,ScopedVector<WebDriverLog> * out_logs,ScopedVector<DevToolsEventListener> * out_listeners)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