Jormungandr: The Node stops creating blocks (BFT and Genesis)

[dorin100]

Describe the bug
After 15 mins (tens of transactions), the Node stops creating blocks (BFT and Genesis)

To Reproduce
Even simpler:

1. start node
2. create 1 transaction and wait 15 mins while blocks are created
3. after 15 mins, blocks are no longer created

Steps to reproduce the behavior:

1. generate files using bootstrap script: bash bootstrap -p 8607 -b | tee initialValues.txt
2. start node: jormungandr --genesis-block ./block-0.bin --config ./config.yaml --secret ./pool-secret1.yaml
3. run attached script (one-transaction-per-slot.sh) - after some time, the node stops creating new blocks; In this state, no new transactions are accepted and the script will fail;

Expected behavior
Especially because we are in BFT mode, as long as the node is ON, the leader should create blocks.

Additional context
Machine used: Win10
I ran the script in Genesis mode too and the behavior was the same (there still was stake in the system - on Faucet account)

As @rinor observed, if you don't make any transaction, the blocks will continue to be created even after 15 mins.

Attached:

• print screen -
  

• node logs (logger: verbosity: 4) -
  nodeLogs.txt

• storage file -
  blocks.sqlite.txt

• one-transaction-per-slot.sh script -
  one-transaction-per-slot.sh.txt

[DavidArayan]

Hey guys, just as a side note i've also noticed that blocks stop getting created if the bootstrap port is somehow blocked/not exposed in docker. It may be unrelated to this issue but thought i'd mention it. The terminal does not warn when this happens.

[Proxiweb]

My node has this bug too. Installed with nix on ubuntu 18.10. I start my node with this command :

nix-shell -A shell https://github.com/input-output-hk/jormungandr-nix/archive/68168ddb54de32a52b2aeb61f2810cdc84cfc375.tar.gz --arg faucetAmounts "[ 1000000000 2000000000 3000000000 4000000000 5000000000 6000000000 7000000000 8000000000 9000000000 ]" --arg numberOfStakePools 9 --arg slot_duration 5 --argstr logger_output gelf --argstr storage "/tmp/jormungandr-storage-nix-9nodes-5" --run run-jormungandr

After some epochs with successfull transactions, it stops without error message.

[rinor]

os: Linux 4.19.0-5-amd64 #1 SMP Debian 4.19.37-5 (2019-06-19) x86_64 GNU/Linux
rustc --version: rustc 1.35.0 (3c235d560 2019-05-20)
node build from: cd1d36fa8ce11f662f11f30d81a9154c4c085c47

I made several tests (5 till now to be exact) with block0_consensus: bft (default bootstrap config) in the following scenario:

• Start the node
• Wait for 1 or 2 blocks to be added
• Send at least 1 transaction (you can send more, like _1 x slot,_ but the behaviour remains the same)
• _15 minutes_ after the Node start time (not the transaction sent time), the node stops producing blocks.

Jul 01 15:03:50.793 INFO starting, sub_task: End Of Epoch Reminder, task: leadership
...
...
---> the block that included the transaction
Jul 01 15:05:26.008 INFO Leader scheduled event, scheduled_at_date: 0.282, scheduled at_time: SystemTime { tv_sec: 1561993526, tv_nsec: 0 }, sub_task: Leader Task, task: leadership
Jul 01 15:05:26.110 INFO block added successfully to Node's blockchain, date: 0.282, id: 6077d51b408fe1c2174638e987d5cdd0df60610362ffb2443535acffd49ebc1e, task: block
...
...
Jul 01 15:18:46.037 INFO Leader scheduled event, scheduled_at_date: 0.362, scheduled at_time: SystemTime { tv_sec: 1561994326, tv_nsec: 0 }, sub_task: Leader Task, task: leadership
Jul 01 15:18:46.112 INFO block added successfully to Node's blockchain, date: 0.362, id: 494aa9b79fdaa78d52adba40375aa8e6c8e03819fc1ca05a615e503ab265a17b, task: block
Jul 01 15:18:56.050 INFO Leader scheduled event, scheduled_at_date: 0.363, scheduled at_time: SystemTime { tv_sec: 1561994336, tv_nsec: 0 }, sub_task: Leader Task, task: leadership
---> no more blocks

- fragment_id: 627b9016a23dda65f60f1c92a46d8775da55250d6954728a1a78ca7b5e0afd8c
  last_updated_at: "2019-07-01T15:05:26.014979092+00:00"
  received_at: "2019-07-01T15:05:17.929865771+00:00"
  received_from: Rest
  status:
    InABlock:
      date: "0.282"

The behaviour was _exactly the same_ in all the tests I made.

If you do not send any transaction, the Node always continues to produce blocks even after _15 minutes_

