shill: Improves logging for scan.

Looking at the logs, it's hard to tell why shill chooses to do a scan.
This CL adds a 'reason' (which is really the name of the calling
function) to Scan calls to make it clear why we're scanning.

BUG=None
TEST=unittest

Change-Id: Ibd128625681fc5d61d359b60953bb78d89e97dfe
Reviewed-on: https://gerrit.chromium.org/gerrit/63357
Reviewed-by: mukesh agrawal <quiche@chromium.org>
Commit-Queue: Wade Guthrie <wdg@chromium.org>
Reviewed-by: Wade Guthrie <wdg@chromium.org>
Tested-by: Wade Guthrie <wdg@chromium.org>
diff --git a/cellular.cc b/cellular.cc
index 2896a32..b082a0b 100644
--- a/cellular.cc
+++ b/cellular.cc
@@ -438,7 +438,8 @@
   }
 }
 
-void Cellular::Scan(ScanType scan_type, Error *error) {
+void Cellular::Scan(ScanType /*scan_type*/, Error *error,
+                    const string &/*reason*/) {
   // |scan_type| is ignored because Cellular only does a full scan.
   // TODO(ers): for now report immediate success or failure.
   capability_->Scan(error, ResultCallback());
diff --git a/cellular.h b/cellular.h
index 0387388..dcc0f9c 100644
--- a/cellular.h
+++ b/cellular.h
@@ -176,7 +176,8 @@
   virtual void Start(Error *error, const EnabledStateChangedCallback &callback);
   virtual void Stop(Error *error, const EnabledStateChangedCallback &callback);
   virtual void LinkEvent(unsigned int flags, unsigned int change);
-  virtual void Scan(ScanType scan_type, Error *error);
+  virtual void Scan(ScanType /*scan_type*/, Error *error,
+                    const std::string &/*reason*/);
   virtual void RegisterOnNetwork(const std::string &network_id,
                                  Error *error,
                                  const ResultCallback &callback);
diff --git a/cellular_capability_classic.cc b/cellular_capability_classic.cc
index a7fd487..bf40872 100644
--- a/cellular_capability_classic.cc
+++ b/cellular_capability_classic.cc
@@ -314,7 +314,7 @@
 }
 
 void CellularCapabilityClassic::Scan(Error *error,
-                              const ResultCallback &callback) {
+                                     const ResultCallback &callback) {
   OnUnsupportedOperation(__func__, error);
 }
 
diff --git a/device.cc b/device.cc
index 545ff58..d035735 100644
--- a/device.cc
+++ b/device.cc
@@ -181,8 +181,9 @@
                   << std::dec << std::noshowbase;
 }
 
-void Device::Scan(ScanType scan_type, Error *error) {
-  SLOG(Device, 2) << "Device " << link_name_ << " scan requested.";
+void Device::Scan(ScanType scan_type, Error *error, const string &reason) {
+  SLOG(Device, 2) << __func__ << " [Device] on " << link_name() << " from "
+                  << reason;
   Error::PopulateAndLog(error, Error::kNotSupported,
                         "Device doesn't support scan.");
 }
diff --git a/device.h b/device.h
index 4e911da..bfba743 100644
--- a/device.h
+++ b/device.h
@@ -84,7 +84,8 @@
   virtual void LinkEvent(unsigned flags, unsigned change);
 
   // The default implementation sets |error| to kNotSupported.
-  virtual void Scan(ScanType scan_type, Error *error);
+  virtual void Scan(ScanType scan_type, Error *error,
+                    const std::string &reason);
   virtual void RegisterOnNetwork(const std::string &network_id, Error *error,
                                  const ResultCallback &callback);
   virtual void RequirePIN(const std::string &pin, bool require,
diff --git a/device_dbus_adaptor.cc b/device_dbus_adaptor.cc
index 5803c96..00d7a5f 100644
--- a/device_dbus_adaptor.cc
+++ b/device_dbus_adaptor.cc
@@ -117,7 +117,7 @@
   // User scan requests, which are the likely source of DBus requests, probably
   // aren't time-critical so we might as well perform a complete scan.  It
   // also provides a failsafe for progressive scan.
-  device_->Scan(Device::kFullScan, &e);
+  device_->Scan(Device::kFullScan, &e, __func__);
   e.ToDBusError(&error);
 }
 
diff --git a/manager.cc b/manager.cc
index 7e90718..b202777 100644
--- a/manager.cc
+++ b/manager.cc
@@ -1913,7 +1913,7 @@
     for (vector<DeviceRefPtr>::iterator it = wifi_devices.begin();
          it != wifi_devices.end();
          ++it) {
-      (*it)->Scan(scan_type, error);
+      (*it)->Scan(scan_type, error, __func__);
     }
   } else {
     // TODO(quiche): support scanning for other technologies?
diff --git a/manager_unittest.cc b/manager_unittest.cc
index 9de3a3b..951fd6f 100644
--- a/manager_unittest.cc
+++ b/manager_unittest.cc
@@ -1488,10 +1488,10 @@
     manager()->RegisterDevice(mock_devices_[1].get());
     EXPECT_CALL(*mock_devices_[0], technology())
         .WillRepeatedly(Return(Technology::kWifi));
-    EXPECT_CALL(*mock_devices_[0], Scan(Device::kFullScan, _));
+    EXPECT_CALL(*mock_devices_[0], Scan(Device::kFullScan, _, _));
     EXPECT_CALL(*mock_devices_[1], technology())
         .WillRepeatedly(Return(Technology::kUnknown));
-    EXPECT_CALL(*mock_devices_[1], Scan(_, _)).Times(0);
+    EXPECT_CALL(*mock_devices_[1], Scan(_, _, _)).Times(0);
     manager()->RequestScan(Device::kFullScan, flimflam::kTypeWifi, &error);
   }
 
