conman: logging improvements
Make sure all logging is scoped to a named logger (enforced by unit
tests). This will make it easier to follow the flow of large log
excerpts.
Change-Id: If028821ad4094272d0e83f64da558d6e96f2e671
diff --git a/conman/Makefile b/conman/Makefile
index 6126f84..2914b4a 100644
--- a/conman/Makefile
+++ b/conman/Makefile
@@ -9,7 +9,7 @@
echo 'echo "(gpylint-missing)" >&2'; \
fi \
)
-NOINSTALL=%_test.py options.py experiment.py experiment_testutils.py
+NOINSTALL=%_test.py options.py experiment.py experiment_testutils.py test_common.py
all:
diff --git a/conman/connection_manager.py b/conman/connection_manager.py
index e484e67..326b946 100755
--- a/conman/connection_manager.py
+++ b/conman/connection_manager.py
@@ -26,6 +26,8 @@
import ratchet
import status
+logger = logging.getLogger(__name__)
+
try:
import monotime # pylint: disable=unused-import,g-import-not-at-top
except ImportError:
@@ -77,6 +79,7 @@
def __init__(self, band, wifi, command_lines):
self.band = band
self.wifi = wifi
+ self.logger = self.wifi.logger.getChild(self.band)
self.command = command_lines.splitlines()
self.access_point_up = False
self.ssid = None
@@ -106,7 +109,7 @@
raise ValueError('Command file does not specify SSID')
if self.client_up:
- logging.info('Connected to WLAN at startup')
+ self.logger.info('Connected to WLAN at startup')
@property
def client_up(self):
@@ -126,9 +129,9 @@
try:
subprocess.check_output(self.command, stderr=subprocess.STDOUT)
self.access_point_up = True
- logging.info('Started %s GHz AP', self.band)
+ self.logger.info('Started %s GHz AP', self.band)
except subprocess.CalledProcessError as e:
- logging.error('Failed to start access point: %s', e.output)
+ self.logger.error('Failed to start access point: %s', e.output)
def stop_access_point(self):
if not self.access_point_up:
@@ -141,25 +144,25 @@
try:
subprocess.check_output(command, stderr=subprocess.STDOUT)
self.access_point_up = False
- logging.info('Stopped %s GHz AP', self.band)
+ self.logger.info('Stopped %s GHz AP', self.band)
except subprocess.CalledProcessError as e:
- logging.error('Failed to stop access point: %s', e.output)
+ self.logger.error('Failed to stop access point: %s', e.output)
return
def start_client(self):
"""Join the WLAN as a client."""
if experiment.enabled('WifiNo2GClient') and self.band == '2.4':
- logging.info('WifiNo2GClient enabled; not starting 2.4 GHz client.')
+ self.logger.info('WifiNo2GClient enabled; not starting 2.4 GHz client.')
return
up = self.client_up
if up:
- logging.debug('Wifi client already started on %s GHz', self.band)
+ self.logger.debug('Wifi client already started on %s GHz', self.band)
return
if self._actually_start_client():
self.wifi.status.connected_to_wlan = True
- logging.info('Started wifi client on %s GHz', self.band)
+ self.logger.info('Started wifi client on %s GHz', self.band)
def _actually_start_client(self):
"""Actually run wifi setclient.
@@ -177,7 +180,7 @@
self.wifi.status.trying_wlan = True
subprocess.check_output(command, stderr=subprocess.STDOUT, env=env)
except subprocess.CalledProcessError as e:
- logging.error('Failed to start wifi client: %s', e.output)
+ self.logger.error('Failed to start wifi client: %s', e.output)
self.wifi.status.wlan_failed = True
return False
@@ -185,7 +188,7 @@
def stop_client(self):
if not self.client_up:
- logging.debug('Wifi client already stopped on %s GHz', self.band)
+ self.logger.debug('Wifi client already stopped on %s GHz', self.band)
return
try:
@@ -193,10 +196,10 @@
stderr=subprocess.STDOUT)
# 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.logger.info('Stopped wifi client on %s GHz', self.band)
self.wifi.update()
except subprocess.CalledProcessError as e:
- logging.error('Failed to stop wifi client: %s', e.output)
+ self.logger.error('Failed to stop wifi client: %s', e.output)
class ConnectionManager(object):
@@ -259,7 +262,7 @@
self._interface_status_dir, self._moca_tmp_dir):
if not os.path.exists(directory):
os.makedirs(directory)
- logging.info('Created monitored directory: %s', directory)
+ logger.info('Created monitored directory: %s', directory)
acs_autoprov_filepath = os.path.join(self._tmp_dir,
'acs_autoprovisioning')
@@ -273,8 +276,8 @@
status_dir = os.path.join(self._status_dir, ifc.name)
if not os.path.exists(status_dir):
os.makedirs(status_dir)
- ifc.status = status.Status(status_dir)
- self._status = status.CompositeStatus(self._status_dir,
+ ifc.status = status.Status(ifc.name, status_dir)
+ self._status = status.CompositeStatus(__name__, self._status_dir,
[i.status for i in self.interfaces()])
wm = pyinotify.WatchManager()
@@ -316,7 +319,7 @@
# the routing table.
for ifc in self.interfaces():
ifc.initialize()
- logging.info('%s initialized', ifc.name)
+ logger.info('%s initialized', ifc.name)
# Make sure no unwanted APs or clients are running.
for wifi in self.wifi:
@@ -325,20 +328,20 @@
if config:
if config.access_point and self.bridge.internet():
# If we have a config and want an AP, we don't want a client.
- logging.info('Stopping pre-existing %s client on %s',
- band, wifi.name)
+ logger.info('Stopping pre-existing %s client on %s',
+ band, wifi.name)
self._stop_wifi(band, False, True)
else:
# If we have a config but don't want an AP, make sure we aren't
# running one.
- logging.info('Stopping pre-existing %s AP on %s', band, wifi.name)
+ logger.info('Stopping pre-existing %s AP on %s', band, wifi.name)
self._stop_wifi(band, True, False)
break
else:
# If we have no config for this radio, neither a client nor an AP should
# be running.
- logging.info('Stopping pre-existing %s AP and clienton %s',
- band, wifi.name)
+ logger.info('Stopping pre-existing %s AP and clienton %s',
+ band, wifi.name)
self._stop_wifi(wifi.bands[0], True, True)
self._interface_update_counter = 0
@@ -459,7 +462,7 @@
for wifi in self.wifi:
if self.currently_provisioning(wifi):
- logging.debug('Currently provisioning, nothing else to do.')
+ logger.debug('Currently provisioning, nothing else to do.')
continue
provisioning_failed = self.provisioning_failed(wifi)
@@ -493,14 +496,14 @@
wifi.update()
if continue_wifi:
- logging.debug('Running AP on %s, nothing else to do.', wifi.name)
+ logger.debug('Running AP on %s, nothing else to do.', wifi.name)
continue
# If this interface is connected to the user's WLAN, there is nothing else
# to do.
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)
+ logger.debug('Connected to WLAN on %s, nothing else to do.', wifi.name)
continue
# This interface is not connected to the WLAN, so scan for potential
@@ -508,7 +511,7 @@
if ((not self.acs() or provisioning_failed) and
not getattr(wifi, 'last_successful_bss_info', None) and
_gettime() > wifi.last_wifi_scan_time + self._wifi_scan_period_s):
- logging.debug('Performing scan on %s.', wifi.name)
+ logger.debug('Performing scan on %s.', wifi.name)
self._wifi_scan(wifi)
# Periodically retry rejoining the WLAN. If the WLAN configuration is
@@ -519,15 +522,15 @@
for band in wifi.bands:
wlan_configuration = self._wlan_configuration.get(band, None)
if wlan_configuration and _gettime() >= self._try_wlan_after[band]:
- logging.info('Trying to join WLAN on %s.', wifi.name)
+ logger.info('Trying to join WLAN on %s.', wifi.name)
wlan_configuration.start_client()
if self._connected_to_wlan(wifi):
- logging.info('Joined WLAN on %s.', wifi.name)
+ logger.info('Joined WLAN on %s.', wifi.name)
wifi.status.connected_to_wlan = True
self._try_wlan_after[band] = 0
break
else:
- logging.error('Failed to connect to WLAN on %s.', wifi.name)
+ logger.error('Failed to connect to WLAN on %s.', wifi.name)
wifi.status.connected_to_wlan = False
self._try_wlan_after[band] = _gettime() + self._wlan_retry_s
else:
@@ -537,10 +540,10 @@
# 1) The configuration didn't change, and we should retry connecting.
# 2) cwmpd isn't writing a configuration, possibly because the device
# isn't registered to any accounts.
- logging.debug('Unable to join WLAN on %s', wifi.name)
+ logger.debug('Unable to join WLAN on %s', wifi.name)
wifi.status.connected_to_wlan = False
if self.acs():
- logging.debug('Connected to ACS')
+ logger.debug('Connected to ACS')
if wifi.acs():
wifi.last_successful_bss_info = getattr(wifi,
@@ -551,8 +554,8 @@
now = _gettime()
if self._wlan_configuration:
- logging.info('ACS has not updated WLAN configuration; will retry '
- ' with old config.')
+ logger.info('ACS has not updated WLAN configuration; will retry '
+ ' with old config.')
for w in self.wifi:
for b in w.bands:
self._try_wlan_after[b] = now
@@ -562,18 +565,18 @@
elif (hasattr(wifi, 'complain_about_acs_at')
and now >= wifi.complain_about_acs_at):
wait = wifi.complain_about_acs_at - self.provisioning_since(wifi)
- logging.info('Can ping ACS, but no WLAN configuration for %ds.',
- wait)
+ logger.info('Can ping ACS, but no WLAN configuration for %ds.',
+ wait)
wifi.complain_about_acs_at += wait
# If we didn't manage to join the WLAN, and we don't have an ACS
# connection or the ACS session failed, we should try another open AP.
if not self.acs() or provisioning_failed:
now = _gettime()
if self._connected_to_open(wifi) and not provisioning_failed:
- logging.debug('Waiting for provisioning for %ds.',
- now - self.provisioning_since(wifi))
+ logger.debug('Waiting for provisioning for %ds.',
+ now - self.provisioning_since(wifi))
else:
- logging.debug('Not connected to ACS or provisioning failed')
+ logger.debug('Not connected to ACS or provisioning failed')
self._try_next_bssid(wifi)
time.sleep(max(0, self._run_duration_s - (_gettime() - start_time)))
@@ -637,8 +640,8 @@
if lowest_metric_interface:
ip = lowest_metric_interface[1].get_ip_address()
ip_line = '%s %s\n' % (ip, HOSTNAME) if ip else ''
- logging.info('Lowest metric default route is on dev %r',
- lowest_metric_interface[1].name)
+ logger.info('Lowest metric default route is on dev %r',
+ lowest_metric_interface[1].name)
new_tmp_hosts = '%s127.0.0.1 localhost' % ip_line
@@ -687,7 +690,7 @@
if e.errno == errno.ENOENT:
# Logging about failing to open .tmp files results in spammy logs.
if not filename.endswith('.tmp'):
- logging.error('Not a file: %s', filepath)
+ logger.error('Not a file: %s', filepath)
return
else:
raise
@@ -696,10 +699,10 @@
if filename == self.ETHERNET_STATUS_FILE:
try:
self.bridge.ethernet = bool(int(contents))
- logging.info('Ethernet %s', 'up' if self.bridge.ethernet else 'down')
+ logger.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)
+ logger.error('Status file contents should be 0 or 1, not %s',
+ contents)
return
elif path == self._config_dir:
@@ -718,7 +721,7 @@
wifi = self.wifi_for_band(band)
if wifi and band in self._wlan_configuration:
self._wlan_configuration[band].access_point = True
- logging.info('AP enabled for %s GHz', band)
+ logger.info('AP enabled for %s GHz', band)
elif path == self._tmp_dir:
if filename.startswith(self.GATEWAY_FILE_PREFIX):
@@ -730,16 +733,16 @@
ifc = self.interface_by_name(interface_name)
if ifc:
ifc.set_gateway_ip(contents)
- logging.info('Received gateway %r for interface %s', contents,
- ifc.name)
+ logger.info('Received gateway %r for interface %s', contents,
+ ifc.name)
if filename.startswith(self.SUBNET_FILE_PREFIX):
interface_name = filename.split(self.SUBNET_FILE_PREFIX)[-1]
ifc = self.interface_by_name(interface_name)
if ifc:
ifc.set_subnet(contents)
- logging.info('Received subnet %r for interface %s', contents,
- ifc.name)
+ logger.info('Received subnet %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)
@@ -747,7 +750,7 @@
try:
json_contents = json.loads(contents)
except ValueError:
- logging.error('Cannot parse %s as JSON.', filepath)
+ logger.error('Cannot parse %s as JSON.', filepath)
return
node = json_contents['NodeId']
had_moca = self.bridge.moca
@@ -769,9 +772,9 @@
if band in wifi.bands:
return wifi
- logging.error('No wifi interface for %s GHz. wlan interfaces:\n%s',
- band, '\n'.join('%s: %r' %
- (w.name, w.bands) for w in self.wifi))
+ logger.error('No wifi interface for %s GHz. wlan interfaces:\n%s',
+ band, '\n'.join('%s: %r' %
+ (w.name, w.bands) for w in self.wifi))
def ifplugd_action(self, interface_name, up):
subprocess.call(self.IFPLUGD_ACTION + [interface_name,
@@ -779,13 +782,13 @@
def _wifi_scan(self, wifi):
"""Perform a wifi scan and update wifi.cycler."""
- logging.info('Scanning on %s...', wifi.name)
+ logger.info('Scanning on %s...', wifi.name)
wifi.last_wifi_scan_time = _gettime()
subprocess.call(self.IFUP + [wifi.name])
# /bin/wifi takes a --band option but then finds the right interface for it,
# so it's okay to just pick the first band here.
items = self._find_bssids(wifi.bands[0])
- logging.info('Done scanning on %s', wifi.name)
+ logger.info('Done scanning on %s', wifi.name)
if not hasattr(wifi, 'cycler'):
wifi.cycler = cycler.AgingPriorityCycler(
cycle_length_s=self._bssid_cycle_length_s)
@@ -813,8 +816,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.info('Attempting to connect to SSID %s (%s) for provisioning',
- bss_info.ssid, bss_info.bssid)
+ logger.info('Attempting to connect to SSID %s (%s) for provisioning',
+ bss_info.ssid, bss_info.bssid)
self.start_provisioning(wifi)
connected = self._try_bssid(wifi, bss_info)
if connected:
@@ -822,7 +825,7 @@
wifi.status.connected_to_open = True
now = _gettime()
wifi.complain_about_acs_at = now + 5
- logging.info('Attempting to provision via SSID %s', bss_info.ssid)
+ logger.info('Attempting to provision via SSID %s', bss_info.ssid)
self._try_to_upload_logs = True
# If we can no longer connect to this, it's no longer successful.
else:
@@ -836,7 +839,7 @@
# Relatedly, once we find ACS access on an open network we may want to
# save that SSID/BSSID and that first in future. If we do that then we
# can declare that provisioning has failed much more aggressively.
- logging.info('Ran out of BSSIDs to try on %s', wifi.name)
+ logger.info('Ran out of BSSIDs to try on %s', wifi.name)
wifi.status.provisioning_failed = True
return False
@@ -863,7 +866,7 @@
band = wlan_configuration.band
current = self._wlan_configuration.get(band, None)
if current is None or wlan_configuration.command != current.command:
- logging.debug('Received new WLAN configuration for band %s', band)
+ logger.debug('Received new WLAN configuration for band %s', band)
if current is not None:
wlan_configuration.access_point = current.access_point
else:
@@ -874,7 +877,7 @@
wlan_configuration.access_point = os.path.exists(ap_file)
self._wlan_configuration[band] = wlan_configuration
self.wifi_for_band(band).status.have_config = True
- logging.info('Updated WLAN configuration for %s GHz', band)
+ logger.info('Updated WLAN configuration for %s GHz', band)
self._update_access_point(wlan_configuration)
def _update_access_point(self, wlan_configuration):
@@ -911,7 +914,7 @@
try:
self._binwifi(*full_command)
except subprocess.CalledProcessError as e:
- logging.error('wifi %s failed: "%s"', ' '.join(full_command), e.output)
+ logger.error('wifi %s failed: "%s"', ' '.join(full_command), e.output)
def _binwifi(self, *command):
"""Test seam for calls to /bin/wifi.
@@ -929,13 +932,13 @@
stderr=subprocess.STDOUT)
def _try_upload_logs(self):
- logging.info('Attempting to upload logs')
+ logger.info('Attempting to upload logs')
if subprocess.call(self.UPLOAD_LOGS_AND_WAIT) != 0:
- logging.error('Failed to upload logs')
+ logger.error('Failed to upload logs')
def cwmp_wakeup(self):
if subprocess.call(self.CWMP_WAKEUP) != 0:
- logging.error('cwmp wakeup failed')
+ logger.error('cwmp wakeup failed')
def start_provisioning(self, wifi):
wifi.set_gateway_ip(None)
@@ -948,12 +951,12 @@
if wifi.provisioning_ratchet.done_after:
wifi.status.provisioning_completed = True
wifi.provisioning_ratchet.stop()
- logging.info('%s successfully provisioned', wifi.name)
+ logger.info('%s successfully provisioned', wifi.name)
return False
except ratchet.TimeoutException:
wifi.status.provisioning_failed = True
- logging.info('%s failed to provision: %s', wifi.name,
- wifi.provisioning_ratchet.current_step().name)
+ logger.info('%s failed to provision: %s', wifi.name,
+ wifi.provisioning_ratchet.current_step().name)
return True
def provisioning_completed(self, wifi):
@@ -972,7 +975,7 @@
try:
return subprocess.check_output(['wifi', 'show'])
except subprocess.CalledProcessError as e:
- logging.error('Failed to call "wifi show": %s', e)
+ logger.error('Failed to call "wifi show": %s', e)
return ''
@@ -980,7 +983,7 @@
try:
return subprocess.check_output(['get-quantenna-interfaces']).split()
except subprocess.CalledProcessError:
- logging.fatal('Failed to call get-quantenna-interfaces')
+ logger.fatal('Failed to call get-quantenna-interfaces')
raise
diff --git a/conman/connection_manager_test.py b/conman/connection_manager_test.py
index 1e447d0..e9807cd 100755
--- a/conman/connection_manager_test.py
+++ b/conman/connection_manager_test.py
@@ -15,9 +15,11 @@
import interface_test
import iw
import status
+import test_common
from wvtest import wvtest
-logging.basicConfig(level=logging.DEBUG)
+logger = logging.getLogger(__name__)
+
FAKE_MOCA_NODE1_FILE = """{
"NodeId": 1,
@@ -66,7 +68,7 @@
"""
-@wvtest.wvtest
+@test_common.wvtest
def get_client_interfaces_test():
"""Test get_client_interfaces."""
subprocess.reset()
@@ -96,7 +98,7 @@
{'wcli0': {'frenzy': True, 'bands': set(['5'])}})
-@wvtest.wvtest
+@test_common.wvtest
def WLANConfigurationParseTest(): # pylint: disable=invalid-name
"""Test WLANConfiguration parsing."""
subprocess.reset()
@@ -202,7 +204,7 @@
self.run_once()
def run_until_scan(self, band):
- logging.debug('running until scan on band %r', band)
+ logger.debug('running until scan on band %r', band)
wifi = self.wifi_for_band(band)
wifi_scan_counter = wifi.wifi_scan_counter
while wifi_scan_counter == wifi.wifi_scan_counter:
@@ -285,7 +287,7 @@
f(c)
except Exception:
- logging.error('Uncaught exception!')
+ logger.error('Uncaught exception!')
traceback.print_exc()
raise
finally:
@@ -751,43 +753,43 @@
wvtest.WVPASS(c.has_status_files([status.P.PROVISIONING_COMPLETED]))
-@wvtest.wvtest
+@test_common.wvtest
@connection_manager_test(WIFI_SHOW_OUTPUT_MARVELL8897)
def connection_manager_test_generic_marvell8897_2g(c):
connection_manager_test_generic(c, '2.4')
-@wvtest.wvtest
+@test_common.wvtest
@connection_manager_test(WIFI_SHOW_OUTPUT_MARVELL8897)
def connection_manager_test_generic_marvell8897_5g(c):
connection_manager_test_generic(c, '5')
-@wvtest.wvtest
+@test_common.wvtest
@connection_manager_test(WIFI_SHOW_OUTPUT_ATH9K_ATH10K)
def connection_manager_test_generic_ath9k_ath10k_2g(c):
connection_manager_test_generic(c, '2.4')
-@wvtest.wvtest
+@test_common.wvtest
@connection_manager_test(WIFI_SHOW_OUTPUT_ATH9K_ATH10K)
def connection_manager_test_generic_ath9k_ath10k_5g(c):
connection_manager_test_generic(c, '5')
-@wvtest.wvtest
+@test_common.wvtest
@connection_manager_test(WIFI_SHOW_OUTPUT_ATH9K_FRENZY)
def connection_manager_test_generic_ath9k_frenzy_2g(c):
connection_manager_test_generic(c, '2.4')
-@wvtest.wvtest
+@test_common.wvtest
@connection_manager_test(WIFI_SHOW_OUTPUT_ATH9K_FRENZY)
def connection_manager_test_generic_ath9k_frenzy_5g(c):
connection_manager_test_generic(c, '5')
-@wvtest.wvtest
+@test_common.wvtest
@connection_manager_test(WIFI_SHOW_OUTPUT_FRENZY)
def connection_manager_test_generic_frenzy_5g(c):
connection_manager_test_generic(c, '5')
@@ -889,13 +891,13 @@
wvtest.WVPASS(subprocess.upload_logs_and_wait.uploaded_logs())
-@wvtest.wvtest
+@test_common.wvtest
@connection_manager_test(WIFI_SHOW_OUTPUT_ATH9K_ATH10K)
def connection_manager_test_dual_band_two_radios_ath9k_ath10k(c):
connection_manager_test_dual_band_two_radios(c)
-@wvtest.wvtest
+@test_common.wvtest
@connection_manager_test(WIFI_SHOW_OUTPUT_ATH9K_FRENZY)
def connection_manager_test_dual_band_two_radios_ath9k_frenzy(c):
connection_manager_test_dual_band_two_radios(c)
@@ -981,13 +983,13 @@
wvtest.WVPASS(subprocess.upload_logs_and_wait.uploaded_logs())
-@wvtest.wvtest
+@test_common.wvtest
@connection_manager_test(WIFI_SHOW_OUTPUT_MARVELL8897)
def connection_manager_test_dual_band_one_radio_marvell8897(c):
connection_manager_test_dual_band_one_radio(c)
-@wvtest.wvtest
+@test_common.wvtest
@connection_manager_test(WIFI_SHOW_OUTPUT_MARVELL8897_NO_5GHZ)
def connection_manager_test_marvell8897_no_5ghz(c):
"""Test ConnectionManager for the case documented in b/27328894.
@@ -1033,7 +1035,7 @@
wvtest.WVPASS(c.wifi_for_band('2.4').current_routes())
-@wvtest.wvtest
+@test_common.wvtest
@connection_manager_test(WIFI_SHOW_OUTPUT_MARVELL8897,
__test_interfaces_already_up=['eth0', 'wcli0'])
def connection_manager_test_wifi_already_up(c):
@@ -1046,7 +1048,7 @@
wvtest.WVPASS(c.wifi_for_band('2.4').current_routes())
-@wvtest.wvtest
+@test_common.wvtest
@connection_manager_test(WIFI_SHOW_OUTPUT_MARVELL8897, wlan_configs={'5': True})
def connection_manager_one_radio_marvell8897_existing_config_5g_ap(c):
wvtest.WVPASSEQ(len(c._binwifi_commands), 1)
@@ -1054,7 +1056,7 @@
c._binwifi_commands[0])
-@wvtest.wvtest
+@test_common.wvtest
@connection_manager_test(WIFI_SHOW_OUTPUT_MARVELL8897,
wlan_configs={'5': False})
def connection_manager_one_radio_marvell8897_existing_config_5g_no_ap(c):
@@ -1063,7 +1065,7 @@
c._binwifi_commands[0])
-@wvtest.wvtest
+@test_common.wvtest
@connection_manager_test(WIFI_SHOW_OUTPUT_ATH9K_ATH10K,
wlan_configs={'5': True})
def connection_manager_two_radios_ath9k_ath10k_existing_config_5g_ap(c):
@@ -1073,7 +1075,7 @@
in c._binwifi_commands)
-@wvtest.wvtest
+@test_common.wvtest
@connection_manager_test(WIFI_SHOW_OUTPUT_MARVELL8897)
def connection_manager_conman_no_2g_wlan(c):
unused_raii = experiment_testutils.MakeExperimentDirs()
diff --git a/conman/cycler_test.py b/conman/cycler_test.py
index de1e6c0..1493a83 100755
--- a/conman/cycler_test.py
+++ b/conman/cycler_test.py
@@ -5,10 +5,11 @@
import time
import cycler
+import test_common
from wvtest import wvtest
-@wvtest.wvtest
+@test_common.wvtest
def cycler_test():
c = cycler.AgingPriorityCycler()
wvtest.WVPASS(c.next() is None)
diff --git a/conman/interface.py b/conman/interface.py
index 68aa35b..1de5a59 100755
--- a/conman/interface.py
+++ b/conman/interface.py
@@ -7,10 +7,6 @@
import re
import subprocess
-# This has to be called before another module calls it with a higher log level.
-# pylint: disable=g-import-not-at-top
-logging.basicConfig(level=logging.DEBUG)
-
import experiment
METRIC_5GHZ = 20
@@ -36,6 +32,7 @@
def __init__(self, name, base_metric):
self.name = name
+ self.logger = logging.getLogger(self.name)
# Currently connected links for this interface, e.g. ethernet.
self.links = set()
@@ -67,18 +64,18 @@
"""
# Until initialized, we want to act as if the interface is down.
if not self._initialized:
- logging.info('%s not initialized; not running connection_check%s',
- self.name, ' (ACS)' if check_acs else '')
+ self.logger.info('not initialized; not running connection_check%s',
+ ' (ACS)' if check_acs else '')
return None
if not self.links:
- logging.info('Connection check for %s failed due to no links', self.name)
+ self.logger.info('Connection check failed due to no links')
return False
- logging.debug('Gateway IP for %s is %s', self.name, self._gateway_ip)
+ self.logger.debug('Gateway IP is %s', self._gateway_ip)
if self._gateway_ip is None:
- logging.info('Connection check%s for %s failed due to no gateway IP',
- ' (ACS)' if check_acs else '', self.name)
+ self.logger.info('Connection check%s failed due to no gateway IP',
+ ' (ACS)' if check_acs else '')
return False
self.add_routes()
@@ -91,10 +88,9 @@
with open(os.devnull, 'w') as devnull:
result = subprocess.call(cmd, stdout=devnull, stderr=devnull) == 0
- logging.info('Connection check%s for %s %s',
- ' (ACS)' if check_acs else '',
- self.name,
- 'passed' if result else 'failed')
+ self.logger.info('Connection check%s %s',
+ ' (ACS)' if check_acs else '',
+ 'passed' if result else 'failed')
return result
@@ -119,7 +115,7 @@
Remove any stale routes and add any missing desired routes.
"""
if self.metric is None:
- logging.info('Cannot add route for %s without a metric.', self.name)
+ self.logger.info('Cannot add route without a metric.')
return
# If the current routes are the same, there is nothing to do. If either
@@ -132,7 +128,7 @@
if self._subnet:
if ((subnet.get('route', None), subnet.get('metric', None)) !=
(self._subnet, str(self.metric))):
- logging.debug('Adding subnet route for dev %s', self.name)
+ self.logger.debug('Adding subnet route')
to_add.append(('subnet', ('add', self._subnet, 'dev', self.name,
'metric', str(self.metric))))
subnet = self._subnet
@@ -145,7 +141,7 @@
if (subnet and
(default.get('via', None), default.get('metric', None)) !=
(self._gateway_ip, str(self.metric))):
- logging.debug('Adding default route for dev %s', self.name)
+ self.logger.debug('Adding default route')
to_add.append(('default',
('add', 'default', 'via', self._gateway_ip,
'dev', self.name, 'metric', str(self.metric))))
@@ -154,7 +150,7 @@
# RFC2365 multicast route.
if current.get('multicast', {}).get('metric', None) != str(self.metric):
- logging.debug('Adding multicast route for dev %s', self.name)
+ self.logger.debug('Adding multicast route')
to_add.append(('multicast', ('add', RFC2385_MULTICAST_ROUTE,
'dev', self.name,
'metric', str(self.metric))))
@@ -184,7 +180,7 @@
# Use a sorted list to ensure that default comes before subnet.
for route_type in sorted(list(args)):
while route_type in self.current_routes():
- logging.debug('Deleting %s route for dev %s', route_type, self.name)
+ self.logger.debug('Deleting %s route', route_type)
self._ip_route('del', self.current_routes()[route_type]['route'],
'dev', self.name)
@@ -222,23 +218,23 @@
def _ip_route(self, *args):
if not self._initialized:
- logging.info('Not initialized, not running %s %s',
- ' '.join(self.IP_ROUTE), ' '.join(args))
+ self.logger.info('Not initialized, not running %s %s',
+ ' '.join(self.IP_ROUTE), ' '.join(args))
return ''
try:
- logging.debug('%s calling ip route %s', self.name, ' '.join(args))
+ self.logger.debug('calling ip route %s', ' '.join(args))
return subprocess.check_output(self.IP_ROUTE + list(args))
except subprocess.CalledProcessError as e:
- logging.error('Failed to call "ip route" with args %r: %s', args,
- e.message)
+ self.logger.error('Failed to call "ip route" with args %r: %s', args,
+ e.message)
return ''
def _ip_addr_show(self):
try:
return subprocess.check_output(self.IP_ADDR_SHOW + [self.name])
except subprocess.CalledProcessError as e:
- logging.error('Could not get IP address for %s: %s', self.name, e.message)
+ self.logger.error('Could not get IP address: %s', e.message)
return None
def get_ip_address(self):
@@ -247,12 +243,12 @@
return match and match.group('IP') or None
def set_gateway_ip(self, gateway_ip):
- logging.info('New gateway IP %s for %s', gateway_ip, self.name)
+ self.logger.info('New gateway IP %s', gateway_ip)
self._gateway_ip = gateway_ip
self.update_routes(expire_cache=True)
def set_subnet(self, subnet):
- logging.info('New subnet %s for %s', subnet, self.name)
+ self.logger.info('New subnet %s', subnet)
self._subnet = subnet
self.update_routes(expire_cache=True)
@@ -264,10 +260,10 @@
had_links = bool(self.links)
if is_up:
- logging.info('%s gained link %s', self.name, link)
+ self.logger.info('gained link %s', link)
self.links.add(link)
else:
- logging.info('%s lost link %s', self.name, link)
+ self.logger.info('lost link %s', link)
self.links.remove(link)
# If a link goes away, we may have lost access to something but not gained
@@ -282,7 +278,7 @@
self.update_routes(expire_cache=False)
def expire_connection_status_cache(self):
- logging.debug('Expiring connection status cache for %s', self.name)
+ self.logger.debug('Expiring connection status cache')
self._has_internet = self._has_acs = None
def update_routes(self, expire_cache=True):
@@ -296,7 +292,7 @@
expire_cache: If true, force a recheck of connection status before
deciding how to prioritize routes.
"""
- logging.debug('Updating routes for %s', self.name)
+ self.logger.debug('Updating routes')
if expire_cache:
self.expire_connection_status_cache()
@@ -318,7 +314,7 @@
"""
if not self._initialized:
return
- logging.info('%s routes have normal priority', self.name)
+ self.logger.info('routes have normal priority')
self.metric_offset = 0
self.add_routes()
@@ -330,7 +326,7 @@
"""
if not self._initialized:
return
- logging.info('%s routes have low priority', self.name)
+ self.logger.info('routes have low priority')
self.metric_offset = 50
self.add_routes()
@@ -401,9 +397,10 @@
failure_s = self._acs_session_failure_s()
if (experiment.enabled('WifiSimulateWireless')
and 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)
+ self.logger.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)
@@ -453,7 +450,7 @@
lines = subprocess.check_output(['wpa_cli', '-i', self.name,
'status']).splitlines()
except subprocess.CalledProcessError:
- logging.error('wpa_cli status request failed')
+ self.logger.error('wpa_cli status request failed')
return {}
for line in lines:
@@ -462,7 +459,7 @@
k, v = line.strip().split('=', 1)
status[k] = v
- logging.debug('wpa_status is %r', status)
+ self.logger.debug('wpa_status is %r', status)
return status
def update(self):
@@ -495,7 +492,7 @@
try:
return subprocess.check_output(['qcsapi'] + list(command)).strip()
except subprocess.CalledProcessError as e:
- logging.error('QCSAPI call failed: %s: %s', e, e.output)
+ self.logger.error('QCSAPI call failed: %s: %s', e, e.output)
raise
def wpa_status(self):
diff --git a/conman/interface_test.py b/conman/interface_test.py
index f080285..3ab58e6 100755
--- a/conman/interface_test.py
+++ b/conman/interface_test.py
@@ -2,19 +2,15 @@
"""Tests for connection_manager.py."""
-import logging
import os
import shutil
import subprocess
import tempfile
import time
-# This has to be called before another module calls it with a higher log level.
-# pylint: disable=g-import-not-at-top
-logging.basicConfig(level=logging.DEBUG)
-
import experiment_testutils
import interface
+import test_common
from wvtest import wvtest
@@ -57,7 +53,7 @@
pass
-@wvtest.wvtest
+@test_common.wvtest
def bridge_test():
"""Test Interface and Bridge."""
tmp_dir = tempfile.mkdtemp()
@@ -197,7 +193,7 @@
wvtest.WVFAIL(w.wpa_supplicant)
-@wvtest.wvtest
+@test_common.wvtest
def wifi_test():
"""Test Wifi."""
w = Wifi('wcli0', '21')
@@ -217,7 +213,7 @@
shutil.rmtree(conman_path)
-@wvtest.wvtest
+@test_common.wvtest
def frenzy_wifi_test():
"""Test FrenzyWifi."""
w = FrenzyWifi('wlan0', '20')
@@ -237,7 +233,7 @@
shutil.rmtree(conman_path)
-@wvtest.wvtest
+@test_common.wvtest
def simulate_wireless_test():
"""Test the WifiSimulateWireless experiment."""
unused_raii = experiment_testutils.MakeExperimentDirs()
diff --git a/conman/iw_test.py b/conman/iw_test.py
index 202d10c..9f5f0e6 100755
--- a/conman/iw_test.py
+++ b/conman/iw_test.py
@@ -5,6 +5,7 @@
import subprocess
import iw
+import test_common
from wvtest import wvtest
@@ -34,7 +35,7 @@
)
-@wvtest.wvtest
+@test_common.wvtest
def find_bssids_test():
"""Test iw.find_bssids."""
subprocess.mock('wifi', 'interfaces',
diff --git a/conman/ratchet.py b/conman/ratchet.py
index 61e8705..8013c3d 100644
--- a/conman/ratchet.py
+++ b/conman/ratchet.py
@@ -16,11 +16,6 @@
_gettime = time.time
-# This has to be called before another module calls it with a higher log level.
-# pylint: disable=g-import-not-at-top
-logging.basicConfig(level=logging.DEBUG)
-
-
class TimeoutException(Exception):
pass
@@ -33,7 +28,7 @@
if evaluate:
self.evaluate = evaluate
self.timeout = timeout
- self.logger = logger or logging
+ self.logger = logger or logging.getLogger(self.name)
self.callback = callback
self.reset()
@@ -129,7 +124,7 @@
self.name = name
self.steps = steps
for step in self.steps:
- step.logger = logging.getLogger(self.name)
+ step.logger = logging.getLogger(self.name).getChild(step.name)
self._status = status
super(Ratchet, self).__init__(name, None, 0)
diff --git a/conman/ratchet_test.py b/conman/ratchet_test.py
index 48b693c..e0b831e 100755
--- a/conman/ratchet_test.py
+++ b/conman/ratchet_test.py
@@ -9,10 +9,11 @@
import ratchet
import status
+import test_common
from wvtest import wvtest
-@wvtest.wvtest
+@test_common.wvtest
def condition_test():
"""Test basic Condition functionality."""
x = y = 0
@@ -42,7 +43,7 @@
wvtest.WVPASSEQ(len(callback_sink), 2)
-@wvtest.wvtest
+@test_common.wvtest
def file_condition_test():
"""Test File*Condition functionality."""
_, filename = tempfile.mkstemp()
@@ -70,7 +71,7 @@
wvtest.WVFAIL(c_touched.check())
-@wvtest.wvtest
+@test_common.wvtest
def ratchet_test():
"""Test Ratchet functionality."""
@@ -88,7 +89,7 @@
ratchet.Condition('x', lambda: x, 0.1),
ratchet.Condition('y', lambda: y, 0.1),
ratchet.Condition('z', lambda: z, 0.1),
- ], status.Status(status_export_path))
+ ], status.Status('test ratchet', status_export_path))
x = y = 1
# Test that timeouts are not just summed, but start whenever the previous
diff --git a/conman/status.py b/conman/status.py
index b5b1bae..0b6ac6a 100644
--- a/conman/status.py
+++ b/conman/status.py
@@ -132,6 +132,7 @@
"""
def __init__(self, *args, **kwargs):
+ self._scope = kwargs.pop('scope', '')
super(Proposition, self).__init__(*args, **kwargs)
self._value = None
self._implications = set()
@@ -175,7 +176,8 @@
self.export()
for parent in self.parents:
parent.export()
- logging.debug('%s is now %s', self._name, self._value)
+ logging.getLogger(self._scope).getChild(self._name).debug(
+ 'now %s', self._value)
if value:
for implication in self._implications:
@@ -209,7 +211,8 @@
class Status(object):
"""Provides a convenient API for conman to describe system status."""
- def __init__(self, export_path):
+ def __init__(self, name, export_path):
+ self._name = name
if not os.path.isdir(export_path):
os.makedirs(export_path)
@@ -219,7 +222,7 @@
def _set_up_propositions(self):
self._propositions = {
- p: Proposition(p, self._export_path)
+ p: Proposition(p, self._export_path, scope=self._name)
for p in dict(inspect.getmembers(P)) if not p.startswith('_')
}
@@ -255,9 +258,9 @@
class CompositeStatus(Status):
- def __init__(self, export_path, children):
+ def __init__(self, name, export_path, children):
self._children = children
- super(CompositeStatus, self).__init__(export_path)
+ super(CompositeStatus, self).__init__(name, export_path)
def _set_up_propositions(self):
self._propositions = {
diff --git a/conman/status_test.py b/conman/status_test.py
index 38dda83..6a591aa 100755
--- a/conman/status_test.py
+++ b/conman/status_test.py
@@ -2,16 +2,14 @@
"""Tests for connection_manager.py."""
-import logging
import os
import shutil
import tempfile
import status
+import test_common
from wvtest import wvtest
-logging.basicConfig(level=logging.DEBUG)
-
def file_in(path, filename):
return os.path.exists(os.path.join(path, filename))
@@ -21,7 +19,7 @@
return file_in(s._export_path, filename)
-@wvtest.wvtest
+@test_common.wvtest
def test_proposition():
export_path = tempfile.mkdtemp()
@@ -73,16 +71,16 @@
shutil.rmtree(export_path)
-@wvtest.wvtest
+@test_common.wvtest
def test_status():
export_path_s = tempfile.mkdtemp()
export_path_t = tempfile.mkdtemp()
export_path_st = tempfile.mkdtemp()
try:
- s = status.Status(export_path_s)
- t = status.Status(export_path_t)
- st = status.CompositeStatus(export_path_st, [s, t])
+ s = status.Status('s', export_path_s)
+ t = status.Status('t', export_path_t)
+ st = status.CompositeStatus('s_or t', export_path_st, [s, t])
# Sanity check that there are no contradictions.
for p, (want_true, want_false) in status.IMPLICATIONS.iteritems():
diff --git a/conman/test/fake_python/subprocess/ip.py b/conman/test/fake_python/subprocess/ip.py
index d8baaf3..9fcd5da 100644
--- a/conman/test/fake_python/subprocess/ip.py
+++ b/conman/test/fake_python/subprocess/ip.py
@@ -9,6 +9,8 @@
import ifup
+logger = logging.getLogger(__name__)
+
_ROUTING_TABLE = {}
_IP_TABLE = {}
@@ -74,17 +76,17 @@
if not can_add_route(dev):
return (1, 'Tried to add default route without subnet route: %r' %
_ROUTING_TABLE)
- logging.debug('Adding route for %r', key)
+ logger.debug('Adding route for %r', key)
_ROUTING_TABLE[key] = ' '.join(args[1:])
elif args[0] == 'del':
if key in _ROUTING_TABLE:
- logging.debug('Deleting route for %r', key)
+ logger.debug('Deleting route for %r', key)
del _ROUTING_TABLE[key]
elif key[2] is None:
# pylint: disable=g-builtin-op
for k in _ROUTING_TABLE.keys():
if k[:-1] == key[:-1]:
- logging.debug('Deleting route for %r (generalized from %s)', k, key)
+ logger.debug('Deleting route for %r (generalized from %s)', k, key)
del _ROUTING_TABLE[k]
break
diff --git a/conman/test/fake_python/subprocess/qcsapi.py b/conman/test/fake_python/subprocess/qcsapi.py
index 3625772..a7622a5 100644
--- a/conman/test/fake_python/subprocess/qcsapi.py
+++ b/conman/test/fake_python/subprocess/qcsapi.py
@@ -14,11 +14,9 @@
def mock(*args, **kwargs):
- import logging
if 'value' not in kwargs:
raise ValueError('Must specify value for mock qcsapi call %r' % args)
value = kwargs['value']
- logging.debug ('qcsapi %r mocked: %r', args, value)
if value is None and args in STATE:
del STATE[args]
else:
diff --git a/conman/test_common.py b/conman/test_common.py
new file mode 100644
index 0000000..202b712
--- /dev/null
+++ b/conman/test_common.py
@@ -0,0 +1,40 @@
+#!/usr/bin/python
+
+"""Configures generic stuff for unit tests."""
+
+
+import collections
+import logging
+
+from wvtest import wvtest as real_wvtest
+
+
+logging.basicConfig(level=logging.DEBUG)
+logger = logging.getLogger(__name__)
+
+
+class LoggerCounter(logging.Handler):
+ """Counts the number of messages from each logger."""
+
+ def __init__(self):
+ super(LoggerCounter, self).__init__()
+ self.counts = collections.defaultdict(int)
+
+ def handle(self, record):
+ self.counts[record.name] += 1
+
+
+def num_root_messages(logger_counter):
+ logging.getLogger(__name__).debug('logger counts: %s', logger_counter.counts)
+ return logger_counter.counts['root']
+
+
+def wvtest(f):
+ @real_wvtest.wvtest
+ def inner(*args, **kwargs):
+ logger_counter = LoggerCounter()
+ logging.getLogger().addHandler(logger_counter)
+ f(*args, **kwargs)
+ real_wvtest.WVPASSEQ(num_root_messages(logger_counter), 0)
+ inner.func_name = f.func_name
+ return inner
diff --git a/experiment.py b/experiment.py
index 7ec45ef..1318974 100644
--- a/experiment.py
+++ b/experiment.py
@@ -6,6 +6,7 @@
import os
import subprocess
+logger = logging.getLogger(__name__)
EXPERIMENTS_TMP_DIR = '/tmp/experiments'
EXPERIMENTS_DIR = '/config/experiments'
@@ -18,10 +19,10 @@
try:
rv = subprocess.call(['register_experiment', name])
except OSError as e:
- logging.info('register_experiment: %s', e)
+ logger.info('register_experiment: %s', e)
else:
if rv:
- logging.error('Failed to register experiment %s.', name)
+ logger.error('Failed to register experiment %s.', name)
def enabled(name):
@@ -39,14 +40,14 @@
name + '.available')):
if name not in _experiment_warned:
_experiment_warned.add(name)
- logging.warning('Warning: experiment %r not registered.', name)
+ logger.warning('Warning: experiment %r not registered.', name)
else:
is_enabled = os.path.exists(os.path.join(EXPERIMENTS_DIR,
name + '.active'))
if is_enabled and name not in _experiment_enabled:
_experiment_enabled.add(name)
- logging.info('Notice: using experiment %r.', name)
+ logger.info('Notice: using experiment %r.', name)
elif not is_enabled and name in _experiment_enabled:
_experiment_enabled.remove(name)
- logging.info('Notice: stopping experiment %r.', name)
+ logger.info('Notice: stopping experiment %r.', name)
return is_enabled
diff --git a/experiment_testutils.py b/experiment_testutils.py
index f5886e5..3561ca3 100644
--- a/experiment_testutils.py
+++ b/experiment_testutils.py
@@ -9,12 +9,14 @@
import experiment
+logger = logging.getLogger(__name__)
+
def enable(name):
"""Enable an experiment. For unit tests only."""
open(os.path.join(experiment.EXPERIMENTS_TMP_DIR, name + '.available'), 'w')
open(os.path.join(experiment.EXPERIMENTS_DIR, name + '.active'), 'w')
- logging.debug('Enabled %s for unit tests', name)
+ logger.debug('Enabled %s for unit tests', name)
def disable(name):
@@ -22,7 +24,7 @@
filename = os.path.join(experiment.EXPERIMENTS_DIR, name + '.active')
if os.path.exists(filename):
os.unlink(filename)
- logging.debug('Disabled %s for unit tests', name)
+ logger.debug('Disabled %s for unit tests', name)
class MakeExperimentDirs(object):
