Test Failure: read_only_trxs/with_3_read_only_threads_no_tierup is stuck

[linh2931]

While running plugin_test to try to reproduce the problem in #1794, I saw plugin_test was stuck in read_only_trxs/with_3_read_only_threads_no_tierup and eventually timed out after 1500 seconds.

The test calls activate_protocol_features_set_bios_contract which in turns calls set_code. The set_code fails due to exceeding max_transaction-time (10000us).

There are two issues here

• max_transaction-time is set too short.
• set_code should not get stuck even if it fails to set code. Need to investigate further why it is stuck in failure.

...
1989: info  2023-10-24T15:06:49.059 plugin_te producer_plugin.cpp:1242      plugin_initialize    ] read-only-write-window-time-us: 100000 us, read-only-read-window-time-us: 40000 us, effective read window time to be used: 30000 us
1989: info  2023-10-24T15:06:49.059 plugin_te producer_plugin.cpp:1260      plugin_initialize    ] Read-only max transaction time 10000us set to fit in the effective read-only window 30000us.
1989: info  2023-10-24T15:06:49.059 plugin_te producer_plugin.cpp:1262      plugin_initialize    ] read-only-threads 3, max read-only trx time to be enforced: 10000 us
1989: warn  2023-10-24T15:06:49.060 plugin_te controller.cpp:637            startup              ] No existing chain state or fork database. Initializing fresh blockchain state and resetting fork database.
1989: warn  2023-10-24T15:06:49.060 plugin_te controller.cpp:483            initialize_blockchai ] Initializing new blockchain with genesis state
1989: info  2023-10-24T15:06:49.083 plugin_te controller.cpp:557            replay               ] no irreversible blocks need to be replayed
1989: info  2023-10-24T15:06:49.083 plugin_te controller.cpp:573            replay               ] 0 reversible blocks replayed
1989: info  2023-10-24T15:06:49.083 plugin_te controller.cpp:581            replay               ] replayed 0 blocks in 0 seconds, 0.00000000001443550 ms/block
1989: info  2023-10-24T15:06:49.083 plugin_te chain_plugin.cpp:1143         plugin_startup       ] starting chain in read/write mode
1989: info  2023-10-24T15:06:49.083 plugin_te chain_plugin.cpp:1147         plugin_startup       ] Blockchain started; head block is #1, genesis timestamp is 2018-06-01T12:00:00.000
1989: info  2023-10-24T15:06:49.083 plugin_te producer_plugin.cpp:1313      plugin_startup       ] producer plugin:  plugin_startup() begin
1989: info  2023-10-24T15:06:49.083 plugin_te producer_plugin.cpp:1354      plugin_startup       ] Launching block production for 1 producers at 2023-10-24T15:06:49.083.
1989: debug 2023-10-24T15:06:49.084 plugin_te producer_plugin.cpp:1858      start_block          ] Starting block #2 at 2023-10-24T15:06:49.084 producer eosio
1989: debug 2023-10-24T15:06:49.084 plugin_te controller.cpp:2503           clear_expired_input_ ] removed 0 expired transactions of the 0 input dedup list, pending block time 2023-10-24T15:06:49.500
1989: debug 2023-10-24T15:06:49.084 plugin_te producer_plugin.cpp:2015      remove_expired_trxs  ] Processed 0 expired transactions of the 0 transactions in the unapplied queue.
1989: debug 2023-10-24T15:06:49.084 plugin_te producer_plugin.cpp:2523      schedule_maybe_produ ] Scheduling Block Production on Normal Block #2 for 2023-10-24T15:06:49.350
1989: info  2023-10-24T15:06:49.084 plugin_te producer_plugin.cpp:1380      plugin_startup       ] producer plugin:  plugin_startup() end
1989: debug 2023-10-24T15:06:49.350 plugin_te producer_plugin.cpp:2540      operator()           ] Produce block timer for 2 running at 2023-10-24T15:06:49.350
1989: debug 2023-10-24T15:06:49.352 plugin_te producer_plugin.cpp:2582      operator()           ] Signing took 1592us
1989: info  2023-10-24T15:06:49.353 plugin_te producer_plugin.cpp:2642      produce_block        ] Produced block f383cf772570abdb... #2 @ 2023-10-24T15:06:49.500 signed by eosio [trxs: 0, lib: 1, confirmed: 0, net: 0, cpu: 100, elapsed: 139, time: 2942]
1989: debug 2023-10-24T15:06:49.353 plugin_te producer_plugin.cpp:288       report               ] Block #2 eosio trx idle: 265696us out of 269296us, success: 0, 0us, fail: 0, 0us, transient: 0, 0us, other: 3599us
1989: debug 2023-10-24T15:06:49.353 plugin_te producer_plugin.cpp:1858      start_block          ] Starting block #3 at 2023-10-24T15:06:49.353 producer eosio
1989: debug 2023-10-24T15:06:49.355 plugin_te controller.cpp:2503           clear_expired_input_ ] removed 0 expired transactions of the 0 input dedup list, pending block time 2023-10-24T15:06:50.000
1989: debug 2023-10-24T15:06:49.355 plugin_te producer_plugin.cpp:2015      remove_expired_trxs  ] Processed 0 expired transactions of the 0 transactions in the unapplied queue.
1989: debug 2023-10-24T15:06:49.355 plugin_te producer_plugin.cpp:2523      schedule_maybe_produ ] Scheduling Block Production on Normal Block #3 for 2023-10-24T15:06:49.812
1989: debug 2023-10-24T15:06:49.355 plugin_te producer_plugin.cpp:2542      operator()           ] Producing Block #2 returned: true
1989: debug 2023-10-24T15:06:49.660 plugin_te producer_plugin.cpp:2077      log_trx_results      ] [TRX_TRACE] Block 3 for producer eosio is REJECTING tx: 0170c14d176ba71424c5c18aaaf7c913c9e470d1acd892409147386ffb6da497, auth: eosio, action: eosio:setcode, transaction 0170c14d176ba71424c5c18aaaf7c913c9e470d1acd892409147386ffb6da497 was executing for too long 10843us reached node configured max-transaction-time 10000us
1989: debug 2023-10-24T15:06:49.662 plugin_te producer_plugin.cpp:2084      log_trx_results      ] [TRX_TRACE] Block 3 for producer eosio is REJECTING tx: {"expiration":"2023-10-24T15:07:19","ref_block_num":2,"ref_block_prefix":3685445669,"max_net_usage_words":0,"max_cpu_usage_ms":0,"delay_sec":0,"context_free_actions":[],"actions":[{"account":"eosio","name":"setcode","authorization":[{"actor":"eosio","permission":"active"}],"code_hash":"241108ec5076fe0df9dbe9e6aab249bc26cef0362f6805ff43118ab74115cabd","data":{"account":"eosio","vmtype":0,"vmversion":0,"code":{"size":19646,"trimmed_hex":"0061736d010000000198011960000060027f7f0060037f7f7f0060047e7e7e7e017f6000017e60047f7e7e7f0060057f7f7f7f7f017f60037f7f7f017f60027f"}},"hex_data":{"size":19659,"trimmed_hex":"0000000000ea30550000be99010061736d010000000198011960000060027f7f0060037f7f7f0060047e7e7e7e017f6000017e60047f7e7e7f0060057f7f7f7f"}}]}
1989: debug 2023-10-24T15:06:49.664 plugin_te producer_plugin.cpp:2087      log_trx_results      ] [TRX_TRACE] Block 3 for producer eosio is REJECTING tx: {"id":"0170c14d176ba71424c5c18aaaf7c913c9e470d1acd892409147386ffb6da497","block_num":3,"block_time":"2023-10-24T15:06:50.000","producer_block_id":null,"receipt":null,"elapsed":19731,"net_usage":6874,"scheduled":false,"action_traces":[{"action_ordinal":1,"creator_action_ordinal":0,"closest_unnotified_ancestor_action_ordinal":0,"receipt":null,"receiver":"eosio","act":{"account":"eosio","name":"setcode","authorization":[{"actor":"eosio","permission":"active"}],"code_hash":"241108ec5076fe0df9dbe9e6aab249bc26cef0362f6805ff43118ab74115cabd","data":{"account":"eosio","vmtype":0,"vmversion":0,"code":{"size":19646,"trimmed_hex":"0061736d010000000198011960000060027f7f0060037f7f7f0060047e7e7e7e017f6000017e60047f7e7e7f0060057f7f7f7f7f017f60037f7f7f017f60027f"}},"hex_data":{"size":19659,"trimmed_hex":"0000000000ea30550000be99010061736d010000000198011960000060027f7f0060037f7f7f0060047e7e7e7e017f6000017e60047f7e7e7f0060057f7f7f7f"}},"context_free":false,"elapsed":18788,"console":"","trx_id":"0170c14d176ba71424c5c18aaaf7c913c9e470d1acd892409147386ffb6da497","block_num":3,"block_time":"2023-10-24T15:06:50.000","producer_block_id":null,"account_ram_deltas":[{"account":"eosio","delta":196460}],"except":{"code":3080004,"name":"tx_cpu_usage_exceeded","message":"Transaction exceeded the current CPU usage limit imposed on the transaction","stack":[{"context":{"level":"error","file":"transaction_context.cpp","line":478,"method":"checktime","hostname":"","thread_name":"plugin_test","timestamp":"2023-10-24T15:06:49.660"},"format":"transaction ${id} was executing for too long ${billing_timer}us reached node configured max-transaction-time ${limit}us","data":{"id":"0170c14d176ba71424c5c18aaaf7c913c9e470d1acd892409147386ffb6da497","billing_timer":10843,"subjective":0,"limit":10000}},{"context":{"level":"warn","file":"apply_context.cpp","line":134,"method":"exec_one","hostname":"","thread_name":"plugin_test","timestamp":"2023-10-24T15:06:49.660"},"format":"pending console output: ${console}","data":{"console":""}}]},"error_code":"10000000000000000000","return_value_hex_data":""}],"account_ram_delta":null,"except":{"code":3080004,"name":"tx_cpu_usage_exceeded","message":"Transaction exceeded the current CPU usage limit imposed on the transaction","stack":[{"context":{"level":"error","file":"transaction_context.cpp","line":478,"method":"checktime","hostname":"","thread_name":"plugin_test","timestamp":"2023-10-24T15:06:49.660"},"format":"transaction ${id} was executing for too long ${billing_timer}us reached node configured max-transaction-time ${limit}us","data":{"id":"0170c14d176ba71424c5c18aaaf7c913c9e470d1acd892409147386ffb6da497","billing_timer":10843,"subjective":0,"limit":10000}},{"context":{"level":"warn","file":"apply_context.cpp","line":134,"method":"exec_one","hostname":"","thread_name":"plugin_test","timestamp":"2023-10-24T15:06:49.660"},"format":"pending console output: ${console}","data":{"console":""}}]},"error_code":"10000000000000000000"}
1989: debug 2023-10-24T15:06:49.813 plugin_te producer_plugin.cpp:2540      operator()           ] Produce block timer for 3 running at 2023-10-24T15:06:49.813
1989: debug 2023-10-24T15:06:49.814 plugin_te producer_plugin.cpp:2582      operator()           ] Signing took 387us

