Workaround for Hardhat timestamp bug

Likely due to a Hardhat bug in which the callbacks for subscription events are called and awaited before updating its local understanding of the last block time, Hardhat will report a block time in the `newHeads` event that is generally 1 second before the time reported from `getLatestBlock.timestamp`. This was causing issues with the OnChainClock's offset and therefore the `now()` used by the `OnChainClock` would sometimes be off by a second (or more), causing tests to fail.

This commit introduce a `codex_use_hardhat` compilation flag, that when set, will always get the latest block timestamp from Hardhat via the `getLatestBlock.timestamp` RPC call for `OnChainClock.now` calls. Otherwise, the last block timestamp reported in the `newHeads` event will be used.

Update the docker dist tests compilation flag for simulated proof failures (it was not correct), and explicitly add the `codex_use_hardhat=false` for clarity.

.github/workflows/docker-dist-tests.yml

@@ -24,7 +24,7 @@ jobs:
     name: Build and Push
     uses: ./.github/workflows/docker-reusable.yml
     with:
-      nimflags: '-d:disableMarchNative -d:codex_enable_api_debug_peers=true -d:codex_enable_simulated_proof_failures -d:codex_enable_log_counter=true'
+      nimflags: '-d:disableMarchNative -d:codex_enable_api_debug_peers=true -d:codex_enable_proof_failures=true -d:codex_use_hardhat=false -d:codex_enable_log_counter=true'
       nat_ip_auto: true
       tag_latest: ${{ github.ref_name == github.event.repository.default_branch || startsWith(github.ref, 'refs/tags/') }}
       tag_suffix: dist-tests

build.nims

@@ -25,13 +25,13 @@ task codex, "build codex binary":
   buildBinary "codex", params = "-d:chronicles_runtime_filtering -d:chronicles_log_level=TRACE"
 
 task testCodex, "Build & run Codex tests":
-  test "testCodex", params = "-d:codex_enable_proof_failures=true"
+  test "testCodex", params = "-d:codex_enable_proof_failures=true -d:codex_use_hardhat=true"
 
 task testContracts, "Build & run Codex Contract tests":
   test "testContracts"
 
 task testIntegration, "Run integration tests":
-  buildBinary "codex", params = "-d:chronicles_runtime_filtering -d:chronicles_log_level=TRACE -d:codex_enable_proof_failures=true"
+  buildBinary "codex", params = "-d:chronicles_runtime_filtering -d:chronicles_log_level=TRACE -d:codex_enable_proof_failures=true -d:codex_use_hardhat=true"
   test "testIntegration"
 
 task build, "build codex binary":

codex/conf.nim

@@ -45,6 +45,7 @@ export net, DefaultQuotaBytes, DefaultBlockTtl, DefaultBlockMaintenanceInterval,
 const
   codex_enable_api_debug_peers* {.booldefine.} = false
   codex_enable_proof_failures* {.booldefine.} = false
+  codex_use_hardhat* {.booldefine.} = false
   codex_enable_log_counter* {.booldefine.} = false
 
 type

codex/contracts/clock.nim

@@ -1,18 +1,21 @@
-import std/times
 import pkg/ethers
 import pkg/chronos
 import pkg/stint
 import ../clock
+import ../conf
 
 export clock
 
+logScope:
+  topics = "contracts clock"
+
 type
   OnChainClock* = ref object of Clock
     provider: Provider
     subscription: Subscription
-    offset: times.Duration
     started: bool
     newBlock: AsyncEvent
+    lastBlockTime: UInt256
 
 proc new*(_: type OnChainClock, provider: Provider): OnChainClock =
   OnChainClock(provider: provider, newBlock: newAsyncEvent())
@@ -20,29 +23,43 @@ proc new*(_: type OnChainClock, provider: Provider): OnChainClock =
 method start*(clock: OnChainClock) {.async.} =
   if clock.started:
     return
-  clock.started = true
 
   proc onBlock(blck: Block) {.upraises:[].} =
-    let blockTime = initTime(blck.timestamp.truncate(int64), 0)
-    let computerTime = getTime()
-    clock.offset = blockTime - computerTime
+    clock.lastBlockTime = blck.timestamp
     clock.newBlock.fire()
 
   if latestBlock =? (await clock.provider.getBlock(BlockTag.latest)):
     onBlock(latestBlock)
 
   clock.subscription = await clock.provider.subscribe(onBlock)
+  clock.started = true
 
 method stop*(clock: OnChainClock) {.async.} =
   if not clock.started:
     return
-  clock.started = false
 
   await clock.subscription.unsubscribe()
+  clock.started = false
 
 method now*(clock: OnChainClock): SecondsSince1970 =
-  doAssert clock.started, "clock should be started before calling now()"
-  toUnix(getTime() + clock.offset)
+  when codex_use_hardhat:
+    # hardhat's latest block.timestamp is usually 1s behind the block timestamp
+    # in the newHeads event. When testing, always return the latest block.
+    try:
+      if queriedBlock =? (waitFor clock.provider.getBlock(BlockTag.latest)):
+        trace "using last block timestamp for clock.now",
+          lastBlockTimestamp = queriedBlock.timestamp.truncate(int64),
+          cachedBlockTimestamp = clock.lastBlockTime.truncate(int64)
+        return queriedBlock.timestamp.truncate(int64)
+    except CatchableError as e:
+      warn "failed to get latest block timestamp", error = e.msg
+      return clock.lastBlockTime.truncate(int64)
+
+  else:
+    doAssert clock.started, "clock should be started before calling now()"
+    trace "using cached block timestamp (newHeads) for clock.now",
+      timestamp = clock.lastBlockTime.truncate(int64)
+    return clock.lastBlockTime.truncate(int64)
 
 method waitUntil*(clock: OnChainClock, time: SecondsSince1970) {.async.} =
   while (let difference = time - clock.now(); difference > 0):

config.nims

@@ -95,8 +95,6 @@ if not defined(macosx):
     --define:nimStackTraceOverride
     switch("import", "libbacktrace")
 
-switch("define", "codex_enable_proof_failures=true")
-
 # `switch("warning[CaseTransition]", "off")` fails with "Error: invalid command line option: '--warning[CaseTransition]'"
 switch("warning", "CaseTransition:off")
 

tests/contracts/testClock.nim

@@ -25,11 +25,6 @@ ethersuite "On-Chain Clock":
     discard await provider.send("evm_mine")
     check clock.now() == future
 
-  test "updates time using wall-clock in-between blocks":
-    let past = clock.now()
-    await sleepAsync(chronos.seconds(1))
-    check clock.now() > past
-
   test "can wait until a certain time is reached by the chain":
     let future = clock.now() + 42 # seconds
     let waiting = clock.waitUntil(future)
@@ -37,20 +32,6 @@ ethersuite "On-Chain Clock":
     discard await provider.send("evm_mine")
     check await waiting.withTimeout(chronos.milliseconds(100))
 
-  test "can wait until a certain time is reached by the wall-clock":
-    let future = clock.now() + 1 # seconds
-    let waiting = clock.waitUntil(future)
-    check await waiting.withTimeout(chronos.seconds(2))
-
-  test "raises when not started":
-    expect AssertionDefect:
-      discard OnChainClock.new(provider).now()
-
-  test "raises when stopped":
-    await clock.stop()
-    expect AssertionDefect:
-      discard clock.now()
-
   test "handles starting multiple times":
     await clock.start()
     await clock.start()