Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Parachain not producing any block: expected 0 to be at least 10 #182

Closed
AuroraLantean opened this issue May 4, 2022 · 12 comments · Fixed by #188
Closed

Parachain not producing any block: expected 0 to be at least 10 #182

AuroraLantean opened this issue May 4, 2022 · 12 comments · Fixed by #188

Comments

@AuroraLantean
Copy link

AuroraLantean commented May 4, 2022 •
edited
Loading

I was following your guide https://paritytech.github.io/zombienet/docs/book/test-dsl-definition-spec.html#available-assertions
I copied this line below from that Available Assertions and pasted it into 0001-small-network.feature file
alice: parachain 100 block height is at least 10 within 250 seconds

Then I ran the test:
./zombienet-linux -p kubernetes test zombienet/0001-small-network.feature

Then the output:

    ✔ alice: is up (162ms)
    ✔ bob: is up (93ms)
2022-05-04 16:31:17        API/INIT: RPC methods not decorated: beefy_getFinalizedHead, state_trieMigrationStatus
    ✔ alice: parachain 100 is registered within 225 seconds (3026ms)

	 Error:  
		 createType(Header):: decodeU8a: failed at 0xf10d89ba1e7bce… on extrinsicsRoot: H256:: Expected at least 32 bytes (256 bits), found 7 bytes

    1) alice: parachain 100 block height is at least 10 within 250 seconds
    ✔ alice: reports node_roles is 4
    ✔ alice: reports sub_libp2p_is_major_syncing is 0
    ✔ alice: reports histogram polkadot_pvf_execution_time has at least 2 samples in buckets ["0.1", "0.25", "0.5", "+Inf"] within 100 seconds (57673ms)
    ✔ bob: log line matches glob "*rted #1*" within 10 seconds (93ms)
    ✔ bob: log line matches "Imported #[0-9]+" within 10 seconds (5387ms)
2022-05-04 16:32:24        API/INIT: RPC methods not decorated: beefy_getFinalizedHead, state_trieMigrationStatus
    ✔ bob: system event contains "A candidate was included" within 20 seconds (5463ms)
2022-05-04 16:32:30        API/INIT: RPC methods not decorated: beefy_getFinalizedHead, state_trieMigrationStatus
    ✔ alice: system event matches glob "*was backed*" within 10 seconds (6004ms)

	 Node's logs are available in /tmp/zombie-565dcdb9f5d009de77be982a45df2e00_-184760-mHpt5Q0PMcI9/logs

	 Deleting network
child process exited


  10 passing (4m)
  1 failing

  1) small network( Small Network test )
       alice: parachain 100 block height is at least 10 within 250 seconds:

      AssertionError: expected 0 to be at least 10
      + expected - actual

      -0
      +10
      
      at /snapshot/zombienet/dist/test-runner/index.js:265:37
      at Generator.next (<anonymous>)
      at fulfilled (/snapshot/zombienet/dist/test-runner/index.js:24:58)
      at processTicksAndRejections (node:internal/process/task_queues:96:5)

It seems the parachain is not producing any block!???
What is this error below?

createType(Header):: decodeU8a: failed at 0xf10d89ba1e7bce… on extrinsicsRoot: H256:: Expected at least 32 bytes (256 bits), found 7 bytes

How can I solve this? What is wrong? please advise. Thank you
@AuroraLantean AuroraLantean changed the title expected 0 to be at least 10 Parachain not producing any block: expected 0 to be at least 10 May 4, 2022
@pepoviola
Copy link
Collaborator

Hi @AuroraLantean, thanks for submit this issue and your feedback. In this case the error:

createType(Header):: decodeU8a: failed at 0xf10d89ba1e7bce… on extrinsicsRoot: H256:: Expected at least 32 bytes (256 bits), found 7 bytes

Is from polkadotjs and is because you need to set the needed types to decoding the response.

You need to add this types to the network spec file (.toml)

[types.Header]
number = "u64"
parent_hash = "Hash"
post_state = "Hash"

So, in your case will be:

[relaychain]
default_image = "docker.io/paritypr/polkadot-debug:master"
default_command = "polkadot"
default_args = [ "-lparachain=debug" ]

