Logging API in chromedriver2.

chrome/test/chromedriver/chrome/devtools_event_logger.cc

Index: chrome/test/chromedriver/chrome/devtools_event_logger.cc
===================================================================
--- chrome/test/chromedriver/chrome/devtools_event_logger.cc	(revision 0)
+++ chrome/test/chromedriver/chrome/devtools_event_logger.cc	(revision 0)
@@ -0,0 +1,135 @@
+// Copyright (c) 2013 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include <stdint.h>
+
+#include "base/json/json_writer.h"
+#include "base/logging.h"
+#include "base/string_util.h"
+#include "base/time.h"
+#include "base/values.h"
+#include "chrome/test/chromedriver/chrome/devtools_client.h"
+#include "chrome/test/chromedriver/chrome/devtools_event_logger.h"
+#include "chrome/test/chromedriver/chrome/status.h"
+
+DevToolsEventLogger::DevToolsEventLogger(
+    const std::string& log_type,
+    const std::vector<std::string>& domains,
+    const std::string& logging_level)
+: log_type_(log_type),
+  domains_(domains),
+  logging_level_(logging_level),
+  log_entries_(new base::ListValue()) {
+  VLOG(1) << "DevToolsEventLogger(" <<
+      log_type_ << ", " << logging_level_ << ")";
+}
+
+DevToolsEventLogger::~DevToolsEventLogger() {
+  VLOG(1) << "Log type '" << log_type_ <<
+      "' lost " << log_entries_->GetSize() << " entries on destruction";
+}
+
+const std::string& DevToolsEventLogger::GetLogType() {
+  return log_type_;
+}
+
+Status DevToolsEventLogger::AddDevToolsClient(DevToolsClient* client) {
+  client->AddListener(this);
+  return OnConnected(client);
+}
+
+static const std::string GetDomainEnableCommand(const std::string& domain) {
+  if ("Timeline" == domain) {
+    return "Timeline.start";
+  } else if ("Page" == domain) {
+    return "";  // Page domain is always enabled for core features.

[kkania, 2013/04/18 17:34:39]

Just return Page.enable. I'd prefer to call Page.enable again. I don't want to
depend on internals of other code.

[klm, 2013/04/18 19:11:31]

Done. Hope it's idempotent:)

+  } else {
+    return domain + ".enable";
+  }
+}
+
+Status DevToolsEventLogger::OnConnected(DevToolsClient* client) {
+  base::DictionaryValue params;  // All our enable commands have empty params.
+  scoped_ptr<base::DictionaryValue> result;
+  for (std::vector<std::string>::const_iterator domain = domains_.begin();
+       domain != domains_.end(); ++domain) {
+    const std::string command = GetDomainEnableCommand(*domain);
+    if (0 == command.length()) {
+      continue;
+    }
+    VLOG(1) << "Log type '" << log_type_ << "' sending command: " << command;
+    Status status = client->SendCommandAndGetResult(command, params, &result);
+    // The client may or may not be connected, e.g. from AddDevToolsClient().
+    if (!status.IsOk() && status.code() != kDisconnected) {
+      return status;
+    }
+  }
+  return Status(kOk);
+}
+
+scoped_ptr<base::ListValue> DevToolsEventLogger::GetAndClearLogEntries() {
+  scoped_ptr<base::ListValue> ret(log_entries_.release());
+  log_entries_.reset(new base::ListValue());
+  return ret.Pass();
+}
+
+bool DevToolsEventLogger::IsOurMethod(const std::string& method) {

[kkania, 2013/04/18 17:34:39]

rename to ShouldLogEvent

[klm, 2013/04/18 19:11:31]

Done.

+  for (std::vector<std::string>::const_iterator domain = domains_.begin();
+       domain != domains_.end(); ++domain) {
+    size_t prefix_len = domain->length();
+    if (method.length() > prefix_len && method[prefix_len] == '.' &&
+        StartsWithASCII(method, *domain, true)) {
+      return true;
+    }
+  }
+  return false;
+}
+
+scoped_ptr<DictionaryValue> DevToolsEventLogger::GetLogEntry(
+    DevToolsClient* client,
+    const std::string& method,
+    const base::DictionaryValue& params) {
+  // Get the log event timestamp ASAP. TODO(klm): extract from params?
+  double timestamp_epoch_ms = base::Time::Now().ToJsTime();
+
+  // I (klm) have benchmarked potential implementations, with 100000 iterations:

[kkania, 2013/04/18 17:34:39]

change this to a one line summary comment about perf

[klm, 2013/04/18 19:11:31]

Done.

+  // * JSON by hand: create the entry JSON string by hand.
+  // * JSON writer: create DictionaryValues and use JSONWriter.
+  // * Store a DictionaryValue and delay JSON serialization for the entry.
+  // Make sure params are nontrivial, so the cost or DeepCopy() weighs in.
+  //
+  // End result -- it doesn't matter, the difference is 1/1000's of a ms,
+  // i.e. total single milliseconds difference over a thousand events processed.
+  // For example, on a Macbook Air:
+  //
+  // JSON by hand took 0.0410 ms.
+  // JSON by writer took 0.0403 ms.
+  // Entry as Dictionary, message by hand took 0.0405 ms.
+  // Entry as Dictionary, message via writer took 0.0404 ms.
+
+  base::DictionaryValue log_message_dict;
+  log_message_dict.SetString("webview", client->GetId());
+  log_message_dict.SetString("message.method", method);
+  log_message_dict.Set("message.params", params.DeepCopy());
+  std::string log_message_json;
+  base::JSONWriter::Write(&log_message_dict, &log_message_json);
+
+  scoped_ptr<base::DictionaryValue> log_entry_dict(new base::DictionaryValue());
+  log_entry_dict->SetDouble("timestamp", (int64_t)timestamp_epoch_ms);

[kkania, 2013/04/18 17:34:39]

static_cast<int64>, include base/basictypes.h, remove stdint.h

[klm, 2013/04/18 19:11:31]

Done.

+  log_entry_dict->SetString("level", logging_level_);
+  log_entry_dict->SetString("message", log_message_json);
+  return log_entry_dict.Pass();
+}
+
+void DevToolsEventLogger::OnEvent(DevToolsClient* client,
+                                  const std::string& method,
+                                  const base::DictionaryValue& params) {
+  if (!IsOurMethod(method)) {
+    return;
+  }
+
+  scoped_ptr<DictionaryValue> entry = GetLogEntry(client, method, params);
+  // TODO(klm): C++11: std::move(log_entry_json).

[kkania, 2013/04/18 17:34:39]

remove

[klm, 2013/04/18 19:11:31]

Done.

+  log_entries_->Append(entry.release());
+}