Add NetworkEventLog and NetworkEventLogSource to log chromeos network events

This also extracts about_network from about_ui for the chrome://network UI, updating it for NetworkState and NetworkEventLog.
Additionally network event logs (and a dbus summary) are added to feedback reports)

BUG=161369
For chrome/browser/ui/webui/:
TBR=jhawkins@chromium.org


Review URL: https://chromiumcodereview.appspot.com/11416041

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@168946 0039d316-1c4b-4281-b951-d872f2087c98

6 files changed, 369 insertions, 5 deletions

diff --git a/chromeos/chromeos.gyp b/chromeos/chromeos.gyp
index 3cbb1c6..a3ecafb 100644
--- a/chromeos/chromeos.gyp
+++ b/chromeos/chromeos.gyp
@@ -128,6 +128,8 @@
         'network/managed_state.h',
         'network/network_configuration_handler.cc',
         'network/network_configuration_handler.h',
+        'network/network_event_log.cc',
+        'network/network_event_log.h',
         'network/network_sms_handler.cc',
         'network/network_sms_handler.h',
         'network/network_state.cc',
@@ -289,6 +291,7 @@
         'dbus/modem_messaging_client_unittest.cc',
         'disks/disk_mount_manager_unittest.cc',
         'network/network_configuration_handler_unittest.cc',
+        'network/network_event_log_unittest.cc',
         'network/network_sms_handler_unittest.cc',
         'network/network_state_handler_unittest.cc',
         'network/shill_property_handler_unittest.cc',