diff --git a/mock_device.h b/mock_device.h
index dc9060b..9e274f5 100644
--- a/mock_device.h
+++ b/mock_device.h
@@ -33,7 +33,8 @@
   MOCK_METHOD3(SetEnabledPersistent, void(bool enable,
                                           Error* error,
                                           const ResultCallback &callback));
-  MOCK_METHOD2(Scan, void(Device::ScanType scan_type, Error *error));
+  MOCK_METHOD3(Scan, void(Device::ScanType scan_type, Error *error,
+                          const std::string &reason));
   MOCK_METHOD1(Load, bool(StoreInterface *storage));
   MOCK_METHOD1(Save, bool(StoreInterface *storage));
   MOCK_METHOD0(DisableIPv6, void());
diff --git a/mock_wifi.h b/mock_wifi.h
index 07ba44d..eedf52b 100644
--- a/mock_wifi.h
+++ b/mock_wifi.h
@@ -38,7 +38,8 @@
                            const EnabledStateChangedCallback &callback));
   MOCK_METHOD2(Stop, void(Error *error,
                           const EnabledStateChangedCallback &callback));
-  MOCK_METHOD2(Scan, void(ScanType scan_type, Error *error));
+  MOCK_METHOD3(Scan, void(ScanType scan_type, Error *error,
+                          const std::string &reason));
   MOCK_METHOD1(DisconnectFrom, void(WiFiService *service));
   MOCK_METHOD1(ClearCachedCredentials, void(const WiFiService *service));
   MOCK_METHOD2(ConnectTo,
diff --git a/wifi.cc b/wifi.cc
index 2684f39..e619a27 100644
--- a/wifi.cc
+++ b/wifi.cc
@@ -302,10 +302,10 @@
                 << endpoint_by_rpcid_.size() << " EndpointMap entries.";
 }
 
