Reduce NetworkStateHandler event spam

With WebUI we rely more on networkingPrivate events which are
triggered by NetworkStateHandler.

NetworkPropertiesUpdated is getting triggered more often than is
necessary. In areas with a large number of visible WiFi networks
this can generate significant extra work for the WebUI JS when
scanning (i.e. when the WiFI subpage is open).

This CL eliminates some uninteresting event notifications (most
of which were already removed from the log but were still firing
events).

Bug: 784026
Change-Id: I7ccf7dc443d6ce59ea36cf425cec6e9a1c1f0222
Reviewed-on: https://chromium-review.googlesource.com/773507
Commit-Queue: Steven Bennetts <stevenjb@chromium.org>
Reviewed-by: Kyle Horimoto <khorimoto@chromium.org>
Cr-Commit-Position: refs/heads/master@{#517589}

chromeos/network/network_state_handler.cc

@@ -12,8 +12,6 @@
 #include "base/command_line.h"
 #include "base/format_macros.h"
 #include "base/guid.h"
-#include "base/json/json_string_value_serializer.h"
-#include "base/json/json_writer.h"
 #include "base/location.h"
 #include "base/memory/ptr_util.h"
 #include "base/metrics/histogram_macros.h"
@@ -63,13 +61,6 @@ std::string GetLogName(const ManagedState* state) {
                             state->path().c_str());
 }
 
