Merge "conman:  Don't interrupt provisioning."
diff --git a/conman/connection_manager.py b/conman/connection_manager.py
index c27ef8d..076f1a6 100755
--- a/conman/connection_manager.py
+++ b/conman/connection_manager.py
@@ -179,6 +179,7 @@
     return True
 
   def _post_start_client(self):
+    self.wifi.handle_wpa_events()
     self.wifi.status.connected_to_wlan = True
     logging.info('Started wifi client on %s GHz', self.band)
     self.wifi.attach_wpa_control(self._wpa_control_interface)
@@ -196,6 +197,7 @@
       # TODO(rofrankel): Make this work for dual-radio devices.
       self.wifi.status.connected_to_wlan = False
       logging.info('Stopped wifi client on %s GHz', self.band)
+      self.wifi.handle_wpa_events()
     except subprocess.CalledProcessError as e:
       logging.error('Failed to stop wifi client: %s', e.output)
 
@@ -233,7 +235,7 @@
                moca_tmp_dir='/tmp/cwmp/monitoring/moca2',
                wpa_control_interface='/var/run/wpa_supplicant',
                run_duration_s=1, interface_update_period=5,
-               wifi_scan_period_s=120, wlan_retry_s=15, associate_wait_s=15,
+               wifi_scan_period_s=120, wlan_retry_s=120, associate_wait_s=15,
                dhcp_wait_s=10, acs_start_wait_s=20, acs_finish_wait_s=120,
                bssid_cycle_length_s=30):
 
@@ -452,6 +454,11 @@
 
     for wifi in self.wifi:
       continue_wifi = False
+      provisioning_failed = self.provisioning_failed(wifi)
+      if self.currently_provisioning(wifi):
+        continue
+
+      provisioning_failed = self.provisioning_failed(wifi)
 
       # Only one wlan_configuration per interface will have access_point ==
       # True.  Try 5 GHz first, then 2.4 GHz.  If both bands are supported by
@@ -489,11 +496,11 @@
       if self._connected_to_wlan(wifi):
         wifi.status.connected_to_wlan = True
         logging.debug('Connected to WLAN on %s, nothing else to do.', wifi.name)
-        break
+        continue
 
       # This interface is not connected to the WLAN, so scan for potential
       # routes to the ACS for provisioning.
-      if ((not self.acs() or self.provisioning_failed(wifi)) and
+      if ((not self.acs() or provisioning_failed) and
           not getattr(wifi, 'last_successful_bss_info', None) and
           time.time() > wifi.last_wifi_scan_time + self._wifi_scan_period_s):
         logging.debug('Performing scan on %s.', wifi.name)
@@ -506,7 +513,7 @@
       # case 5 is unavailable for some reason.
       for band in wifi.bands:
         wlan_configuration = self._wlan_configuration.get(band, None)
-        if wlan_configuration and time.time() > self._try_wlan_after[band]:
+        if wlan_configuration and time.time() >= self._try_wlan_after[band]:
           logging.info('Trying to join WLAN on %s.', wifi.name)
           wlan_configuration.start_client()
           if self._connected_to_wlan(wifi):
@@ -527,7 +534,6 @@
         #    isn't registered to any accounts.
         logging.debug('Unable to join WLAN on %s', wifi.name)
         wifi.status.connected_to_wlan = False
-        provisioning_failed = self.provisioning_failed(wifi)
         if self.acs():
           logging.debug('Connected to ACS')
           if self._try_to_upload_logs:
@@ -811,6 +817,8 @@
       self.start_provisioning(wifi)
       connected = self._try_bssid(wifi, bss_info)
       if connected:
+        wifi.attach_wpa_control(self._wpa_control_interface)
+        wifi.handle_wpa_events()
         wifi.status.connected_to_open = True
         now = time.time()
         wifi.complain_about_acs_at = now + 5
@@ -946,6 +954,14 @@
                    wifi.provisioning_ratchet.current_step().name)
       return True
 
