Jormungandr: Mined transactions are not propagated to other nodes - RC5, local cluster with 2 nodes

[dorin100]

Describe the bug
Mined transactions are not propagated to other nodes.

Mandatory Information

jcli 0.7.0-rc5 (HEAD-d4ac194b, release, windows [x86_64]) - [rustc 1.39.0 (4560ea788 2019-11-04)]
jormungandr 0.7.0-rc5 (HEAD-d4ac194b, release, windows [x86_64]) - [rustc 1.39.0 (4560ea788 2019-11-04)]

To Reproduce
Steps to reproduce the behavior:

1. Start node1 --> jormungandr ---genesis-block block-0.bin --config node_config.yaml --secret node_secret.yaml
2. wait for node1 to create some blocks
3. Start node2 --> jormungandr ---config node_config.yaml --genesis-block-hash 55dedb3c348adb8b7ff3ef1a9ae3a114c8609f338c42d5c44ee806cd290a85c8
4. Send some funds from faucet to a new account --> bash send-money.sh ca1sku4yc68q9cuwlsg296l6yrk6ccth2pzqu26r4s5r8enymyfeyptgl5vxk4 28000000000000 9001 ed25519e_sk18r7nd20gaxjfgmahyqu2vngv98leqefcdcft2nevcakpf999spx55t4ph8ryqslp6ac7uryekjcqsqzl63rjpmh0k92dvquesweq38cc8a0wc
5. Wait for 1 new block to be created

• on node1 (9001 - stake pool):

$ jcli rest v0 account get ca1sku4yc68q9cuwlsg296l6yrk6ccth2pzqu26r4s5r8enymyfeyptgl5vxk4 --host "http://127.0.0.1:9001/api"
---
counter: 0
delegation:
  pools: []
value: 28000000000000

$ jcli rest v0 message logs --host "http://127.0.0.1:9001/api"
---
- fragment_id: 4dafd8a161052003376babc518971443f124de240a7ade5a92817d1e74103ab2
  last_updated_at: "2019-11-08T08:54:10.005584+00:00"
  received_at: "2019-11-08T08:54:08.286583300+00:00"
  received_from: Rest
  status:
    InABlock:
      block: 1f498921bfb2656773d708897763797dcd46dd06e457fe14a2d0df6b996a0a5a
      date: "5504.25"



md5-4bfababebae418464582ceaf6d1c7094



$ jcli rest v0 network stats  get --host "http://127.0.0.1:9001/api"
---
- establishedAt: "2019-11-08T08:52:56.200634400+00:00"
  lastBlockReceived: ~
  lastFragmentReceived: "2019-11-08T08:54:08.286583300+00:00"
  lastGossipReceived: "2019-11-08T09:04:06.199587500+00:00"
  nodeId: 1e9fa055813c1d4e7a98cc2673e2c342d713fc0e32fa446e



md5-5098265e0be1a985433f4a934c471dc5



$ jcli rest v0 account get ca1sku4yc68q9cuwlsg296l6yrk6ccth2pzqu26r4s5r8enymyfeyptgl5vxk4 --host "http://127.0.0.1:9002/api"
failed to make a REST request
  |-> node rejected request because of invalid parameters
  |-> http://127.0.0.1:9002/api/v0/account/b95263470171c77e085175fd1076d630bba8220715a1d61419f3326c89c902b4: Client Error: 404 Not Found



md5-4bfababebae418464582ceaf6d1c7094



$ jcli rest v0 message logs --host "http://127.0.0.1:9002/api"
---
- fragment_id: 4dafd8a161052003376babc518971443f124de240a7ade5a92817d1e74103ab2
  last_updated_at: "2019-11-08T08:54:08.286583300+00:00"
  received_at: "2019-11-08T08:54:08.286583300+00:00"
  received_from: Network
  status: Pending



md5-4bfababebae418464582ceaf6d1c7094



$ jcli rest v0 node stats get --host "http://127.0.0.1:9002/api"
---
blockRecvCnt: 318
lastBlockDate: "5503.38"
lastBlockFees: 0
lastBlockHash: f17e0ef8c1b2121af05eae0960bac2b012df94c69f1d8b92438dff767e02fdb0
lastBlockHeight: "15"
lastBlockSum: 0
lastBlockTime: "2019-11-08T09:03:48+00:00"
lastBlockTx: 0
state: Running
txRecvCnt: 1
uptime: 652



md5-4bfababebae418464582ceaf6d1c7094



