conman:  Tune logging.

Move some (but not all!) debug log messages to info log messages, and
make sure conman logs info messages by default.

Also, fix a bug which sometimes prevented the conman main loop
sleeping before running again (which substantially contributed to high
log volume).

BUG=30608525

Change-Id: I6d2c599d914238c4d1b1e73b695088fd843b38ae
diff --git a/conman/connection_manager.py b/conman/connection_manager.py
index a312b2c..2a3f574 100755
--- a/conman/connection_manager.py
+++ b/conman/connection_manager.py
@@ -93,7 +93,7 @@
       raise ValueError('Command file does not specify SSID')
 
     if self.wifi.initial_ssid == self.ssid:
-      logging.debug('Connected to WLAN at startup')
+      logging.info('Connected to WLAN at startup')
 
   @property
   def client_up(self):
@@ -117,7 +117,7 @@
     try:
       subprocess.check_output(self.command, stderr=subprocess.STDOUT)
       self.access_point_up = True
-      logging.debug('Started %s GHz AP', self.band)
+      logging.info('Started %s GHz AP', self.band)
     except subprocess.CalledProcessError as e:
       logging.error('Failed to start access point: %s', e.output)
 
@@ -132,7 +132,7 @@
     try:
       subprocess.check_output(command, stderr=subprocess.STDOUT)
       self.access_point_up = False
-      logging.debug('Stopped %s GHz AP', self.band)
+      logging.info('Stopped %s GHz AP', self.band)
     except subprocess.CalledProcessError as e:
       logging.error('Failed to stop access point: %s', e.output)
       return
@@ -140,7 +140,7 @@
   def start_client(self):
     """Join the WLAN as a client."""
     if experiment.enabled('WifiNo2GClient') and self.band == '2.4':
-      logging.debug('WifiNo2GClient enabled; not starting 2.4 GHz client.')
+      logging.info('WifiNo2GClient enabled; not starting 2.4 GHz client.')
       return
 
     up = self.client_up
@@ -187,7 +187,7 @@
                               stderr=subprocess.STDOUT)
       # TODO(rofrankel): Make this work for dual-radio devices.
       self._status.connected_to_wlan = False
-      logging.debug('Stopped wifi client on %s GHz', self.band)
+      logging.info('Stopped wifi client on %s GHz', self.band)
     except subprocess.CalledProcessError as e:
       logging.error('Failed to stop wifi client: %s', e.output)
 
@@ -318,7 +318,7 @@
     # the routing table.
     for ifc in [self.bridge] + self.wifi:
       ifc.initialize()
-      logging.debug('%s initialized', ifc.name)
+      logging.info('%s initialized', ifc.name)
 
     self._interface_update_counter = 0
     self._try_wlan_after = {'5': 0, '2.4': 0}
@@ -449,7 +449,7 @@
       if self._connected_to_wlan(wifi):
         self._status.connected_to_wlan = True
         logging.debug('Connected to WLAN on %s, nothing else to do.', wifi.name)
-        return
+        break
 
       # This interface is not connected to the WLAN, so scan for potential
       # routes to the ACS for provisioning.
@@ -467,10 +467,10 @@
       for band in wifi.bands:
         wlan_configuration = self._wlan_configuration.get(band, None)
         if wlan_configuration and time.time() > self._try_wlan_after[band]:
-          logging.debug('Trying to join WLAN on %s.', wifi.name)
+          logging.info('Trying to join WLAN on %s.', wifi.name)
           wlan_configuration.start_client()
           if self._connected_to_wlan(wifi):
-            logging.debug('Joined WLAN on %s.', wifi.name)
+            logging.info('Joined WLAN on %s.', wifi.name)
             self._status.connected_to_wlan = True
             self._try_wlan_after[band] = 0
             break
@@ -605,7 +605,7 @@
       if filename == self.ETHERNET_STATUS_FILE:
         try:
           self.bridge.ethernet = bool(int(contents))
-          logging.debug('Ethernet %s', 'up' if self.bridge.ethernet else 'down')
+          logging.info('Ethernet %s', 'up' if self.bridge.ethernet else 'down')
         except ValueError:
           logging.error('Status file contents should be 0 or 1, not %s',
                         contents)
@@ -628,7 +628,7 @@
           wifi = self.wifi_for_band(band)
           if wifi and band in self._wlan_configuration:
             self._wlan_configuration[band].access_point = True
-          logging.debug('AP enabled for %s GHz', band)
+          logging.info('AP enabled for %s GHz', band)
 
     elif path == self._tmp_dir:
       if filename.startswith(self.GATEWAY_FILE_PREFIX):
@@ -636,8 +636,8 @@
         ifc = self.interface_by_name(interface_name)
         if ifc:
           ifc.set_gateway_ip(contents)
-          logging.debug('Received gateway %r for interface %s', contents,
-                        ifc.name)
+          logging.info('Received gateway %r for interface %s', contents,
+                       ifc.name)
 
     elif path == self._moca_tmp_dir:
       match = re.match(r'^%s\d+$' % self.MOCA_NODE_FILE_PREFIX, filename)