+  def provisioning_completed(self, wifi):
+    return bool(wifi.provisioning_ratchet.done_after)
+
+  def currently_provisioning(self, wifi):
+    return (self._connected_to_open(wifi) and
+            (not (self.provisioning_failed(wifi) or
+                  self.provisioning_completed(wifi))))
+
   def provisioning_since(self, wifi):
     return wifi.provisioning_ratchet.t0
 
diff --git a/conman/connection_manager_test.py b/conman/connection_manager_test.py
index a64ab79..9b806f9 100755
--- a/conman/connection_manager_test.py
+++ b/conman/connection_manager_test.py
@@ -181,17 +181,24 @@
   WIFI_SETCLIENT = ['echo', 'setclient']
   WIFI_STOPCLIENT = ['echo', 'stopclient']
 
+  def __init__(self, *args, **kwargs):
+    super(WLANConfiguration, self).__init__(*args, **kwargs)
+    self.stale = False
+
   def _actually_start_client(self):
     self.client_was_up = self.client_up
     self.was_attached = self.wifi.attached()
     self.wifi._secure_testonly = True
-    # Do this before calling the super method so that the attach call at the end
-    # succeeds.
+
+    super(WLANConfiguration, self)._actually_start_client()
+
     if not self.client_was_up and not self.was_attached:
       self.wifi._initial_ssid_testonly = self.ssid
       self.wifi.start_wpa_supplicant_testonly(self._wpa_control_interface)
 
-    return True
+    if self.wifi._wpa_control:
+      self.wifi._wpa_control.connected = not self.stale
+    return not self.stale
 
   def _post_start_client(self):
     if not self.client_was_up:
@@ -327,6 +334,8 @@
     self.dhcp_failure_on_s3 = False
     self.log_upload_count = 0
     self.acs_session_fails = False
+    for wifi in self.wifi:
+      wifi.bssids_tried_testonly = 0
 
   def create_wifi_interfaces(self):
     super(ConnectionManager, self).create_wifi_interfaces()
@@ -349,11 +358,14 @@
         wifi.add_terminating_event()
 
   def _try_bssid(self, wifi, bss_info):
-    wifi.add_disconnected_event()
+    if wifi.wpa_status().get('wpa_state', None) == 'COMPLETED':
+      wifi.add_disconnected_event()
     self.last_provisioning_attempt = bss_info
 
     super(ConnectionManager, self)._try_bssid(wifi, bss_info)
 
+    wifi.bssids_tried_testonly += 1
+
     def connect(connection_check_result, dhcp_failure=False):
       # pylint: disable=protected-access
       if wifi.attached():
@@ -446,6 +458,11 @@
 
   # Test methods
 
+  def tried_to_upload_logs(self):
+    result = getattr(self, 'last_log_upload_count', 0) < self.log_upload_count
+    self.last_log_upload_count = self.log_upload_count
+    return result
+
   def delete_wlan_config(self, band):
     delete_wlan_config(self._config_dir, band)
 
@@ -614,6 +631,7 @@
                               wpa_control_interface=wpa_control_interface,
                               run_duration_s=run_duration_s,
                               interface_update_period=interface_update_period,
+                              wlan_retry_s=0,
                               wifi_scan_period_s=wifi_scan_period_s,
                               associate_wait_s=associate_wait_s,
                               dhcp_wait_s=dhcp_wait_s,
@@ -752,7 +770,7 @@
   wvtest.WVPASS(c.internet())
   wvtest.WVFAIL(c.client_up(band))
   wvtest.WVPASS(c.wifi_for_band(band).current_routes())
-  wvtest.WVPASSEQ(c.log_upload_count, 1)
+  wvtest.WVPASS(c.tried_to_upload_logs())
   # Disable scan results again.
   c.interface_with_scan_results = None
   c.run_until_interface_update()
@@ -774,11 +792,35 @@
   c.wifi_for_band(band).kill_wpa_supplicant_testonly(c._wpa_control_interface)
   wvtest.WVFAIL(c.client_up(band))
   wvtest.WVFAIL(c._connected_to_wlan(c.wifi_for_band(band)))
+  # Make sure we stay connected to s2, rather than disconnecting and
+  # reconnecting.
   c.run_once()
   wvtest.WVPASS(c.has_status_files([status.P.CONNECTED_TO_WLAN]))
   wvtest.WVPASS(c.client_up(band))
   wvtest.WVPASS(c._connected_to_wlan(c.wifi_for_band(band)))
 
