[live] header ancestry mismatch in light client sync

[brenzi]

[2023-12-12T14:21:31Z TRACE itc_parentchain_light_client::io] [Integritee] Backup light client state to /opt/sidechain/integritee_lcdb/db.bin.backup
[2023-12-12T14:21:31Z TRACE itc_parentchain_light_client::io] [Integritee] Seal light client State. Current state: LightValidationState { relay_state: RelayInfo { last_finalized_block_header_number: 3648578, current_validator_set: [], current_validator_set_id: 0, number of unjustified headers: 0 } }
[2023-12-12T14:21:31Z INFO  integritee_service::parentchain_handler] [Integritee] Synced 3659578 out of 3666546 finalized parentchain blocks
[2023-12-12T14:21:32Z INFO  integritee_service::parentchain_handler] [Integritee] Found 1000 block(s) to sync in this chunk
[2023-12-12T14:21:32Z TRACE integritee_service::parentchain_handler] skipping invocations for fast-sync for blocks older than shard creation: 3661578 < 3666546
[2023-12-12T14:21:32Z TRACE enclave_runtime] [Integritee] Dispatching Import of 1000 blocks and 0 events
[2023-12-12T14:21:32Z DEBUG itc_parentchain_block_importer::block_importer] [Integritee] Import blocks to light-client!
[2023-12-12T14:21:32Z DEBUG integritee_service::ocall_bridge::bridge_api] Requesting WorkerOnChain OCall API instance
[2023-12-12T14:21:32Z TRACE itc_parentchain_light_client::io] [Integritee] Backup light client state to /opt/sidechain/integritee_lcdb/db.bin.backup
[2023-12-12T14:21:32Z TRACE itc_parentchain_light_client::io] [Integritee] Seal light client State. Current state: LightValidationState { relay_state: RelayInfo { last_finalized_block_header_number: 3648578, current_validator_set: [], current_validator_set_id: 0, number of unjustified headers: 0 } }
[2023-12-12T14:21:32Z INFO  integritee_service::parentchain_handler] [Integritee] Synced 3660578 out of 3666546 finalized parentchain blocks

[2023-12-12T14:21:36Z INFO  integritee_service::parentchain_handler] [Integritee] Found 1000 block(s) to sync in this chunk
[2023-12-12T14:21:36Z TRACE integritee_service::parentchain_handler] skipping invocations for fast-sync for blocks older than shard creation: 3662578 < 3666546
[2023-12-12T14:21:36Z TRACE enclave_runtime] [Integritee] Dispatching Import of 1000 blocks and 0 events
[2023-12-12T14:21:36Z DEBUG itc_parentchain_block_importer::block_importer] [Integritee] Import blocks to light-client!
[2023-12-12T14:21:36Z DEBUG integritee_service::ocall_bridge::bridge_api] Requesting WorkerOnChain OCall API instance
[2023-12-12T14:21:36Z TRACE itc_parentchain_light_client::io] [Integritee] Backup light client state to /opt/sidechain/integritee_lcdb/db.bin.backup
[2023-12-12T14:21:36Z TRACE itc_parentchain_light_client::io] [Integritee] Seal light client State. Current state: LightValidationState { relay_state: RelayInfo { last_finalized_block_header_number: 3648578, current_validator_set: [], current_validator_set_id: 0, number of unjustified headers: 0 } }
[2023-12-12T14:21:36Z INFO  integritee_service::parentchain_handler] [Integritee] Synced 3661578 out of 3666546 finalized parentchain blocks

[2023-12-12T14:21:38Z INFO  integritee_service::parentchain_handler] [Integritee] Found 1000 block(s) to sync in this chunk
[2023-12-12T14:21:38Z TRACE integritee_service::parentchain_handler] skipping invocations for fast-sync for blocks older than shard creation: 3663578 < 3666546
[2023-12-12T14:21:38Z TRACE enclave_runtime] [Integritee] Dispatching Import of 1000 blocks and 0 events
[2023-12-12T14:21:38Z DEBUG itc_parentchain_block_importer::block_importer] [Integritee] Import blocks to light-client!
[2023-12-12T14:21:38Z DEBUG integritee_service::ocall_bridge::bridge_api] Requesting WorkerOnChain OCall API instance
[2023-12-12T14:21:38Z TRACE itc_parentchain_light_client::io] [Integritee] Backup light client state to /opt/sidechain/integritee_lcdb/db.bin.backup
[2023-12-12T14:21:38Z TRACE itc_parentchain_light_client::io] [Integritee] Seal light client State. Current state: LightValidationState { relay_state: RelayInfo { last_finalized_block_header_number: 3648578, current_validator_set: [], current_validator_set_id: 0, number of unjustified headers: 0 } }
[2023-12-12T14:21:38Z INFO  integritee_service::parentchain_handler] [Integritee] Synced 3662578 out of 3666546 finalized parentchain blocks

