[BUG] Proof already submitted

[benbierens]

Seen in devnet:
DBG 2025-11-10 18:40:07.224+00:00 Proof is required topics="marketplace sales proving" tid=1 challenge=0xe2b2..a7c0 provingPeriod=5875999 requestId=0xf549..efa8 slotIndex=7 slotId=0x5ddb..e1cd count=101566
Followed by:
WRN 2025-11-10 18:41:53.595+00:00 Failed to generate proof in time topics="marketplace sales proving" tid=1 periodAtFinish=5876000 provingPeriod=5875999 requestId=0xf549..efa8 slotIndex=7 slotId=0x5ddb..e1cd count=102815

At the time that proof is required, the period is determined to be 5875999.
By the time proof is submitted, the period is 5876000, resulting in the above warning.

But from the timestamps we can see that 1 minute and 46 seconds has passed while the proving period is 5 minutes.

We can see the logs from the affected host, around these times, filtered to the relevant slot.

Here we can see the following happen:

• The node determines it is period 5875999. This is out of sync with the chain.
• Proof requirement is determined by the chain. The on-chain period is already 5876000. And proof is required here.
• The node fetches the challenge for period 5876000 and begins proof calculation.
• When submitting, the node determines that the period is now 5876000 as well (in sync with chain) and produces this warning.
• Now that the node thinks it is in a new period, it re-checks the proof requirement: Yes proof is required this period.
• It fetched the same challenge again and calculates proof.
• When it tries to submit this, the transaction reverts with EVM reverted: Proofs_ProofAlreadySubmitted

Questions:

• How out-of-sync can the node's on-chain clock be before the situation is considered an error?
• When proof is already submitted, shouldn't the chain-call that determines whether proof is required take this into consideration?
• Delays in RPC calls and long-blocking functions inside the node can cause the node's estimate of the on-chain clock to drift. How large are these deviations and when might those be large enough to be considered an error?

In-progress:
Enabled "contract, clock" logging topics in devnet to gather "updated clock" log message and see the value of the on-chain clock offset.

[benbierens]

From the same storage node, we see:
updated clock topics="contracts clock" tid=1 blockTime=1762871219 blockNumber=768001 offset=-1 second, -248 milliseconds, -938 microseconds, and -440 nanoseconds
up to
updated clock topics="contracts clock" tid=1 blockTime=1762871419 blockNumber=768394 offset=-30 seconds, -696 milliseconds, -454 microseconds, and -237 nanoseconds

[benbierens]

Analysis of devnet nodes (storage + validator)
Distribution of the time interval between the "updated clock" log entry.

This shows that most clock updates happen within 0.5 seconds of the previous one.
With rare, occassional spikes to 4.5 to 4.7 seconds.
With highly rare and exceptional spikes to up to 2 minutes.

[benbierens]

Analysis of devnet nodes (storage + validator)
Distribution of on-chain clock offset:

Most nodes agree on an offset between -15 and -7 seconds.
Episodes where the distribution becomes spread out to larger (negative) offsets, are correlated:

(Horizontal axis: time)
From the Cyan series (validator) we can view the baseline noise in delay on the RPC connection. Storage nodes rarely and never by much decide on a lower offset than the validator.

[benbierens]

We have introduce the option to replace the on-chain clock component with a (regular) system clock:
ARCHIVIST_USE_SYSTEM_CLOCK : 1

We've been using this in the devnet from December onward and the issue described above has not been giving us trouble. The line "Failed to generate proof in time" occurs in the devnet logs twice in the past 90 days.

I think we got this one.