commit ac6d89e6c0b9bca6a8d33f7ddac1cbc8d65d5956
author Austin Schuh <austin.schuh@bluerivertech.com> Wed Mar 27 14:56:09 2024 -0700
committer Austin Schuh <austin.linux@gmail.com> Sat May 11 14:59:28 2024 -0700
tree f163415422f80996c0b6d613c680d0c2d4edfc56
parent 9d50f0dd7b5e8921a2567cab567c27d6b6aef7b6

Logger: Pipe the monotonic_remote_transmit_time through event loop

Populate the field in all the network bridges and pipe it through
all the required spots in the event loop.  Update all the tests to match
the update.

As part of this, we realized that our modeling of network delay was
wrong.  Wakeups don't always take 50 uS if something else triggers the
wakeup and the message is ready in shared memory.  This wasn't being
handled properly.

Change-Id: Idf94c5c6d7c87f4d65868c71b1cceedca7bf3853
Signed-off-by: James Kuszmaul <james.kuszmaul@bluerivertech.com>

aos/network/message_bridge_test.cc

diff --git a/aos/network/message_bridge_test.cc b/aos/network/message_bridge_test.cc
index c211c89..d55438f 100644
--- a/aos/network/message_bridge_test.cc
+++ b/aos/network/message_bridge_test.cc
@@ -344,6 +344,9 @@
               chrono::nanoseconds(header.realtime_sent_time()));
           const aos::monotonic_clock::time_point header_monotonic_remote_time(
               chrono::nanoseconds(header.monotonic_remote_time()));
+          const aos::monotonic_clock::time_point
+              header_monotonic_remote_transmit_time(
+                  chrono::nanoseconds(header.monotonic_remote_transmit_time()));
           const aos::realtime_clock::time_point header_realtime_remote_time(
               chrono::nanoseconds(header.realtime_remote_time()));
 
@@ -396,12 +399,19 @@
           EXPECT_EQ(pi2_context->monotonic_remote_time,
                     header_monotonic_remote_time);
 
+          EXPECT_LT(header_monotonic_remote_transmit_time,
+                    pi2_context->monotonic_event_time);
+          EXPECT_GT(header_monotonic_remote_transmit_time,
+                    pi2_context->monotonic_remote_time);
+
           // Confirm the forwarded message also matches the source message.
           EXPECT_EQ(pi1_context->queue_index, header.queue_index());
           EXPECT_EQ(pi1_context->monotonic_event_time,
                     header_monotonic_remote_time);
           EXPECT_EQ(pi1_context->realtime_event_time,
                     header_realtime_remote_time);
+          EXPECT_EQ(header_monotonic_remote_transmit_time,
+                    pi2_context->monotonic_remote_transmit_time);
         });
   }
 
@@ -860,6 +870,8 @@
           &pi1_remote_timestamp_event_loop);
 
   {
+    const aos::monotonic_clock::time_point startup_time =
+        aos::monotonic_clock::now();
     // Now spin up a client for 2 seconds.
     MakePi2Client();
 
@@ -878,6 +890,10 @@
               0u);
 
     EXPECT_TRUE(ping_fetcher.Fetch());
+    EXPECT_GT(ping_fetcher.context().monotonic_remote_transmit_time,
+              startup_time);
+    EXPECT_LT(ping_fetcher.context().monotonic_remote_transmit_time,
+              aos::monotonic_clock::now());
     EXPECT_FALSE(unreliable_ping_fetcher.Fetch());
     EXPECT_EQ(ping_timestamp_count, 1);
 
@@ -990,6 +1006,8 @@
           &pi1_remote_timestamp_event_loop);
 
   {
+    const aos::monotonic_clock::time_point startup_time =
+        aos::monotonic_clock::now();
     // Now, spin up a server for 2 seconds.
     MakePi1Server();
 
@@ -1008,6 +1026,11 @@
               0u);
 
     EXPECT_TRUE(ping_fetcher.Fetch());
+    EXPECT_GT(ping_fetcher.context().monotonic_remote_transmit_time,
+              startup_time);
+    EXPECT_LT(ping_fetcher.context().monotonic_remote_transmit_time,
+              aos::monotonic_clock::now());
+
     EXPECT_FALSE(unreliable_ping_fetcher.Fetch());
     EXPECT_EQ(ping_timestamp_count, 1);
     LOG(INFO) << "Shutting down first pi1 MessageBridgeServer";
@@ -1144,6 +1167,8 @@
   }
 
   {
+    const aos::monotonic_clock::time_point startup_time =
+        aos::monotonic_clock::now();
     // Now, spin up a client for 2 seconds.
     MakePi2Client();
 
@@ -1165,6 +1190,11 @@
     // We should have gotten precisely one more ping message--the latest one
     // sent should've made it, but no previous ones.
     EXPECT_TRUE(ping_fetcher.FetchNext());
+    EXPECT_GT(ping_fetcher.context().monotonic_remote_transmit_time,
+              startup_time);
+    EXPECT_LT(ping_fetcher.context().monotonic_remote_transmit_time,
+              aos::monotonic_clock::now());
+
     EXPECT_EQ(ping_index, ping_fetcher->value());
     EXPECT_FALSE(ping_fetcher.FetchNext());