Fix #2252 (consistent typing for the 'delay' log property)

beacon_chain/eth2_network.nim

@@ -958,7 +958,7 @@ proc resolvePeer(peer: Peer) =
     inc(nbc_successful_discoveries)
     let delay = now(chronos.Moment) - startTime
     nbc_resolve_time.observe(delay.toFloatSeconds())
-    debug "Peer's ENR recovered", delay = $delay
+    debug "Peer's ENR recovered", delay
 
 proc handlePeer*(peer: Peer) {.async.} =
   let res = peer.network.peerPool.addPeerNoWait(peer, peer.direction)

beacon_chain/time.nim

@@ -1,7 +1,7 @@
 {.push raises: [Defect].}
 
 import
-  chronos,
+  chronos, chronicles,
   spec/datatypes
 
 from times import Time, getTime, fromUnix, `<`, `-`, inNanoseconds
@@ -104,6 +104,79 @@ proc addTimer*(fromNow: Duration, cb: CallbackFunc, udata: pointer = nil) =
     # https://github.com/nim-lang/Nim/issues/10288 - sigh
     raiseAssert e.msg
 
+func humaneStr*(a: Duration): string {.inline.} =
+  ## Returns a "humane" string representation of the duration that uses
+  ## the most appropriate unit type depending on the actual Duration.
+  var v = a.nanoseconds
+  let days = v div nanoseconds(Day)
+  if days > 0:
+    if days >= 14:
+      return $(v div nanoseconds(Week)) & " weeks"
+    elif days >= 2:
+      return $days & " days"
+
+  let hours = v div nanoseconds(Hour)
+  if hours > 0:
+    if hours >= 2:
+      result = $hours & " hours"
+    else:
+      result = "1 hour"
+    v = v mod nanoseconds(Hour)
+
+  let minutes = v div nanoseconds(Minute)
+  if minutes > 0:
+    if hours > 0:
+      result.add " "
+    if minutes >= 2:
+      result.add $minutes
+      result.add " minutes"
+    else:
+      result.add "1 minute"
+    v = v mod nanoseconds(Minute)
+
+  let
+    isMoreThanAMinute = minutes > 0 or hours > 0
+    seconds = v div nanoseconds(Second)
+
+  if seconds > 0:
+    if isMoreThanAMinute:
+      result.add " "
+      if seconds >= 2:
+        result.add $seconds
+        result.add " seconds"
+      else:
+        result.add "1 second"
+    else:
+      result = $seconds
+      v = v mod nanoseconds(Second)
+      let milliseconds = v div nanoseconds(Millisecond)
+      if milliseconds > 0:
+        let millisecondsStr = $milliseconds
+        result.add "."
+        for _ in millisecondsStr.len ..< 3: result.add "0"
+        result.add millisecondsStr
+      elif seconds == 1:
+        return "1 second"
+      result.add " seconds"
+    return
+
+  if isMoreThanAMinute:
+    return
+
+  let milliseconds = v div nanoseconds(Millisecond)
+  if milliseconds >= 2:
+    return $milliseconds & " milliseconds"
+
+  let microseconds = v div nanoseconds(Microsecond)
+  if microseconds >= 2:
+    return $microseconds & " microseconds"
+
+  let nanoseconds = v div nanoseconds(Nanosecond)
+  if nanoseconds == 1:
+    return "1 nanosecond"
+
+  return $nanoseconds & " nanoseconds"
+
 func shortLog*(d: Duration): string =
   $d
 
@@ -111,4 +184,8 @@ func toFloatSeconds*(d: Duration): float =
   float(milliseconds(d)) / 1000.0
 
 func `$`*(v: BeaconTime): string = $Duration(v)
-func shortLog*(v: BeaconTime): Duration = Duration(v)
+func shortLog*(v: BeaconTime): string = humaneStr Duration(v)
+
+chronicles.formatIt Duration: humaneStr(it)
+chronicles.formatIt BeaconTime: humaneStr(Duration it)
+