+  # Now, update the WLAN configuration and make sure we reprovision.
+
+  # The AP restarts with a new configuration, kicking us off.  We should
+  # reprovision.
+  c._wlan_configuration[band].stale = True
+  c.wifi_for_band(band).add_disconnected_event()
+  c.run_once()
+  wvtest.WVFAIL(c.client_up(band))
+  wvtest.WVPASS(c._connected_to_open(c.wifi_for_band(band)))
+  wvtest.WVPASSEQ(c.last_provisioning_attempt.ssid, 's2')
+
+  # Now that we're on the provisioning network, create the new WLAN
+  # configuration, which should be connected to.
+  ssid = 'wlan2'
+  psk = 'password2'
+  c.write_wlan_config(band, ssid, psk)
+  c.run_once()
+  wvtest.WVPASS(c.client_up(band))
+  wvtest.WVPASS(c.wifi_for_band(band).wpa_status()['ssid'] == ssid)
+  wvtest.WVPASS(c.has_status_files([status.P.CONNECTED_TO_WLAN]))
+  wvtest.WVPASS(c.wifi_for_band(band).current_routes())
+
   # Now, remove the WLAN configuration and make sure we are disconnected.  Then
   # disable the previously used ACS connection via s2, re-enable scan results,
   # add the user's WLAN to the scan results, and scan again.  This time, the
@@ -796,14 +838,11 @@
   wvtest.WVPASSEQ(c.last_provisioning_attempt.bssid, 'ff:ee:dd:cc:bb:aa')
   # The log upload happens on the next main loop after joining s3.
   c.run_once()
-  wvtest.WVPASSEQ(c.log_upload_count, 2)
+  wvtest.WVPASS(c.tried_to_upload_logs())
 
   # Now, recreate the same WLAN configuration, which should be connected to.
   # Also, test that atomic writes/renames work.
-  ssid = 'wlan'
-  psk = 'password'
   c.write_wlan_config(band, ssid, psk, atomic=True)
-  c.disable_access_point(band)
   c.run_once()
   wvtest.WVPASS(c.client_up(band))
   wvtest.WVPASS(c.wifi_for_band(band).current_routes())
@@ -872,7 +911,7 @@
   # Make sure we didn't scan on `band`.
   wvtest.WVPASSEQ(scan_count_for_band, c.wifi_for_band(band).wifi_scan_counter)
   c.run_once()
-  wvtest.WVPASSEQ(c.log_upload_count, 3)
+  wvtest.WVPASS(c.tried_to_upload_logs())
 
   # Now re-create the WLAN config, connect to the WLAN, and make sure that s3 is
   # unset as last_successful_bss_info, since it is no longer available.
@@ -898,6 +937,9 @@
   # 4) Connect to s2 but get no ACS access; see that last_successful_bss_info is
   #    unset.
   c.write_wlan_config(band, ssid, psk)
+  # Connect
+  c.run_once()
+  # Process DHCP results
   c.run_once()
   wvtest.WVPASS(c.acs())
   wvtest.WVPASS(c.internet())
@@ -916,7 +958,7 @@
   s2_bss = iw.BssInfo('01:23:45:67:89:ab', 's2')
   wvtest.WVPASSEQ(c.wifi_for_band(band).last_successful_bss_info, s2_bss)
   c.run_once()
-  wvtest.WVPASSEQ(c.log_upload_count, 4)
+  wvtest.WVPASS(c.tried_to_upload_logs())
 
   c.s2_fail = True
   c.write_wlan_config(band, ssid, psk)
@@ -925,9 +967,12 @@
   wvtest.WVPASS(c.internet())
 
   wvtest.WVPASSEQ(c.wifi_for_band(band).last_successful_bss_info, s2_bss)
-  c.delete_wlan_config(band)
+  c._wlan_configuration[band].stale = True
+  c.wifi_for_band(band).add_disconnected_event()
   # Run once so that c will reconnect to s2.
   c.run_once()