[2023-12-12T14:21:40Z INFO  integritee_service::parentchain_handler] [Integritee] Found 1000 block(s) to sync in this chunk
[2023-12-12T14:21:40Z TRACE integritee_service::parentchain_handler] skipping invocations for fast-sync for blocks older than shard creation: 3664578 < 3666546
[2023-12-12T14:21:40Z TRACE enclave_runtime] [Integritee] Dispatching Import of 1000 blocks and 0 events
[2023-12-12T14:21:40Z DEBUG itc_parentchain_block_importer::block_importer] [Integritee] Import blocks to light-client!
[2023-12-12T14:21:40Z DEBUG integritee_service::ocall_bridge::bridge_api] Requesting WorkerOnChain OCall API instance
[2023-12-12T14:21:40Z TRACE itc_parentchain_light_client::io] [Integritee] Backup light client state to /opt/sidechain/integritee_lcdb/db.bin.backup
[2023-12-12T14:21:40Z TRACE itc_parentchain_light_client::io] [Integritee] Seal light client State. Current state: LightValidationState { relay_state: RelayInfo { last_finalized_block_header_number: 3648578, current_validator_set: [], current_validator_set_id: 0, number of unjustified headers: 0 } }
[2023-12-12T14:21:40Z INFO  integritee_service::parentchain_handler] [Integritee] Synced 3663578 out of 3666546 finalized parentchain blocks

[2023-12-12T14:21:42Z INFO  integritee_service::parentchain_handler] [Integritee] Found 1000 block(s) to sync in this chunk
[2023-12-12T14:21:42Z TRACE integritee_service::parentchain_handler] skipping invocations for fast-sync for blocks older than shard creation: 3665578 < 3666546
[2023-12-12T14:21:42Z TRACE enclave_runtime] [Integritee] Dispatching Import of 1000 blocks and 0 events
[2023-12-12T14:21:42Z DEBUG itc_parentchain_block_importer::block_importer] [Integritee] Import blocks to light-client!
[2023-12-12T14:21:42Z DEBUG integritee_service::ocall_bridge::bridge_api] Requesting WorkerOnChain OCall API instance
[2023-12-12T14:21:42Z TRACE itc_parentchain_light_client::io] [Integritee] Backup light client state to /opt/sidechain/integritee_lcdb/db.bin.backup
[2023-12-12T14:21:42Z TRACE itc_parentchain_light_client::io] [Integritee] Seal light client State. Current state: LightValidationState { relay_state: RelayInfo { last_finalized_block_header_number: 3648578, current_validator_set: [], current_validator_set_id: 0, number of unjustified headers: 0 } }
[2023-12-12T14:21:42Z INFO  integritee_service::parentchain_handler] [Integritee] Synced 3664578 out of 3666546 finalized parentchain blocks

[2023-12-12T14:21:46Z INFO  integritee_service::parentchain_handler] [Integritee] Found 968 block(s) to sync in this chunk
[2023-12-12T14:21:46Z INFO  integritee_service::parentchain_handler] [Integritee] Found 968 event vector(s) to sync in this chunk
[2023-12-12T14:21:47Z INFO  enclave_runtime] Validating events, events_proofs_length: 968, blocks_merkle_roots_lengths: 968
[2023-12-12T14:21:47Z TRACE enclave_runtime] [Integritee] Dispatching Import of 968 blocks and 968 events
[2023-12-12T14:21:47Z DEBUG itc_parentchain_block_importer::block_importer] [Integritee] Import blocks to light-client!
[2023-12-12T14:21:47Z TRACE itc_parentchain_light_client::io] [Integritee] Backup light client state to /opt/sidechain/integritee_lcdb/db.bin.backup
[2023-12-12T14:21:47Z TRACE itc_parentchain_light_client::io] [Integritee] Seal light client State. Current state: LightValidationState { relay_state: RelayInfo { last_finalized_block_header_number: 3648578, current_validator_set: [], current_validator_set_id: 0, number of unjustified headers: 0 } }
[2023-12-12T14:21:47Z ERROR itc_parentchain_block_importer::block_importer] [Integritee] Header submission to light client failed: HeaderAncestryMismatch
[2023-12-12T14:21:47Z ERROR enclave_runtime] Error synching parentchain: ParentchainBlockImportDispatch(BlockImport(LightClient(HeaderAncestryMismatch)))