beacon_chain/validator_duties.nim

@@ -213,9 +213,9 @@ proc createAndSendAttestation(node: BeaconNode,
 
   let (delayStr, delayMillis) =
     if wallTime < deadline:
-      ("-" & $(deadline - wallTime), -toFloatSeconds(deadline - wallTime))
+      (humaneStr(deadline - wallTime) & " earlier", -toFloatSeconds(deadline - wallTime))
     else:
-      ($(wallTime - deadline), toFloatSeconds(wallTime - deadline))
+      (humaneStr(wallTime - deadline), toFloatSeconds(wallTime - deadline))
 
   notice "Attestation sent", attestation = shortLog(attestation),
                              validator = shortLog(validator), delay = delayStr,

tests/all_tests.nim

@@ -16,20 +16,21 @@ import # Unit test
   ./test_beacon_node,
   ./test_beaconstate,
   ./test_bitseqs,
-  ./test_statediff,
   ./test_block_pool,
   ./test_datatypes,
-  ./test_helpers,
   ./test_eth1_monitor,
-  ./test_ssz,
-  ./test_state_transition,
-  ./test_sync_protocol,
-  ./test_zero_signature,
   ./test_exit_pool,
-  ./test_peer_pool,
-  ./test_sync_manager,
+  ./test_helpers,
   ./test_honest_validator,
   ./test_interop,
+  ./test_peer_pool,
+  ./test_ssz,
+  ./test_state_transition,
+  ./test_statediff,
+  ./test_sync_manager,
+  ./test_sync_protocol,
+  ./test_timeutils,
+  ./test_zero_signature,
   ./fork_choice/tests_fork_choice,
   ./slashing_protection/test_slashing_interchange,
   ./slashing_protection/test_slashing_protection_db

tests/test_timeutils.nim

@@ -0,0 +1,36 @@
+# beacon_chain
+# Copyright (c) 2018 Status Research & Development GmbH
+# Licensed and distributed under either of
+#   * MIT license (license terms in the root directory or at https://opensource.org/licenses/MIT).
+#   * Apache v2 license (license terms in the root directory or at https://www.apache.org/licenses/LICENSE-2.0).
+# at your option. This file may not be copied, modified, or distributed except according to those terms.
+
+{.used.}
+
+import
+  unittest, ./testutil,
+  chronos/timer,
+  ../beacon_chain/time
+
+suiteReport "Time utilities":
+  timedTest "humaneStr":
+    check:
+      humaneStr(2.weeks) == "2 weeks"
+      humaneStr(2.weeks + 2.days) == "2 weeks"
+      humaneStr(2.weeks + 7.days) == "3 weeks"
+      humaneStr(1.weeks + 3.days) == "10 days"
+      humaneStr(1.weeks + 3.days + 2.hours) == "10 days"
+      humaneStr(5.days + 3.hours) == "5 days"
+      humaneStr(1.days + 3.hours + 10.minutes) == "27 hours 10 minutes"
+      humaneStr(1.days + 15.seconds + 342.milliseconds) == "24 hours 15 seconds"
+      humaneStr(12.hours + 2.minutes + 12.seconds + 342.milliseconds) == "12 hours 2 minutes 12 seconds"
+      humaneStr(4.seconds + 342.milliseconds) == "4.342 seconds"
+      humaneStr(2.seconds) == "2 seconds"
+      humaneStr(1.seconds) == "1 second"
+      humaneStr(1.seconds + 12.milliseconds) == "1.012 seconds"
+      humaneStr(1320.milliseconds) == "1.320 seconds"
+      humaneStr(1000.milliseconds) == "1 second"
+      humaneStr(124.milliseconds) == "124 milliseconds"
+      humaneStr(312.nanoseconds) == "312 nanoseconds"
+      humaneStr(123431.nanoseconds) == "123 microseconds"
+