...

1989: info  2023-10-24T15:31:40.590 plugin_te producer_plugin.cpp:2642      produce_block        ] Produced block 596350d1ff5fc553... #2985 @ 2023-10-24T15:31:41.000 signed by eosio [trxs: 0, lib: 2984, confirmed: 0, net: 0, cpu: 100, elapsed: 279, time: 2681]
1989: debug 2023-10-24T15:31:40.590 plugin_te producer_plugin.cpp:288       report               ] Block #2985 eosio trx idle: 458364us out of 462042us, success: 0, 0us, fail: 0, 0us, transient: 0, 0us, other: 3677us
1989: debug 2023-10-24T15:31:40.590 plugin_te producer_plugin.cpp:1858      start_block          ] Starting block #2986 at 2023-10-24T15:31:40.590 producer eosio
1989: debug 2023-10-24T15:31:40.591 plugin_te controller.cpp:2503           clear_expired_input_ ] removed 0 expired transactions of the 0 input dedup list, pending block time 2023-10-24T15:31:41.500
1989: debug 2023-10-24T15:31:40.591 plugin_te producer_plugin.cpp:2015      remove_expired_trxs  ] Processed 0 expired transactions of the 0 transactions in the unapplied queue.
1989: debug 2023-10-24T15:31:40.591 plugin_te producer_plugin.cpp:2523      schedule_maybe_produ ] Scheduling Block Production on Normal Block #2986 for 2023-10-24T15:31:41.050
1989: debug 2023-10-24T15:31:40.592 plugin_te producer_plugin.cpp:2542      operator()           ] Producing Block #2985 returned: true
1/1 Test #1989: plugin_test ......................***Timeout 1500.02 sec