[2023-12-12T14:21:47Z INFO  integritee_service::parentchain_handler] [Integritee] Synced 3665578 out of 3666546 finalized parentchain blocks
[2023-12-12T14:21:47Z INFO  integritee_service::parentchain_handler] [Integritee] Found 0 block(s) to sync in this chunk
[Integritee] synced block number: #3666546

...

[2023-12-12T14:21:48Z INFO  integritee_service::main_impl] [Integritee] Received finalized header update (3666549), syncing parent chain...
[2023-12-12T14:21:48Z TRACE integritee_service::parentchain_handler] [Integritee] Getting current head
[2023-12-12T14:21:48Z INFO  integritee_service::parentchain_handler] [Integritee] Syncing blocks from 3666546 to 3666549
[2023-12-12T14:21:48Z TRACE enclave_runtime] fetched shard creation header from state: (Integritee, <wasm:stripped>)
[2023-12-12T14:21:48Z TRACE integritee_service::parentchain_handler] shard_creation header is from Integritee: Header { parent_hash: 0x9495fefc91fa763ae362234ec611544512240fba95ad670b8e7cf33dc52e989d, number: 3666546, state_root: 0x77f0aa05aa1fd489a1f1e9cb94dec4138a3e822d102e7d32baa3cd400a20ff2b, extrinsics_root: 0x1eaa8c9ef2508b61f7ea27cdd711bd109ee832095c45cdd1c3d0f70acb4085f0, digest: Digest { logs: [DigestItem::PreRuntime([97, 117, 114, 97], [175, 179, 116, 8, 0, 0, 0, 0]), DigestItem::Seal([97, 117, 114, 97], [202, 168, 191, 157, 231, 81, 50, 0, 222, 18, 232, 95, 181, 158, 253, 34, 73, 102, 36, 78, 28, 42, 244, 11, 206, 104, 34, 218, 59, 166, 129, 110, 135, 2, 72, 117, 13, 10, 215, 55, 138, 248, 106, 159, 74, 110, 80, 132, 10, 151, 82, 177, 167, 0, 21, 78, 212, 242, 60, 88, 58, 167, 253, 136])] } }
[2023-12-12T14:21:48Z INFO  integritee_service::parentchain_handler] [Integritee] Found 3 block(s) to sync in this chunk
[2023-12-12T14:21:48Z INFO  integritee_service::parentchain_handler] [Integritee] Found 3 event vector(s) to sync in this chunk
[2023-12-12T14:21:48Z WARN  substrate_api_client::rpc::tungstenite_client::client] Expected subscription, but received an id response instead: Object {"id": String("1"), "jsonrpc": String("2.0"), "result": String("ZJmhwqQGAFebxYSx")}
[2023-12-12T14:21:48Z INFO  enclave_runtime] Validating events, events_proofs_length: 3, blocks_merkle_roots_lengths: 3
[2023-12-12T14:21:48Z TRACE enclave_runtime] [Integritee] Dispatching Import of 3 blocks and 3 events
[2023-12-12T14:21:48Z INFO  integritee_service::parentchain_handler] [Integritee] Synced 3666546 out of 3666549 finalized parentchain blocks
[2023-12-12T14:21:48Z INFO  integritee_service::parentchain_handler] [Integritee] Found 0 block(s) to sync in this chunk

the error is ignored and the flow continues.
no block import is attempted from here onwards
no confirmparentchainblock extrinsic is sent to the chain
which probably causes #1525

questions:

• could it happen that some blocks have simply been ignored?

[brenzi]

reproduce:

1. set const BLOCK_SYNC_BATCH_SIZE: u32 = 10;
2. start worker after >10 blocks

in my case, there was still a light client db from a previous run against the same parentchain. not sure if that matters