diff --git a/monitoring/deployment_manager/actions/test/hello_world.py b/monitoring/deployment_manager/actions/test/hello_world.py index b591c5d10b..e12d0086d3 100644 --- a/monitoring/deployment_manager/actions/test/hello_world.py +++ b/monitoring/deployment_manager/actions/test/hello_world.py @@ -1,10 +1,9 @@ -import time - from monitoring.deployment_manager import deploylib import monitoring.deployment_manager.deploylib.namespaces import monitoring.deployment_manager.deploylib.systems from monitoring.deployment_manager.infrastructure import deployment_action, Context from monitoring.deployment_manager.systems.test import hello_world +from monitoring.monitorlib.delay import sleep @deployment_action("test/hello_world/deploy") @@ -52,7 +51,7 @@ def destroy(context: Context) -> None: namespace.metadata.name, context.spec.cluster.name ) ) - time.sleep(15) + sleep(15, "destruction of hello_world system may take a few seconds") deploylib.systems.delete_resources( existing_resources, namespace, context.clients, context.log diff --git a/monitoring/mock_uss/flights/planning.py b/monitoring/mock_uss/flights/planning.py index 7acb6baa61..c2a9b4eee1 100644 --- a/monitoring/mock_uss/flights/planning.py +++ b/monitoring/mock_uss/flights/planning.py @@ -3,6 +3,7 @@ from typing import Callable, Optional from monitoring.mock_uss.flights.database import FlightRecord, db, DEADLOCK_TIMEOUT +from monitoring.monitorlib.delay import sleep def lock_flight(flight_id: str, log: Callable[[str], None]) -> FlightRecord: @@ -25,7 +26,7 @@ def lock_flight(flight_id: str, log: Callable[[str], None]) -> FlightRecord: break # We found an existing flight but it was locked; wait for it to become # available - time.sleep(0.5) + sleep(0.5, f"flight {flight_id} is currently already locked") if datetime.utcnow() > deadline: raise RuntimeError( @@ -61,7 +62,10 @@ def delete_flight_record(flight_id: str) -> Optional[FlightRecord]: # No FlightRecord found return None # There is a race condition with another handler to create or modify the requested flight; wait for that to resolve - time.sleep(0.5) + sleep( + 0.5, + f"flight {flight_id} is currently already locked while we are trying to delete it", + ) if datetime.utcnow() > deadline: raise RuntimeError( f"Deadlock in delete_flight while attempting to gain access to flight {flight_id} (now: {datetime.utcnow()}, deadline: {deadline})" diff --git a/monitoring/mock_uss/ridsp/behavior.py b/monitoring/mock_uss/ridsp/behavior.py index 6a3c3cd141..0e23723012 100644 --- a/monitoring/mock_uss/ridsp/behavior.py +++ b/monitoring/mock_uss/ridsp/behavior.py @@ -1,6 +1,6 @@ -from time import sleep from typing import Optional +from monitoring.monitorlib.delay import sleep from monitoring.monitorlib.rid_automated_testing.injection_api import TestFlight from implicitdict import ImplicitDict from uas_standards.astm.f3411.v19.api import RIDFlight @@ -56,6 +56,9 @@ def adjust_reported_flight( p.position.alt *= FEET_PER_METER if behavior.delay_flight_report_s > 0: - sleep(behavior.delay_flight_report_s) + sleep( + behavior.delay_flight_report_s, + "specified Service Provider behavior is to delay before reporting flight", + ) return adjusted diff --git a/monitoring/monitorlib/delay.py b/monitoring/monitorlib/delay.py new file mode 100644 index 0000000000..ab1df44286 --- /dev/null +++ b/monitoring/monitorlib/delay.py @@ -0,0 +1,27 @@ +from datetime import timedelta +import time +from typing import Union + +from loguru import logger + + +MAX_SILENT_DELAY_S = 0.4 +"""Number of seconds to delay above which a reasoning message should be displayed.""" + + +def sleep(duration: Union[float, timedelta], reason: str) -> None: + """Sleep for the specified amount of time, logging the fact that the delay is occurring (when appropriate). + + Args: + duration: Amount of time to sleep for; interpreted as seconds if float. + reason: Reason the delay is happening (to be printed to console/log if appropriate). + """ + if isinstance(duration, timedelta): + duration = duration.total_seconds() + if duration <= 0: + # No need to delay + return + + if duration > MAX_SILENT_DELAY_S: + logger.debug(f"Delaying {duration:.1f} seconds because {reason}") + time.sleep(duration) diff --git a/monitoring/prober/rid/v1/test_isa_expiry.py b/monitoring/prober/rid/v1/test_isa_expiry.py index 94d1dabd76..9ab9a800eb 100644 --- a/monitoring/prober/rid/v1/test_isa_expiry.py +++ b/monitoring/prober/rid/v1/test_isa_expiry.py @@ -3,6 +3,7 @@ import datetime import time +from monitoring.monitorlib.delay import sleep from monitoring.monitorlib.infrastructure import default_scope from monitoring.monitorlib import rid_v1 from monitoring.prober.infrastructure import register_resource_type @@ -64,7 +65,7 @@ def test_valid_immediately(ids, session_ridv1): def test_sleep_5_seconds(): # But if we wait 5 seconds it will expire... - time.sleep(5) + sleep(5, "if we wait 5 seconds, the ISA of interest will expire") @default_scope(Scope.Read) diff --git a/monitoring/prober/rid/v2/test_isa_expiry.py b/monitoring/prober/rid/v2/test_isa_expiry.py index d4caf15fb4..ba06ee1828 100644 --- a/monitoring/prober/rid/v2/test_isa_expiry.py +++ b/monitoring/prober/rid/v2/test_isa_expiry.py @@ -68,7 +68,7 @@ def test_valid_immediately(ids, session_ridv2): def test_sleep_5_seconds(): # But if we wait 5 seconds it will expire... - time.sleep(5) + sleep(5, "if we wait 5 seconds, the ISA of interest will expire") @default_scope(Scope.DisplayProvider) diff --git a/monitoring/uss_qualifier/scenarios/astm/netrid/common/dss/isa_expiry.py b/monitoring/uss_qualifier/scenarios/astm/netrid/common/dss/isa_expiry.py index 1007381a3e..f9e973928c 100644 --- a/monitoring/uss_qualifier/scenarios/astm/netrid/common/dss/isa_expiry.py +++ b/monitoring/uss_qualifier/scenarios/astm/netrid/common/dss/isa_expiry.py @@ -4,6 +4,7 @@ import arrow +from monitoring.monitorlib.delay import sleep from monitoring.prober.infrastructure import register_resource_type from monitoring.uss_qualifier.common_data_definitions import Severity from monitoring.uss_qualifier.resources.astm.f3411.dss import DSSInstanceResource @@ -83,7 +84,7 @@ def _check_expiry_behaviors(self): ) # Wait for it to expire - time.sleep(5) + sleep(5, "we need to wait for the short-lived ISA to expire") # Search for ISAs: we should not find the expired one with self.check( diff --git a/monitoring/uss_qualifier/scenarios/astm/netrid/common/dss_interoperability.py b/monitoring/uss_qualifier/scenarios/astm/netrid/common/dss_interoperability.py index 93573d0a5e..fb5ded23af 100644 --- a/monitoring/uss_qualifier/scenarios/astm/netrid/common/dss_interoperability.py +++ b/monitoring/uss_qualifier/scenarios/astm/netrid/common/dss_interoperability.py @@ -1,6 +1,5 @@ import ipaddress import socket -import time import uuid from dataclasses import dataclass import datetime @@ -10,6 +9,7 @@ import s2sphere +from monitoring.monitorlib.delay import sleep from monitoring.monitorlib.fetch.rid import ISA from monitoring.uss_qualifier.common_data_definitions import Severity from monitoring.uss_qualifier.resources.astm.f3411.dss import ( @@ -499,8 +499,10 @@ def step9(self): """Expired ISA automatically removed, ISA modifications accessible from all non-primary DSSs""" - # sleep X seconds for ISA_1 to expire - time.sleep(SHORT_WAIT_SEC) + sleep( + SHORT_WAIT_SEC, + "ISA_1 needs to expire so we can check it is automatically removed", + ) isa_1 = self._context["isa_1"] @@ -590,7 +592,10 @@ def step11(self): def step12(self): """Expired Subscriptions don’t trigger subscription notification requests""" - time.sleep(SHORT_WAIT_SEC) + sleep( + SHORT_WAIT_SEC, + "ISA needs to expire so we can check it doesn't trigger notifications", + ) isa_3 = self._new_isa("isa_3") all_sub_2_ids = self._get_entities_by_prefix("sub_2_").keys() diff --git a/monitoring/uss_qualifier/scenarios/astm/netrid/virtual_observer.py b/monitoring/uss_qualifier/scenarios/astm/netrid/virtual_observer.py index 4c7033cf21..040e71f052 100644 --- a/monitoring/uss_qualifier/scenarios/astm/netrid/virtual_observer.py +++ b/monitoring/uss_qualifier/scenarios/astm/netrid/virtual_observer.py @@ -1,4 +1,3 @@ -import time from datetime import timedelta, datetime from typing import Optional, Callable, List from loguru import logger @@ -6,6 +5,7 @@ import arrow from s2sphere import LatLngRect +from monitoring.monitorlib.delay import sleep from monitoring.uss_qualifier.scenarios.astm.netrid.injected_flight_collection import ( InjectedFlightCollection, ) @@ -114,7 +114,6 @@ def start_polling( break delay = t_next - arrow.utcnow() if delay.total_seconds() > 0: - logger.debug( - f"Waiting {delay.total_seconds()} seconds before polling RID system again..." + sleep( + delay, "RID sytem doesn't need to be polled again until this time" ) - time.sleep(delay.total_seconds()) diff --git a/monitoring/uss_qualifier/scenarios/astm/utm/data_exchange_validation/test_steps/expected_interactions_test_steps.py b/monitoring/uss_qualifier/scenarios/astm/utm/data_exchange_validation/test_steps/expected_interactions_test_steps.py index 20c178b88d..52cb6958d0 100644 --- a/monitoring/uss_qualifier/scenarios/astm/utm/data_exchange_validation/test_steps/expected_interactions_test_steps.py +++ b/monitoring/uss_qualifier/scenarios/astm/utm/data_exchange_validation/test_steps/expected_interactions_test_steps.py @@ -3,7 +3,6 @@ from datetime import datetime, timedelta import re from typing import Callable, Dict, List, Tuple, Optional -import time import arrow from implicitdict import StringBasedDateTime @@ -13,6 +12,7 @@ from monitoring.monitorlib.clients.mock_uss.interactions import Interaction from monitoring.monitorlib.clients.mock_uss.interactions import QueryDirection +from monitoring.monitorlib.delay import sleep from monitoring.monitorlib.fetch import QueryError, Query from monitoring.uss_qualifier.common_data_definitions import Severity from monitoring.uss_qualifier.resources.interuss.mock_uss.client import MockUSSClient @@ -54,7 +54,10 @@ def expect_mock_uss_receives_op_intent_notification( break dt = (wait_until - arrow.utcnow().datetime).total_seconds() if dt > 0: - time.sleep(min(dt, WAIT_INTERVAL_SECONDS)) + sleep( + min(dt, WAIT_INTERVAL_SECONDS), + "the expected notification was not found yet", + ) with scenario.check("Expect Notification sent", [participant_id]) as check: if not found: @@ -77,8 +80,10 @@ def expect_no_interuss_post_interactions( st: the earliest time a notification may have been sent participant_id: id of the participant responsible to send the notification """ - # Wait for next MaxTimeToWaitForSubscriptionNotificationSeconds duration to capture any notification - time.sleep(max_wait_time) + sleep( + max_wait_time, + "we have to wait the longest it may take a USS to send a notification before we can establish that they didn't send a notification", + ) found, query = mock_uss_interactions( scenario=scenario, mock_uss=mock_uss, diff --git a/monitoring/uss_qualifier/scenarios/dev/noop.py b/monitoring/uss_qualifier/scenarios/dev/noop.py index 7272905cc0..6980c7eabc 100644 --- a/monitoring/uss_qualifier/scenarios/dev/noop.py +++ b/monitoring/uss_qualifier/scenarios/dev/noop.py @@ -1,6 +1,6 @@ -import time from datetime import datetime +from monitoring.monitorlib.delay import sleep from monitoring.uss_qualifier.resources.dev import NoOpResource from monitoring.uss_qualifier.scenarios.scenario import TestScenario from monitoring.uss_qualifier.suites.suite import ExecutionContext @@ -21,7 +21,7 @@ def run(self, context: ExecutionContext): f"Starting at {datetime.utcnow().isoformat()}Z, sleeping for {self.sleep_secs}s...", ) - time.sleep(self.sleep_secs) + sleep(self.sleep_secs, "the no-op scenario sleeps for the specified time") self.record_note("End time", f"Ending at {datetime.utcnow().isoformat()}Z.")