Kagome: execution-time-bad does not throw Timeout error and does not update kagome_pvf_execution_time metrics

[dimitrovmaksim]

Test case: code-size-bad

Injecting Infinite loop into validate_block function using wasm-injector
Kagome Version: 0.9.0-127
Polkadot 0.9.43-ba42b9ce51d
extracted genesis wasm for rococo-staging using polkadot-parachain 1.0.0-2306bfb7565
Zombienet 1.3.65

Polkadot behaviour:

Polkadot throws HardTimeout error and continues working:

2023-09-01 10:17:26.137  INFO tokio-runtime-worker parachain::candidate-validation: Failed to validate candidate para_id=Id(2000) error=InvalidCandidate(HardTimeout)
2023-09-01 10:17:26.137  WARN tokio-runtime-worker parachain::candidate-backing: Validation yielded an invalid candidate candidate_hash=0x1997722630b91344ae40a7f17cc684a99c948926408491b465f407459e336f97 reason=Timeout traceID=34017051940705670366927701642387555497

polkadot_pvf_execution_time has samples in buckets > 2s

polkadot_pvf_execution_time_bucket{chain="rococo_local_testnet",le="0.01"} 0
polkadot_pvf_execution_time_bucket{chain="rococo_local_testnet",le="0.025"} 0
polkadot_pvf_execution_time_bucket{chain="rococo_local_testnet",le="0.05"} 0
polkadot_pvf_execution_time_bucket{chain="rococo_local_testnet",le="0.1"} 0
polkadot_pvf_execution_time_bucket{chain="rococo_local_testnet",le="0.25"} 0
polkadot_pvf_execution_time_bucket{chain="rococo_local_testnet",le="0.5"} 0
polkadot_pvf_execution_time_bucket{chain="rococo_local_testnet",le="1"} 0
polkadot_pvf_execution_time_bucket{chain="rococo_local_testnet",le="2"} 0
polkadot_pvf_execution_time_bucket{chain="rococo_local_testnet",le="3"} 1
polkadot_pvf_execution_time_bucket{chain="rococo_local_testnet",le="4"} 1
polkadot_pvf_execution_time_bucket{chain="rococo_local_testnet",le="5"} 1
polkadot_pvf_execution_time_bucket{chain="rococo_local_testnet",le="6"} 1
polkadot_pvf_execution_time_bucket{chain="rococo_local_testnet",le="8"} 1
polkadot_pvf_execution_time_bucket{chain="rococo_local_testnet",le="10"} 1
polkadot_pvf_execution_time_bucket{chain="rococo_local_testnet",le="12"} 1
polkadot_pvf_execution_time_bucket{chain="rococo_local_testnet",le="+Inf"} 1

Kagome behaviour:

No signs of any timeout errors, but it seems the parachain does't make progress as block height stays 0
No samples are written in any kagome_pvf_execution_time buckets

23.09.01 10:10:00.272557  kagome           Info      ParachainProcessorImpl  Starting validation task.(para id=2000, relay parent=0xb37d…04a8, peer=…RC1v16)
23.09.01 10:10:01.206269  grandpa          Info      GrandpaEnvironment  Found best chain is longer than approved: #29 (0xb37d…04a8) > #12 (0x9993…6607); truncate it

# HELP kagome_pvf_execution_time Time spent in executing PVFs
# TYPE kagome_pvf_execution_time histogram
kagome_pvf_execution_time_count 0
kagome_pvf_execution_time_sum 0
kagome_pvf_execution_time_bucket{le="0.01"} 0
kagome_pvf_execution_time_bucket{le="0.025"} 0
kagome_pvf_execution_time_bucket{le="0.05"} 0
kagome_pvf_execution_time_bucket{le="0.1"} 0
kagome_pvf_execution_time_bucket{le="0.25"} 0
kagome_pvf_execution_time_bucket{le="0.5"} 0
kagome_pvf_execution_time_bucket{le="1"} 0
kagome_pvf_execution_time_bucket{le="2"} 0
kagome_pvf_execution_time_bucket{le="3"} 0
kagome_pvf_execution_time_bucket{le="4"} 0
kagome_pvf_execution_time_bucket{le="5"} 0
kagome_pvf_execution_time_bucket{le="6"} 0
kagome_pvf_execution_time_bucket{le="8"} 0
kagome_pvf_execution_time_bucket{le="10"} 0
kagome_pvf_execution_time_bucket{le="12"} 0
kagome_pvf_execution_time_bucket{le="+Inf"} 0

Logs:

kagome-execution-time-bad.log
polkadot-execution-time-bad.log