I have more test scenarios to do, but i thought this may help the devs

[dorin100]

I confirm the issue described by @rinor above (using a win10 machine).

[psychomb]

If it is of any consolation, I also confirm @rinor issue on MacOSX :)

[dkijania]

I'm trying to reproduce it with automation test. Will post results soon

[bitbox1138]

Yes my node crashed also, after a few distributions from the faucet. UBUNTU 18.04 on VirtualBox

[bitbox1138]

I have a snapshot of the state. Where do I find the correct log file? /var/log? Thanks in advance for any help or log file info available

[Proxiweb]

Any news on that bug ?

[HM999]

So this baby is still going. Is it hard to recreate? because it was happening for me each time, although that was a few releases ago.

[vincenthz]

I think this bug is not relevant anymore, likely fixed as side effect of various cleanup and fixing other related issues; if this is happening on latest version, as usual please open a new issue with the relevant information (log and what has happened before)

[dorin100]

@vincenthz - this bug is still reproducible. The node stops creating blocks after 15 mins so can you please reopen it as it already has a lot of logs from different users inside it?

[Proxiweb]

@vincenthz This bug still occurs in v0.3.1.

[oldcryptogeek]

I think this bug is not relevant anymore, likely fixed as side effect of various cleanup and fixing other related issues; if this is happening on latest version, as usual please open a new issue with the relevant information (log and what has happened before)

Why was the issue closed? What led you to determine the problem was solved?

[vincenthz]

It was closed due to perceived oldness at the time. Whilst the now more accurate version is that it's the symptom of another bug that we've been tracking since last week.

[rinor]

@vincenthz - is there any way we can help gathering more information, ex: by providing freshly tested case scenarios and their output, or you already have all that kind of information?

[vincenthz]

not at the moment @rinor. Thanks for the offer though, much appreciated !

[rinor]

Some more info that may help. Based on my tests the issue is caused by MemPool/Logs garbage collector.
https://github.com/input-output-hk/jormungandr/blob/d239f842b15a322e5186372ba847e9268f15a41a/jormungandr/src/main.rs#L128-L129
Block production stops based on that timing. In local test I change that value to smth like 3600 secods (1 hour) which gives a decent time to test before crashing.

[NicolasDP]

Everyone gives @rinor a big virtual hug. The link in his last comment lead me to find the real issue. Fix is in #703 .

[dorin100]

@NicolasDP - bad news :( , the issue is still reproducing so I propose to reopen this issue in order to keep all the history in one place. The only different things are:

1. the node is creating logs now (even no blocks are created after 15 mins)
2. the node log does not include the blockId anymore

Actual results:
The node logs continue to increment, but after exactly 15 mins, no new blocks are created anymore (the tip remains the same and transactions are no longer created).

Start time: Aug 19 15:34:07
Time when no new blocks are created: Aug 19 15:49:01

Steps to reproduce:

1. use this repo/branch - https://github.com/dorin100/jormungandr/tree/no_blocks/scripts
2. go to \jormungandr-dorin\scripts folder and generate the files using: bash bootstrap -b
3. start the node using: jormungandr --genesis-block ./block-0.bin --config ./config.yaml --secret ./pool-secret1.yaml
4. execute the one-transaction-per-slot-1-account.sh script (creates 1 transaction per slot and waits for the tip to be updated for each slot): bash one-transaction-per-slot-1-account.sh 1000

scriptLogs.txt
nodeLogs.txt

[rinor]

@dorin100 tested before or after https://github.com/input-output-hk/jormungandr/issues/705 ?

[NicolasDP]

@dorin100 , add the git revision

[dorin100]

@rinor - I just saw #705 and the commit for it. I am giving it 1 more try after this commit/pr and will update here.

[NicolasDP]

if you want to see more logs, try --log-level=trace we have reduced the logging verbosity of debug to not display non dev thing

[dorin100]

@NicolasDP - still reproducible even after #705

git revision: 9151595a7ce92a1edbcc62fc437fc318f90962b0

scriptLogs.txt
nodeLogsTraceDebug.txt

[rinor]

@dorin100 can you make sure that you are using the correct binary actually compiled/installed from that revision.
I tested for about 90 minutes using your script from https://github.com/dorin100/jormungandr/tree/no_blocks, in different OS and different configs (debug, release, inmemory,....) and can not replicate.

[NicolasDP]

Same for me so far. your script is at transaction No 252 and still running

[dorin100]

Ok. I got the latest master again (there were some more commits) and now the issue is not reproducible neither on my machine.

Git revision: 17634fc83e578f29ab25ac78c65bbfeb60b67c05

It seems I was too eager to see this working and I needed to wait a little more for all the fixes :). Good job guys!