commit 2f98cf0980fd1bf13c47e66b1dabf77dafe2634a
author Sarah Newman <sarah.newman@bluerivertech.com> Fri Apr 01 16:42:00 2022 -0700
committer James Kuszmaul <james.kuszmaul@bluerivertech.com> Tue May 03 15:48:54 2022 -0700
tree cbeca770de9f54a0298724e4aed63a51ba4bdae5
parent e02b0d17efdb3cfefca584101e72aefe0873d8de

events/ping-pong: clarify error reporting

Without this change, late pong packets look like duplicate pong
packets.

Add a check for duplicates for pong just in case.

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

aos/events/ping_lib.cc

diff --git a/aos/events/ping_lib.cc b/aos/events/ping_lib.cc
index 900ed0d..f9958ff 100644
--- a/aos/events/ping_lib.cc
+++ b/aos/events/ping_lib.cc
@@ -30,6 +30,10 @@
 }
 
 void Ping::SendPing() {
+  if (last_pong_value_ != count_ && (!quiet_ || VLOG_IS_ON(1))) {
+    LOG(WARNING) << "Did not receive response to " << count_ << " within "
+                 << FLAGS_sleep_ms << "ms.";
+  }
   ++count_;
   aos::Sender<examples::Ping>::Builder builder = sender_.MakeBuilder();
   examples::Ping::Builder ping_builder = builder.MakeBuilder<examples::Ping>();
@@ -50,15 +54,17 @@
       monotonic_now - monotonic_send_time;
 
   if (last_pong_value_ + 1 != pong.value() && (!quiet_ || VLOG_IS_ON(1))) {
-    LOG(WARNING) << "Pong message lost";
+    LOG(WARNING) << "Unexpected pong value, wanted " << last_pong_value_ + 1
+                 << ", got " << pong.value();
   }
 
   if (pong.value() == count_) {
     VLOG(1) << "Elapsed time " << round_trip_time.count() << " ns "
             << FlatbufferToJson(&pong);
   } else if (!quiet_ || VLOG_IS_ON(1)) {
-    LOG(WARNING) << "Missmatched pong message, got " << FlatbufferToJson(&pong)
-                 << " expected " << count_;
+    LOG(WARNING) << "Unexpected pong response, got " << FlatbufferToJson(&pong)
+                 << " expected " << count_ << ", elapsed time "
+                 << round_trip_time.count() << " ns ";
   }
 
   last_pong_value_ = pong.value();

aos/events/pong_lib.cc

diff --git a/aos/events/pong_lib.cc b/aos/events/pong_lib.cc
index 9f1c855..77bd8d9 100644
--- a/aos/events/pong_lib.cc
+++ b/aos/events/pong_lib.cc
@@ -11,6 +11,12 @@
     : event_loop_(event_loop),
       sender_(event_loop_->MakeSender<examples::Pong>("/test")) {
   event_loop_->MakeWatcher("/test", [this](const examples::Ping &ping) {
+    if (last_value_ == ping.value()) {
+      LOG(WARNING) << "Duplicate ping value at " << last_value_
+                   << " time difference " << ping.send_time() - last_send_time_;
+    }
+    last_value_ = ping.value();
+    last_send_time_ = ping.send_time();
     aos::Sender<examples::Pong>::Builder builder = sender_.MakeBuilder();
     examples::Pong::Builder pong_builder =
         builder.MakeBuilder<examples::Pong>();

aos/events/pong_lib.h

diff --git a/aos/events/pong_lib.h b/aos/events/pong_lib.h
index 17d779c..0b50599 100644
--- a/aos/events/pong_lib.h
+++ b/aos/events/pong_lib.h
@@ -15,6 +15,8 @@
  private:
   EventLoop *event_loop_;
   aos::Sender<examples::Pong> sender_;
+  int32_t last_value_ = 0;
+  int32_t last_send_time_ = 0;
 };
 
 }  // namespace aos