conman: use monotime.
Establishing connectivity enables clock synchronization. This is likely
to occur in the middle of provisioning, breaking timeout logic in conman
and leading to false provisioning failures.
Change-Id: I8921b4d16f858c7fd99a9d7ac53c719e1db77cc1
diff --git a/conman/connection_manager.py b/conman/connection_manager.py
index 11da31c..f43ee8d 100755
--- a/conman/connection_manager.py
+++ b/conman/connection_manager.py
@@ -26,6 +26,15 @@
import ratchet
import status
+try:
+ import monotime # pylint: disable=unused-import,g-import-not-at-top
+except ImportError:
+ pass
+try:
+ _gettime = time.monotonic
+except AttributeError:
+ _gettime = time.time
+
HOSTNAME = socket.gethostname()
TMP_HOSTS = '/tmp/hosts'
@@ -446,7 +455,7 @@
to join the WLAN again.
7. Sleep for the rest of the duration of _run_duration_s.
"""
- start_time = time.time()
+ start_time = _gettime()
self.notifier.process_events()
while self.notifier.check_events():
self.notifier.read_events()
@@ -507,7 +516,7 @@
# routes to the ACS for provisioning.
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):
+ _gettime() > wifi.last_wifi_scan_time + self._wifi_scan_period_s):
logging.debug('Performing scan on %s.', wifi.name)
self._wifi_scan(wifi)
@@ -518,7 +527,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 _gettime() >= 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):
@@ -529,7 +538,7 @@
else:
logging.error('Failed to connect to WLAN on %s.', wifi.name)
wifi.status.connected_to_wlan = False
- self._try_wlan_after[band] = time.time() + self._wlan_retry_s
+ self._try_wlan_after[band] = _gettime() + self._wlan_retry_s
else:
# If we are aren't on the WLAN, can ping the ACS, and haven't gotten a
# new WLAN configuration yet, there are two possibilities:
@@ -552,7 +561,7 @@
if provisioning_failed:
wifi.last_successful_bss_info = None
- now = time.time()
+ now = _gettime()
if self._wlan_configuration:
logging.info('ACS has not updated WLAN configuration; will retry '
' with old config.')
@@ -571,7 +580,7 @@
# 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 = time.time()
+ now = _gettime()
if self._connected_to_open(wifi) and not provisioning_failed:
logging.debug('Waiting for provisioning for %ds.',
now - self.provisioning_since(wifi))
@@ -579,7 +588,7 @@
logging.debug('Not connected to ACS or provisioning failed')
self._try_next_bssid(wifi)
- time.sleep(max(0, self._run_duration_s - (time.time() - start_time)))
+ time.sleep(max(0, self._run_duration_s - (_gettime() - start_time)))
def acs(self):
result = False
@@ -784,7 +793,7 @@
def _wifi_scan(self, wifi):
"""Perform a wifi scan and update wifi.cycler."""
logging.info('Scanning on %s...', wifi.name)
- wifi.last_wifi_scan_time = time.time()
+ 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.
@@ -825,7 +834,7 @@
wifi.attach_wpa_control(self._wpa_control_interface)
wifi.handle_wpa_events()
wifi.status.connected_to_open = True
- now = time.time()
+ now = _gettime()
wifi.complain_about_acs_at = now + 5
logging.info('Attempting to provision via SSID %s', bss_info.ssid)
self._try_to_upload_logs = True
diff --git a/conman/cycler.py b/conman/cycler.py
index 23f2ce4..7795368 100755
--- a/conman/cycler.py
+++ b/conman/cycler.py
@@ -4,6 +4,15 @@
import time
+try:
+ import monotime # pylint: disable=unused-import,g-import-not-at-top
+except ImportError:
+ pass
+try:
+ _gettime = time.monotonic
+except AttributeError:
+ _gettime = time.time
+
class AgingPriorityCycler(object):
"""A modified priority queue.
@@ -40,7 +49,7 @@
try:
self._items[item][0] = priority
except KeyError:
- self._items[item] = [priority, time.time()]
+ self._items[item] = [priority, _gettime()]
def remove(self, item):
if item in self._items:
@@ -65,7 +74,7 @@
if self.empty():
return
- now = time.time()
+ now = _gettime()
def aged_priority(key_value):
_, (priority, birth) = key_value
@@ -86,7 +95,7 @@
Args:
items: An iterable of (item, priority).
"""
- now = time.time()
+ now = _gettime()
new_items = {}
for item, priority in items:
t = now
diff --git a/conman/ratchet.py b/conman/ratchet.py
index 350ed47..07e61a8 100644
--- a/conman/ratchet.py
+++ b/conman/ratchet.py
@@ -6,6 +6,15 @@
import os
import time
+try:
+ import monotime # pylint: disable=unused-import,g-import-not-at-top
+except ImportError:
+ pass
+try:
+ _gettime = time.monotonic
+except AttributeError:
+ _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)
@@ -37,8 +46,8 @@
t0: The timestamp after which to evaluate the condition.
start_at: The timestamp from which to compute the timeout.
"""
- self.t0 = t0 or time.time()
- self.start_at = start_at or time.time()
+ self.t0 = t0 or _gettime()
+ self.start_at = start_at or _gettime()
self.done_after = None
self.done_by = None
self.timed_out = False
@@ -56,21 +65,21 @@
self.mark_done()
return True
- now = time.time()
+ now = _gettime()
if now > self.start_at + self.timeout:
self.timed_out = True
self.logger.info('%s timed out after %.2f seconds',
self.name, now - self.t0)
raise TimeoutException()
- self.not_done_before = time.time()
+ self.not_done_before = _gettime()
return False
def mark_done(self):
# In general, we don't know when a condition finished, but we know it was
# *after* whenever it was most recently not done.
self.done_after = self.not_done_before
- self.done_by = time.time()
+ self.done_by = _gettime()
self.logger.info('%s completed after %.2f seconds',
self.name, self.done_by - self.t0)
