Setting block_interval_ms to values lower than 175 results in "3030000 block_validate_exception: Block exception"

[cmadh]

Setting block_interval_ms to values lower than 175 results in "3030000 block_validate_exception: Block exception"

Tested this (already a while ago) with leap 4.x.x and now with the new 5.0.0-RC2 version.

Log of nodeos running with block_interval_ms = 175 (leap 5.0.0-RC2):

debug 2023-10-16T20:27:04.973 nodeos    producer_plugin.cpp:2577      operator()           ] Signing took 93us
info  2023-10-16T20:27:04.984 nodeos    producer_plugin.cpp:2641      produce_block        ] Produced block 7649580f6b4a1e73... #2 @ 2023-10-16T20:27:04.600 signed by eosio [trxs: 0, lib: 1, confirmed: 0, net: 0, cpu: 100, elapsed: 450376, time: 463676]
debug 2023-10-16T20:27:04.986 nodeos    producer_plugin.cpp:294       report               ] Block #2 eosio trx idle: 7461us out of 488592us, success: 0, 0us, fail: 0, 0us, transient: 0, 0us, other: 481130us
debug 2023-10-16T20:27:04.986 nodeos    producer_plugin.cpp:1853      start_block          ] Starting block #3 at 2023-10-16T20:27:04.986 producer eosio
debug 2023-10-16T20:27:04.987 nodeos    controller.cpp:2504           clear_expired_input_ ] removed 0 expired transactions of the 0 input dedup list, pending block time 2023-10-16T20:27:05.000
debug 2023-10-16T20:27:04.987 nodeos    producer_plugin.cpp:2010      remove_expired_trxs  ] Processed 0 expired transactions of the 0 transactions in the unapplied queue.
debug 2023-10-16T20:27:04.987 nodeos    producer_plugin.cpp:2519      schedule_maybe_produ ] Scheduling Block Production on Normal Block #3 for 2023-10-16T20:27:05.000
debug 2023-10-16T20:27:04.987 nodeos    producer_plugin.cpp:2537      operator()           ] Producing Block #2 returned: true
info  2023-10-16T20:27:04.989 nodeos    listener.hpp:131              log_listening        ] start listening on 127.0.0.1:8888 resolved from 127.0.0.1:8888 for API categories: all
debug 2023-10-16T20:27:05.000 nodeos    producer_plugin.cpp:2535      operator()           ] Produce block timer for 3 running at 2023-10-16T20:27:05.000
debug 2023-10-16T20:27:05.000 nodeos    producer_plugin.cpp:2577      operator()           ] Signing took 520us
info  2023-10-16T20:27:05.006 nodeos    producer_plugin.cpp:2641      produce_block        ] Produced block 2a4502c6040bc6ec... #3 @ 2023-10-16T20:27:05.000 signed by eosio [trxs: 0, lib: 2, confirmed: 0, net: 0, cpu: 100, elapsed: 113, time: 6828]
debug 2023-10-16T20:27:05.006 nodeos    producer_plugin.cpp:294       report               ] Block #3 eosio trx idle: 12623us out of 19983us, success: 0, 0us, fail: 0, 0us, transient: 0, 0us, other: 7360us
debug 2023-10-16T20:27:05.007 nodeos    producer_plugin.cpp:1853      start_block          ] Starting block #4 at 2023-10-16T20:27:05.006 producer eosio
debug 2023-10-16T20:27:05.007 nodeos    controller.cpp:2504           clear_expired_input_ ] removed 0 expired transactions of the 0 input dedup list, pending block time 2023-10-16T20:27:05.200
debug 2023-10-16T20:27:05.007 nodeos    producer_plugin.cpp:2010      remove_expired_trxs  ] Processed 0 expired transactions of the 0 transactions in the unapplied queue.
debug 2023-10-16T20:27:05.007 nodeos    producer_plugin.cpp:2519      schedule_maybe_produ ] Scheduling Block Production on Normal Block #4 for 2023-10-16T20:27:05.200
debug 2023-10-16T20:27:05.007 nodeos    producer_plugin.cpp:2537      operator()           ] Producing Block #3 returned: true
debug 2023-10-16T20:27:05.200 nodeos    producer_plugin.cpp:2535      operator()           ] Produce block timer for 4 running at 2023-10-16T20:27:05.200
debug 2023-10-16T20:27:05.200 nodeos    producer_plugin.cpp:2577      operator()           ] Signing took 205us
info  2023-10-16T20:27:05.201 nodeos    producer_plugin.cpp:2641      produce_block        ] Produced block 0bda8a32debd29f9... #4 @ 2023-10-16T20:27:05.200 signed by eosio [trxs: 0, lib: 3, confirmed: 0, net: 0, cpu: 100, elapsed: 116, time: 1672]
debug 2023-10-16T20:27:05.201 nodeos    producer_plugin.cpp:294       report               ] Block #4 eosio trx idle: 192564us out of 194716us, success: 0, 0us, fail: 0, 0us, transient: 0, 0us, other: 2151us
debug 2023-10-16T20:27:05.201 nodeos    producer_plugin.cpp:1853      start_block          ] Starting block #5 at 2023-10-16T20:27:05.201 producer eosio
debug 2023-10-16T20:27:05.202 nodeos    controller.cpp:2504           clear_expired_input_ ] removed 0 expired transactions of the 0 input dedup list, pending block time 2023-10-16T20:27:05.400
debug 2023-10-16T20:27:05.202 nodeos    producer_plugin.cpp:2010      remove_expired_trxs  ] Processed 0 expired transactions of the 0 transactions in the unapplied queue.
debug 2023-10-16T20:27:05.202 nodeos    producer_plugin.cpp:2519      schedule_maybe_produ ] Scheduling Block Production on Normal Block #5 for 2023-10-16T20:27:05.400
debug 2023-10-16T20:27:05.202 nodeos    producer_plugin.cpp:2537      operator()           ] Producing Block #4 returned: true
debug 2023-10-16T20:27:05.400 nodeos    producer_plugin.cpp:2535      operator()           ] Produce block timer for 5 running at 2023-10-16T20:27:05.400
debug 2023-10-16T20:27:05.400 nodeos    producer_plugin.cpp:2577      operator()           ] Signing took 83us
info  2023-10-16T20:27:05.402 nodeos    producer_plugin.cpp:2641      produce_block        ] Produced block 5fec030df7f8ca61... #5 @ 2023-10-16T20:27:05.400 signed by eosio [trxs: 0, lib: 4, confirmed: 0, net: 0, cpu: 100, elapsed: 120, time: 2166]
debug 2023-10-16T20:27:05.402 nodeos    producer_plugin.cpp:294       report               ] Block #5 eosio trx idle: 197623us out of 200347us, success: 0, 0us, fail: 0, 0us, transient: 0, 0us, other: 2723us
debug 2023-10-16T20:27:05.402 nodeos    producer_plugin.cpp:1853      start_block          ] Starting block #6 at 2023-10-16T20:27:05.402 producer eosio
debug 2023-10-16T20:27:05.402 nodeos    controller.cpp:2504           clear_expired_input_ ] removed 0 expired transactions of the 0 input dedup list, pending block time 2023-10-16T20:27:05.600
debug 2023-10-16T20:27:05.402 nodeos    producer_plugin.cpp:2010      remove_expired_trxs  ] Processed 0 expired transactions of the 0 transactions in the unapplied queue.
debug 2023-10-16T20:27:05.402 nodeos    producer_plugin.cpp:2519      schedule_maybe_produ ] Scheduling Block Production on Normal Block #6 for 2023-10-16T20:27:05.600
debug 2023-10-16T20:27:05.402 nodeos    producer_plugin.cpp:2537      operator()           ] Producing Block #5 returned: true