-std::string ValueAsString(const base::Value& value) {
-  std::string vstr;
-  base::JSONWriter::WriteWithOptions(
-      value, base::JSONWriter::OPTIONS_OMIT_BINARY_VALUES, &vstr);
-  return vstr.empty() ? "''" : vstr;
-}
-
 bool ShouldIncludeNetworkInList(const NetworkState* network_state,
                                 bool configured_only,
                                 bool visible_only,
@@ -1149,51 +1140,47 @@ void NetworkStateHandler::UpdateNetworkServiceProperty(
   if (!changed)
     return;
 
+  // If added to a Profile, request a full update so that a NetworkState
+  // gets created.
+  bool request_update =
+      prev_profile_path.empty() && !network->profile_path().empty();
+
+  bool notify_default = network->path() == default_network_path_;
+
   if (key == shill::kStateProperty || key == shill::kVisibleProperty) {
     network_list_sorted_ = false;
     if (ConnectionStateChanged(network, prev_connection_state,
                                prev_is_captive_portal)) {
-      OnNetworkConnectionStateChanged(network);
+      if (OnNetworkConnectionStateChanged(network))
+        notify_default = false;  // already notified
       // If the connection state changes, other properties such as IPConfig
       // may have changed, so request a full update.
-      RequestUpdateForNetwork(service_path);
-    }
-  } else {
-    std::string value_str;
-    value.GetAsString(&value_str);
-    // Some property changes are noisy and not interesting:
-    // * Wifi SignalStrength
-    // * WifiFrequencyList updates
-    // * Device property changes to "/" (occurs before a service is removed)
-    if (key != shill::kSignalStrengthProperty &&
-        key != shill::kWifiFrequencyListProperty &&
-        (key != shill::kDeviceProperty || value_str != "/")) {
-      std::string log_event = "NetworkPropertyUpdated";
-      // Trigger a default network update for interesting changes only.
-      if (network->path() == default_network_path_) {
-        NotifyDefaultNetworkChanged(network);
-        log_event = "Default" + log_event;
-      }
-      // Log event.
-      std::string detail = network->name() + "." + key;
-      detail += " = " + ValueAsString(value);
-      device_event_log::LogLevel log_level;
-      if (key == shill::kErrorProperty || key == shill::kErrorDetailsProperty) {
-        log_level = device_event_log::LOG_LEVEL_ERROR;
-      } else {
-        log_level = device_event_log::LOG_LEVEL_EVENT;
-      }
-      NET_LOG_LEVEL(log_level, log_event, detail);
+      request_update = true;
     }
   }
 
-  // All property updates signal 'NetworkPropertiesUpdated'.
-  NotifyNetworkPropertiesUpdated(network);
-
-  // If added to a Profile, request a full update so that a NetworkState
-  // gets created.
-  if (prev_profile_path.empty() && !network->profile_path().empty())
+  if (request_update)
     RequestUpdateForNetwork(service_path);
+
+  std::string value_str;
+  value.GetAsString(&value_str);
+  if (key == shill::kSignalStrengthProperty || key == shill::kWifiBSsid ||
+      key == shill::kWifiFrequency ||
+      key == shill::kWifiFrequencyListProperty ||
+      (key == shill::kDeviceProperty && value_str == "/")) {
+    // Uninteresting update. This includes 'Device' property changes to "/"
+    // (occurs before just a service is removed).
+    // For non active networks do not log or send any notifications.
+    if (!network->IsConnectingOrConnected())
+      return;
+    // Otherwise do not trigger 'default network changed'.
+    notify_default = false;
+  }
+
+  LogPropertyUpdated(network, key, value);
+  if (notify_default)
+    NotifyDefaultNetworkChanged(network);
+  NotifyNetworkPropertiesUpdated(network);
 }
 
 void NetworkStateHandler::UpdateDeviceProperty(const std::string& device_path,
@@ -1206,10 +1193,7 @@ void NetworkStateHandler::UpdateDeviceProperty(const std::string& device_path,
   if (!device->PropertyChanged(key, value))
     return;
 
-  std::string detail = device->name() + "." + key;
-  detail += " = " + ValueAsString(value);
-  NET_LOG_EVENT("DevicePropertyUpdated", detail);
-
+  LogPropertyUpdated(device, key, value);
   NotifyDeviceListChanged();
   NotifyDevicePropertiesUpdated(device);
 
@@ -1573,7 +1557,7 @@ NetworkStateHandler::ManagedStateList* NetworkStateHandler::GetManagedList(
   return nullptr;
 }
 
-void NetworkStateHandler::OnNetworkConnectionStateChanged(
+bool NetworkStateHandler::OnNetworkConnectionStateChanged(
     NetworkState* network) {
   SCOPED_NET_LOG_IF_SLOW();
   DCHECK(network);
@@ -1605,6 +1589,7 @@ void NetworkStateHandler::OnNetworkConnectionStateChanged(
     observer.NetworkConnectionStateChanged(network);
   if (notify_default)
     NotifyDefaultNetworkChanged(network);
+  return notify_default;
 }
 
 void NetworkStateHandler::NotifyDefaultNetworkChanged(
@@ -1645,6 +1630,23 @@ void NetworkStateHandler::NotifyScanCompleted(const DeviceState* device) {
     observer.ScanCompleted(device);
 }
 
+void NetworkStateHandler::LogPropertyUpdated(const ManagedState* state,
+                                             const std::string& key,
+                                             const base::Value& value) {
+  std::string type_str =
+      state->managed_type() == ManagedState::MANAGED_TYPE_DEVICE
+          ? "Device"
+          : state->path() == default_network_path_ ? "DefaultNetwork"
+                                                   : "Network";
+  device_event_log::LogLevel log_level =
+      (key == shill::kErrorProperty || key == shill::kErrorDetailsProperty)
+          ? device_event_log::LOG_LEVEL_ERROR
+          : device_event_log::LOG_LEVEL_EVENT;
+  DEVICE_LOG(::device_event_log::LOG_TYPE_NETWORK, log_level)
+      << type_str << "PropertyUpdated: " << state->name() << "." << key << " = "
+      << value;
+}
+
 std::string NetworkStateHandler::GetTechnologyForType(
     const NetworkTypePattern& type) const {
   if (type.MatchesType(shill::kTypeEthernet))

chromeos/network/network_state_handler.h

@@ -464,7 +464,8 @@ class CHROMEOS_EXPORT NetworkStateHandler
   ManagedStateList* GetManagedList(ManagedState::ManagedType type);
 
   // Helper function to notify observers. Calls CheckDefaultNetworkChanged().
-  void OnNetworkConnectionStateChanged(NetworkState* network);
+  // Returns true if NotifyDefaultNetworkChanged() was called.
+  bool OnNetworkConnectionStateChanged(NetworkState* network);
 
   // Notifies observers when the default network or its properties change.
   void NotifyDefaultNetworkChanged(const NetworkState* default_network);
@@ -481,6 +482,11 @@ class CHROMEOS_EXPORT NetworkStateHandler
   // Called whenever Device.Scanning state transitions to false.
   void NotifyScanCompleted(const DeviceState* device);
 
+  // Helper function to log property updated events.
+  void LogPropertyUpdated(const ManagedState* network,
+                          const std::string& key,
+                          const base::Value& value);
+
   // Returns one technology type for |type|. This technology will be the
   // highest priority technology in the type pattern.
   std::string GetTechnologyForType(const NetworkTypePattern& type) const;

chromeos/network/network_state_handler_unittest.cc

@@ -113,8 +113,8 @@ class TestObserver final : public chromeos::NetworkStateHandlerObserver {
     default_network_ = network ? network->path() : "";
     default_network_connection_state_ =
         network ? network->connection_state() : "";
-    DVLOG(1) << "DefaultNetworkChanged: " << default_network_
-             << " State: " << default_network_connection_state_;
+    VLOG(1) << "DefaultNetworkChanged: " << default_network_
+            << " State: " << default_network_connection_state_;
   }
 
   void NetworkConnectionStateChanged(const NetworkState* network) override {
@@ -149,7 +149,7 @@ class TestObserver final : public chromeos::NetworkStateHandlerObserver {
   size_t scan_requested_count() { return scan_requested_count_; }
   size_t scan_completed_count() { return scan_completed_count_; }
   void reset_change_counts() {
-    DVLOG(1) << "=== RESET CHANGE COUNTS ===";
+    VLOG(1) << "=== RESET CHANGE COUNTS ===";
     default_network_change_count_ = 0;
     device_list_changed_count_ = 0;
     network_list_changed_count_ = 0;
@@ -827,24 +827,63 @@ TEST_F(NetworkStateHandlerTest, TetherScanningState) {
   EXPECT_EQ(1u, test_observer_->scan_completed_count());
 }
 
-TEST_F(NetworkStateHandlerTest, ServicePropertyChanged) {
-  // Set a service property.
+TEST_F(NetworkStateHandlerTest, ServicePropertyChangedDefaultNetwork) {
+  // Set a service property on the default network.
   const std::string eth1 = kShillManagerClientStubDefaultService;
   const NetworkState* ethernet = network_state_handler_->GetNetworkState(eth1);
   ASSERT_TRUE(ethernet);
   EXPECT_EQ("", ethernet->security_class());
   EXPECT_EQ(1, test_observer_->PropertyUpdatesForService(eth1));
+  EXPECT_EQ(0u, test_observer_->default_network_change_count());
   base::Value security_class_value("TestSecurityClass");
   SetServiceProperty(eth1, shill::kSecurityClassProperty, security_class_value);
   base::RunLoop().RunUntilIdle();
   ethernet = network_state_handler_->GetNetworkState(eth1);
   EXPECT_EQ("TestSecurityClass", ethernet->security_class());
   EXPECT_EQ(2, test_observer_->PropertyUpdatesForService(eth1));
+  EXPECT_EQ(1u, test_observer_->default_network_change_count());
 
   // Changing a service to the existing value should not trigger an update.
   SetServiceProperty(eth1, shill::kSecurityClassProperty, security_class_value);
   base::RunLoop().RunUntilIdle();
   EXPECT_EQ(2, test_observer_->PropertyUpdatesForService(eth1));
+  EXPECT_EQ(1u, test_observer_->default_network_change_count());
+}
+
+TEST_F(NetworkStateHandlerTest, ServicePropertyChangedNotIneterstingActive) {
+  // Set an uninteresting service property on an active network.
+  const std::string wifi1 = kShillManagerClientStubDefaultWifi;
+  const NetworkState* wifi = network_state_handler_->GetNetworkState(wifi1);
+  ASSERT_TRUE(wifi);
+  EXPECT_EQ(1, wifi->signal_strength());
+  EXPECT_EQ(1, test_observer_->PropertyUpdatesForService(wifi1));
+  EXPECT_EQ(0u, test_observer_->default_network_change_count());
+  base::Value signal_strength_value(11);
+  SetServiceProperty(wifi1, shill::kSignalStrengthProperty,
+                     signal_strength_value);
+  base::RunLoop().RunUntilIdle();
+  wifi = network_state_handler_->GetNetworkState(wifi1);
+  EXPECT_EQ(11, wifi->signal_strength());
+  // The change should trigger an additional properties updated event.
+  EXPECT_EQ(2, test_observer_->PropertyUpdatesForService(wifi1));
+  EXPECT_EQ(0u, test_observer_->default_network_change_count());
+}
+
+TEST_F(NetworkStateHandlerTest, ServicePropertyChangedNotIneterstingInactive) {
+  // Set an uninteresting service property on an inactive network.
+  const std::string wifi2 = kShillManagerClientStubWifi2;
+  const NetworkState* wifi = network_state_handler_->GetNetworkState(wifi2);
+  ASSERT_TRUE(wifi);
+  EXPECT_EQ(1, wifi->signal_strength());
+  EXPECT_EQ(1, test_observer_->PropertyUpdatesForService(wifi2));
+  base::Value signal_strength_value(11);
+  SetServiceProperty(wifi2, shill::kSignalStrengthProperty,
+                     signal_strength_value);
+  base::RunLoop().RunUntilIdle();
+  wifi = network_state_handler_->GetNetworkState(wifi2);
+  EXPECT_EQ(11, wifi->signal_strength());
+  // The change should *not* trigger an additional properties updated event.
+  EXPECT_EQ(1, test_observer_->PropertyUpdatesForService(wifi2));
 }
 
 TEST_F(NetworkStateHandlerTest, GetState) {