chain = "rococo-local"

  [[relaychain.nodes]]
  name = "alice"
  validator = true

  [[relaychain.nodes]]
  name = "bob"
  validator = true

[[parachains]]
id = 100

  [parachains.collator]
  name = "collator01"
  image = "docker.io/paritypr/colander:master"
  command = "adder-collator"

[types.Header]
number = "u64"
parent_hash = "Hash"
post_state = "Hash"

Thanks!

@AuroraLantean
Copy link
Author

Hi @pepoviola , thank you for your quick reply!
Yes, that solves that problem... but now there is a new problem...
This test below is failing now. I tried to increase it from 10 to 20 seconds but it still fails due to timeout:
bob: log line matches glob "*rted #1*" within 20 seconds
Maybe this error is triggered by the [types.Header] ???

	 Error: Timeout(20), "getting log pattern *rted #1* within 20 secs".
    1) bob: log line matches glob "*rted #1*" within 20 seconds

  10 passing (6m)
  1 failing
  1) small network( Small Network test )
       bob: log line matches glob "*rted #1*" within 20 seconds:
     AssertionError: expected false to be truthy
      at /snapshot/zombienet/dist/test-runner/index.js:347:32
      at Generator.next (<anonymous>)
      at fulfilled (/snapshot/zombienet/dist/test-runner/index.js:24:58)

@pepoviola
Copy link
Collaborator

Hi @AuroraLantean,
Thanks for your feedback :) No, the log assertion does not use the polkadotjs. Can you check bob's logs to see if blocks are imported.

Thanks!

@AuroraLantean
Copy link
Author

Hi @pepoviola
where are bob's logs ?
Is that in the terminal output?
Here are the logs from the terminal output:

  small network( Small Network test )