-void WiFi::Scan(ScanType scan_type, Error */*error*/) {
-  LOG(INFO) << __func__;
+void WiFi::Scan(ScanType scan_type, Error */*error*/, const string &reason) {
   if (progressive_scan_enabled_ && scan_type == kProgressiveScan) {
-    LOG(INFO) << "Doing progressive scan on " << link_name();
+    LOG(INFO) << __func__ << " [progressive] on " << link_name() << " from "
+              << reason;
     if (!scan_session_) {
       // TODO(wdg): Perform in-depth testing to determine the best values for
       // the different scans. chromium:235293
@@ -336,8 +336,10 @@
     dispatcher()->PostTask(
         Bind(&WiFi::ProgressiveScanTask, weak_ptr_factory_.GetWeakPtr()));
   } else {
-    LOG(INFO) << "Doing full scan on " << link_name() << " - progressive scan "
-              << (progressive_scan_enabled_ ? "ENABLED" : "DISABLED");
+    LOG(INFO) << __func__ << " [full] on " << link_name()
+              << " (progressive scan "
+              << (progressive_scan_enabled_ ? "ENABLED" : "DISABLED")
+              << ") from " << reason;
     // Needs to send a D-Bus message, but may be called from D-Bus
     // signal handler context (via Manager::RequestScan). So defer work
     // to event loop.
@@ -697,7 +699,7 @@
       // We may want to reconsider this immediate scan, if/when shill
       // takes greater responsibility for scanning (vs. letting
       // supplicant handle most of it).
-      Scan(kProgressiveScan, NULL);
+      Scan(kProgressiveScan, NULL, __func__);
     }
   } else {
     HandleRoam(new_bss);
@@ -1231,7 +1233,7 @@
              << "do a regular scan";
   scan_session_.reset();
   SetScanState(kScanScanning, kScanMethodProgressiveFinishedToFull, __func__);
-  Scan(kFullScan, NULL);
+  Scan(kFullScan, NULL, __func__);
 }
 
 void WiFi::OnFailedProgressiveScan() {
@@ -1239,7 +1241,7 @@
              << " -- doing a regular scan";
   scan_session_.reset();
   SetScanState(kScanScanning, kScanMethodProgressiveErrorToFull, __func__);
-  Scan(kFullScan, NULL);
+  Scan(kFullScan, NULL, __func__);
 }
 
 string WiFi::GetServiceLeaseName(const WiFiService &service) {
@@ -1498,7 +1500,7 @@
 
   if (IsIdle()) {
     // Not scanning/connecting/connected, so let's get things rolling.
-    Scan(kProgressiveScan, NULL);
+    Scan(kProgressiveScan, NULL, __func__);
     RestartFastScanAttempts();
   } else {
     SLOG(WiFi, 1) << __func__
@@ -1573,7 +1575,7 @@
 void WiFi::ScanTimerHandler() {
   SLOG(WiFi, 2) << "WiFi Device " << link_name() << ": " << __func__;
   if (scan_state_ == kScanIdle && IsIdle()) {
-    Scan(kProgressiveScan, NULL);
+    Scan(kProgressiveScan, NULL, __func__);
     if (fast_scans_remaining_ > 0) {
       --fast_scans_remaining_;
     }
@@ -1822,7 +1824,7 @@
                << "May be running an older version of wpa_supplicant.";
   }
 
-  Scan(kProgressiveScan, NULL);
+  Scan(kProgressiveScan, NULL, __func__);
   StartScanTimer();
 }
 
diff --git a/wifi.h b/wifi.h
index 20c6b6a..1ff9a6a 100644
--- a/wifi.h
+++ b/wifi.h
@@ -128,7 +128,8 @@
 
   virtual void Start(Error *error, const EnabledStateChangedCallback &callback);
   virtual void Stop(Error *error, const EnabledStateChangedCallback &callback);
-  virtual void Scan(ScanType scan_type, Error *error);
+  virtual void Scan(ScanType scan_type, Error *error,
+                    const std::string &reason);
   // Callback for system resume. If this WiFi device is idle, a scan
   // is initiated. Additionally, the base class implementation is
   // invoked unconditionally.
diff --git a/wifi_unittest.cc b/wifi_unittest.cc
index 4c9e3bb..042690e 100644
--- a/wifi_unittest.cc
+++ b/wifi_unittest.cc
@@ -590,7 +590,7 @@
     wifi_->ScanTimerHandler();
   }
   void TriggerFullScan() {
-    wifi_->Scan(Device::kFullScan, NULL);
+    wifi_->Scan(Device::kFullScan, NULL, __func__);
   }
   const WiFiServiceRefPtr &GetCurrentService() {
     return wifi_->current_service_;
diff --git a/wimax.cc b/wimax.cc
index b9f10d8..cbc87b7 100644
--- a/wimax.cc
+++ b/wimax.cc
@@ -85,7 +85,8 @@
   }
 }
 
-void WiMax::Scan(ScanType scan_type, Error *error) {
+void WiMax::Scan(ScanType /*scan_type*/, Error *error,
+                 const string &/*reason*/) {
   SLOG(WiMax, 2) << __func__;
   if (scanning_) {
     Error::PopulateAndLog(
diff --git a/wimax.h b/wimax.h
index b51a772..c1790c9 100644
--- a/wimax.h
+++ b/wimax.h
@@ -35,7 +35,8 @@
   // Inherited from Device.
   virtual void Start(Error *error, const EnabledStateChangedCallback &callback);
   virtual void Stop(Error *error, const EnabledStateChangedCallback &callback);
-  virtual void Scan(ScanType scan_type, Error *error);
+  virtual void Scan(ScanType /*scan_type*/, Error *error,
+                    const std::string &/*reason*/);
 
   virtual void ConnectTo(const WiMaxServiceRefPtr &service, Error *error);
   virtual void DisconnectFrom(const ServiceRefPtr &service, Error *error);