diff --git a/paseos/activities/activity_processor.py b/paseos/activities/activity_processor.py index 8e35acf..fbd5359 100644 --- a/paseos/activities/activity_processor.py +++ b/paseos/activities/activity_processor.py @@ -83,7 +83,12 @@ async def _update(self, elapsed_time: float): Args: elapsed_time (float): Elapsed time in seconds. """ - assert elapsed_time > 0, "Elapsed time cannot be negative." + assert elapsed_time >= 0, "Elapsed time cannot be negative." + # A zero interval can occur when updates are scheduled back-to-back. advance_time + # already treats it as a no-op, so return early here to skip the redundant call + # and its per-tick debug logging. + if elapsed_time == 0: + return logger.debug("Running ActivityProcessor update.") logger.debug(f"Time since last update: {elapsed_time}s") logger.trace(f"Applying time multiplier of {self._time_multiplier}") diff --git a/paseos/paseos.py b/paseos/paseos.py index d842528..b9e4fe1 100644 --- a/paseos/paseos.py +++ b/paseos/paseos.py @@ -98,97 +98,108 @@ def advance_time( float: Time remaining to advance (or 0 if done) """ + assert current_power_consumption_in_W >= 0, "Power consumption cannot be negative." + assert time_to_advance >= 0, "Time to advance cannot be negative." + + # In real-time (async activity) mode the measured interval between updates can + # round to zero. Advancing by zero is a no-op, so return before touching the + # re-entrancy guard to avoid leaving it set. + if time_to_advance == 0: + return 0.0 + assert not self._is_advancing_time, ( "advance_time is already running. This function is not thread-safe. Avoid mixing (async) activities and calling it." ) self._is_advancing_time = True - - assert time_to_advance > 0, "Time to advance has to be positive." - assert current_power_consumption_in_W >= 0, "Power consumption cannot be negative." - - # Check constraint function returns something - if constraint_function is not None: - assert constraint_function() is not None, ( - "Your constraint function failed to return True or False." - ) - - logger.debug("Advancing time by " + str(time_to_advance) + " s.") - target_time = self._state.time + time_to_advance - dt = self._cfg.sim.dt - - time_since_constraint_check = float("inf") - - # Perform timesteps until target_time - dt reached, - # then final smaller or equal timestep to reach target_time - while self._state.time < target_time: - # Check constraint function - if ( - constraint_function is not None - and time_since_constraint_check > self._cfg.sim.activity_timestep - ): - time_since_constraint_check = 0 - if not constraint_function(): - logger.info("Time advancing interrupted. Constraint false.") - break - - if self._state.time > target_time - dt: - # compute final timestep to catch up - dt = target_time - self._state.time - logger.trace(f"Time {self._state.time}, advancing {dt}") - - # Perform updates for local actor (e.g. charging) - # Each actor only updates itself - - # check for device and / or activity failure - if self.local_actor.has_radiation_model: - if self.local_actor.is_dead: - logger.warning(f"Tried to advance time on dead actor {self.local_actor}.") - return max(target_time - self._state.time, 0) - if self.local_actor._radiation_model.did_device_restart(dt): - logger.info(f"Actor {self.local_actor} interrupted during advance_time.") - self.local_actor.set_was_interrupted() - return max(target_time - self._state.time, 0) - if self.local_actor._radiation_model.did_device_experience_failure(dt): - logger.info(f"Actor {self.local_actor} died during advance_time.") - self.local_actor.set_is_dead() - return max(target_time - self._state.time, 0) - - # charge from current moment to time after timestep - if self.local_actor.has_power_model: - self._local_actor.charge(dt) - - # Update actor temperature - if self.local_actor.has_thermal_model: - self.local_actor._thermal_model.update_temperature( - dt, current_power_consumption_in_W + # Wrap the body so the guard is always released, even on an early return or an + # exception. Leaking it True would poison every later advance_time call. + try: + # Check constraint function returns something + if constraint_function is not None: + assert constraint_function() is not None, ( + "Your constraint function failed to return True or False." ) - # Update state of charge - if self.local_actor.has_power_model: - self.local_actor.discharge(current_power_consumption_in_W, dt) - - # Update user-defined properties in the actor - for property_name in self.local_actor.custom_properties.keys(): - update_function = self.local_actor.get_custom_property_update_function( - property_name - ) - new_value = update_function(self.local_actor, dt, current_power_consumption_in_W) - self.local_actor.set_custom_property(property_name, new_value) - - self._state.time += dt - time_since_constraint_check += dt - self.local_actor.set_time(pk.epoch(self._state.time * pk.SEC2DAY)) - - # Check if we should update the status log - if self._time_since_previous_log > self._cfg.io.logging_interval: - self.log_status() - self._time_since_previous_log = 0 - else: - self._time_since_previous_log += dt - - logger.debug("New time is: " + str(self._state.time) + " s.") - self._is_advancing_time = False - return max(target_time - self._state.time, 0) + logger.debug("Advancing time by " + str(time_to_advance) + " s.") + target_time = self._state.time + time_to_advance + dt = self._cfg.sim.dt + + time_since_constraint_check = float("inf") + + # Perform timesteps until target_time - dt reached, + # then final smaller or equal timestep to reach target_time + while self._state.time < target_time: + # Check constraint function + if ( + constraint_function is not None + and time_since_constraint_check > self._cfg.sim.activity_timestep + ): + time_since_constraint_check = 0 + if not constraint_function(): + logger.info("Time advancing interrupted. Constraint false.") + break + + if self._state.time > target_time - dt: + # compute final timestep to catch up + dt = target_time - self._state.time + logger.trace(f"Time {self._state.time}, advancing {dt}") + + # Perform updates for local actor (e.g. charging) + # Each actor only updates itself + + # check for device and / or activity failure + if self.local_actor.has_radiation_model: + if self.local_actor.is_dead: + logger.warning(f"Tried to advance time on dead actor {self.local_actor}.") + return max(target_time - self._state.time, 0) + if self.local_actor._radiation_model.did_device_restart(dt): + logger.info(f"Actor {self.local_actor} interrupted during advance_time.") + self.local_actor.set_was_interrupted() + return max(target_time - self._state.time, 0) + if self.local_actor._radiation_model.did_device_experience_failure(dt): + logger.info(f"Actor {self.local_actor} died during advance_time.") + self.local_actor.set_is_dead() + return max(target_time - self._state.time, 0) + + # charge from current moment to time after timestep + if self.local_actor.has_power_model: + self._local_actor.charge(dt) + + # Update actor temperature + if self.local_actor.has_thermal_model: + self.local_actor._thermal_model.update_temperature( + dt, current_power_consumption_in_W + ) + + # Update state of charge + if self.local_actor.has_power_model: + self.local_actor.discharge(current_power_consumption_in_W, dt) + + # Update user-defined properties in the actor + for property_name in self.local_actor.custom_properties.keys(): + update_function = self.local_actor.get_custom_property_update_function( + property_name + ) + new_value = update_function( + self.local_actor, dt, current_power_consumption_in_W + ) + self.local_actor.set_custom_property(property_name, new_value) + + self._state.time += dt + time_since_constraint_check += dt + self.local_actor.set_time(pk.epoch(self._state.time * pk.SEC2DAY)) + + # Check if we should update the status log + if self._time_since_previous_log > self._cfg.io.logging_interval: + self.log_status() + self._time_since_previous_log = 0 + else: + self._time_since_previous_log += dt + + logger.debug("New time is: " + str(self._state.time) + " s.") + return max(target_time - self._state.time, 0) + finally: + self._is_advancing_time = False def add_known_actor(self, actor: BaseActor): """Adds an actor to the simulation. diff --git a/paseos/tests/advance_time_test.py b/paseos/tests/advance_time_test.py new file mode 100644 index 0000000..fe88112 --- /dev/null +++ b/paseos/tests/advance_time_test.py @@ -0,0 +1,45 @@ +"""Regression tests for the advance_time re-entrancy guard. + +These cover the failure modes fixed alongside the uv/Python 3.8 CI migration: +the guard used to be set before argument validation and only cleared on the +normal return, so a zero-length interval or an exception mid-advance_time left +it stuck True and poisoned every later call (deadlocking wait_for_activity). +""" + +import sys + +sys.path.append("../..") + +import pytest +from test_utils import get_default_instance + + +def test_advance_time_zero_interval_is_noop(): + """Advancing by zero returns 0.0 and never engages the guard.""" + sim, _, _ = get_default_instance() + + assert sim.advance_time(0, 0) == 0.0 + assert sim._is_advancing_time is False + + # A normal advancement still works right after a zero-length call. + assert sim.advance_time(10, 0) == 0 + assert sim._is_advancing_time is False + + +def test_advance_time_releases_guard_on_exception(): + """An exception mid-advance_time must still release the guard. + + Previously the guard leaked True and the next call failed the + 'advance_time is already running' assertion, deadlocking the simulation. + """ + sim, _, _ = get_default_instance() + + # A constraint function returning None raises inside advance_time (after the + # guard is set), which must be cleaned up by the finally block. + with pytest.raises(AssertionError): + sim.advance_time(10, 0, constraint_function=lambda: None) + assert sim._is_advancing_time is False + + # The guard was not left poisoned, so a subsequent call still succeeds. + assert sim.advance_time(10, 0) == 0 + assert sim._is_advancing_time is False