Cannot add second collator to parachain (Collation failure: timeout)

[JoshOrndorff]

Following the instructions in the readme (along with the workaround described in #25). I'm able to start a collator and register it with the relay chain.

I then try to start a second collator by running the same command with a different data directory. The first collator continues to work as well as it ever did (see #26). But the second collator is not able to collate. It give the log message Collation failure: timeout.

Full logs:

$ ./target/release/cumulus-test-parachain-collator --base-path /tmp/p1c2 --chain=../polkadot/polkadot_chainspec.json --bootnodes /ip4/127.0.0.1/tcp/30333/p2p/QmbQMG8VWKumRyXg47UixQiosUMP2nWRsmWRojqDqJTG9t --ws-port 9966
2019-11-29 12:58:18 Cumulus Test Parachain Collator
2019-11-29 12:58:18   version 0.1.0-x86_64-linux-gnu
2019-11-29 12:58:18   by Parity Technologies <[email protected]>, 2019
2019-11-29 12:58:18 Chain specification: Local Testnet
2019-11-29 12:58:18 Node name: intelligent-balls-4461
2019-11-29 12:58:18 Roles: FULL
2019-11-29 12:58:18 Parachain id: Id(0)
2019-11-29 12:58:18 Initializing Genesis block/state (state: 0x80d8…a364, header-hash: 0x6a09…b372)
2019-11-29 12:58:18 Highest known block at #0
2019-11-29 12:58:18 Using default protocol ID "sup" because none is configured in the chain specs
2019-11-29 12:58:18 Local node identity is: QmaqWJguAo8RbVpqoVxrSEEdGdki9pwZfpH8DUB6tWxzGD
2019-11-29 12:58:19 Not registering Substrate logger, as there is already a global logger registered!
2019-11-29 12:58:19 Cumulus Test Parachain Collator
2019-11-29 12:58:19   version 0.1.0-x86_64-linux-gnu
2019-11-29 12:58:19   by Parity Technologies <[email protected]>, 2017-2019
2019-11-29 12:58:19 Chain specification: Local Testnet
2019-11-29 12:58:19 Node name: entertaining-cord-8336
2019-11-29 12:58:19 Roles: FULL
2019-11-29 12:58:20 Initializing Genesis block/state (state: 0x09d4…4b97, header-hash: 0x680f…0321)
2019-11-29 12:58:20 Loading GRANDPA authority set from genesis on what appears to be first startup.
2019-11-29 12:58:20 Loaded block-time = BabeConfiguration { slot_duration: 6000, epoch_length: 2400, c: (1, 4), genesis_authorities: [(Public(8eaf04151687736326c9fea17e25fc5287613693c912909cb226aa4794f26a48 (5FHneW46...)), 1), (Public(d43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d (5GrwvaEF...)), 1)], randomness: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0], secondary_slots: true } seconds from genesis on first-launch
2019-11-29 12:58:20 Creating empty BABE epoch changes on what appears to be first startup.
2019-11-29 12:58:20 Highest known block at #0
2019-11-29 12:58:20 Local node identity is: QmQPawAffS3Ta1z7dHG6DzBCcW16p9UySF6JAamFLemwq6
2019-11-29 12:58:20 Can't listen on /ip4/0.0.0.0/tcp/30333 because: Other(Custom { kind: Other, error: Other(A(A(A(B(Underlying(B(Os { code: 98, kind: AddrInUse, message: "Address already in use" }))))))) })
2019-11-29 12:58:21 Unable to bind server to 127.0.0.1:9966. Trying random port.
2019-11-29 12:58:21 New epoch 0 launching at block 0xb5f4…5022 (block slot 262507676 >= start slot 262507676).
2019-11-29 12:58:21 Next epoch starts at slot 262510076
2019-11-29 12:58:24 Imported #707 (0xa728…d6bb)
2019-11-29 12:58:24 Starting consensus session on top of parent 0xec571ca6ed84a69f305de6cabc233e7daa362ec911c313a04d187b4c206dbf88
2019-11-29 12:58:24 Proposing failed: UnknownBlock("Hash(0xec571ca6ed84a69f305de6cabc233e7daa362ec911c313a04d187b4c206dbf88)")
2019-11-29 12:58:24 Collation failure: timeout
2019-11-29 12:58:26 Idle (1 peers), best: #707 (0xa728…d6bb), finalized #706 (0xe451…44be), ⬇ 111.5kiB/s ⬆ 0.9kiB/s
2019-11-29 12:58:30 Imported #708 (0x0532…9907)
2019-11-29 12:58:30 Starting consensus session on top of parent 0xec571ca6ed84a69f305de6cabc233e7daa362ec911c313a04d187b4c206dbf88
2019-11-29 12:58:30 Proposing failed: UnknownBlock("Hash(0xec571ca6ed84a69f305de6cabc233e7daa362ec911c313a04d187b4c206dbf88)")
2019-11-29 12:58:30 Collation failure: timeout
2019-11-29 12:58:31 Idle (1 peers), best: #708 (0x0532…9907), finalized #706 (0xe451…44be), ⬇ 0.4kiB/s ⬆ 0.3kiB/s
2019-11-29 12:58:36 Idle (1 peers), best: #708 (0x0532…9907), finalized #707 (0xa728…d6bb), ⬇ 0.9kiB/s ⬆ 0.4kiB/s
2019-11-29 12:58:36 Imported #709 (0x9ff5…9317)
2019-11-29 12:58:36 Starting consensus session on top of parent 0x3253a5215fafb8fcabadf6aa27bd7394ef8744b831ab38ea275bb648fcbbaeb3
2019-11-29 12:58:36 Proposing failed: UnknownBlock("Hash(0x3253a5215fafb8fcabadf6aa27bd7394ef8744b831ab38ea275bb648fcbbaeb3)")
2019-11-29 12:58:36 Collation failure: timeout
2019-11-29 12:58:36 Imported #709 (0xa319…5e13)
2019-11-29 12:58:36 Starting consensus session on top of parent 0xec571ca6ed84a69f305de6cabc233e7daa362ec911c313a04d187b4c206dbf88
2019-11-29 12:58:36 Proposing failed: UnknownBlock("Hash(0xec571ca6ed84a69f305de6cabc233e7daa362ec911c313a04d187b4c206dbf88)")
2019-11-29 12:58:36 Collation failure: timeout
2019-11-29 12:58:41 Idle (1 peers), best: #709 (0x9ff5…9317), finalized #708 (0x0532…9907), ⬇ 1.2kiB/s ⬆ 0.5kiB/s
2019-11-29 12:58:42 Imported #710 (0x0c33…5335)
2019-11-29 12:58:42 Starting consensus session on top of parent 0x3253a5215fafb8fcabadf6aa27bd7394ef8744b831ab38ea275bb648fcbbaeb3
2019-11-29 12:58:42 Proposing failed: UnknownBlock("Hash(0x3253a5215fafb8fcabadf6aa27bd7394ef8744b831ab38ea275bb648fcbbaeb3)")
2019-11-29 12:58:42 Collation failure: timeout
2019-11-29 12:58:46 Idle (1 peers), best: #710 (0x0c33…5335), finalized #709 (0x9ff5…9317), ⬇ 1.0kiB/s ⬆ 0.4kiB/s
2019-11-29 12:58:48 Imported #711 (0x8d75…c160)
2019-11-29 12:58:48 Starting consensus session on top of parent 0x744f4f97067d635274a57984d1f2396a954b859865511b03b522ef8de1705d65
2019-11-29 12:58:48 Proposing failed: UnknownBlock("Hash(0x744f4f97067d635274a57984d1f2396a954b859865511b03b522ef8de1705d65)")
2019-11-29 12:58:48 Collation failure: timeout
2019-11-29 12:58:51 Idle (1 peers), best: #711 (0x8d75…c160), finalized #710 (0x0c33…5335), ⬇ 0.8kiB/s ⬆ 0.1kiB/s
2019-11-29 12:58:54 Imported #712 (0x7ae3…3abf)
2019-11-29 12:58:54 Starting consensus session on top of parent 0x744f4f97067d635274a57984d1f2396a954b859865511b03b522ef8de1705d65
2019-11-29 12:58:54 Proposing failed: UnknownBlock("Hash(0x744f4f97067d635274a57984d1f2396a954b859865511b03b522ef8de1705d65)")
2019-11-29 12:58:54 Collation failure: timeout

[JoshOrndorff]

I began to suspect that the second collator was not syncing the previous parachain blocks because it only had a single peer (a relay chain node). I decided to add the first collator as a bootnode and then realized that the collator actually gives two node identities (probably related to #19).

Adding both identities of the first collator plus the relay chain node for a total of three bootnodes, does cause the second colaltor to intermittently gain a second peer, but does not start it collating.

[JoshOrndorff]

At @bkchr 's suggestion (in a private chat) I removed this line https://github.com/paritytech/cumulus/blob/master/test/parachain/src/cli.rs#L86 and tried again manually specifying to first collator as a bootnode.

Now the collators can peer together and sync the parachain blocks. Thus they can both author parachain blocks.