1// Copyright 2014 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/performance_logger.h"
6
7#include "base/compiler_specific.h"
8#include "base/format_macros.h"
9#include "base/json/json_reader.h"
10#include "base/memory/scoped_vector.h"
11#include "base/time/time.h"
12#include "base/values.h"
13#include "chrome/test/chromedriver/chrome/devtools_client_impl.h"
14#include "chrome/test/chromedriver/chrome/log.h"
15#include "chrome/test/chromedriver/chrome/status.h"
16#include "chrome/test/chromedriver/chrome/stub_devtools_client.h"
17#include "chrome/test/chromedriver/session.h"
18#include "testing/gtest/include/gtest/gtest.h"
19
20namespace {
21
22struct DevToolsCommand {
23  DevToolsCommand(const std::string& in_method,
24                  base::DictionaryValue* in_params)
25      : method(in_method) {
26    params.reset(in_params);
27  }
28  ~DevToolsCommand() {}
29
30  std::string method;
31  scoped_ptr<base::DictionaryValue> params;
32};
33
34class FakeDevToolsClient : public StubDevToolsClient {
35 public:
36  explicit FakeDevToolsClient(const std::string& id)
37      : id_(id), listener_(NULL), command_index_(0) {}
38  virtual ~FakeDevToolsClient() {}
39
40  bool PopSentCommand(DevToolsCommand** out_command) {
41    if (sent_commands_.size() > command_index_) {
42      *out_command = sent_commands_.get().at(command_index_++);
43      return true;
44    }
45    return false;
46  }
47
48  Status TriggerEvent(const std::string& method) {
49    base::DictionaryValue empty_params;
50    return listener_->OnEvent(this, method, empty_params);
51  }
52
53  Status TriggerEvent(const std::string& method,
54                      const base::DictionaryValue& params) {
55    return listener_->OnEvent(this, method, params);
56  }
57
58  // Overridden from DevToolsClient:
59  virtual Status ConnectIfNecessary() OVERRIDE {
60    return listener_->OnConnected(this);
61  }
62
63  virtual Status SendCommandAndGetResult(
64      const std::string& method,
65      const base::DictionaryValue& params,
66      scoped_ptr<base::DictionaryValue>* result) OVERRIDE {
67    sent_commands_.push_back(new DevToolsCommand(method,
68                                                 params.DeepCopy()));
69    return Status(kOk);
70  }
71
72  virtual void AddListener(DevToolsEventListener* listener) OVERRIDE {
73    CHECK(!listener_);
74    listener_ = listener;
75  }
76
77  virtual const std::string& GetId() OVERRIDE {
78    return id_;
79  }
80
81 private:
82  const std::string id_;  // WebView id.
83  ScopedVector<DevToolsCommand> sent_commands_;  // Commands that were sent.
84  DevToolsEventListener* listener_;  // The fake allows only one event listener.
85  size_t command_index_;
86};
87
88struct LogEntry {
89  const base::Time timestamp;
90  const Log::Level level;
91  const std::string source;
92  const std::string message;
93
94  LogEntry(const base::Time& timestamp,
95           Log::Level level,
96           const std::string& source,
97           const std::string& message)
98      : timestamp(timestamp), level(level), source(source), message(message) {}
99};
100
101class FakeLog : public Log {
102 public:
103  virtual void AddEntryTimestamped(const base::Time& timestamp,
104                        Level level,
105                        const std::string& source,
106                        const std::string& message) OVERRIDE;
107
108  const ScopedVector<LogEntry>& GetEntries() {
109    return entries_;
110  }
111
112 private:
113  ScopedVector<LogEntry> entries_;
114};
115
116void FakeLog::AddEntryTimestamped(const base::Time& timestamp,
117                                  Level level,
118                                  const std::string& source,
119                                  const std::string& message) {
120  entries_.push_back(new LogEntry(timestamp, level, source, message));
121}
122
123scoped_ptr<base::DictionaryValue> ParseDictionary(const std::string& json) {
124  std::string error;
125  scoped_ptr<base::Value> value(base::JSONReader::ReadAndReturnError(
126      json, base::JSON_PARSE_RFC, NULL, &error));
127  if (value == NULL) {
128    SCOPED_TRACE(json.c_str());
129    SCOPED_TRACE(error.c_str());
130    ADD_FAILURE();
131    return scoped_ptr<base::DictionaryValue>();
132  }
133  base::DictionaryValue* dict = NULL;
134  if (!value->GetAsDictionary(&dict)) {
135    SCOPED_TRACE("JSON object is not a dictionary");
136    ADD_FAILURE();
137    return scoped_ptr<base::DictionaryValue>();
138  }
139  return scoped_ptr<base::DictionaryValue>(dict->DeepCopy());
140}
141
142void ValidateLogEntry(const LogEntry *entry,
143                      const std::string& expected_webview,
144                      const std::string& expected_method,
145                      const base::DictionaryValue& expected_params) {
146  EXPECT_EQ(Log::kInfo, entry->level);
147  EXPECT_LT(0, entry->timestamp.ToTimeT());
148
149  scoped_ptr<base::DictionaryValue> message(ParseDictionary(entry->message));
150  std::string webview;
151  EXPECT_TRUE(message->GetString("webview", &webview));
152  EXPECT_EQ(expected_webview, webview);
153  std::string method;
154  EXPECT_TRUE(message->GetString("message.method", &method));
155  EXPECT_EQ(expected_method, method);
156  base::DictionaryValue* params;
157  EXPECT_TRUE(message->GetDictionary("message.params", &params));
158  EXPECT_TRUE(params->Equals(&expected_params));
159}
160
161void ValidateLogEntry(const LogEntry *entry,
162                      const std::string& expected_webview,
163                      const std::string& expected_method) {
164  base::DictionaryValue empty_params;
165  ValidateLogEntry(entry, expected_webview, expected_method, empty_params);
166}
167
168void ExpectCommand(FakeDevToolsClient& client, const std::string& method) {
169  DevToolsCommand* cmd;
170  // Use ASSERT so that test fails if no command is returned.
171  ASSERT_TRUE(client.PopSentCommand(&cmd));
172  EXPECT_EQ(method, cmd->method);
173}
174
175void ExpectEnableDomains(FakeDevToolsClient& client) {
176  ExpectCommand(client, "Network.enable");
177  ExpectCommand(client, "Page.enable");
178  ExpectCommand(client, "Timeline.start");
179}
180
181}  // namespace
182
183TEST(PerformanceLogger, OneWebView) {
184  FakeDevToolsClient client("webview-1");
185  FakeLog log;
186  Session session("test");
187  PerformanceLogger logger(&log, &session);
188
189  client.AddListener(&logger);
190  logger.OnConnected(&client);
191  ExpectEnableDomains(client);
192  ASSERT_EQ(kOk, client.TriggerEvent("Network.gaga").code());
193  ASSERT_EQ(kOk, client.TriggerEvent("Page.ulala").code());
194  // Ignore -- different domain.
195  ASSERT_EQ(kOk, client.TriggerEvent("Console.bad").code());
196
197  ASSERT_EQ(2u, log.GetEntries().size());
198  ValidateLogEntry(log.GetEntries()[0], "webview-1", "Network.gaga");
199  ValidateLogEntry(log.GetEntries()[1], "webview-1", "Page.ulala");
200}
201
202TEST(PerformanceLogger, TwoWebViews) {
203  FakeDevToolsClient client1("webview-1");
204  FakeDevToolsClient client2("webview-2");
205  FakeLog log;
206  Session session("test");
207  PerformanceLogger logger(&log, &session);
208
209  client1.AddListener(&logger);
210  client2.AddListener(&logger);
211  logger.OnConnected(&client1);
212  logger.OnConnected(&client2);
213  ExpectEnableDomains(client1);
214  ExpectEnableDomains(client2);
215  // OnConnected sends the enable command only to that client, not others.
216  client1.ConnectIfNecessary();
217  ExpectEnableDomains(client1);
218  DevToolsCommand* cmd;
219  ASSERT_FALSE(client2.PopSentCommand(&cmd));
220
221  ASSERT_EQ(kOk, client1.TriggerEvent("Page.gaga1").code());
222  ASSERT_EQ(kOk, client2.TriggerEvent("Timeline.gaga2").code());
223
224  ASSERT_EQ(2u, log.GetEntries().size());
225  ValidateLogEntry(log.GetEntries()[0], "webview-1", "Page.gaga1");
226  ValidateLogEntry(log.GetEntries()[1], "webview-2", "Timeline.gaga2");
227}
228
229TEST(PerformanceLogger, PerfLoggingPrefs) {
230  FakeDevToolsClient client("webview-1");
231  FakeLog log;
232  Session session("test");
233  PerfLoggingPrefs prefs;
234  EXPECT_EQ(PerfLoggingPrefs::InspectorDomainStatus::kDefaultEnabled,
235            prefs.network);
236  prefs.network = PerfLoggingPrefs::InspectorDomainStatus::kExplicitlyDisabled;
237  prefs.trace_categories = "benchmark,blink.console";
238  PerformanceLogger logger(&log, &session, prefs);
239
240  client.AddListener(&logger);
241  logger.OnConnected(&client);
242  ExpectCommand(client, "Page.enable");
243  // Do not expect Timeline.enable command since specifying trace categories
244  // implicitly disables Timeline feed.
245  DevToolsCommand* cmd;
246  ASSERT_FALSE(client.PopSentCommand(&cmd));
247}
248
249namespace {
250
251class FakeBrowserwideClient : public FakeDevToolsClient {
252 public:
253  FakeBrowserwideClient()
254      : FakeDevToolsClient(DevToolsClientImpl::kBrowserwideDevToolsClientId),
255        events_handled_(false) {}
256  virtual ~FakeBrowserwideClient() {}
257
258  bool events_handled() const {
259    return events_handled_;
260  }
261
262  // Overridden from DevToolsClient:
263  virtual Status HandleEventsUntil(
264      const ConditionalFunc& conditional_func,
265      const base::TimeDelta& timeout) OVERRIDE {
266    TriggerEvent("Tracing.tracingComplete");
267    events_handled_ = true;
268    return Status(kOk);
269  }
270
271 private:
272  bool events_handled_;
273};
274
275}  // namespace
276
277TEST(PerformanceLogger, TracingStartStop) {
278  FakeBrowserwideClient client;
279  FakeLog log;
280  Session session("test");
281  PerfLoggingPrefs prefs;
282  prefs.trace_categories = "benchmark,blink.console";
283  PerformanceLogger logger(&log, &session, prefs);
284
285  client.AddListener(&logger);
286  logger.OnConnected(&client);
287  DevToolsCommand* cmd;
288  ASSERT_TRUE(client.PopSentCommand(&cmd));
289  EXPECT_EQ("Tracing.start", cmd->method);
290  std::string expected_cats;
291  EXPECT_TRUE(cmd->params->GetString("categories", &expected_cats));
292  EXPECT_EQ("benchmark,blink.console", expected_cats);
293  int expected_interval = 0;
294  EXPECT_TRUE(cmd->params->GetInteger("bufferUsageReportingInterval",
295                                      &expected_interval));
296  EXPECT_GT(expected_interval, 0);
297  ASSERT_FALSE(client.PopSentCommand(&cmd));
298
299  EXPECT_FALSE(client.events_handled());
300  // Trigger a dump of the DevTools trace buffer.
301  ASSERT_EQ(kOk, logger.BeforeCommand("GetLog").code());
302  EXPECT_TRUE(client.events_handled());
303  ExpectCommand(client, "Tracing.end");
304  ExpectCommand(client, "Tracing.start");  // Tracing should re-start.
305  ASSERT_FALSE(client.PopSentCommand(&cmd));
306}
307
308TEST(PerformanceLogger, RecordTraceEvents) {
309  FakeBrowserwideClient client;
310  FakeLog log;
311  Session session("test");
312  PerfLoggingPrefs prefs;
313  prefs.trace_categories = "benchmark,blink.console";
314  PerformanceLogger logger(&log, &session, prefs);
315
316  client.AddListener(&logger);
317  logger.OnConnected(&client);
318  base::DictionaryValue params;
319  base::ListValue* trace_events = new base::ListValue();
320  base::DictionaryValue* event1 = new base::DictionaryValue();
321  event1->SetString("cat", "foo");
322  trace_events->Append(event1);
323  base::DictionaryValue* event2 = new base::DictionaryValue();
324  event2->SetString("cat", "bar");
325  trace_events->Append(event2);
326  params.Set("value", trace_events);
327  ASSERT_EQ(kOk, client.TriggerEvent("Tracing.dataCollected", params).code());
328
329  ASSERT_EQ(2u, log.GetEntries().size());
330  ValidateLogEntry(log.GetEntries()[0],
331                   DevToolsClientImpl::kBrowserwideDevToolsClientId,
332                   "Tracing.dataCollected", *event1);
333  ValidateLogEntry(log.GetEntries()[1],
334                   DevToolsClientImpl::kBrowserwideDevToolsClientId,
335                   "Tracing.dataCollected", *event2);
336}
337
338TEST(PerformanceLogger, ShouldRequestTraceEvents) {
339  FakeBrowserwideClient client;
340  FakeLog log;
341  Session session("test");
342  PerfLoggingPrefs prefs;
343  prefs.trace_categories = "benchmark,blink.console";
344  PerformanceLogger logger(&log, &session, prefs);
345
346  client.AddListener(&logger);
347  logger.OnConnected(&client);
348  EXPECT_FALSE(client.events_handled());
349  // Trace events should not be dumped for commands not in whitelist.
350  ASSERT_EQ(kOk, logger.BeforeCommand("Blah").code());
351  EXPECT_FALSE(client.events_handled());
352  ASSERT_EQ(kOk, logger.BeforeCommand("Foo").code());
353  EXPECT_FALSE(client.events_handled());
354  // Trace events should always be dumped for GetLog command.
355  ASSERT_EQ(kOk, logger.BeforeCommand("GetLog").code());
356  EXPECT_TRUE(client.events_handled());
357}
358
359TEST(PerformanceLogger, WarnWhenTraceBufferFull) {
360  FakeBrowserwideClient client;
361  FakeLog log;
362  Session session("test");
363  PerfLoggingPrefs prefs;
364  prefs.trace_categories = "benchmark,blink.console";
365  PerformanceLogger logger(&log, &session, prefs);
366
367  client.AddListener(&logger);
368  logger.OnConnected(&client);
369  base::DictionaryValue params;
370  params.SetDouble("value", 1.0);
371  ASSERT_EQ(kOk, client.TriggerEvent("Tracing.bufferUsage", params).code());
372
373  ASSERT_EQ(1u, log.GetEntries().size());
374  LogEntry* entry = log.GetEntries()[0];
375  EXPECT_EQ(Log::kWarning, entry->level);
376  EXPECT_LT(0, entry->timestamp.ToTimeT());
377  scoped_ptr<base::DictionaryValue> message(ParseDictionary(entry->message));
378  std::string webview;
379  EXPECT_TRUE(message->GetString("webview", &webview));
380  EXPECT_EQ(DevToolsClientImpl::kBrowserwideDevToolsClientId, webview);
381  std::string method;
382  EXPECT_TRUE(message->GetString("message.method", &method));
383  EXPECT_EQ("Tracing.bufferUsage", method);
384  base::DictionaryValue* actual_params;
385  EXPECT_TRUE(message->GetDictionary("message.params", &actual_params));
386  EXPECT_TRUE(actual_params->HasKey("error"));
387}
388