From b6924f3ef1d4b021437bdc920130326308e4b9fe Mon Sep 17 00:00:00 2001 From: Jason Rhinelander Date: Wed, 26 Oct 2022 21:20:14 -0300 Subject: [PATCH] Replace duration/timestamp formats with functions We're defining formats for std::chrono types, which feels wrong (because fmt itself also has these), so just replace them with functions: short_time_from_now(...) gives a short "in 14m12s" or "5.123s ago" time span relative to now, given a time point. Precision gets reduced for larger deviations from now (e.g. "4h12m ago"). ToString(Duration_t) gives a string such as "-3h22m02.123s" for a duration. --- llarp/messages/relay_commit.cpp | 8 +++- llarp/path/path.cpp | 6 +-- llarp/path/pathbuilder.cpp | 4 +- llarp/router/router.cpp | 18 ++++---- llarp/util/time.cpp | 56 ++++++++++++++++++++++ llarp/util/time.hpp | 82 ++++++++------------------------- 6 files changed, 94 insertions(+), 80 deletions(-) diff --git a/llarp/messages/relay_commit.cpp b/llarp/messages/relay_commit.cpp index 4cffe912f..887fc680e 100644 --- a/llarp/messages/relay_commit.cpp +++ b/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 diff --git a/llarp/path/path.cpp b/llarp/path/path.cpp index 0790c1238..f777611e7 100644 --- a/llarp/path/path.cpp +++ b/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); } diff --git a/llarp/path/pathbuilder.cpp b/llarp/path/pathbuilder.cpp index 478060005..abf149024 100644 --- a/llarp/path/pathbuilder.cpp +++ b/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 diff --git a/llarp/router/router.cpp b/llarp/router/router.cpp index 2c2032b21..941e10b5e 100644 --- a/llarp/router/router.cpp +++ b/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,7 +880,7 @@ 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(); } @@ -902,14 +902,12 @@ namespace llarp " | {} active paths | block {} ", pathContext().CurrentTransitPaths(), (m_lokidRpcClient ? m_lokidRpcClient->BlockHeight() : 0)); + auto maybe_last = _rcGossiper.LastGossipAt(); fmt::format_to( out, - " | gossip: (next/last) {} / ", - time_delta{_rcGossiper.NextGossipAt()}); - if (auto maybe = _rcGossiper.LastGossipAt()) - fmt::format_to(out, "{}", time_delta{*maybe}); - else - fmt::format_to(out, "never"); + " | gossip: (next/last) {} / {}", + short_time_from_now(_rcGossiper.NextGossipAt()), + maybe_last ? short_time_from_now(*maybe_last) : "never"); } else { diff --git a/llarp/util/time.cpp b/llarp/util/time.cpp index 46d9a5fa4..1b0b24351 100644 --- a/llarp/util/time.cpp +++ b/llarp/util/time.cpp @@ -1,6 +1,7 @@ #include "time.hpp" #include #include +#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(dur).count(), + (std::chrono::duration_cast(dur) % 1h).count(), + (std::chrono::duration_cast(dur) % 1min).count(), + (std::chrono::duration_cast(dur) % 1s).count()); + } + + std::string + short_time_from_now(const TimePoint_t& t, const Duration_t& now_threshold) + { + auto delta = std::chrono::duration_cast(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 diff --git a/llarp/util/time.hpp b/llarp/util/time.hpp index c50c28bc7..ef73f50fc 100644 --- a/llarp/util/time.hpp +++ b/llarp/util/time.hpp @@ -25,69 +25,25 @@ namespace llarp nlohmann::json to_json(const Duration_t& t); - template - 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 - struct formatter> : formatter - { - template - auto - format(const llarp::time_delta& td, FormatContext& ctx) - { - const auto dlt = - std::chrono::duration_cast(llarp::TimePoint_t::clock::now() - td.at); - using Parent = formatter; - 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 : formatter - { - template - auto - format(llarp::Duration_t elapsed, FormatContext& ctx) - { - bool neg = elapsed < 0s; - if (neg) - elapsed = -elapsed; - const auto hours = std::chrono::duration_cast(elapsed).count(); - const auto mins = (std::chrono::duration_cast(elapsed) % 1h).count(); - const auto secs = (std::chrono::duration_cast(elapsed) % 1min).count(); - const auto ms = (std::chrono::duration_cast(elapsed) % 1s).count(); - return formatter::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 : formatter - { - template - auto - format(const llarp::TimePoint_t& tp, FormatContext& ctx) - { - return formatter::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 +// { +// }; +//} // namespace fmt