Log of nodeos running with block_interval_ms = 174 (leap 5.0.0-RC2):

warn  2023-10-16T22:39:04.506 nodeos    producer_plugin.cpp:1923      start_block          ] 3030000 block_validate_exception: Block exception
next block must be in the future
    {}
    nodeos  block_header_state.cpp:44 next

error 2023-10-16T22:39:04.506 nodeos    producer_plugin.cpp:2459      schedule_production_ ] Failed to start a pending block, will try again later
debug 2023-10-16T22:39:04.523 nodeos    producer_plugin.cpp:1853      start_block          ] Starting block #2 at 2023-10-16T22:39:04.523 producer eosio
warn  2023-10-16T22:39:04.524 nodeos    producer_plugin.cpp:1923      start_block          ] 3030000 block_validate_exception: Block exception
next block must be in the future
    {}
    nodeos  block_header_state.cpp:44 next

error 2023-10-16T22:39:04.524 nodeos    producer_plugin.cpp:2459      schedule_production_ ] Failed to start a pending block, will try again later
debug 2023-10-16T22:39:04.541 nodeos    producer_plugin.cpp:1853      start_block          ] Starting block #2 at 2023-10-16T22:39:04.541 producer eosio
warn  2023-10-16T22:39:04.542 nodeos    producer_plugin.cpp:1923      start_block          ] 3030000 block_validate_exception: Block exception
next block must be in the future
    {}
    nodeos  block_header_state.cpp:44 next