+  wvtest.WVPASS(c.wifi_for_band(band).connected_to_open())
+  wvtest.WVPASSEQ(c.wifi_for_band(band).wpa_status().get('ssid'), 's2')
   # Now run until it sees the lack of ACS access.
   c.run_until_interface_update()
   wvtest.WVPASSEQ(c.wifi_for_band(band).last_successful_bss_info, None)
@@ -935,7 +980,8 @@
   # Test that we wait dhcp_wait_s seconds for a DHCP lease before trying the
   # next BSSID.  The scan results contain an s3 AP with vendor IEs that fails to
   # send a DHCP lease.  This ensures that s3 will be tried before any other AP,
-  # which lets us force a timeout and proceed to the next AP.
+  # which lets us force a timeout and proceed to the next AP.  Having a stale
+  # WLAN configuration shouldn't interrupt provisioning.
   del c.wifi_for_band(band).cycler
   c.interface_with_scan_results = c.wifi_for_band(band).name
   c.scan_results_include_hidden = True
@@ -946,6 +992,7 @@
   last_bss_info = c.wifi_for_band(band).last_attempted_bss_info
   wvtest.WVPASSEQ(last_bss_info.ssid, 's3')
   wvtest.WVPASSEQ(last_bss_info.bssid, 'ff:ee:dd:cc:bb:aa')
+  c.write_wlan_config(band, ssid, psk)
   # Second iteration: check that we try s3 again since there's no gateway yet.
   c.run_once()
   last_bss_info = c.wifi_for_band(band).last_attempted_bss_info
@@ -960,6 +1007,9 @@
   wvtest.WVPASSNE(last_bss_info.ssid, 's3')
   wvtest.WVPASSNE(last_bss_info.bssid, 'ff:ee:dd:cc:bb:aa')
 
+  # We can delete the stale WLAN config now, to simplify subsequent tests.
+  c.delete_wlan_config(band)
+
   # Now repeat the above, but for an ACS session that takes a while.  We don't
   # necessarily want to leave if it fails (so we don't want the third check),
   # but we do want to make sure we don't leave while we're still waiting for it.
@@ -1151,7 +1201,7 @@
   wvtest.WVPASS(c.wifi_for_band('2.4').current_routes())
   wvtest.WVFAIL(c.wifi_for_band('5').current_routes_normal_testonly())
   c.run_once()
-  wvtest.WVPASSEQ(c.log_upload_count, 1)
+  wvtest.WVPASS(c.tried_to_upload_logs())
 
 
 @wvtest.wvtest
@@ -1285,6 +1335,9 @@
 
   # Make sure 2.4 still works.
   c.write_wlan_config('2.4', 'my ssid', 'my psk')
+  # Connect
+  c.run_once()
+  # Process DHCP results
   c.run_once()
   wvtest.WVPASS(c.wifi_for_band('2.4').acs())
   wvtest.WVPASS(c.wifi_for_band('2.4').internet())
diff --git a/conman/interface.py b/conman/interface.py
index 6557049..e71a322 100755
--- a/conman/interface.py
+++ b/conman/interface.py
@@ -507,7 +507,6 @@
         k, v = line.strip().split('=', 1)
         status[k] = v
 
-    logging.debug('%s wpa status is %s', self.name, status)
     return status
 
   def get_wpa_control(self, socket):
@@ -533,6 +532,7 @@
       match = self.WPA_EVENT_RE.match(self._wpa_control.recv())
       if match:
         event = match.group('event')
+        logging.debug('%s got wpa_supplicant event %s', self.name, event)
         if event == 'CONNECTED':
           self.wpa_supplicant = True
         elif event in ('DISCONNECTED', 'TERMINATING', 'ASSOC-REJECT',
diff --git a/conman/interface_test.py b/conman/interface_test.py
index e8f0876..74363b8 100755
--- a/conman/interface_test.py
+++ b/conman/interface_test.py
@@ -43,6 +43,8 @@
 
   def _connection_check(self, *args, **kwargs):
     result = super(FakeInterfaceMixin, self)._connection_check(*args, **kwargs)
+    if not self.links:
+      return False
     if (self.current_routes().get('default', {}).get('via', None) !=
         self._gateway_ip):
       return False