Change incorrect way of time meassurements

examples/layer_2/threaded/network_down_detectors_no_runner.py

@@ -63,8 +63,8 @@ def ping_observing_task(ext_io_connection, ping_ip):
 
     with ext_io_connection.open():
         observing_timeout = 10
-        start_time = time.time()
-        while time.time() < start_time + observing_timeout:
+        start_time = time.monotonic()
+        while time.monotonic() < start_time + observing_timeout:
             # anytime new data comes it may change status of observer
             if not net_drop_found and net_down_detector.done():
                 net_drop_found = True

examples/network_toggle_observers.py

@@ -31,7 +31,7 @@ def data_received(self, data, recv_time):
         """Awaiting ping output change"""
         if not self.done():
             if self.detect_pattern in data:
-                when_detected = time.time()
+                when_detected = time.monotonic()
                 self.logger.debug("Network {} {}!".format(self.net_ip,
                                                           self.detected_status))
                 self.set_result(result=when_detected)

moler/asyncio_runner.py

@@ -344,7 +344,7 @@ def wait_for(self, connection_observer, connection_observer_future, timeout=None
         max_timeout = timeout
         observer_timeout = connection_observer.timeout
         # we count timeout from now if timeout is given; else we use .life_status.start_time and .timeout of observer
-        start_time = time.time() if max_timeout else connection_observer.life_status.start_time
+        start_time = time.monotonic() if max_timeout else connection_observer.life_status.start_time
         await_timeout = max_timeout if max_timeout else observer_timeout
         if max_timeout:
             remain_time, msg = his_remaining_time("await max.", timeout=max_timeout, from_start_time=start_time)
@@ -393,7 +393,7 @@ def _cancel_submitted_future(self, connection_observer, connection_observer_futu
                 del self._submitted_futures[id(future)]
 
     def _wait_for_time_out(self, connection_observer, connection_observer_future, timeout):
-        passed = time.time() - connection_observer.life_status.start_time
+        passed = time.monotonic() - connection_observer.life_status.start_time
         future = connection_observer_future or connection_observer._future
         if future:
             with future.observer_lock:
@@ -593,7 +593,7 @@ async def feed(self, connection_observer, subscribed_data_receiver, observer_loc
                 if connection_observer.done():
                     self.logger.debug("done {}".format(connection_observer))
                     break
-                run_duration = time.time() - start_time
+                run_duration = time.monotonic() - start_time
                 # we need to check connection_observer.timeout at each round since timeout may change
                 # during lifetime of connection_observer
                 if (connection_observer.timeout is not None) and (run_duration >= connection_observer.timeout):
@@ -742,7 +742,7 @@ def wait_for(self, connection_observer, connection_observer_future, timeout=None
         self.logger.debug("go foreground: {!r} - await max. {} [sec]".format(connection_observer, timeout))
         if connection_observer.done():  # may happen when failed to start observer feeder
             return None
-        start_time = time.time()
+        start_time = time.monotonic()
 
         async def wait_for_connection_observer_done():
             result_of_future = await connection_observer_future  # feed() always returns None
@@ -784,7 +784,7 @@ async def conn_observer_fut_cancel():
                 thread4async.start_async_coroutine(conn_observer_fut_cancel())
 
         # handle timeout
-        passed = time.time() - start_time
+        passed = time.monotonic() - start_time
         fired_timeout = timeout if timeout else connection_observer.timeout
         time_out_observer(connection_observer=connection_observer,
                           timeout=fired_timeout, passed_time=passed,
@@ -916,7 +916,7 @@ async def _await_stop_loop(self, loop_started, stop_event):
 
     def run_async_coroutine(self, coroutine_to_run, timeout):
         """Start coroutine in dedicated thread and await its result with timeout"""
-        start_time = time.time()
+        start_time = time.monotonic()
         coro_future = self.start_async_coroutine(coroutine_to_run)
         # run_coroutine_threadsafe returns future as concurrent.futures.Future() and not asyncio.Future
         # so, we can await it with timeout inside current thread
@@ -925,7 +925,7 @@ def run_async_coroutine(self, coroutine_to_run, timeout):
             self.logger.debug("scheduled {} returned {}".format(coroutine_to_run, coro_result))
             return coro_result
         except concurrent.futures.TimeoutError:
-            passed = time.time() - start_time
+            passed = time.monotonic() - start_time
             raise MolerTimeout(timeout=timeout,
                                kind="run_async_coroutine({})".format(coroutine_to_run),
                                passed_time=passed)

moler/cmd/unix/tail_latest_file.py

@@ -86,7 +86,7 @@ def on_new_line(self, line, is_full_line):
         """
         if is_full_line:
             if not self._first_line_time:
-                self._first_line_time = time.time()
+                self._first_line_time = time.monotonic()
         super(TailLatestFile, self).on_new_line(line=line, is_full_line=is_full_line)
 
     def is_failure_indication(self, line, is_full_line):
@@ -98,7 +98,7 @@ def is_failure_indication(self, line, is_full_line):
         :return: False if line does not match regex with failure, True if line matches the failure regex.
         """
         if self._check_failure_indication:
-            if time.time() - self._first_line_time < self.time_for_failure:
+            if time.monotonic() - self._first_line_time < self.time_for_failure:
                 return self._regex_helper.search_compiled(self.re_fail, line) is not None
             else:
                 self._check_failure_indication = False  # do not check time for future output. It's too late already.

moler/command_scheduler.py

@@ -106,7 +106,7 @@ def _add_command_to_connection(self, cmd, wait_for_slot=True):
                 cmd.set_exception(CommandTimeout(cmd,
                                                  timeout=cmd.timeout,
                                                  kind="scheduler.await_done",
-                                                 passed_time=time.time() - start_time))
+                                                 passed_time=time.monotonic() - start_time))
                 cmd.set_end_of_life()
                 self._remove_command(cmd=cmd)
         return False
@@ -144,9 +144,9 @@ def _wait_for_slot_for_command(self, cmd):
         """
         connection = cmd.connection
         lock = self._lock_for_connection(connection)
-        start_time = time.time()
+        start_time = time.monotonic()
         conn_atr = self._locks[connection]
-        while cmd.timeout >= (time.time() - start_time):
+        while cmd.timeout >= (time.monotonic() - start_time):
             time.sleep(0.005)
             with lock:
                 if conn_atr['current_cmd'] is None and len(conn_atr['queue']) >= 1 and cmd == conn_atr['queue'][0]:

moler/connection_observer.py

@@ -159,7 +159,7 @@ def start(self, timeout: Optional[float] = None, *args, **kwargs):
             # That is so, since observer lifetime starts with it's timeout-clock
             # and timeout is counted from calling observer.start()
             self.life_status._is_running = True
-            self.life_status.start_time = time.time()
+            self.life_status.start_time = time.monotonic()
             # Besides not started parallelism machinery causing start-delay
             # we can have start-delay caused by commands queue on connection
             # (can't submit command to background-run till previous stops running)

moler/device/proxy_pc2.py

@@ -461,7 +461,7 @@ def _detect_prompt_get_cmd(self):
         for try_nr in range(1, 10, 1):
             if self._after_open_prompt_detector is None or self._after_open_prompt_detector.running() is False:
                 self._detect_after_open_prompt(self._set_after_open_prompt)
-            while time.time() - self._after_open_prompt_detector.life_status.start_time < self._prompt_detector_timeout:
+            while time.monotonic() - self._after_open_prompt_detector.life_status.start_time < self._prompt_detector_timeout:
                 time.sleep(0.1)
                 if self._prompt_detected is True:
                     break

moler/device/textualdevice.py

@@ -449,13 +449,13 @@ def await_goto_state(self, timeout=10):
         :return: None
         :raise DeviceChangeStateFailure: if the goto_state chain is not empty and timeout occurs.
         """
-        start_time = time.time()
-        while time.time() - start_time <= timeout:
+        start_time = time.monotonic()
+        while time.monotonic() - start_time <= timeout:
             if self._queue_states.empty() and self._thread_for_goto_state is None:
                 return
         raise DeviceChangeStateFailure(device=self.__class__.__name__,
                                        exception="After {} seconds there are still states to go: '{}' and/or thread to"
-                                                 " change state".format(time.time() - start_time, self._queue_states,
+                                                 " change state".format(time.monotonic() - start_time, self._queue_states,
                                                                         self._thread_for_goto_state),
                                        device_name=self.name)
 
@@ -519,7 +519,7 @@ def _goto_state_to_run_in_try(self, dest_state, keep_state, timeout, rerun, send
 
         is_dest_state = False
         is_timeout = False
-        start_time = time.time()
+        start_time = time.monotonic()
         final_timeout = timeout_multiply * timeout
         next_stage_timeout = final_timeout
 
@@ -534,7 +534,7 @@ def _goto_state_to_run_in_try(self, dest_state, keep_state, timeout, rerun, send
                 is_dest_state = True
 
             if timeout > 0:
-                next_stage_timeout = final_timeout - (time.time() - start_time)
+                next_stage_timeout = final_timeout - (time.monotonic() - start_time)
                 if next_stage_timeout <= 0:
                     is_timeout = True
         if keep_state:

moler/event_awaiter.py

@@ -29,7 +29,7 @@ def wait_for_all(cls, timeout, events, interval=0.001):
         :return: True if all events are done, False otherwise.
         """
         grand_timeout = timeout
-        start_time = time.time()
+        start_time = time.monotonic()
         all_done = True
         while timeout >= 0:
             time.sleep(interval)
@@ -40,7 +40,7 @@ def wait_for_all(cls, timeout, events, interval=0.001):
                     break
             if all_done:
                 break
-            timeout = grand_timeout - (time.time() - start_time)
+            timeout = grand_timeout - (time.monotonic() - start_time)
         return all_done
 
     @classmethod
@@ -54,15 +54,15 @@ def wait_for_any(cls, timeout, events, interval=0.001):
         :return: True if any event is done, False otherwise.
         """
         grand_timeout = timeout
-        start_time = time.time()
+        start_time = time.monotonic()
         any_done = False
         while timeout >= 0 and not any_done:
             time.sleep(interval)
             for event in events:
                 if event.done():
                     any_done = True
                     break
-            timeout = grand_timeout - (time.time() - start_time)
+            timeout = grand_timeout - (time.monotonic() - start_time)
         return any_done
 
     @classmethod

moler/io/raw/sshshell.py

@@ -233,7 +233,7 @@ def send(self, data, timeout=1):
                 raise  # let any other error be visible
 
     def _send(self, data, timeout=1.0):
-        start_time = time.time()
+        start_time = time.monotonic()
         nb_bytes_to_send = len(data)
         nb_bytes_sent = 0
         data2send = data
@@ -246,7 +246,7 @@ def _send(self, data, timeout=1.0):
                 nb_bytes_sent = 0
             if nb_bytes_sent >= nb_bytes_to_send:
                 break
-            if time.time() - start_time >= timeout:
+            if time.monotonic() - start_time >= timeout:
                 send_status = '[{} of {} bytes] {}'.format(nb_bytes_sent, nb_bytes_to_send, data)
                 # don't want to show class name - just ssh address
                 # want same output from any implementation of SshShell-connection

moler/moler_connection_for_single_thread_runner.py

@@ -109,7 +109,7 @@ def notify_observers(self, data, recv_time):
         """
         super(MolerConnectionForSingleThreadRunner, self).notify_observers(data=data, recv_time=recv_time)
         for connection_observer in self._connection_observers:
-            connection_observer.life_status.last_feed_time = time.time()
+            connection_observer.life_status.last_feed_time = time.monotonic()
 
     def _create_observer_wrapper(self, observer_reference, self_for_observer):
         """

moler/runner.py

@@ -315,7 +315,7 @@ def submit(self, connection_observer):
 
         c_future = CancellableFuture(connection_observer_future, observer_lock,
                                      stop_feeding, feed_done)
-        connection_observer.life_status.last_feed_time = time.time()
+        connection_observer.life_status.last_feed_time = time.monotonic()
         return c_future
 
     def wait_for(self, connection_observer, connection_observer_future, timeout=None):
@@ -349,7 +349,7 @@ def wait_for(self, connection_observer, connection_observer_future, timeout=None
         max_timeout = timeout
         observer_timeout = connection_observer.timeout
         # we count timeout from now if timeout is given; else we use .life.status.start_time and .timeout of observer
-        start_time = time.time() if max_timeout else connection_observer.life_status.start_time
+        start_time = time.monotonic() if max_timeout else connection_observer.life_status.start_time
         await_timeout = max_timeout if max_timeout else observer_timeout
         if max_timeout:
             remain_time, msg = his_remaining_time("await max.", timeout=max_timeout, from_start_time=start_time)
@@ -397,7 +397,7 @@ def _execute_till_eol(self, connection_observer, connection_observer_future, max
                     if (future in done) or connection_observer.done():
                         self._cancel_submitted_future(connection_observer, future)
                         return True
-                    already_passed = time.time() - connection_observer.life_status.start_time
+                    already_passed = time.monotonic() - connection_observer.life_status.start_time
                     eol_timeout = connection_observer.timeout + connection_observer.life_status.terminating_timeout
                     eol_remain_time = eol_timeout - already_passed
                     timeout = connection_observer.timeout
@@ -414,10 +414,10 @@ def _execute_till_eol(self, connection_observer, connection_observer_future, max
     def _wait_for_not_started_connection_observer_is_done(self, connection_observer):
         # Have to wait till connection_observer is done with terminaing timeout.
         eol_remain_time = connection_observer.life_status.terminating_timeout
-        start_time = time.time()
+        start_time = time.monotonic()
         while not connection_observer.done() and eol_remain_time > 0.0:
             time.sleep(self._tick)
-            eol_remain_time = start_time + connection_observer.life_status.terminating_timeout - time.time()
+            eol_remain_time = start_time + connection_observer.life_status.terminating_timeout - time.monotonic()
 
     def _end_of_life_of_future_and_connection_observer(self, connection_observer, connection_observer_future):
         future = connection_observer_future or connection_observer._future
@@ -432,7 +432,7 @@ def _cancel_submitted_future(connection_observer, connection_observer_future):
             future.cancel(no_wait=True)
 
     def _wait_for_time_out(self, connection_observer, connection_observer_future, timeout):
-        passed = time.time() - connection_observer.life_status.start_time
+        passed = time.monotonic() - connection_observer.life_status.start_time
         future = connection_observer_future or connection_observer._future
         if future:
             self.logger.debug(">>> Entering {}. conn-obs '{}' runner '{}' future '{}'".format(future.observer_lock, connection_observer, self, future))
@@ -478,7 +478,7 @@ def secure_data_received(data, timestamp):
                 with observer_lock:
                     self.logger.debug(u">>> Entered  {}. conn-obs '{}' runner '{}' data '{}'".format(observer_lock, connection_observer, self, data))
                     connection_observer.data_received(data, timestamp)
-                    connection_observer.life_status.last_feed_time = time.time()
+                    connection_observer.life_status.last_feed_time = time.monotonic()
                 self.logger.debug(u">>> Exited   {}. conn-obs '{}' runner '{}' data '{}'".format(observer_lock, connection_observer, self, data))
 
             except Exception as exc:  # TODO: handling stacktrace
@@ -583,7 +583,7 @@ def _feed_loop(self, connection_observer, stop_feeding, observer_lock):
             if connection_observer.done():
                 self.logger.debug("done {}".format(connection_observer))
                 break
-            current_time = time.time()
+            current_time = time.monotonic()
             run_duration = current_time - start_time
             # we need to check connection_observer.timeout at each round since timeout may change
             # during lifetime of connection_observer
@@ -605,7 +605,7 @@ def _feed_loop(self, connection_observer, stop_feeding, observer_lock):
                                           passed_time=run_duration,
                                           runner_logger=self.logger)
                         if connection_observer.life_status.terminating_timeout >= 0.0:
-                            start_time = time.time()
+                            start_time = time.monotonic()
                             connection_observer.life_status.in_terminating = True
                         else:
                             break
@@ -649,7 +649,7 @@ def his_remaining_time(prefix, timeout, from_start_time):
     :param from_start_time: start of lifetime for the object
     :return: remaining time as float and related description message
     """
-    already_passed = time.time() - from_start_time
+    already_passed = time.monotonic() - from_start_time
     remain_time = timeout - already_passed
     if remain_time < 0.0:
         remain_time = 0.0
@@ -668,7 +668,7 @@ def await_future_or_eol(connection_observer, remain_time, start_time, timeout, l
             logger.debug("{} is done before creating future".format(connection_observer))
             end_of_life = True
             break
-        now = time.time()
+        now = time.monotonic()
         already_passed = now - start_time
         remain_time = timeout - already_passed
         observer_lifetime_passed = now - connection_observer.life_status.start_time