Merge pull request #2039 from jagerman/shorter-gossip-times

Shorten gossip times in systemd status line

llarp/messages/relay_commit.cpp

@@ -411,13 +411,17 @@ namespace llarp
       if (self->record.work && self->record.work->IsValid(now))
       {
         llarp::LogDebug(
-            "LRCM extended lifetime by ", self->record.work->extendedLifetime, " for ", info);
+            "LRCM extended lifetime by ",
+            ToString(self->record.work->extendedLifetime),
+            " for ",
+            info);
         self->hop->lifetime += self->record.work->extendedLifetime;
       }
       else if (self->record.lifetime < path::default_lifetime && self->record.lifetime > 10s)
       {
         self->hop->lifetime = self->record.lifetime;
-        llarp::LogDebug("LRCM short lifespan set to ", self->hop->lifetime, " for ", info);
+        llarp::LogDebug(
+            "LRCM short lifespan set to ", ToString(self->hop->lifetime), " for ", info);
       }
 
       // TODO: check if we really want to accept it

llarp/path/path.cpp

@@ -308,7 +308,7 @@ namespace llarp
       }
       else if (st == ePathEstablished && _status == ePathBuilding)
       {
-        LogInfo("path ", Name(), " is built, took ", now - buildStarted);
+        LogInfo("path ", Name(), " is built, took ", ToString(now - buildStarted));
       }
       else if (st == ePathTimeout && _status == ePathEstablished)
       {
@@ -449,7 +449,7 @@ namespace llarp
           const auto dlt = now - buildStarted;
           if (dlt >= path::build_timeout)
           {
-            LogWarn(Name(), " waited for ", dlt, " and no path was built");
+            LogWarn(Name(), " waited for ", ToString(dlt), " and no path was built");
             r->routerProfiling().MarkPathFail(this);
             EnterState(ePathExpired, now);
             return;
@@ -473,7 +473,7 @@ namespace llarp
         dlt = now - m_LastRecvMessage;
         if (dlt >= path::alive_timeout)
         {
-          LogWarn(Name(), " waited for ", dlt, " and path looks dead");
+          LogWarn(Name(), " waited for ", ToString(dlt), " and path looks dead");
           r->routerProfiling().MarkPathFail(this);
           EnterState(ePathTimeout, now);
         }

llarp/path/pathbuilder.cpp

@@ -461,7 +461,7 @@ namespace llarp
       buildIntervalLimit = PATH_BUILD_RATE;
       m_router->routerProfiling().MarkPathSuccess(p.get());
 
-      LogInfo(p->Name(), " built latency=", p->intro.latency);
+      LogInfo(p->Name(), " built latency=", ToString(p->intro.latency));
       m_BuildStats.success++;
     }
 
@@ -478,7 +478,7 @@ namespace llarp
       static constexpr std::chrono::milliseconds MaxBuildInterval = 30s;
       // linear backoff
       buildIntervalLimit = std::min(PATH_BUILD_RATE + buildIntervalLimit, MaxBuildInterval);
-      LogWarn(Name(), " build interval is now ", buildIntervalLimit);
+      LogWarn(Name(), " build interval is now ", ToString(buildIntervalLimit));
     }
 
     void

llarp/router/router.cpp

@@ -862,11 +862,11 @@ namespace llarp
     if (IsServiceNode())
     {
       LogInfo(NumberOfConnectedClients(), " client connections");
-      LogInfo(_rc.Age(now), " since we last updated our RC");
-      LogInfo(_rc.TimeUntilExpires(now), " until our RC expires");
+      LogInfo(ToString(_rc.Age(now)), " since we last updated our RC");
+      LogInfo(ToString(_rc.TimeUntilExpires(now)), " until our RC expires");
     }
     if (m_LastStatsReport > 0s)
-      LogInfo(now - m_LastStatsReport, " last reported stats");
+      LogInfo(ToString(now - m_LastStatsReport), " last reported stats");
     m_LastStatsReport = now;
   }
 
