Block time calculation gets warped with high stakes

[ryoqun]

Problem

solana get-block-time XXX can return warped value:

ryoqun@ubuqun:~/work/solana/solana$ solana get-block-time 27771
310409
ryoqun@ubuqun:~/work/solana/solana$ date -d @310409
Sun 04 Jan 1970 11:13:29 PM JST

under the configuration of:

ryoqun@ubuqun:~/work/solana/solana$ solana show-validators && solana get-transaction-count && solana get-epoch-info

Active Stake: 60000.44053376 SOL

  Identity Pubkey                               Vote Account Pubkey                           Commission  Last Vote  Root Block   Uptime  Active Stake
  FayTdFSG6eJLz6qS7aasMx9HjUHejB3s4X6cFrqxrZb3  zsyDxqBvs8t1wxWYjcNk6W5vrcjz12ezbpNvPeLSgDH         100%      27771       27740   98.26%  19999.98513344 SOL (33.33%)
  7SgZJnxM7PSSE7PJ7BgPXdG1NH5sqxDDnNyiie5d1Aqg  8b7Q1HCqvssRTUsjp1L2jre1uNoSrNVExzYNCHinwD4i        100%      27771       27740   98.20%  19999.98513344 SOL (33.33%)
  BQgq3WRtoB3TwQ16dLZTamupnEz6WY7FvV7RfivLyag9  7Aetw8C36S6vtKGzLxj36LC43YzPakUJ7FzsyhSTgVtH        100%      27771       27740   97.84%  19999.98513344 SOL (33.33%)
  2buEt4ko3sgCZCb1aX9RTrW9dyr8DPYfdSgM7uYoF9t7  APw1ue8TLFyLPUH1VCXLHiL96PSQdNnY2XrEufmaAKTw          0%      27771       27740   98.52%  0.48513344 SOL (0.00%)

105199

Current epoch: 57
Current slot: 27803
Total slots in current epoch: 512
Remaining slots in current epoch: 325
Time remaining in current epoch: 2m 10s

Proposed Solution

My rough guess was timestamp (around 30 bits these days) * stake (~ 44 bits) could have been overflowed. Oddity is that rust's checked integer operation didn't complain...

ryoqun@ubuqun:~/work/solana/solana$ solana get-block-time 27771
1578909061
ryoqun@ubuqun:~/work/solana/solana$ date -d @1578909061
Mon 13 Jan 2020 06:51:01 PM JST


ryoqun@ubuqun:~/work/solana/solana$ node -p 'Math.log2(Date.now() / 1000)'
30.556330346288025
ryoqun@ubuqun:~/work/solana/solana$ node -p 'Math.log2(19999_000_000_000)'
44.184993096980236

under this hacky patch:

ryoqun@ubuqun:~/work/solana/solana$ git diff ledger/src/blocktree.rs
diff --git a/ledger/src/blocktree.rs b/ledger/src/blocktree.rs
index d56671266..ae9e49310 100644
--- a/ledger/src/blocktree.rs
+++ b/ledger/src/blocktree.rs
@@ -1264,7 +1264,7 @@ impl Blocktree {
                 let offset = (slot - timestamp_slot) as u32 * slot_duration;
                 stakes
                     .get(&vote_pubkey)
-                    .map(|(stake, _account)| ((timestamp as u64 + offset.as_secs()) * stake, stake))
+                    .map(|(stake, _account)| ((timestamp as u128 + offset.as_secs() as u128) * *stake as u128, *stake as u128))
             })
             .fold((0, 0), |(timestamps, stakes), (timestamp, stake)| {
                 (timestamps + timestamp, stakes + stake)

background

I've tested large stakes hoping something odd for the bank hash mismatch #7736; And I've found this instead as part of the investigation. This block time calculation doesn't happen on chain (is it ok, btw?) and the vote timestamps in ledger themselves are fine.

[ryoqun]

@CriesofCarrots Could you take a look at this to see if this behavior is indeed a bug?

[CriesofCarrots]

@ryoqun , at a glance, this does appear to be a bug! I'll write a failing test to expose it.