Increase timeout in feature_assumevalid.py

[kostyantyn]

On my machine, MacBook Pro 2.8 GHz Intel Core i7 120 sec is not enough to process 2202 blocks. Here are logs of that step:

2019-05-03T13:38:40.194000Z TestFramework (INFO): Send all blocks to node1. All blocks will be accepted.
2019-05-03T13:44:56.843000Z TestFramework (INFO): Send blocks to node2. Block 102 will be rejected.

Bitcoin already increased this timeout to 200 secs https://github.com/dtr-org/unit-e/blob/master/test/functional/feature_assumevalid.py#L246 but I suggest to increase it even more to accommodate slower machines like mine :)

Signed-off-by: Kostiantyn Stepaniuk kostia@thirdhash.com

[AM5800]

I quickly profiled that part of test

I am not making any conclusions yet =)

[kostyantyn]

@cmihai re-run without the debug and it took 1min49sec to pass that step. But as it's quite close to that limit we have on the master, would recommend to still increment the timeout.

2019-05-03T15:04:49.983000Z TestFramework (INFO): Initializing test directory /var/folders/r9/s635cnq5265dp3bgh1kcw7b40000gn/T/testt8qyr2v_
2019-05-03T15:04:49.983000Z TestFramework (INFO): Debug file at /var/folders/r9/s635cnq5265dp3bgh1kcw7b40000gn/T/testt8qyr2v_/node0/regtest/debug.log
Starting node 0 with args:
Starting node 1 with args:
Starting node 2 with args:
2019-05-03T15:04:55.571000Z TestFramework (INFO): Create the first block with a coinbase output to our key
2019-05-03T15:04:55.581000Z TestFramework (INFO): Bury the block 100 deep so the coinbase output is spendable
2019-05-03T15:04:55.940000Z TestFramework (INFO): Create a transaction spending the coinbase output with an invalid (null) signature
2019-05-03T15:04:55.945000Z TestFramework (INFO): Bury the assumed valid block 2100 deep
2019-05-03T15:05:04.687000Z TestFramework (INFO): Start node1 and node2 with assumevalid so they accept a block with a bad signature.
2019-05-03T15:05:06.017000Z TestFramework (INFO): Send blocks to node0. Block 103 will be rejected.
2019-05-03T15:05:11.406000Z TestFramework (INFO): Send all blocks to node1. All blocks will be accepted.
2019-05-03T15:07:00.094000Z TestFramework (INFO): Send blocks to node2. Block 102 will be rejected.
2019-05-03T15:07:03.034000Z TestFramework.mininode (WARNING): Connection lost to 127.0.0.1:15992 due to [Errno 32] Broken pipe
2019-05-03T15:07:03.370000Z TestFramework (INFO): Stopping nodes
2019-05-03T15:07:04.257000Z TestFramework (INFO): Cleaning up /var/folders/r9/s635cnq5265dp3bgh1kcw7b40000gn/T/testt8qyr2v_ on exit
2019-05-03T15:07:04.258000Z TestFramework (INFO): Tests successful

[kostyantyn]

@AM5800 if you are curious about the snapshot, it's not used but you see the function ProcessSnapshotParentBlock because it wraps all the blocks we process.

I managed to significantly reduce the execution time by disabling finalization. See logs:

2019-05-03T15:15:57.656000Z TestFramework (INFO): Initializing test directory /var/folders/r9/s635cnq5265dp3bgh1kcw7b40000gn/T/test8_0heh93
2019-05-03T15:15:57.656000Z TestFramework (INFO): Debug file at /var/folders/r9/s635cnq5265dp3bgh1kcw7b40000gn/T/test8_0heh93/node0/regtest/debug.log
Starting node 0 with args: -esperanzaconfig={"epochLength": 99999}
Starting node 1 with args: -esperanzaconfig={"epochLength": 99999}
Starting node 2 with args: -esperanzaconfig={"epochLength": 99999}
2019-05-03T15:16:02.273000Z TestFramework (INFO): Create the first block with a coinbase output to our key
2019-05-03T15:16:02.283000Z TestFramework (INFO): Bury the block 100 deep so the coinbase output is spendable
2019-05-03T15:16:02.773000Z TestFramework (INFO): Create a transaction spending the coinbase output with an invalid (null) signature
2019-05-03T15:16:02.779000Z TestFramework (INFO): Bury the assumed valid block 2100 deep
2019-05-03T15:16:12.425000Z TestFramework (INFO): Start node1 and node2 with assumevalid so they accept a block with a bad signature.
2019-05-03T15:16:13.728000Z TestFramework (INFO): Send blocks to node0. Block 103 will be rejected.
2019-05-03T15:16:17.880000Z TestFramework (INFO): Send all blocks to node1. All blocks will be accepted.
2019-05-03T15:16:32.386000Z TestFramework (INFO): Send blocks to node2. Block 102 will be rejected.
2019-05-03T15:16:32.625000Z TestFramework.mininode (WARNING): Connection lost to 127.0.0.1:11913 due to [Errno 32] Broken pipe
2019-05-03T15:16:32.940000Z TestFramework (INFO): Stopping nodes
2019-05-03T15:16:33.846000Z TestFramework (INFO): Cleaning up /var/folders/r9/s635cnq5265dp3bgh1kcw7b40000gn/T/test8_0heh93 on exit
2019-05-03T15:16:33.846000Z TestFramework (INFO): Tests successful

Should we go with this approach?

[scravy]

This:

2019-05-03T15:05:11.406000Z TestFramework (INFO): Send all blocks to node1. All blocks will be accepted.
2019-05-03T15:07:00.094000Z TestFramework (INFO): Send blocks to node2. Block 102 will be rejected.

2019-05-03T15:16:17.880000Z TestFramework (INFO): Send all blocks to node1. All blocks will be accepted.
2019-05-03T15:16:32.386000Z TestFramework (INFO): Send blocks to node2. Block 102 will be rejected.

~2 minutes vs 15 seconds is pretty impressive.

Should we go with this approach?

I think we have in general performance problems with finalization right now, also when syncing test net etc. These should be fixed. It's nice that this test unearths it. Maybe as an interim solution we can disable it, but in general it should be made more efficient.

[scravy]

If we can reduce the runtime of the test, as we can do apparently, then I think we should do this instead of evermore increasing this timeout.

[kostyantyn]

Closing this PR in favor of the https://github.com/dtr-org/unit-e/pull/1061