speed up tests

- advance to next period and mine every 500ms
- update eventually checks in tests to check for number of periods, not time
- change log file format to include test name
This commit is contained in:
Eric 2023-11-08 16:14:58 +11:00
parent 045f770128
commit e762860e6b
No known key found for this signature in database
4 changed files with 95 additions and 78 deletions

View File

@ -79,6 +79,7 @@ proc proveLoop(
debug "Proof is required", period = currentPeriod
await state.prove(slot, onProve, market, currentPeriod)
debug "waiting until next period"
await waitUntilPeriod(currentPeriod + 1)
method `$`*(state: SaleProving): string = "SaleProving"

View File

@ -16,16 +16,32 @@ template marketplacesuite*(name: string, startNodes: Nodes, body: untyped) =
var period: uint64
var periodicity: Periodicity
var token {.inject, used.}: Erc20Token
var continuousMineFut: Future[void]
proc getCurrentPeriod(): Future[Period] {.async.} =
return periodicity.periodOf(await ethProvider.currentTime())
proc advanceToNextPeriod() {.async.} =
let periodicity = Periodicity(seconds: period.u256)
let currentPeriod = periodicity.periodOf(await ethProvider.currentTime())
let currentTime = await ethProvider.currentTime()
let currentPeriod = periodicity.periodOf(currentTime)
let endOfPeriod = periodicity.periodEnd(currentPeriod)
await ethProvider.advanceTimeTo(endOfPeriod + 1)
template eventuallyP(condition: untyped, finalPeriod: Period): bool =
proc eventuallyP: Future[bool] {.async.} =
while(
let currentPeriod = await getCurrentPeriod();
currentPeriod <= finalPeriod
):
if condition:
return true
await sleepAsync(1.millis)
return condition
await eventuallyP()
proc timeUntil(period: Period): Future[times.Duration] {.async.} =
let currentPeriod = await getCurrentPeriod()
let endOfCurrPeriod = periodicity.periodEnd(currentPeriod)
@ -60,9 +76,6 @@ template marketplacesuite*(name: string, startNodes: Nodes, body: untyped) =
let expiry = (await ethProvider.currentTime()) + expiry.u256
# avoid timing issues by filling the slot at the start of the next period
await advanceToNextPeriod()
let id = client.requestStorage(
cid,
expiry=expiry,
@ -76,6 +89,14 @@ template marketplacesuite*(name: string, startNodes: Nodes, body: untyped) =
return id
proc continuouslyAdvanceEvery(every: chronos.Duration) {.async.} =
try:
while true:
await advanceToNextPeriod()
await sleepAsync(every)
except CancelledError:
discard
setup:
marketplace = Marketplace.new(Marketplace.address, ethProvider.getSigner())
let tokenAddress = await marketplace.token()
@ -84,11 +105,9 @@ template marketplacesuite*(name: string, startNodes: Nodes, body: untyped) =
period = config.proofs.period.truncate(uint64)
periodicity = Periodicity(seconds: period.u256)
discard await ethProvider.send("evm_setIntervalMining", @[%1000])
continuousMineFut = continuouslyAdvanceEvery(chronos.millis(500))
# Our Hardhat configuration does use automine, which means that time tracked by `provider.currentTime()` is not
# advanced until blocks are mined and that happens only when transaction is submitted.
# As we use in tests provider.currentTime() which uses block timestamp this can lead to synchronization issues.
await ethProvider.advanceTime(1.u256)
teardown:
await continuousMineFut.cancelAndWait()
body

View File

@ -26,14 +26,14 @@ type
providers*: NodeConfig
validators*: NodeConfig
hardhat*: HardhatConfig
NodeConfig* = object
Config* = object of RootObj
logFile*: bool
NodeConfig* = object of Config
numNodes*: int
cliOptions*: seq[CliOption]
logFile*: bool
logTopics*: seq[string]
debugEnabled*: bool
HardhatConfig* = ref object
logFile*: bool
HardhatConfig* = ref object of Config
Role* {.pure.} = enum
Client,
Provider,
@ -98,19 +98,10 @@ proc withLogTopics*(
startConfig.logTopics = startConfig.logTopics.concat(@topics)
return startConfig
proc withLogFile*(
config: NodeConfig,
proc withLogFile*[T: Config](
config: T,
logToFile: bool = true
): NodeConfig =
var startConfig = config
startConfig.logFile = logToFile
return startConfig
proc withLogFile*(
config: HardhatConfig,
logToFile: bool = true
): HardhatConfig =
): T =
var startConfig = config
startConfig.logFile = logToFile
@ -123,17 +114,32 @@ template multinodesuite*(name: string, startNodes: Nodes, body: untyped) =
var running: seq[RunningNode]
var bootstrap: string
let starttime = now().format("yyyy-MM-dd'_'HH:mm:ss")
var currentTestName = ""
template test(namet, bodyt) =
currentTestName = namet
test namet:
bodyt
proc getLogFile(role: Role, index: ?int): string =
var nameSanitized = name
# create log file path, format:
# tests/integration/logs/<start_datetime> <suite_name>/<test_name>/<node_role>_<node_idx>.log
var suiteNameSanitized = name
var testNameSanitized = currentTestName
for invalid in invalidFilenameChars.items:
nameSanitized = nameSanitized.replace(invalid, '_')
var logDir = currentSourcePath.parentDir() / "logs" / nameSanitized / $starttime
suiteNameSanitized = suiteNameSanitized.replace(invalid, '_')
testNameSanitized = testNameSanitized.replace(invalid, '_')
var logDir = currentSourcePath.parentDir() /
"logs" /
$starttime & " " & suiteNameSanitized / $testNameSanitized
createDir(logDir)
var fn = $role
if idx =? index:
fn &= "_" & $idx
fn &= ".log"
let fileName = logDir / fn
return fileName

View File

@ -12,23 +12,23 @@ export chronicles
logScope:
topics = "integration test proofs"
marketplacesuite "Simulate invalid proofs - 1 provider node",
marketplacesuite "Simulate invalid proofs, 1 provider node, every proof invalid",
Nodes(
# Uncomment to start Hardhat automatically, mainly so logs can be inspected locally
# hardhat: HardhatConfig()
# .withLogFile(),
# .withLogFile() # uncomment to output log file to tests/integration/logs/<start_datetime> <suite_name>/<test_name>/<node_role>_<node_idx>.log,
clients: NodeConfig()
.nodes(1)
.debug()
.withLogFile()
# .debug() # uncomment to enable console log output
# .withLogFile() # uncomment to output log file to tests/integration/logs/<start_datetime> <suite_name>/<test_name>/<node_role>_<node_idx>.log
.withLogTopics("node"),
providers: NodeConfig()
.nodes(1)
.simulateProofFailuresFor(providerIdx=0, failEveryNProofs=1)
.debug()
.withLogFile()
# .debug() # uncomment to enable console log output
# .withLogFile() # uncomment to output log file to tests/integration/logs/<start_datetime> <suite_name>/<test_name>/<node_role>_<node_idx>.log
.withLogTopics(
"marketplace",
"sales",
@ -43,21 +43,21 @@ marketplacesuite "Simulate invalid proofs - 1 provider node",
validators: NodeConfig()
.nodes(1)
.withLogFile()
.debug()
# .withLogFile() # uncomment to output log file to tests/integration/logs/<start_datetime> <suite_name>/<test_name>/<node_role>_<node_idx>.log
# .debug() # uncomment to enable console log output
.withLogTopics("validator", "initial-proving", "proving", "clock", "onchain", "ethers")
):
test "slot is freed after too many invalid proofs submitted":
let client0 = clients()[0].node.client
let totalProofs = 50
let totalPeriods = 50
let data = byteutils.toHex(await exampleData())
createAvailabilities(data.len, totalProofs.periods)
createAvailabilities(data.len, totalPeriods.periods)
let cid = client0.upload(data).get
let purchaseId = await client0.requestStorage(cid, duration=totalProofs.periods)
let purchaseId = await client0.requestStorage(cid, duration=totalPeriods.periods)
let requestId = client0.requestId(purchaseId).get
check eventually client0.purchaseStateIs(purchaseId, "started")
@ -71,28 +71,27 @@ marketplacesuite "Simulate invalid proofs - 1 provider node",
let subscription = await marketplace.subscribe(SlotFreed, onSlotFreed)
let currentPeriod = await getCurrentPeriod()
let timeUntilLastPeriod = await timeUntil(currentPeriod + totalProofs.u256 + 1)
check eventually(slotWasFreed, timeUntilLastPeriod.inMilliseconds.int)
check eventuallyP(slotWasFreed, currentPeriod + totalPeriods.u256 + 1)
await subscription.unsubscribe()
marketplacesuite "Simulate invalid proofs - 1 provider node",
marketplacesuite "Simulate invalid proofs, 1 provider node, every 3rd proof invalid",
Nodes(
# Uncomment to start Hardhat automatically, mainly so logs can be inspected locally
# hardhat: HardhatConfig()
# .withLogFile(),
# .withLogFile() # uncomment to output log file to tests/integration/logs/<start_datetime> <suite_name>/<test_name>/<node_role>_<node_idx>.log,
clients: NodeConfig()
.nodes(1)
.debug()
.withLogFile()
# .debug() # uncomment to enable console log output
# .withLogFile() # uncomment to output log file to tests/integration/logs/<start_datetime> <suite_name>/<test_name>/<node_role>_<node_idx>.log
.withLogTopics("node"),
providers: NodeConfig()
.nodes(1)
.simulateProofFailuresFor(providerIdx=0, failEveryNProofs=3)
.debug()
.withLogFile()
# .debug() # uncomment to enable console log output
# .withLogFile() # uncomment to output log file to tests/integration/logs/<start_datetime> <suite_name>/<test_name>/<node_role>_<node_idx>.log
.withLogTopics(
"marketplace",
"sales",
@ -107,20 +106,20 @@ marketplacesuite "Simulate invalid proofs - 1 provider node",
validators: NodeConfig()
.nodes(1)
.withLogFile()
# .withLogFile() # uncomment to output log file to tests/integration/logs/<start_datetime> <suite_name>/<test_name>/<node_role>_<node_idx>.log
.withLogTopics("validator", "initial-proving", "proving", "clock", "onchain", "ethers")
):
test "hosts submit periodic proofs for slots they fill":
let client0 = clients()[0].node.client
let totalProofs = 50
let totalPeriods = 50
let data = byteutils.toHex(await exampleData())
createAvailabilities(data.len, totalProofs.periods)
createAvailabilities(data.len, totalPeriods.periods)
let cid = client0.upload(data).get
let purchaseId = await client0.requestStorage(cid, duration=totalProofs.periods)
let purchaseId = await client0.requestStorage(cid, duration=totalPeriods.periods)
check eventually client0.purchaseStateIs(purchaseId, "started")
var proofWasSubmitted = false
@ -130,21 +129,20 @@ marketplacesuite "Simulate invalid proofs - 1 provider node",
let subscription = await marketplace.subscribe(ProofSubmitted, onProofSubmitted)
let currentPeriod = await getCurrentPeriod()
let timeUntilLastPeriod = await timeUntil(currentPeriod + totalProofs.u256 + 1)
check eventually(proofWasSubmitted, timeUntilLastPeriod.inMilliseconds.int)
check eventuallyP(proofWasSubmitted, currentPeriod + totalPeriods.u256 + 1)
await subscription.unsubscribe()
test "slot is not freed when not enough invalid proofs submitted":
let client0 = clients()[0].node.client
let totalProofs = 25
let totalPeriods = 25
let data = byteutils.toHex(await exampleData())
createAvailabilities(data.len, totalProofs.periods)
createAvailabilities(data.len, totalPeriods.periods)
let cid = client0.upload(data).get
let purchaseId = await client0.requestStorage(cid, duration=totalProofs.periods)
let purchaseId = await client0.requestStorage(cid, duration=totalPeriods.periods)
let requestId = client0.requestId(purchaseId).get
check eventually client0.purchaseStateIs(purchaseId, "started")
@ -159,8 +157,7 @@ marketplacesuite "Simulate invalid proofs - 1 provider node",
# check not freed
let currentPeriod = await getCurrentPeriod()
let timeUntilLastPeriod = await timeUntil(currentPeriod + totalProofs.u256 + 1)
check not eventually(slotWasFreed, timeUntilLastPeriod.inMilliseconds.int)
check not eventuallyP(slotWasFreed, currentPeriod + totalPeriods.u256 + 1)
await subscription.unsubscribe()
@ -168,19 +165,19 @@ marketplacesuite "Simulate invalid proofs",
Nodes(
# Uncomment to start Hardhat automatically, mainly so logs can be inspected locally
# hardhat: HardhatConfig()
# .withLogFile(),
# .withLogFile() # uncomment to output log file to tests/integration/logs/<start_datetime> <suite_name>/<test_name>/<node_role>_<node_idx>.log,
clients: NodeConfig()
.nodes(1)
.debug()
.withLogFile()
# .debug() # uncomment to enable console log output.debug()
# .withLogFile() # uncomment to output log file to tests/integration/logs/<start_datetime> <suite_name>/<test_name>/<node_role>_<node_idx>.log
.withLogTopics("node", "erasure"),
providers: NodeConfig()
.nodes(2)
.simulateProofFailuresFor(providerIdx=0, failEveryNProofs=2)
.debug()
.withLogFile()
# .debug() # uncomment to enable console log output
# .withLogFile() # uncomment to output log file to tests/integration/logs/<start_datetime> <suite_name>/<test_name>/<node_role>_<node_idx>.log
.withLogTopics(
"marketplace",
"sales",
@ -194,7 +191,7 @@ marketplacesuite "Simulate invalid proofs",
validators: NodeConfig()
.nodes(1)
.withLogFile()
# .withLogFile() # uncomment to output log file to tests/integration/logs/<start_datetime> <suite_name>/<test_name>/<node_role>_<node_idx>.log
.withLogTopics("validator", "initial-proving", "proving")
):
@ -207,14 +204,13 @@ marketplacesuite "Simulate invalid proofs",
let client0 = clients()[0].node.client
let provider0 = providers()[0]
let provider1 = providers()[1]
let totalProofs = 25
let totalPeriods = 25
let data = byteutils.toHex(await exampleData())
# createAvailabilities(data.len, totalProofs.periods)
discard provider0.node.client.postAvailability(
size=data.len.u256, # should match 1 slot only
duration=totalProofs.periods.u256,
duration=totalPeriods.periods.u256,
minPrice=300.u256,
maxCollateral=200.u256
)
@ -223,8 +219,7 @@ marketplacesuite "Simulate invalid proofs",
let purchaseId = await client0.requestStorage(
cid,
duration=totalProofs.periods,
# tolerance=1
duration=totalPeriods.periods
)
without requestId =? client0.requestId(purchaseId):
@ -244,7 +239,7 @@ marketplacesuite "Simulate invalid proofs",
# the remaining slot in its queue
discard provider1.node.client.postAvailability(
size=data.len.u256, # should match 1 slot only
duration=totalProofs.periods.u256,
duration=totalPeriods.periods.u256,
minPrice=300.u256,
maxCollateral=200.u256
)
@ -258,19 +253,15 @@ marketplacesuite "Simulate invalid proofs",
check eventually client0.purchaseStateIs(purchaseId, "started")
let currentPeriod = await getCurrentPeriod()
let timeUntilLastPeriod = await timeUntil(currentPeriod + totalProofs.u256 + 1)
# check eventually(
# client0.purchaseStateIs(purchaseId, "finished"),
# timeUntilLastPeriod.inMilliseconds.int)
check eventually(
check eventuallyP(
# SaleFinished happens too quickly, check SalePayout instead
provider0.node.client.saleStateIs(provider0slotId, "SalePayout"),
timeUntilLastPeriod.inMilliseconds.int)
currentPeriod + totalPeriods.u256 + 1)
check eventually(
check eventuallyP(
# SaleFinished happens too quickly, check SalePayout instead
provider1.node.client.saleStateIs(provider1slotId, "SalePayout"),
timeUntilLastPeriod.inMilliseconds.int)
currentPeriod + totalPeriods.u256 + 1)
check eventually(
(await token.balanceOf(!provider1.address)) >