shill: wimax: Handle vanishing RPC devices promptly.

As soon as an RPC device vanishes, destroy its proxy, fail any
associated services and disable the device. This ensures that we won't
try to explicitly call Disable on the non-existent RPC device and
prevents any race between the RPC device disappearing and then
appearing shortly thereafter -- shill will create a new WiMax device
for the new device instance. Disabling the device also clears the live
network set and updates the provider state.

Also, promote basic WiMAX create/destroy logging to the INFO level.

BUG=chrome-os-partner:9832
TEST=unit tests

Change-Id: Ib4467f2f6c9dfb58c8b73173923b0bd9535dbb61
Reviewed-on: https://gerrit.chromium.org/gerrit/24379
Tested-by: Darin Petkov <petkov@chromium.org>
Reviewed-by: Paul Stewart <pstew@chromium.org>
Reviewed-by: Ben Chan <benchan@chromium.org>
Commit-Ready: Ben Chan <benchan@chromium.org>
Tested-by: Ben Chan <benchan@chromium.org>
diff --git a/wimax.cc b/wimax.cc
index 13eb280..3668eb2 100644
--- a/wimax.cc
+++ b/wimax.cc
@@ -21,7 +21,7 @@
 
 namespace shill {
 
-const int WiMax::kTimeoutDefault = 30000;
+const int WiMax::kTimeoutDefault = 30000;  // milliseconds
 
 WiMax::WiMax(ControlInterface *control,
              EventDispatcher *dispatcher,
@@ -36,13 +36,13 @@
       path_(path),
       scanning_(false),
       proxy_factory_(ProxyFactory::GetInstance()) {
-  SLOG(WiMax, 2) << __func__ << "(" << link_name << ", " << path << ")";
+  LOG(INFO) << "WiMAX device created: " << link_name << " @ " << path;
   PropertyStore *store = mutable_store();
   store->RegisterConstBool(flimflam::kScanningProperty, &scanning_);
 }
 
 WiMax::~WiMax() {
-  SLOG(WiMax, 2) << __func__ << "(" << link_name() << ", " << path_ << ")";
+  LOG(INFO) << "WiMAX device destroyed: " << link_name();
 }
 
 void WiMax::Start(Error *error, const EnabledStateChangedCallback &callback) {
@@ -63,10 +63,16 @@
     Error error;
     DisconnectFrom(selected_service(), &error);
   }
+  scanning_ = false;
   networks_.clear();
   manager()->wimax_provider()->OnNetworksChanged();
-  proxy_->Disable(
-      error, Bind(&WiMax::OnDisableComplete, this, callback), kTimeoutDefault);
+  if (proxy_.get()) {
+    proxy_->Disable(
+        error, Bind(&WiMax::OnDisableComplete, this, callback),
+        kTimeoutDefault);
+  } else {
+    OnDisableComplete(callback, Error());
+  }
 }
 
 bool WiMax::TechnologyIs(const Technology::Identifier type) const {
@@ -141,6 +147,7 @@
 }
 
 void WiMax::OnServiceStopped(const WiMaxServiceRefPtr &service) {
+  SLOG(WiMax, 2) << __func__;
   if (service == selected_service()) {
     DropConnection();
   }
@@ -149,6 +156,15 @@
   }
 }
 
+void WiMax::OnDeviceVanished() {
+  LOG(INFO) << "WiMAX device vanished: " << link_name();
+  proxy_.reset();
+  DropService(Service::kStateIdle);
+  // Disable the device. This will also clear any relevant properties such as
+  // the live network set.
+  SetEnabled(false);
+}
+
 void WiMax::OnScanNetworksComplete(const Error &/*error*/) {
   SLOG(WiMax, 2) << __func__;
   scanning_ = false;
@@ -162,12 +178,7 @@
     // signal.
     return;
   }
-  if (pending_service_) {
-    LOG(ERROR) << "Unable to initiate connection to "
-               << pending_service_->GetStorageIdentifier();
-    pending_service_->SetState(Service::kStateFailure);
-    pending_service_ = NULL;
-  }
+  DropService(Service::kStateFailure);
 }
 
 void WiMax::OnDisconnectComplete(const Error &/*error*/) {
@@ -180,6 +191,8 @@
   if (error.IsFailure()) {
     proxy_.reset();
   } else {
+    LOG(INFO) << "WiMAX device " << link_name() << " enabled. "
+              << "Initiating network scan.";
     // Scan for networks to allow service creation when the network list becomes
     // available.
     Error e;
@@ -190,7 +203,7 @@
 
 void WiMax::OnDisableComplete(const EnabledStateChangedCallback &callback,
                               const Error &error) {
-  SLOG(WiMax, 2) << __func__;
+  LOG(INFO) << "WiMAX device " << link_name() << " disabled.";
   proxy_.reset();
   callback.Run(error);
 }
@@ -211,38 +224,49 @@
         return;
       }
       if (AcquireIPConfig()) {
-        LOG(INFO) << "Connected to "
+        LOG(INFO) << "WiMAX device " << link_name() << " connected to "
                   << pending_service_->GetStorageIdentifier();
         SelectService(pending_service_);
+        pending_service_ = NULL;
         SetServiceState(Service::kStateConfiguring);
       } else {
-        LOG(ERROR) << "Unable to connect to "
-                   << pending_service_->GetStorageIdentifier();
-        pending_service_->SetState(Service::kStateFailure);
+        DropService(Service::kStateFailure);
       }
-      pending_service_ = NULL;
       break;
     case wimax_manager::kDeviceStatusConnecting:
       // Nothing to do.
       break;
     default:
       if (pending_service_) {
-        pending_service_->SetState(Service::kStateFailure);
         // For now, assume that failing to connect to a live network indicates
         // bad user credentials. Reset the password to trigger the user/password
         // dialog in the UI.
         pending_service_->ClearPassphrase();
-        pending_service_ = NULL;
       }
-      if (selected_service()) {
-        selected_service()->SetState(Service::kStateFailure);
-        DropConnection();
-      }
+      DropService(Service::kStateFailure);
       break;
   }
 }
 
+void WiMax::DropService(Service::ConnectState state) {
+  SLOG(WiMax, 2) << __func__
+                 << "(" << Service::ConnectStateToString(state) << ")";
+  if (pending_service_) {
+    LOG(WARNING) << "Unable to initiate connection to: "
+                 << pending_service_->GetStorageIdentifier();
+    pending_service_->SetState(state);
+    pending_service_ = NULL;
+  }
+  if (selected_service()) {
+    LOG(WARNING) << "Service disconnected: "
+                 << selected_service()->GetStorageIdentifier();
+    selected_service()->SetState(state);
+    DropConnection();
+  }
+}
+
 void WiMax::DropConnection() {
+  SLOG(WiMax, 2) << __func__;
   DestroyIPConfig();
   SelectService(NULL);
 }