runningNetworkSpecPath undefined
	 Launching network... this can take a while.
{
  name: 'alice',
  key: '2bd806c97f0e00af1a1fc3328fa763a9269723c8db8fac4f93af71db186d6e90',
  accounts: {
    seed: '0x69e9544a1ba5caffdec07037b0d684104d6442248f96f61cd515493e597fe948',
    sr_account: {
      address: '5CcPfttgq883D172JcARf1v2BdEykQqpFogvrdqcbKaVWUyX',
      publicKey: '0x182aa25efd0f85dad4cc341d55d9522f8ccf6b70402d26cbc7bb4a5bab72344d'
    },
    sr_stash: {
      address: '5Cw6KigSnx9aR7zWFxxuNFzAGfKnbYvANt4WqBB74bx1giHS',
      publicKey: '0x266de619e00a10aab81821cf5dbd3b8958252b4149c6b30408d2e0f75f64f706'
    },
    ed_account: {
      address: '5HoqztB6JcXR6rGuhv4AMU1gh8RB61iAi34biCptGkUocxjE',
      publicKey: '0xfe142076c9c73ab3c1de5ef7650b43f76fcc5e0a3e5198927458dce9bd36f9dc'
    },
    ec_account: { publicKey: [Uint8Array] }
  },
  command: 'polkadot',
  commandWithArgs: undefined,
  image: 'docker.io/paritypr/polkadot-debug:master',
  chain: 'rococo-local',
  validator: true,
  args: [ '-lparachain=debug' ],
  env: [
    { name: 'COLORBT_SHOW_HIDDEN', value: '1' },
    { name: 'RUST_BACKTRACE', value: 'FULL' }
  ],
  bootnodes: [],
  telemetryUrl: '',
  telemetry: false,
  prometheus: true,
  overrides: [],
  addToBootnodes: false,
  resources: undefined,
  zombieRole: 'node',
  group: 'alice'
}
{
  name: 'bob',
  key: '81b637d8fcd2c6da6359e6963113a1170de795e4b725b84d1e0b4cfd9ec58ce9',
  accounts: {
    seed: '0xda182bff9a98af593bb2c88b96bb501946d6b93fcf4b3c35a4886d68647eb01e',
    sr_account: {
      address: '5CJJ1CK6hQ8frXbCXZkfj5f22BEoxUJyBiKE7Pu2urUe3nRr',
      publicKey: '0x0a5d23adb3809a96f89dc6ceb6b948863c87c79ec05fe5abc12f215ddb55347e'
    },
    sr_stash: {
      address: '5DPrAxLwbUMUVzdaQMMTAuc86wxcjoTK5ddnfaFUBPGVzAvw',
      publicKey: '0x3ad5e34b225464ff5fb0be92827b102e06b8cfb726d85fd0668250874d468e3a'
    },
    ed_account: {
      address: '5DnkKjNWrcAJxf9g5ufeDxDN13Ds1WY1b6xc4PEe4Uwgm6eH',
      publicKey: '0x4c4cd7ff5c439f9990731f53e8f4703a45995ab73a65ceb7b48ba675b0dbdb02'
    },
    ec_account: { publicKey: [Uint8Array] }
  },
  command: 'polkadot',
  commandWithArgs: undefined,
  image: 'docker.io/paritypr/polkadot-debug:master',
  chain: 'rococo-local',
  validator: true,
  args: [ '-lparachain=debug' ],
  env: [
    { name: 'COLORBT_SHOW_HIDDEN', value: '1' },
    { name: 'RUST_BACKTRACE', value: 'FULL' }
  ],
  bootnodes: [],
  telemetryUrl: '',
  telemetry: false,
  prometheus: true,
  overrides: [],
  addToBootnodes: false,
  resources: undefined,
  zombieRole: 'node',
  group: 'bob'
}

	 Using provider: kubernetes

	 Launching network under namespace: zombie-8f06e7ba48bbee0c4362eb16bad622e7
		 Using temporary directory: /tmp/zombie-8f06e7ba48bbee0c4362eb16bad622e7_-221849-fRVykUIlNVQL

	launching temp pod with image docker.io/paritypr/polkadot-debug:master
		 with command: bash -c polkadot build-spec --chain rococo-local --disable-default-bootnode > /cfg/rococo-local-plain.json && until [ -f /tmp/finished.txt ]; do echo waiting for copy files to finish; sleep 1; done; echo copy files has finished
		temp pod is ready!

		🧹 Starting with a fresh authority set...
			  👤 Added Genesis Authority alice - 5Cw6KigSnx9aR7zWFxxuNFzAGfKnbYvANt4WqBB74bx1giHS
			  👤 Added Genesis Authority bob - 5DPrAxLwbUMUVzdaQMMTAuc86wxcjoTK5ddnfaFUBPGVzAvw

	launching temp-collator pod with image docker.io/paritypr/colander:master
		 with command: bash -c adder-collator export-genesis-state > /cfg/genesis-state && adder-collator export-genesis-wasm > /cfg/genesis-wasm && until [ -f /tmp/finished.txt ]; do echo waiting for copy files to finish; sleep 1; done; echo copy files has finished
		temp-collator pod is ready!

		  ✓ Added Genesis Parachain 100

	launching temp-1 pod with image docker.io/paritypr/polkadot-debug:master
		 with command: bash -c polkadot build-spec --chain /cfg/rococo-local-plain.json --disable-default-bootnode  --raw > /cfg/rococo-local-raw.json && until [ -f /tmp/finished.txt ]; do echo waiting for copy files to finish; sleep 1; done; echo copy files has finished
uploading to fileserver: /tmp/zombie-8f06e7ba48bbee0c4362eb16bad622e7_-221849-fRVykUIlNVQL/rococo-local-plain.json as:72f67c91c2912a0bf72b99de708a2d7256a2f7f7c47889888e7594a622df4344
		temp-1 pod is ready!

		 Chain name: Rococo Local Testnet

		 ⚙ Clear Boot Nodes

	launching alice pod with image docker.io/paritypr/polkadot-debug:master
		 with command: /cfg/zombie-wrapper.sh polkadot --chain /cfg/rococo-local.json --name alice --rpc-cors all --unsafe-rpc-external --rpc-methods unsafe --unsafe-ws-external -lparachain=debug --no-mdns --node-key 2bd806c97f0e00af1a1fc3328fa763a9269723c8db8fac4f93af71db186d6e90 --no-telemetry --prometheus-external --jaeger-agent localhost:6831 --validator --listen-addr /ip4/0.0.0.0/tcp/30333/ws --base-path /data