@@ -880,56 +880,54 @@ namespace llarp
     if (const auto delta = now - _lastTick; _lastTick != 0s and delta > TimeskipDetectedDuration)
     {
       // we detected a time skip into the futre, thaw the network
-      LogWarn("Timeskip of ", delta, " detected. Resetting network state");
+      LogWarn("Timeskip of ", ToString(delta), " detected. Resetting network state");
       Thaw();
     }
 
 #if defined(WITH_SYSTEMD)
     {
       std::string status;
       auto out = std::back_inserter(status);
-      out = fmt::format_to(out, "WATCHDOG=1\nSTATUS=v{}", llarp::VERSION_STR);
+      fmt::format_to(out, "WATCHDOG=1\nSTATUS=v{}", llarp::VERSION_STR);
       if (IsServiceNode())
       {
-        out = fmt::format_to(
+        fmt::format_to(
             out,
             " snode | known/svc/clients: {}/{}/{}",
             nodedb()->NumLoaded(),
             NumberOfConnectedRouters(),
             NumberOfConnectedClients());
-        out = fmt::format_to(
+        fmt::format_to(
             out,
             " | {} active paths | block {} ",
             pathContext().CurrentTransitPaths(),
             (m_lokidRpcClient ? m_lokidRpcClient->BlockHeight() : 0));
-        out = fmt::format_to(
+        auto maybe_last = _rcGossiper.LastGossipAt();
+        fmt::format_to(
             out,
-            " | gossip: (next/last) {} / ",
-            time_delta<std::chrono::seconds>{_rcGossiper.NextGossipAt()});
-        if (auto maybe = _rcGossiper.LastGossipAt())
-          out = fmt::format_to(out, "{}", time_delta<std::chrono::seconds>{*maybe});
-        else
-          out = fmt::format_to(out, "never");
+            " | gossip: (next/last) {} / {}",
+            short_time_from_now(_rcGossiper.NextGossipAt()),
+            maybe_last ? short_time_from_now(*maybe_last) : "never");
       }
       else
       {
-        out = fmt::format_to(
+        fmt::format_to(
             out,
             " client | known/connected: {}/{}",
             nodedb()->NumLoaded(),
             NumberOfConnectedRouters());
 
         if (auto ep = hiddenServiceContext().GetDefault())
         {
-          out = fmt::format_to(
+          fmt::format_to(
               out,
               " | paths/endpoints {}/{}",
               pathContext().CurrentOwnedPaths(),
               ep->UniqueEndpoints());
 
           if (auto success_rate = ep->CurrentBuildStats().SuccessRatio(); success_rate < 0.5)
           {
-            out = fmt::format_to(
+            fmt::format_to(
                 out, " [ !!! Low Build Success Rate ({:.1f}%) !!! ]", (100.0 * success_rate));
           }
         };

llarp/router_contact.cpp

@@ -116,10 +116,10 @@ namespace llarp
     std::string result;
     auto out = std::back_inserter(result);
     for (const auto& addr : addrs)
-      out = fmt::format_to(out, "ai_addr={}; ai_pk={}; ", addr.toIpAddress(), addr.pubkey);
-    out = fmt::format_to(out, "updated={}; onion_pk={}; ", last_updated.count(), enckey.ToHex());
+      fmt::format_to(out, "ai_addr={}; ai_pk={}; ", addr.toIpAddress(), addr.pubkey);
+    fmt::format_to(out, "updated={}; onion_pk={}; ", last_updated.count(), enckey.ToHex());
     if (routerVersion.has_value())
-      out = fmt::format_to(out, "router_version={}; ", *routerVersion);
+      fmt::format_to(out, "router_version={}; ", *routerVersion);
     return result;
   }
 

llarp/util/time.cpp

@@ -1,6 +1,7 @@
 #include "time.hpp"
 #include <chrono>
 #include <iomanip>
+#include "types.hpp"
 
 namespace llarp
 {
@@ -49,4 +50,59 @@ namespace llarp
   {
     return ToMS(t);
   }
+
+  static auto
+  extract_h_m_s_ms(const Duration_t& dur)
+  {
+    return std::make_tuple(
+        std::chrono::duration_cast<std::chrono::hours>(dur).count(),
+        (std::chrono::duration_cast<std::chrono::minutes>(dur) % 1h).count(),
+        (std::chrono::duration_cast<std::chrono::seconds>(dur) % 1min).count(),
+        (std::chrono::duration_cast<std::chrono::milliseconds>(dur) % 1s).count());
+  }
+
+  std::string
+  short_time_from_now(const TimePoint_t& t, const Duration_t& now_threshold)
+  {
+    auto delta = std::chrono::duration_cast<Duration_t>(llarp::TimePoint_t::clock::now() - t);
+    bool future = delta < 0s;
+    if (future)
+      delta = -delta;
+
+    auto [hours, mins, secs, ms] = extract_h_m_s_ms(delta);
+
+    using namespace fmt::literals;
+    return fmt::format(
+        delta < now_threshold ? "now"
+            : delta < 10s     ? "{in}{secs:d}.{ms:03d}s{ago}"
+            : delta < 1h      ? "{in}{mins:d}m{secs:02d}s{ago}"
+                              : "{in}{hours:d}h{mins:02d}m{ago}",
+        "in"_a = future ? "in " : "",
+        "ago"_a = future ? "" : " ago",
+        "hours"_a = hours,
+        "mins"_a = mins,
+        "secs"_a = secs,
+        "ms"_a = ms);
+  }
+
+  std::string
+  ToString(Duration_t delta)
+  {
+    bool neg = delta < 0s;
+    if (neg)
+      delta = -delta;
+
+    auto [hours, mins, secs, ms] = extract_h_m_s_ms(delta);
+
+    using namespace fmt::literals;
+    return fmt::format(
+        delta < 1min     ? "{neg}{secs:d}.{ms:03d}s"
+            : delta < 1h ? "{neg}{mins:d}m{secs:02d}.{ms:03d}s"
+                         : "{neg}{hours:d}h{mins:02d}m{secs:02d}.{ms:03d}s",
+        "neg"_a = neg ? "-" : "",
+        "hours"_a = hours,
+        "mins"_a = mins,
+        "secs"_a = secs,
+        "ms"_a = ms);
+  }
 }  // namespace llarp

llarp/util/time.hpp

@@ -25,69 +25,25 @@ namespace llarp
   nlohmann::json
   to_json(const Duration_t& t);
 
-  template <typename Time_Duration>
-  struct time_delta
-  {
-    const TimePoint_t at;
-  };
-}  // namespace llarp
+  // Returns a string such as "27m13s ago" or "in 1h12m" or "now".  You get precision of minutes
+  // (for >=1h), seconds (>=10s), or milliseconds.  The `now_threshold` argument controls how close
+  // to current time (default 1s) the time has to be to get the "now" argument.
+  std::string
+  short_time_from_now(const TimePoint_t& t, const Duration_t& now_threshold = 1s);
 
-namespace fmt
-{
-  template <typename Time_Duration>
-  struct formatter<llarp::time_delta<Time_Duration>> : formatter<std::string>
-  {
-    template <typename FormatContext>
-    auto
-    format(const llarp::time_delta<Time_Duration>& td, FormatContext& ctx)
-    {
-      const auto dlt =
-          std::chrono::duration_cast<llarp::Duration_t>(llarp::TimePoint_t::clock::now() - td.at);
-      using Parent = formatter<std::string>;
-      if (dlt > 0s)
-        return Parent::format(fmt::format("{} ago", dlt), ctx);
-      if (dlt < 0s)
-        return Parent::format(fmt::format("in {}", -dlt), ctx);
-      return Parent::format("now", ctx);
-    }
-  };
+  // Makes a duration human readable.  This always has full millisecond precision, but formats up to
+  // hours. E.g. "-4h04m12.123s" or "1234h00m09.876s.
+  std::string
+  ToString(Duration_t t);
 
-  template <>
-  struct formatter<llarp::Duration_t> : formatter<std::string>
-  {
-    template <typename FormatContext>
-    auto
-    format(llarp::Duration_t elapsed, FormatContext& ctx)
-    {
-      bool neg = elapsed < 0s;
-      if (neg)
-        elapsed = -elapsed;
-      const auto hours = std::chrono::duration_cast<std::chrono::hours>(elapsed).count();
-      const auto mins = (std::chrono::duration_cast<std::chrono::minutes>(elapsed) % 1h).count();
-      const auto secs = (std::chrono::duration_cast<std::chrono::seconds>(elapsed) % 1min).count();
-      const auto ms = (std::chrono::duration_cast<std::chrono::milliseconds>(elapsed) % 1s).count();
-      return formatter<std::string>::format(
-          fmt::format(
-              elapsed >= 1h         ? "{0}{1:d}h{2:02d}m{3:02d}.{4:03d}s"
-                  : elapsed >= 1min ? "{0}{2:d}m{3:02d}.{4:03d}s"
-                                    : "{0}{3:d}.{4:03d}s",
-              neg ? "-" : "",
-              hours,
-              mins,
-              secs,
-              ms),
-          ctx);
-    }
-  };
+}  // namespace llarp
 
-  template <>
-  struct formatter<llarp::TimePoint_t> : formatter<std::string>
-  {
-    template <typename FormatContext>
-    auto
-    format(const llarp::TimePoint_t& tp, FormatContext& ctx)
-    {
-      return formatter<std::string>::format(fmt::format("{:%c %Z}", tp), ctx);
-    }
-  };
-}  // namespace fmt
+// Duration_t is currently just a typedef to std::chrono::milliseconds, and specializing
+// that seems wrong; leaving this here to remind us not to add it back in again.
+// namespace fmt
+//{
+//  template <>
+//  struct formatter<llarp::Duration_t>
+//  {
+//  };
+//}  // namespace fmt