Sleep loudly

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

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})"

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

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)

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)

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)

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(

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()

monitoring/uss_qualifier/scenarios/astm/netrid/virtual_observer.py

@@ -1,11 +1,11 @@
-import time
 from datetime import timedelta, datetime
 from typing import Optional, Callable, List
 from loguru import logger
 
 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())

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,

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.")