Sidechain does not send extrinsics to parachain

[ziming-zung]

Reproduce the issue

tee-worker base on this commit: https://github.com/litentry/tee-worker/tree/8ef02571b29a01c1a806c97c0513efab4a2c04cf
parachain base on this commit: https://github.com/litentry/litentry-parachain/tree/a7d1c942bc591382ccfc89533fe9439f2ea635e8

1. Launch parachain and worker

2. Execute script:

#!/usr/bin/env bash

root_dir=$(git rev-parse --show-toplevel)

CLIENT_BIN="$root_dir/bin/integritee-cli"

#NODE PORT
node_port=9912
node_url=ws://integritee-node

worker_url=wss://tee-builder
worker_port=2000

CLIENT="./integritee-cli --node-url ${node_url} --node-port ${node_port} --worker-url ${worker_url} --trusted-worker-port  ${worker_port}"
cd ${root_dir}/bin

./integritee-service mrenclave | tee ~/mrenclave.b58
MRENCLAVE=$(cat ~/mrenclave.b58)

echo "query-credit: https test"
${CLIENT} trusted --mrenclave ${MRENCLAVE} query-credit "//Alice"
echo ""

Log

There are some logs when tee-worker is running:

Synced 9 out of 9 finalized parentchain blocks
[+] Found 0 block(s) to sync
[2022-09-01T03:25:48Z WARN  integritee_service::ocall_bridge::worker_on_chain_ocall] send call..."0xa102840054d1f38ed4ceb09f507422c1ff77038cf82bfd5954e5358f549882d49c241e2200455f3bcfae79fbb4b32cff1dc4a784a841e13e0eacc1d003354ad72aa7cfa050261d04c1f80f5e7ec68edb640ee0a5160a67fa0f66623ae3a0726a696cbab20c005c005a038cd961b207d89da4db36db7e7bb1612184e2d23d5ff1f67d03260798d62e3a0b0000000000000000000000000000000000000000000000000000000000000000"
[2022-09-01T03:25:48Z DEBUG ita_stf::stf_sgx] No storage updates needed...
[2022-09-01T03:25:48Z DEBUG ita_stf::stf_sgx] query_credit([d4, 35, 93, c7, 15, fd, d3, 1c, 61, 14, 1a, bd, 4, a9, 9f, d6, 82, 2c, 85, 58, 85, 4c, cd, e3, 9a, 56, 84, e7, a5, 6d, a2, 7d]
[2022-09-01T03:25:48Z INFO  ita_stf::stf_sgx_litentry] query_credit([d4, 35, 93, c7, 15, fd, d3, 1c, 61, 14, 1a, bd, 4, a9, 9f, d6, 82, 2c, 85, 58, 85, 4c, cd, e3, 9a, 56, 84, e7, a5, 6d, a2, 7d])
[2022-09-01T03:25:48Z INFO  ita_stf::stf_sgx_litentry] send https request, get result as Ok(())
[2022-09-01T03:25:48Z DEBUG ita_stf::helpers] incrementing account nonce
[2022-09-01T03:25:48Z DEBUG ita_stf::helpers] updated account d43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d nonce: 1
[2022-09-01T03:25:48Z WARN  integritee_service::ocall_bridge::worker_on_chain_ocall] send call..."0xc103840054d1f38ed4ceb09f507422c1ff77038cf82bfd5954e5358f549882d49c241e2200c112b07bda8c6c62bdd6acbc621046b380c1ad2a0f034ca691f6b11a0dc6b0a6545035e8b6d01446441a1ac77edd1d1851458aefcb22dc6e6d0c58690a91450d0060005b00aaa9446b3227ac55765fbf3aa7f874916d70a0a9550f3eba642eaa5d68180a5d405683528160661c59404a48b924601ccff9c6376ce3aca29f66b2204b62cde00f00000000000000aaa9446b3227ac55765fbf3aa7f874916d70a0a9550f3eba642eaa5d68180a5d14ee2e820d754b7c9a24626ff0680162358151c3fbdc613a24b1af543529aab7"
[2022-09-01T03:25:48Z WARN  itc_https_client_daemon::https_client] https get result as ( ResponseBody { origin: "103.135.102.19", url: "https://httpbin.org/anything" },)
[2022-09-01T03:25:48Z WARN  itc_https_client_daemon::https_client] ready to send to parentchain
[2022-09-01T03:25:48Z WARN  integritee_service::ocall_bridge::worker_on_chain_ocall] send call..."0x3902840054d1f38ed4ceb09f507422c1ff77038cf82bfd5954e5358f549882d49c241e2200b463411d2ef0d207004266629e0aa8e2b96ab3daad1e72eeefa5ad626b86c82e6593ef1d19422788f75bf8622a6aa09beb9fcf20b4c6691152ea6d8876e7c30c0064004000000000000000d43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d"
[2022-09-01T03:25:48Z ERROR ws::handler] WS Error <Custom(Extrinsic("extrinsic error code 1002: Verification Error: Runtime error: Execution failed: Execution aborted due to trap: wasm trap: wasm `unreachable` instruction executed\nWASM backtrace:\n\n    0: 0x35b912 - <unknown>!rust_begin_unwind\n    1: 0x3e96 - <unknown>!core::panicking::panic_fmt::ha53e328e2bd8426b\n    2: 0xb736e - <unknown>!TaggedTransactionQueue_validate_transaction\n: RuntimeApi(\"Execution failed: Execution aborted due to trap: wasm trap: wasm `unreachable` instruction executed\\nWASM backtrace:\\n\\n    0: 0x35b912 - <unknown>!rust_begin_unwind\\n    1: 0x3e96 - <unknown>!core::panicking::panic_fmt::ha53e328e2bd8426b\\n    2: 0xb736e - <unknown>!TaggedTransactionQueue_validate_transaction\\n\")"))>
[2022-09-01T03:25:54Z WARN  integritee_service::ocall_bridge::worker_on_chain_ocall] send call..."0xc103840054d1f38ed4ceb09f507422c1ff77038cf82bfd5954e5358f549882d49c241e2200acb04e82f11f6b69d0e221e7ec50dde5328e020eaeb9200f8026f103efef9de34a18edc45cdea9e5fd2ea88bdd8ffc92cd1677183f41e43d9d5957e6112a72060068005b00aaa9446b3227ac55765fbf3aa7f874916d70a0a9550f3eba642eaa5d68180a5d55b189364fb4565334ccbe91e25450c56489f3d3f6754099264d5f42a2846d0b1000000000000000aaa9446b3227ac55765fbf3aa7f874916d70a0a9550f3eba642eaa5d68180a5df8cf349f98840f855f4e1a1612bf7e1e172db4759a3d6b905798e4450cdb9ee6"
[+] Received finalized header update (10), syncing parent chain...
[+] Found 1 block(s) to sync
Synced 10 out of 10 finalized parentchain blocks
[+] Found 0 block(s) to sync
[2022-09-01T03:26:00Z WARN  integritee_service::ocall_bridge::worker_on_chain_ocall] send call..."0xa102840054d1f38ed4ceb09f507422c1ff77038cf82bfd5954e5358f549882d49c241e2200555b69024a8e4a82521cd34b61920cd7c6242a4050de6dfae11b6261673652225b9dca3785bcf90f31cd2d7f41481cfd9244257713569050b0ec5251e5c5260d006c005a031f76150ebe7b84bcaff0286669d2c912069c127093d7a75bbbc8243147eb6a400000000000000000000000000000000000000000000000000000000000000000"
[2022-09-01T03:26:00Z WARN  integritee_service::ocall_bridge::worker_on_chain_ocall] send call..."0xc103840054d1f38ed4ceb09f507422c1ff77038cf82bfd5954e5358f549882d49c241e22003f6630c2a456f296151466df3d78b4246fcde8bcd60e74592f0f2a3f5f33c009d58f6aa34f57101f8fed09d0ee407f9c0e85061eba5a513879da6fba22f48a0b0070005b00aaa9446b3227ac55765fbf3aa7f874916d70a0a9550f3eba642eaa5d68180a5d7e9be8cad0f4ff422b85e62ac6be6ef03413fa44f5d646c1b32dcb3649c029311100000000000000aaa9446b3227ac55765fbf3aa7f874916d70a0a9550f3eba642eaa5d68180a5da8430c4dc81825fb786e943af8093e2a7ddef3ba877e2e51dbc446091a90d535"
[2022-09-01T03:26:06Z WARN  integritee_service::ocall_bridge::worker_on_chain_ocall] send call..."0xc103840054d1f38ed4ceb09f507422c1ff77038cf82bfd5954e5358f549882d49c241e2200ef4ba546cef01a5264e0232d693a0c97144be07c1f6bcc53b397209c4b578987a52771c9b6bc6fa9ac0308227ceee0bf889bcb3e9d28f380dfc0a87512ccaa040074005b00aaa9446b3227ac55765fbf3aa7f874916d70a0a9550f3eba642eaa5d68180a5d4ab6dd872f713c8d66c6dea4feacccb03148a2cbe694856623fab7336d74c2581200000000000000aaa9446b3227ac55765fbf3aa7f874916d70a0a9550f3eba642eaa5d68180a5d23e55614b8b300707b8fcd6eddcabddfc9f3feb62ac454c28929758f0dcee186"
[+] Received finalized header update (11), syncing parent chain...
[+] Found 1 block(s) to sync
Synced 11 out of 11 finalized parentchain blocks
[+] Found 0 block(s) to sync
[2022-09-01T03:26:12Z WARN  integritee_service::ocall_bridge::worker_on_chain_ocall] send call..."0xa102840054d1f38ed4ceb09f507422c1ff77038cf82bfd5954e5358f549882d49c241e2200fd7cc0496ae0a92754de48fb8657629ca9ebc76bf215557ad4bf1ceca66522a2a6b2e051d6e8d45664559ef970886922c52ce64a83b875fdde6882d7fa0450040078005a03dc524282061b646592efc3965620b46cf31a668b77ee77e51a4718730343fc380000000000000000000000000000000000000000000000000000000000000000"
[2022-09-01T03:26:12Z WARN  integritee_service::ocall_bridge::worker_on_chain_ocall] send call..."0xc103840054d1f38ed4ceb09f507422c1ff77038cf82bfd5954e5358f549882d49c241e22001adf33e419f2a01a2dc86b257e4c88ff72bb0f7b5e330605dcd0e65e6f510beb92934149a8fee352cb42adb1041a35860e868ed7f3c11d5fd66ccb75744d610f007c005b00aaa9446b3227ac55765fbf3aa7f874916d70a0a9550f3eba642eaa5d68180a5d9efaed2c94f509c5ccf5a1a1a91d6c4605cf128f64124493ff24bbad39c22c231300000000000000aaa9446b3227ac55765fbf3aa7f874916d70a0a9550f3eba642eaa5d68180a5d5c6767b167a150bd690a425438874b0a521b7aef91cdb02fb8ced562bb87852a"
[2022-09-01T03:26:18Z WARN  integritee_service::ocall_bridge::worker_on_chain_ocall] send call..."0xc103840054d1f38ed4ceb09f507422c1ff77038cf82bfd5954e5358f549882d49c241e2200b68043d95bbc951da0e672d572446b92f2e7ff05f7ea02fded136f7970800f5b96c85458cb8a9547b36616471f13715ae6550e18eb9fbea670deaa1967e3fb070080005b00aaa9446b3227ac55765fbf3aa7f874916d70a0a9550f3eba642eaa5d68180a5d7416a72ebe8ea9a2d95d30799fed2797c99162b6f8f569b460f683602744f5a91400000000000000aaa9446b3227ac55765fbf3aa7f874916d70a0a9550f3eba642eaa5d68180a5d8390372318123dbe4666374f8105119ebb78f870128165d95e2f942639db3969"
[+] Received finalized header update (12), syncing parent chain...
[+] Found 1 block(s) to sync
Synced 12 out of 12 finalized parentchain blocks

After sending the error extrinsics to parachain, we can see that there are error logs. The related log:

[2022-09-01T03:25:48Z WARN  integritee_service::ocall_bridge::worker_on_chain_ocall] send call..."0x3902840054d1f38ed4ceb09f507422c1ff77038cf82bfd5954e5358f549882d49c241e2200b463411d2ef0d207004266629e0aa8e2b96ab3daad1e72eeefa5ad626b86c82e6593ef1d19422788f75bf8622a6aa09beb9fcf20b4c6691152ea6d8876e7c30c0064004000000000000000d43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d"
[2022-09-01T03:25:48Z ERROR ws::handler] WS Error <Custom(Extrinsic("extrinsic error code 1002: Verification Error: Runtime error: Execution failed: Execution aborted due to trap: wasm trap: wasm `unreachable` instruction executed\nWASM backtrace:\n\n    0: 0x35b912 - <unknown>!rust_begin_unwind\n    1: 0x3e96 - <unknown>!core::panicking::panic_fmt::ha53e328e2bd8426b\n    2: 0xb736e - <unknown>!TaggedTransactionQueue_validate_transaction\n: RuntimeApi(\"Execution failed: Execution aborted due to trap: wasm trap: wasm `unreachable` instruction executed\\nWASM backtrace:\\n\\n    0: 0x35b912 - <unknown>!rust_begin_unwind\\n    1: 0x3e96 - <unknown>!core::panicking::panic_fmt::ha53e328e2bd8426b\\n    2: 0xb736e - <unknown>!TaggedTransactionQueue_validate_transaction\\n\")"))>

Also we can find that sending extrinsic failed and worker try to send new extrinsic to parachain, but we can't see the ProposedSidechainBlock event on fronend.

we can decode the call on frontend. like: https://polkadot.js.org/apps/?rpc=ws://127.0.0.1:9944#/extrinsics/decode

[Kailai-Wang]

Seems that it doesn't matter if you use direct ocall_api (EnclaveOnChainOCallApi::send_to_parentchain) or use extrinsic_callbacks, once one extrinsic fails, the parentchain can't process sidechain extrinsics anymore:

[Kailai-Wang]

upstream bug tracking issue: integritee-network/worker#1027

[Kailai-Wang]

According to upstream, this one is solved.

Can you confirm it? @zhizming-zhong

[jingleizhang]

cc @zhizming-zhong

[ziming-zung]

Another related issue: integritee-network/worker#970

[ziming-zung]

Maybe we can get pending noce(via RPC) at this function(don't get nonce from cache):

https://github.com/litentry/litentry-parachain/blob/25bf6e0e8137209a0cc1c60cc2c89729ddc83fc6/tee-worker/core-primitives/extrinsics-factory/src/lib.rs#L106-L107.

The nonce error is getting more and more, so it should be fixed as soon as possible and I think this solution should be the easiest.

Let's find a better solution later.

[ziming-zung]

#> Maybe we can get pending noce(via RPC) at this function(don't get nonce from cache):

https://github.com/litentry/litentry-parachain/blob/25bf6e0e8137209a0cc1c60cc2c89729ddc83fc6/tee-worker/core-primitives/extrinsics-factory/src/lib.rs#L106-L107

.
The nonce error is getting more and more, so it should be fixed as soon as possible and I think this solution should be the easiest.

Let's find a better solution later.

One more thing

This solution should not be able to completely solve this BUG. Beacuse the pending nonce returned from RPC is not guaranteed to be 100% correct.

We need to design a mechanism to adjust nonce.

We might check the extrinsic(system_dryRun) before sending to parentchain. Once there is a future nonce error, we should decode the opaque extrinsic and get the call parameters, and then use a new nonce to construct a new extrinsic.

Some relevant code:

• Send extrinsic to parentchain:
  https://github.com/litentry/litentry-parachain/blob/25bf6e0e8137209a0cc1c60cc2c89729ddc83fc6/tee-worker/core/parentchain/light-client/src/light_validation.rs#L267-L275
  In this function ,we can call system_dryRun to check before caching the extrinsic(submit_xt_to_be_included). If occur an error, we can decode and construct a new extrinsic.

• Demonstration how to decode opaque extrinsic:
  https://github.com/litentry/litentry-parachain/blob/25bf6e0e8137209a0cc1c60cc2c89729ddc83fc6/tee-worker/core/parentchain/indirect-calls-executor/src/lib.rs#L232-L233

• Demonstration how to construct extrinsic with nonce
  https://github.com/litentry/litentry-parachain/blob/25bf6e0e8137209a0cc1c60cc2c89729ddc83fc6/tee-worker/core-primitives/extrinsics-factory/src/lib.rs#L120-L139

[ziming-zung]

It is hard to decode the opaque extrinsic if we don't know the call type.
We have 2 options:

• re-introduce my-node-runtime and use the RuntimeCall as call type. like: https://paritytech.github.io/substrate/master/kitchensink_runtime/enum.RuntimeCall.html

• retrieve RuntimeCall from metadata and use scale_value to decode. see:
  https://docs.rs/scale-value/latest/scale_value/scale/fn.decode_as_type.html

[Kailai-Wang]

We'll first implement a simple workaround (try to forcibly reset the nonce when sending parentchain extrinsics fail) and see what we get.

The dryRun way is not considered right now because:

• it's intrinsically complicated
• it can be performance costly
• it still needs adjustment of nonce with on-chain interactions (which brings in several risks - same as the simple workaround: synchronisation, dropping of extrinsics, potential duplicated nonces..)