uploading to fileserver: /tmp/zombie-8f06e7ba48bbee0c4362eb16bad622e7_-221849-fRVykUIlNVQL/rococo-local.json as:ab249e275cc2c73ae93515aacf91f6ba8f2a45ec53bbb91cf0966e741a20d2f7
uploading to fileserver: /tmp/zombie-8f06e7ba48bbee0c4362eb16bad622e7_-221849-fRVykUIlNVQL/zombie-wrapper.sh as:2439e528d10b368ef20eac71742e68ef8d1f752319f984957ad1506e55985857
		alice pod is ready!
	alice running

		 You can follow the logs of the node by running this command: 

			 kubectl logs -f alice

		 ⚙ Added Boot Nodes:  /ip4/172.17.0.7/tcp/30333/ws/p2p/12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm

	launching bob pod with image docker.io/paritypr/polkadot-debug:master
		 with command: /cfg/zombie-wrapper.sh polkadot --chain /cfg/rococo-local.json --name bob --rpc-cors all --unsafe-rpc-external --rpc-methods unsafe --unsafe-ws-external -lparachain=debug --no-mdns --node-key 81b637d8fcd2c6da6359e6963113a1170de795e4b725b84d1e0b4cfd9ec58ce9 --no-telemetry --prometheus-external --jaeger-agent localhost:6831 --validator --bootnodes /ip4/172.17.0.7/tcp/30333/ws/p2p/12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm --listen-addr /ip4/0.0.0.0/tcp/30333/ws --base-path /data
		bob pod is ready!
	bob running

		 You can follow the logs of the node by running this command: 

			 kubectl logs -f bob
	 All relay chain nodes spawned...

	launching collator01 pod with image docker.io/paritypr/colander:master
		 with command: /cfg/zombie-wrapper.sh adder-collator --chain /cfg/rococo-local.json --name collator01 --rpc-cors all --unsafe-rpc-external --rpc-methods unsafe --unsafe-ws-external --no-mdns --node-key 5e123980fad4770d9ab5b7df7bbee8499943822a8555d11995e8203210065342 --no-telemetry --bootnodes /ip4/172.17.0.7/tcp/30333/ws/p2p/12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm --listen-addr /ip4/0.0.0.0/tcp/30333/ws --base-path /data
		collator01 pod is ready!
	collator01 running

		 You can follow the logs of the node by running this command: 

			 kubectl logs -f collator01

	 Warn: Tracing collator service doesn't exist

-----------------------------------------


	 Network launched 🚀🚀

		 In namespace zombie-8f06e7ba48bbee0c4362eb16bad622e7 with kubernetes provider


		 Node name: alice

		 Node direct link: https://polkadot.js.org/apps/?rpc=ws%3A%2F%2F127.0.0.1%3A39489#/explorer

		 Node prometheus link: http://127.0.0.1:44833/metrics

---



		 Node name: bob

		 Node direct link: https://polkadot.js.org/apps/?rpc=ws%3A%2F%2F127.0.0.1%3A41437#/explorer

		 Node prometheus link: http://127.0.0.1:41707/metrics

---




	 Parachain ID: 100


		 Node name: collator01

		 Node direct link: https://polkadot.js.org/apps/?rpc=ws%3A%2F%2F127.0.0.1%3A40561#/explorer

		 Node prometheus link: http://127.0.0.1:34373/metrics

@pepoviola
Copy link
Collaborator

Hi @AuroraLantean, when you run the test command you will see a line like this one (with the actual directory of this ephemeral network)

Node's logs are available in /tmp/zombie-565dcdb9f5d009de77be982a45df2e00_-184760-mHpt5Q0PMcI9/logs

You can see the logs of the node's in this directory.

Thanks!

@AuroraLantean
Copy link
Author

@pepoviola Okay. Thanks. I found them in bob.log:

tokio-runtime-worker substrate: ✨ Imported #1 (0x2b97…3db3) 
tokio-runtime-worker substrate: ✨ Imported #2 (0xc1b4…516f) 
tokio-runtime-worker parachain::approval-voting: Imported new block. block_number=2 block_hash=0xc1b4d436a27ae05fc185ad7affb9dfb2be7990cc665e27a52ccc3ea24f63516f num_candidates=0