error 2023-10-16T22:39:04.542 nodeos    producer_plugin.cpp:2459      schedule_production_ ] Failed to start a pending block, will try again later
debug 2023-10-16T22:39:04.559 nodeos    producer_plugin.cpp:1853      start_block          ] Starting block #2 at 2023-10-16T22:39:04.559 producer eosio
warn  2023-10-16T22:39:04.560 nodeos    producer_plugin.cpp:1923      start_block          ] 3030000 block_validate_exception: Block exception
next block must be in the future
    {}
    nodeos  block_header_state.cpp:44 next

error 2023-10-16T22:39:04.560 nodeos    producer_plugin.cpp:2459      schedule_production_ ] Failed to start a pending block, will try again later
debug 2023-10-16T22:39:04.577 nodeos    producer_plugin.cpp:1853      start_block          ] Starting block #2 at 2023-10-16T22:39:04.577 producer eosio
warn  2023-10-16T22:39:04.578 nodeos    producer_plugin.cpp:1923      start_block          ] 3030000 block_validate_exception: Block exception
next block must be in the future
    {}
    nodeos  block_header_state.cpp:44 next

[cmadh]

Some additional context why we need this:

We are working on a modification of Leap that integrates a deterministic high-performance physics engine, allowing Leap to be utilized as an authoritative game server. The primary components of authoritative game servers typically include a physics engine and low-latency networking. The goal is to empower game developers to implement the entire game logic on the blockchain, facilitating the launch of sidechains based on specific use cases and game logic with a relatively small set of producers and/or in geographically less decentralized networks.

A smaller block time of 100ms (equivalent to 10 authoritative frames per second) or 50ms (equivalent to 20 authoritative frames per second) is necessary to avoid more complex implementations that synchronize time and validated transaction count between frames in other ways without disrupting consensus. For many games, having 10 or 20 authoritative frames provides a suitable balance, while client-side prediction mechanisms must be employed to increase the rendered frame rate.

This innovative approach opens up exciting possibilities for blockchain-based game development by enabling the integration of comprehensive game logic on the blockchain, all while maintaining a high level of determinism and low-latency networking.

[bhazzard]

@cmadh, @heifner mentioned that it would be good to confirm that your max-block-cpu-usage is lower than block_interval_ms (your logs suggest it isn't), and see if that resolves your issue.

[cmadh]

@cmadh, @heifner mentioned that it would be good to confirm that your max-block-cpu-usage is lower than block_interval_ms (your logs suggest it isn't), and see if that resolves your issue.

Sry, that makes sense. Just verified the issue by setting default_max_block_cpu_usage to 20ms, which is resulting in the same log and Block Exception.

Just to make sure we are on the same page: I'm setting block_interval_ms to 174 and default_max_block_cpu_usage to 20'000

[heifner]

The problem is overflow in block_timestamp. You can change block_timestamp_epoch to Oct 1st, 2023 (1696118711000) and that would last until May 11, 2037 before it overflowed. With these two changes you can produce blocks at 100ms (block_interval_ms = 100). Also make sure to provide a --genesis-json with a initial_timestamp greater than Oct 1st, 2023.

Or you will need to make slot a uint64_t. There are likely some additional code changes that would need to be made because of that. Minimum you need to change block_timing_util.hpp calculate_next_block_slot minimum_offset to a uint64_t and also comment out the test_block_timing_util.cpp tests or fix them. There are likely hard to find bugs introduced by that type change, but I was able to get block production at 100ms with this change. I did not run any tests except just a simple run of ./nodeos --data-dir d --config-dir d -e -p eosio.

[cmadh]

The problem is overflow in block_timestamp. You can change block_timestamp_epoch to Oct 1st, 2023 (1696118711000) and that would last until May 11, 2037 before it overflowed. With these two changes you can produce blocks at 100ms (block_interval_ms = 100). Also make sure to provide a --genesis-json with a initial_timestamp greater than Oct 1st, 2023.

Or you will need to make slot a uint64_t. There are likely some additional code changes that would need to be made because of that. Minimum you need to change block_timing_util.hpp calculate_next_block_slot minimum_offset to a uint64_t and also comment out the test_block_timing_util.cpp tests or fix them. There are likely hard to find bugs introduced by that type change, but I was able to get block production at 100ms with this change. I did not run any tests except just a simple run of ./nodeos --data-dir d --config-dir d -e -p eosio.

Awesome, thanks @heifner I'll try around with this tomorrow. I assume it will allow us to continue with our development and testing for some time.