From 6fff02fd91a38fa1261a12aee3a14e36c22c336a Mon Sep 17 00:00:00 2001 From: Eric <5089238+emizzle@users.noreply.github.com> Date: Mon, 4 Dec 2023 13:59:33 +1100 Subject: [PATCH] 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 | 2 +- build.nims | 4 +-- codex/conf.nim | 1 + codex/contracts/clock.nim | 35 ++++++++++++++++++------- config.nims | 2 -- tests/contracts/testClock.nim | 19 -------------- 6 files changed, 30 insertions(+), 33 deletions(-) diff --git a/.github/workflows/docker-dist-tests.yml b/.github/workflows/docker-dist-tests.yml index e6e0973b..5ae2e30a 100644 --- a/.github/workflows/docker-dist-tests.yml +++ b/.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 diff --git a/build.nims b/build.nims index 741484a6..568b16f0 100644 --- a/build.nims +++ b/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": diff --git a/codex/conf.nim b/codex/conf.nim index 9dc3cb8d..4a0e70f4 100644 --- a/codex/conf.nim +++ b/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 diff --git a/codex/contracts/clock.nim b/codex/contracts/clock.nim index 23b678e9..26d2d263 100644 --- a/codex/contracts/clock.nim +++ b/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): diff --git a/config.nims b/config.nims index 2f96ddfe..0a3b205b 100644 --- a/config.nims +++ b/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") diff --git a/tests/contracts/testClock.nim b/tests/contracts/testClock.nim index fafb6092..87ff1512 100644 --- a/tests/contracts/testClock.nim +++ b/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()