@@ -711,8 +711,8 @@
     last_successful_bss_info = getattr(wifi, 'last_successful_bss_info', None)
     bss_info = last_successful_bss_info or wifi.cycler.next()
     if bss_info is not None:
-      logging.debug('Attempting to connect to SSID %s for provisioning',
-                    bss_info.ssid)
+      logging.info('Attempting to connect to SSID %s for provisioning',
+                   bss_info.ssid)
       self._status.trying_open = True
       connected = self._try_bssid(wifi, bss_info)
       if connected:
@@ -763,7 +763,7 @@
         wlan_configuration.access_point = os.path.exists(ap_file)
       self._wlan_configuration[band] = wlan_configuration
       self._status.have_config = True
-      logging.debug('Updated WLAN configuration for %s GHz', band)
+      logging.info('Updated WLAN configuration for %s GHz', band)
       self._update_access_point(wlan_configuration)
 
   def _update_access_point(self, wlan_configuration):
@@ -818,7 +818,7 @@
                             stderr=subprocess.STDOUT)
 
   def _try_upload_logs(self):
-    logging.debug('Attempting to upload logs')
+    logging.info('Attempting to upload logs')
     if subprocess.call(self.UPLOAD_LOGS_AND_WAIT) != 0:
       logging.error('Failed to upload logs')
 
diff --git a/conman/interface.py b/conman/interface.py
index 1b77b18..12fa7ce 100755
--- a/conman/interface.py
+++ b/conman/interface.py
@@ -57,18 +57,18 @@
     """
     # Until initialized, we want to act as if the interface is down.
     if not self._initialized:
-      logging.debug('%s not initialized; not running connection_check%s',
-                    self.name, ' (ACS)' if check_acs else '')
+      logging.info('%s not initialized; not running connection_check%s',
+                   self.name, ' (ACS)' if check_acs else '')
       return None
 
     if not self.links:
-      logging.debug('Connection check for %s failed due to no links', self.name)
+      logging.info('Connection check for %s failed due to no links', self.name)
       return False
 
     logging.debug('Gateway IP for %s is %s', self.name, self._gateway_ip)
     if self._gateway_ip is None:
-      logging.debug('Connection check for %s failed due to no gateway IP',
-                    self.name)
+      logging.info('Connection check%s for %s failed due to no gateway IP',
+                   ' (ACS)' if check_acs else '', self.name)
       return False
 
     # Temporarily add a route to make sure the connection check can be run.
@@ -90,10 +90,10 @@
 
     with open(os.devnull, 'w') as devnull:
       result = subprocess.call(cmd, stdout=devnull, stderr=devnull) == 0
-      logging.debug('Connection check%s for %s %s',
-                    ' (ACS)' if check_acs else '',
-                    self.name,
-                    'passed' if result else 'failed')
+      logging.info('Connection check%s for %s %s',
+                   ' (ACS)' if check_acs else '',
+                   self.name,
+                   'passed' if result else 'failed')
 
     # Delete the temporary route.
     if added_temporary_route:
@@ -175,8 +175,8 @@
 
   def _ip_route(self, *args):
     if not self._initialized:
-      logging.debug('Not initialized, not running %s %s',
-                    ' '.join(self.IP_ROUTE), ' '.join(args))
+      logging.info('Not initialized, not running %s %s',
+                   ' '.join(self.IP_ROUTE), ' '.join(args))
       return ''
 
     return self._really_ip_route(*args)
@@ -191,7 +191,7 @@
       return ''
 
   def set_gateway_ip(self, gateway_ip):
-    logging.debug('New gateway IP %s for %s', gateway_ip, self.name)
+    logging.info('New gateway IP %s for %s', gateway_ip, self.name)
     self._gateway_ip = gateway_ip
     self.update_routes()
 
@@ -203,10 +203,10 @@
     had_links = bool(self.links)
 
     if is_up:
-      logging.debug('%s gained link %s', self.name, link)
+      logging.info('%s gained link %s', self.name, link)
       self.links.add(link)
     else:
-      logging.debug('%s lost link %s', self.name, link)
+      logging.info('%s lost link %s', self.name, link)
       self.links.remove(link)
 
     # If a link goes away, we may have lost access to something but not gained
@@ -319,9 +319,9 @@
     failure_s = self._acs_session_failure_s()
     if (experiment.enabled('WifiSimulateWireless')
         and failure_s < MAX_ACS_FAILURE_S):
-      logging.debug('WifiSimulateWireless: failing bridge connection check (no '
-                    'ACS contact for %d seconds, max %d seconds)',
-                    failure_s, MAX_ACS_FAILURE_S)
+      logging.info('WifiSimulateWireless: failing bridge connection check%s '
+                   '(no ACS contact for %d seconds, max %d seconds)',
+                   ' (ACS)' if check_acs else '', failure_s, MAX_ACS_FAILURE_S)
       return False
 
     return super(Bridge, self)._connection_check(check_acs)