diff --git a/chromeos/network/network_event_log.cc b/chromeos/network/network_event_log.cc
new file mode 100644
index 0000000..a7d7147
--- /dev/null
+++ b/chromeos/network/network_event_log.cc
@@ -0,0 +1,157 @@
+// Copyright (c) 2012 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 "chromeos/network/network_event_log.h"
+
+#include "base/i18n/time_formatting.h"
+#include "base/logging.h"
+#include "base/memory/scoped_ptr.h"
+#include "base/stringprintf.h"
+#include "base/utf_string_conversions.h"
+
+namespace chromeos {
+
+namespace network_event_log {
+
+namespace {
+
+struct LogEntry {
+  LogEntry(const std::string& module,
+           const std::string& event,
+           const std::string& description);
+
+  std::string ToString() const;
+
+  std::string module;
+  std::string event;
+  std::string description;
+  base::Time time;
+  int count;
+};
+
+LogEntry::LogEntry(const std::string& module,
+                   const std::string& event,
+                   const std::string& description)
+    : module(module),
+      event(event),
+      description(description),
+      time(base::Time::Now()),
+      count(1) {
+}
+
+std::string LogEntry::ToString() const {
+  std::string line;
+  line += "[" + UTF16ToUTF8(base::TimeFormatShortDateAndTime(time)) + "]";
+  line += " " + module + "." + event;
+  if (!description.empty())
+    line += ": " + description;
+  if (count > 1)
+    line += StringPrintf(" (%d)", count);
+  line += "\n";
+  return line;
+}
+
+typedef std::deque<LogEntry> LogEntryList;
+
+class NetworkEventLog {
+ public:
+  NetworkEventLog() {}
+  ~NetworkEventLog() {}
+
+  void AddEntry(const std::string& module,
+                const std::string& event,
+                const std::string& description);
+
+  std::string GetAsString(StringOrder order,
+                          size_t max_events);
+
+ private:
+  LogEntryList entries_;
+
+  DISALLOW_COPY_AND_ASSIGN(NetworkEventLog);
+};
+
+void NetworkEventLog::AddEntry(const std::string& module,
+                               const std::string& event,
+                               const std::string& description) {
+  if (!entries_.empty()) {
+    LogEntry& last = entries_.back();
+    if (last.module == module &&
+        last.event == event &&
+        last.description == description) {
+      // Update count and time for identical events to avoid log spam.
+      ++last.count;
+      last.time = base::Time::Now();
+      return;
+    }
+  }
+  if (entries_.size() >= kMaxNetworkEventLogEntries)
+    entries_.pop_front();
+  entries_.push_back(LogEntry(module, event, description));
+}
+
+std::string NetworkEventLog::GetAsString(StringOrder order,
+                                         size_t max_events) {
+  if (entries_.empty())
+    return "No Log Entries.";
+
+  std::string result;
+  if (order == OLDEST_FIRST) {
+    size_t offset = 0;
+    if (max_events > 0 && max_events < entries_.size())
+      offset = entries_.size() - max_events;
+    for (LogEntryList::const_iterator iter = entries_.begin() + offset;
+         iter != entries_.end(); ++iter) {
+      result += (*iter).ToString();
+    }
+  } else {
+    size_t nlines = 0;
+    // Iterate backwards through the list to show the most recent entries first.
+    for (LogEntryList::const_reverse_iterator riter = entries_.rbegin();
+         riter != entries_.rend(); ++riter) {
+      result += (*riter).ToString();
+      if (max_events > 0 && ++nlines >= max_events)
+        break;
+    }
+  }
+  return result;
+}
+
+}  // namespace
+
+NetworkEventLog* g_network_event_log = NULL;
+const size_t kMaxNetworkEventLogEntries = 1000;
+
+void Initialize() {
+  if (g_network_event_log)
+    delete g_network_event_log;  // reset log
+  g_network_event_log = new NetworkEventLog();
+}
+
+void Shutdown() {
+  delete g_network_event_log;
+  g_network_event_log = NULL;
+}
+
+bool IsInitialized() {
+  return g_network_event_log != NULL;
+}
+
+void AddEntry(const std::string& module,
+              const std::string& event,
+              const std::string& description) {
+  if (!g_network_event_log)
+    return;
+  g_network_event_log->AddEntry(module, event, description);
+}
+
+std::string GetAsString(StringOrder order, size_t max_events) {
+  if (!g_network_event_log)
+    return "NetworkEventLog not intitialized.";
+  return g_network_event_log->GetAsString(order, max_events);
+}
+
+}  // namespace network_event_log
+
+}  // namespace chromeos
diff --git a/chromeos/network/network_event_log.h b/chromeos/network/network_event_log.h
new file mode 100644
index 0000000..be5a2e4
--- /dev/null
+++ b/chromeos/network/network_event_log.h
@@ -0,0 +1,52 @@
+// Copyright (c) 2012 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.
+
+#ifndef CHROMEOS_NETWORK_NETWORK_EVENT_LOG_H_
+#define CHROMEOS_NETWORK_NETWORK_EVENT_LOG_H_
+
+#include <deque>
+#include <string>
+
+#include "base/basictypes.h"
+#include "base/time.h"
+#include "chromeos/chromeos_export.h"
+
+namespace chromeos {
+
+// Namespace for functions for logging network events.
+namespace network_event_log {
+
+// Used to determine which order to output event entries in GetAsString.
+enum StringOrder {
+  OLDEST_FIRST,
+  NEWEST_FIRST
+};
+
+// Maximum number of event log entries, exported for testing.
+CHROMEOS_EXPORT extern const size_t kMaxNetworkEventLogEntries;
+
+// Initializes / shuts down network event logging. Calling Initialize more than
+// once will reset the log.
+CHROMEOS_EXPORT void Initialize();
+CHROMEOS_EXPORT void Shutdown();
+
+// Returns true if network event logging has been initialized.
+CHROMEOS_EXPORT bool IsInitialized();
+
+// Adds an entry to the event log. A maximum number of events are recorded
+// after which new events replace old ones. Does nothing unless Initialize()
+// has been called.
+CHROMEOS_EXPORT void AddEntry(const std::string& module,
+                              const std::string& event,
+                              const std::string& description);
+
+// Outputs the log to a formatted string. |order| determines which order to
+// output the events. If |max_events| > 0, limits how many events are output.
+CHROMEOS_EXPORT std::string GetAsString(StringOrder order, size_t max_events);
+
+}  // namespace network_event_log
+
+}  // namespace chromeos
+
+#endif  // CHROMEOS_NETWORK_NETWORK_EVENT_LOG_H_
diff --git a/chromeos/network/network_event_log_unittest.cc b/chromeos/network/network_event_log_unittest.cc
new file mode 100644
index 0000000..3d44f6c
--- /dev/null
+++ b/chromeos/network/network_event_log_unittest.cc
@@ -0,0 +1,108 @@
+// Copyright (c) 2012 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 "chromeos/network/network_event_log.h"
+
+#include <algorithm>
+
+#include "base/basictypes.h"
+#include "base/compiler_specific.h"
+#include "base/format_macros.h"
+#include "base/string_split.h"
+#include "base/stringprintf.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace chromeos {
+
+class NetworkEventLogTest : public testing::Test {
+ public:
+  NetworkEventLogTest() {
+  }
+
+  virtual void SetUp() OVERRIDE {
+    network_event_log::Initialize();
+  }
+
+  virtual void TearDown() OVERRIDE {
+    network_event_log::Shutdown();
+  }
+
+ protected:
+  std::string SkipTime(const std::string& input) {
+    std::string output;
+    std::vector<std::string> lines;
+    base::SplitString(input, '\n', &lines);
+    for (size_t i = 0; i < lines.size(); ++i) {
+      size_t n = lines[i].find(']');
+      if (n != std::string::npos)
+        output += lines[i].substr(n+2) + '\n';
+    }
+    return output;
+  }
+
+  size_t CountLines(const std::string& input) {
+    return std::count(input.begin(), input.end(), '\n');
+  }
+
+ private:
+  DISALLOW_COPY_AND_ASSIGN(NetworkEventLogTest);
+};
+
+TEST_F(NetworkEventLogTest, TestNetworkEvents) {
+  std::string output_none = network_event_log::GetAsString(
+      network_event_log::OLDEST_FIRST, 0);
+  EXPECT_EQ("No Log Entries.", output_none);
+
+  network_event_log::AddEntry("module1", "event1", "description1");
+  network_event_log::AddEntry("module2", "event2", "description2");
+  network_event_log::AddEntry("module3", "event3", "description3");
+  network_event_log::AddEntry("module3", "event3", "description3");
+
+  const std::string expected_output_oldest_first(
+      "module1.event1: description1\n"
+      "module2.event2: description2\n"
+      "module3.event3: description3 (2)\n");
+  std::string output_oldest_first = network_event_log::GetAsString(
+      network_event_log::OLDEST_FIRST, 0);
+  output_oldest_first = SkipTime(output_oldest_first);
+  EXPECT_EQ(expected_output_oldest_first, output_oldest_first);
+
+  const std::string expected_output_oldest_first_short(
+      "module2.event2: description2\n"
+      "module3.event3: description3 (2)\n");
+  std::string output_oldest_first_short = network_event_log::GetAsString(
+      network_event_log::OLDEST_FIRST, 2);
+  output_oldest_first_short = SkipTime(output_oldest_first_short);
+  EXPECT_EQ(expected_output_oldest_first_short, output_oldest_first_short);
+
+  const std::string expected_output_newest_first(
+      "module3.event3: description3 (2)\n"
+      "module2.event2: description2\n"
+      "module1.event1: description1\n");
+  std::string output_newest_first = network_event_log::GetAsString(
+      network_event_log::NEWEST_FIRST, 0);
+  output_newest_first = SkipTime(output_newest_first);
+  EXPECT_EQ(expected_output_newest_first, output_newest_first);
+
+  const std::string expected_output_newest_first_short(
+      "module3.event3: description3 (2)\n"
+      "module2.event2: description2\n");
+  std::string output_newest_first_short = network_event_log::GetAsString(
+      network_event_log::NEWEST_FIRST, 2);
+  output_newest_first_short = SkipTime(output_newest_first_short);
+  EXPECT_EQ(expected_output_newest_first_short, output_newest_first_short);
+}
+
+TEST_F(NetworkEventLogTest, TestMaxNetworkEvents) {
+  const size_t entries_to_add =
+      network_event_log::kMaxNetworkEventLogEntries + 3;
+  for (size_t i = 0; i < entries_to_add; ++i)
+    network_event_log::AddEntry("test", StringPrintf("event_%"PRIuS, i), "");
+
+  std::string output = GetAsString(network_event_log::OLDEST_FIRST, 0);
+  size_t output_lines = CountLines(output);
+  EXPECT_EQ(network_event_log::kMaxNetworkEventLogEntries, output_lines);
+}
+
+}  // namespace chromeos
diff --git a/chromeos/network/network_state_handler.cc b/chromeos/network/network_state_handler.cc
index 738d328..f8d2ef8 100644
--- a/chromeos/network/network_state_handler.cc
+++ b/chromeos/network/network_state_handler.cc
@@ -4,16 +4,23 @@
 
 #include "chromeos/network/network_state_handler.h"
 