So bob's blocks are imported, right? Thanks

@pepoviola
Copy link
Collaborator

@pepoviola Okay. Thanks. I found them in bob.log:

tokio-runtime-worker substrate: ✨ Imported #1 (0x2b97…3db3) 
tokio-runtime-worker substrate: ✨ Imported #2 (0xc1b4…516f) 
tokio-runtime-worker parachain::approval-voting: Imported new block. block_number=2 block_hash=0xc1b4d436a27ae05fc185ad7affb9dfb2be7990cc665e27a52ccc3ea24f63516f num_candidates=0

So bob's blocks are imported, right? Thanks

Yes, bob is imported ok. Can you try with a higher timeout (like 70 secs) ?

Thanks!

@AuroraLantean
Copy link
Author

AuroraLantean commented May 4, 2022 •
edited
Loading

@pepoviola Thank you. Yes, I tried that with 70 but the test still failed...
I think something strange is happening after adding this [types.Header] with this glob pattern matching expression:
bob: log line matches glob "*rted #1*" within 70 seconds
I checked Bob's log:

2022-05-04 14:24:05.338 ... first timestamp!
2022-05-04 14:24:30.065  INFO tokio-runtime-worker substrate: ✨ Imported #1 (0x7ea3…b509)... 15 seconds after the first timestamp!

the above line 2 should be matched by the above glob pattern matching "*rted #1*" in 20 seconds, right?
in all cases, the log pattern matching below always succeeds:
bob: log line matches "Imported #[0-9]+" within 10 seconds
How would you explain why this log pattern match always succeeds but the glob pattern matching always fails?

Actually, I only need to use regex pattern matching "Imported #[0-9]+" to check if the parachain is producing blocks, right?

I don't know what it is but something is not right. please advise.

[types.Header]
number = "u64"
parent_hash = "Hash"
post_state = "Hash"

@pepoviola
Copy link
Collaborator

Hi @AuroraLantean,
I can reproduce the fail and is not because of the change in the network spec, if because of the test are ran in serie, so when you add this line

 alice: parachain 100 block height is at least 10 within 250 seconds:

makes that when the test-runner try to assert this one

bob: log line matches glob "*rted #1*" within 10 seconds

The block import is higher than 1x and will not match until 1xx, and also that why this assertion works always

bob: log line matches "Imported #[0-9]+" within 10 seconds

I hope make sense, but if not please ping me 👍

Thanks!

@AuroraLantean
Copy link
Author

AuroraLantean commented May 5, 2022 •
edited
Loading

Hello @pepoviola Thank you. could you clarify what you meant by "The block import is higher than 1x and will not match until 1xx" ? Did you mean is 1x = 10, 11, 12, etc and 1xx = 100, 101, 102, etc ?

Also I tried this below from the guide, which is slightly different without asterisks, it also failed:
alice: log line matches glob "rted #1" within 10 seconds

I don't think glob match works very well searching text in log files, or it is more complicated to be used...
I will replace glob "*rted #1*" with "Imported #[0-9]+" or "Imported new block.". That way I can avoid using glob match, right?

So this feature file works well

alice: is up
bob: is up
alice: parachain 100 is registered within 225 seconds

# logs
bob: log line matches "Imported new block." within 10 seconds
alice: log line matches "Imported #[0-9]+" within 10 seconds

alice: parachain 100 block height is at least 10 within 250 seconds

Thanks

pepoviola added a commit that referenced this issue May 6, 2022
@pepoviola
fix #182, getLogs full logs before enter in the loop
6ba3aeb
@pepoviola pepoviola mentioned this issue May 6, 2022
Merged
pepoviola added a commit that referenced this issue May 6, 2022
@pepoviola
fix #182, getLogs full logs before enter in the loop (#188)
f013f09
@pepoviola
Copy link
Collaborator

Hi @AuroraLantean,I fix the issue and should works as expected in main.

Thanks!!

@AuroraLantean
Copy link
Author

@pepoviola Okay please close this. Thank you!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

fix #182, getLogs full logs before enter in the loop paritytech/zombienet
2 participants
@pepoviola @AuroraLantean