Debugging instability introduced by ros#317 (ros#323)

* more info on failing comparisons
* ignoring old wrong messages
* fixes in ntp monitor test
---------
Signed-off-by: Christian Henkel <[email protected]>

diagnostic_aggregator/test/test_critical_pub.py

@@ -61,10 +61,10 @@ def publish_message(self, level):
         msg.status.append(DiagnosticStatus())
         msg.status[0].level = level
         msg.status[0].name = 'test status'
-        while len(self.received_state) == 0:
+        while msg.status[0].level not in self.received_state:
+            self.received_state.clear()
             self.publisher.publish(msg)
             rclpy.spin_once(self.node)
-
         return self.node.get_clock().now()
 
     def test_critical_publisher(self):
@@ -73,15 +73,17 @@ def test_critical_publisher(self):
         time_0 = self.publish_message(state)
 
         assert (self.received_state[0] == state), \
-            'Received state is not the same as the sent state'
+            ('Received state is not the same as the sent state:'
+                + f"'{self.received_state[0]}' != '{state}'")
         self.received_state.clear()
 
         # Publish the ok message and expect the toplevel state after 1 second period
         time_1 = self.publish_message(state)
         assert (time_1 - time_0 > rclpy.duration.Duration(seconds=0.99)), \
             'OK message received too early'
         assert (self.received_state[0] == state), \
-            'Received state is not the same as the sent state'
+            ('Received state is not the same as the sent state:'
+                + f"'{self.received_state[0]}' != '{state}'")
         self.received_state.clear()
 
         # Publish the message and expect the critical error message immediately
@@ -91,7 +93,8 @@ def test_critical_publisher(self):
         assert (time_2 - time_1 < rclpy.duration.Duration(seconds=0.1)), \
             'Critical error message not received within 0.1 second'
         assert (self.received_state[0] == state), \
-            'Received state is not the same as the sent state'
+            ('Received state is not the same as the sent state:'
+                + f"'{self.received_state[0]}' != '{state}'")
         self.received_state.clear()
 
         # Next error message should be sent at standard 1 second rate
@@ -100,4 +103,5 @@ def test_critical_publisher(self):
         assert (time_3 - time_1 > rclpy.duration.Duration(seconds=0.99)), \
             'Periodic error message received too early'
         assert (self.received_state[0] == state), \
-            'Received state is not the same as the sent state'
+            ('Received state is not the same as the sent state:'
+                + f"'{self.received_state[0]}' != '{state}'")

diagnostic_common_diagnostics/test/systemtest/test_ntp_monitor.py

@@ -54,7 +54,7 @@ def __init__(self, methodName: str = 'runTest') -> None:
 
     def setUp(self):
         self.n_msgs_received = 0
-        n = self._count_msgs(TIMEOUT_MAX_S)
+        n = self._count_msgs(1.)
         self.assertEqual(n, 0)
         self.subprocess = subprocess.Popen(
             [
@@ -73,20 +73,25 @@ def tearDown(self):
         self.subprocess.kill()
 
     def _diagnostics_callback(self, msg):
+        rclpy.logging.get_logger('test_ntp_monitor').info(
+            f'Received diagnostics message: {msg}'
+        )
         search_strings = [
             'NTP offset from',
             'NTP self-offset for'
         ]
         for search_string in search_strings:
-            if search_string not in ''.join([
+            if search_string in ''.join([
                 s.name for s in msg.status
             ]):
-                return
-        self.n_msgs_received += 1
+                self.n_msgs_received += 1
 
     def _count_msgs(self, timeout_s):
         self.n_msgs_received = 0
         node = rclpy.create_node('test_ntp_monitor')
+        rclpy.logging.get_logger('test_ntp_monitor').info(
+            '_count_msgs'
+        )
         node.create_subscription(
             DiagnosticArray,
             'diagnostics',
@@ -95,9 +100,13 @@ def _count_msgs(self, timeout_s):
         )
         TIME_D_S = .05
         waited_s = 0.
+        start = node.get_clock().now()
         while waited_s < timeout_s and self.n_msgs_received == 0:
             rclpy.spin_once(node, timeout_sec=TIME_D_S)
-            waited_s += TIME_D_S
+            waited_s = (node.get_clock().now() - start).nanoseconds / 1e9
+        rclpy.logging.get_logger('test_ntp_monitor').info(
+            f'received {self.n_msgs_received} messages after {waited_s}s'
+        )
         node.destroy_node()
         return self.n_msgs_received
 

diagnostic_updater/package.xml

@@ -32,7 +32,6 @@
   <test_depend>ament_lint_common</test_depend>
   <test_depend>launch</test_depend>
   <test_depend>launch_testing</test_depend>
-  <!-- <test_depend>launch_testing_ros</test_depend> -->
   <test_depend>python3-pytest</test_depend>
   <test_depend>rclcpp_lifecycle</test_depend>