+#include "base/format_macros.h"
 #include "base/stl_util.h"
 #include "base/string_util.h"
+#include "base/stringprintf.h"
 #include "base/values.h"
 #include "chromeos/network/device_state.h"
 #include "chromeos/network/managed_state.h"
+#include "chromeos/network/network_event_log.h"
 #include "chromeos/network/network_state.h"
 #include "chromeos/network/network_state_handler_observer.h"
 #include "chromeos/network/shill_property_handler.h"
 #include "third_party/cros_system_api/dbus/service_constants.h"
 
+namespace {
+const char kLogModule[] = "NetworkPropertyHandler";
+}
+
 namespace chromeos {
 
 static NetworkStateHandler* g_network_state_handler = NULL;
@@ -230,6 +237,9 @@ void NetworkStateHandler::UpdateManagedList(ManagedState::ManagedType type,
 void NetworkStateHandler::UpdateAvailableTechnologies(
     const base::ListValue& technologies) {
   available_technologies_.clear();
+  network_event_log::AddEntry(
+      kLogModule, "AvailableTechnologiesChanged",
+      StringPrintf("Size: %"PRIuS, technologies.GetSize()));
   for (base::ListValue::const_iterator iter = technologies.begin();
        iter != technologies.end(); ++iter) {
     std::string technology;
@@ -242,6 +252,9 @@ void NetworkStateHandler::UpdateAvailableTechnologies(
 void NetworkStateHandler::UpdateEnabledTechnologies(
     const base::ListValue& technologies) {
   enabled_technologies_.clear();
+  network_event_log::AddEntry(
+      kLogModule, "EnabledTechnologiesChanged",
+      StringPrintf("Size: %"PRIuS, technologies.GetSize()));
   for (base::ListValue::const_iterator iter = technologies.begin();
        iter != technologies.end(); ++iter) {
     std::string technology;
@@ -264,9 +277,10 @@ void NetworkStateHandler::UpdateManagedStateProperties(
   for (base::DictionaryValue::Iterator iter(properties);
        iter.HasNext(); iter.Advance()) {
     if (type == ManagedState::MANAGED_TYPE_NETWORK) {
-      if (ParseNetworkServiceProperty(managed->AsNetworkState(),
-                                      iter.key(), iter.value()))
+      if (ParseNetworkServiceProperty(
+              managed->AsNetworkState(), iter.key(), iter.value())) {
         network_property_changed = true;
+      }
     } else {
       managed->PropertyChanged(iter.key(), iter.value());
     }
@@ -278,6 +292,9 @@ void NetworkStateHandler::UpdateManagedStateProperties(
     FOR_EACH_OBSERVER(NetworkStateHandlerObserver, observers_,
                       NetworkServiceChanged(network));
   }
+  network_event_log::AddEntry(
+      kLogModule, "PropertiesReceived",
+      StringPrintf("%s (%s)", path.c_str(), managed->name().c_str()));
 }
 
 void NetworkStateHandler::UpdateNetworkServiceProperty(
@@ -288,6 +305,11 @@ void NetworkStateHandler::UpdateNetworkServiceProperty(
   if (!network)
     return;
   if (ParseNetworkServiceProperty(network, key, value)) {
+    std::string detail = network->name() + "." + key;
+    std::string vstr;
+    if (value.GetAsString(&vstr))
+      detail += " = " + vstr;
+    network_event_log::AddEntry(kLogModule, "NetworkPropertyChanged", detail);
     FOR_EACH_OBSERVER(NetworkStateHandlerObserver, observers_,
                       NetworkServiceChanged(network));
   }
@@ -299,6 +321,8 @@ void NetworkStateHandler::UpdateNetworkServiceIPAddress(
   NetworkState* network = GetModifiableNetworkState(service_path);
   if (!network)
     return;
+  std::string detail = network->name() + ".IPAddress = " + ip_address;
+  network_event_log::AddEntry(kLogModule, "NetworkIPChanged", detail);
   network->set_ip_address(ip_address);
   FOR_EACH_OBSERVER(
       NetworkStateHandlerObserver, observers_,
@@ -316,6 +340,9 @@ void NetworkStateHandler::ManagedStateListChanged(
     // Notify observers that the list of networks has changed.
     NetworkStateList network_list;
     GetNetworkList(&network_list);
+    network_event_log::AddEntry(
+        kLogModule, "NetworkListChanged",
+        StringPrintf("Size: %"PRIuS, network_list_.size()));
     FOR_EACH_OBSERVER(NetworkStateHandlerObserver, observers_,
                       NetworkListChanged(network_list));
     // Update the active network and notify observers if it has changed.
@@ -325,11 +352,16 @@ void NetworkStateHandler::ManagedStateListChanged(
     if (new_active_network)
       new_active_network_path = new_active_network->path();
     if (new_active_network_path != active_network_path_) {
+      network_event_log::AddEntry(
+          kLogModule, "ActiveNetworkChanged", new_active_network_path);
       active_network_path_ = new_active_network_path;
       FOR_EACH_OBSERVER(NetworkStateHandlerObserver, observers_,
                         ActiveNetworkChanged(new_active_network));
     }
   } else if (type == ManagedState::MANAGED_TYPE_DEVICE) {
+    network_event_log::AddEntry(
+        kLogModule, "DeviceListChanged",
+        StringPrintf("Size: %"PRIuS, device_list_.size()));
     FOR_EACH_OBSERVER(NetworkStateHandlerObserver, observers_,
                       DeviceListChanged());
   } else {
diff --git a/chromeos/network/shill_property_handler.cc b/chromeos/network/shill_property_handler.cc
index 9fecfd6..2fe6f99 100644
--- a/chromeos/network/shill_property_handler.cc
+++ b/chromeos/network/shill_property_handler.cc
@@ -5,20 +5,25 @@
 #include "chromeos/network/shill_property_handler.h"
 
 #include "base/bind.h"
+#include "base/format_macros.h"
 #include "base/stl_util.h"
 #include "base/string_util.h"
+#include "base/stringprintf.h"
 #include "base/values.h"
 #include "chromeos/dbus/dbus_thread_manager.h"
 #include "chromeos/dbus/shill_device_client.h"
 #include "chromeos/dbus/shill_ipconfig_client.h"
 #include "chromeos/dbus/shill_manager_client.h"
 #include "chromeos/dbus/shill_service_client.h"
+#include "chromeos/network/network_event_log.h"
 #include "chromeos/network/shill_service_observer.h"
 #include "dbus/object_path.h"
 #include "third_party/cros_system_api/dbus/service_constants.h"
 
 namespace {
 
+const char kLogModule[] = "ShillPropertyHandler";
+
 // Limit the number of services we observe. Since they are listed in priority
 // order, it should be reasonable to ignore services past this.
 const size_t kMaxObservedServices = 100;
@@ -168,7 +173,7 @@ bool ShillPropertyHandler::ManagerPropertyChanged(const std::string& key,
       UpdateManagedList(ManagedState::MANAGED_TYPE_DEVICE, *vlist);
   } else if (key == flimflam::kAvailableTechnologiesProperty) {
     const base::ListValue* vlist = GetListValue(key, value);
-    if (vlist ) {
+    if (vlist) {
       listener_->UpdateAvailableTechnologies(*vlist);
       notify_manager_changed = true;
     }
@@ -218,11 +223,18 @@ void ShillPropertyHandler::UpdateObservedNetworkServices(
     if (new_observed.size() >= kMaxObservedServices)
       break;
   }
+  network_event_log::AddEntry(
+      kLogModule, "ObservedListChanged",
+      StringPrintf("Entries: %"PRIuS " New: %"PRIuS,
+                   entries.GetSize(), new_observed.size()));
   VLOG(2) << "UpdateObservedNetworkServices, new observed: "
           << new_observed.size();
   // Delete network service observers still in observed_networks_.
-  STLDeleteContainerPairSecondPointers(
-      observed_networks_.begin(), observed_networks_.end());
+  for (ShillServiceObserverMap::iterator iter =  observed_networks_.begin();
+       iter != observed_networks_.end(); ++iter) {
+    network_event_log::AddEntry(kLogModule, "StopObserving", iter->first);
+    delete iter->second;
+  }
   observed_networks_.swap(new_observed);
 }