$ jcli rest v0 network stats  get --host "http://127.0.0.1:9002/api"
---
- establishedAt: "2019-11-08T08:52:56.198634900+00:00"
  lastBlockReceived: "2019-11-08T09:04:12.009542300+00:00"
  lastFragmentReceived: "2019-11-08T08:54:08.286583300+00:00"
  lastGossipReceived: "2019-11-08T09:04:07.085547200+00:00"
  nodeId: 155e591d631ebf6fa8625442f194039809b4ac5b23534e16

Expected behavior
Both blocks have knowledge about mined transactions.

Additional context

• OS: win 10
• scenario description: local cluster with 2 nodes - 1 faucet + stake pool (port 9001), 1 passive (port 9002)
• node1 files
  node1_logs.txt
  node1.zip

• node2 files
  node2_logs.txt
  node2.zip

• send-money.sh script for transactions:
  send-money.zip

[NicolasDP]

So you receive the block announcements but your node never actually _"update current branch tip"_.

EDIT: the connection below logs are normal

also your node 1 is rejecting your node 2:

Nov 08 10:52:56.163 INFO incoming connection on 127.0.0.1:3001, peer_addr: 127.0.0.1:57890, task: network Nov 08 10:52:56.168 INFO incoming connection closed, peer_addr: 127.0.0.1:57890, task: network Nov 08 10:52:56.173 INFO incoming connection on 127.0.0.1:3001, peer_addr: 127.0.0.1:57891, task: network Nov 08 10:52:56.196 INFO incoming connection closed, peer_addr: 127.0.0.1:57891, task: network Nov 08 10:52:56.200 INFO incoming connection on 127.0.0.1:3001, peer_addr: 127.0.0.1:57892, task: network

@mzabaluev what do you make of this?

[dorin100]

still node2 is receiving block announcements + blocks

Nov 08 11:24:36.008 INFO received block announcement, hash: fac9e62c1bcdff277bd8d92225d4453196bae7a8daa25832f264e6165974de82, node_id: 155e591d631ebf6fa8625442f194039809b4ac5b23534e16, peer_addr: 127.0.0.1:3001, task: network
Nov 08 11:24:38.009 INFO received block announcement, hash: 1bc290fb414f1a798ce9a4dd9444ce863680c8fe2ca05412fd3836d57c2ec71a, node_id: 155e591d631ebf6fa8625442f194039809b4ac5b23534e16, peer_addr: 127.0.0.1:3001, task: network

• node2 seems to receive even the transaction (txRecvCnt)

$ jcli rest v0 node stats get --host "http://127.0.0.1:9002/api"
---
blockRecvCnt: 318
lastBlockDate: "5503.38"
lastBlockFees: 0
lastBlockHash: f17e0ef8c1b2121af05eae0960bac2b012df94c69f1d8b92438dff767e02fdb0
lastBlockHeight: "15"
lastBlockSum: 0
lastBlockTime: "2019-11-08T09:03:48+00:00"
lastBlockTx: 0
state: Running
txRecvCnt: 1
uptime: 652

[NicolasDP]

yes, this is something else. could you run with debug log level?

[dorin100]

• here the logs with debug
  node2_logs.txt
  node1_logs.txt

• I also deleted the storage between runs

[GaborPeto]

So you receive the block announcements but your node never actually "update current branch tip".

This is also what I see on my node on both rc4 and rc5

[NicolasDP]

could you try with with master? there are logs improvements that would really help (since #1092 )

[dorin100]

• here are the debug logs with the latest master - new warnings can be seen on node2
  node1_logs.txt
  node2_logs.txt

Nov 08 13:51:30.196 DEBG block is missing a locally stored parent, caching as candidate, date: 5610.23, parent: 590bf1f1d283b03e369f74f18b9866958274c8670e7050a69541cced1e6f8acb, hash: 3a89b067943f487efec511d8df90a5ab0692a24f997db0e1fce4fa898976b4c2, task: block
Nov 08 13:51:30.201 INFO error processing request, reason: Received block 3a89b067943f487efec511d8df90a5ab0692a24f997db0e1fce4fa898976b4c2 is not known from previously received headers, node_id: 155e591d631ebf6fa8625442f194039809b4ac5b23534e16, peer_addr: 127.0.0.1:3001, task: network
Nov 08 13:51:30.209 WARN network block validation failed: Error { code: Internal, source: Error { code: Internal, cause: "Received block 3a89b067943f487efec511d8df90a5ab0692a24f997db0e1fce4fa898976b4c2 is not known from previously received headers" } }, node_id: 155e591d631ebf6fa8625442f194039809b4ac5b23534e16, peer_addr: 127.0.0.1:3001, task: network

[NicolasDP]

This is fixed with rc7 I believe.