Remove sources of unreliablility in extended functional tests

jnewbery commented at 8:28 pm on March 24, 2017: member

This PR removes two sources of unreliability that were causing extended test cases to fail intermittently on travis:

bip9-softforks stop-starts bitcoind twice, but does not wait for the p2p connection to mininode to re-open. This would lead to race conditions where the following call to getblocktemplate() would sometimes fail because there were no p2p connections open to the node. This commit also removes the shutil.rmtree() call that was blatting the test_framework.log file.
forknotify asserts that an alert has been written to a file and fails immediately if the file is empty. This would lead to race conditions where the assert would sometimes be hit before bitcoind had written to the file.

fanquake added the label Tests on Mar 25, 2017

jnewbery force-pushed on Mar 25, 2017

in test/functional/bip9-softforks.py:210 in baeecbbb08 outdated

211-        self.test.clear_all_connections()
212         self.test.add_all_connections(self.nodes)
213-        NetworkThread().start() # Start up network handling in another thread
214-
215+        NetworkThread().start()
216+        self.test.test_nodes[0].wait_for_verack()

JeremyRubin commented at 5:43 pm on March 28, 2017:

Do we want the same behavior on L44?

jnewbery commented at 6:48 pm on March 28, 2017:

wait_for_verack() is called by the comparison test framework at the start of the test run (comptest.py line 300).

in test/functional/bip9-softforks.py:209 in baeecbbb08 outdated

210-        self.test.block_store = BlockStore(self.options.tmpdir)
211-        self.test.clear_all_connections()
212         self.test.add_all_connections(self.nodes)
213-        NetworkThread().start() # Start up network handling in another thread
214-
215+        NetworkThread().start()

JeremyRubin commented at 5:44 pm on March 28, 2017:

Is there any work we can do in-between this and the wait for verack?

Maybe have a comment here about having to wait for verack rather than just deleting the comment.

jnewbery commented at 6:46 pm on March 28, 2017:

No, we need to wait for the network thread to start before receiving the verack (the network thread is what catches the verack and calls the callback).

in test/functional/bip9-softforks.py:205 in baeecbbb08 outdated

199@@ -200,16 +200,14 @@ def test_BIP(self, bipName, activated_version, invalidate, invalidatePostSignatu
200         yield TestInstance([[block, False]])
201 
202         # Restart all
203-        self.test.block_store.close()
204+        self.test.clear_all_connections()
205         stop_nodes(self.nodes)
206-        shutil.rmtree(self.options.tmpdir)
207+        shutil.rmtree(self.options.tmpdir + "/node0")

JeremyRubin commented at 5:44 pm on March 28, 2017:

Is there a more idiomatic way to get the dirname?

jnewbery commented at 6:45 pm on March 28, 2017:

Not that I know of.

I don’t like the fact that this test is using shutil and removing files itself. This change just makes it slightly less damaging (ie it’s only removing the datadir rather than the entire tmpdir)

in test/functional/forknotify.py:53 in baeecbbb08 outdated

52+            if len(alert_text) > 0:
53+                break
54 
55-        if len(alert_text) == 0:
56-            raise AssertionError("-alertnotify did not warn of up-version blocks")
57+            assert timeout > 0, "-alertnotify did not warn of up-version blocks"

JeremyRubin commented at 5:46 pm on March 28, 2017:

Maybe raise the error yourself rather than assert, unless you only want it in debug mode?

jnewbery commented at 6:53 pm on March 28, 2017:

I don’t think there’s any difference. No-one runs the test cases with -O

JeremyRubin commented at 8:02 pm on March 28, 2017:

using asserts as control flow is generally an antipattern (I think that the for/else loop is a bit clearer in any case).

jnewbery commented at 8:11 pm on March 28, 2017:

ah. I see what you’re saying now. Yes, I’ll remove the assert from the control flow.

in test/functional/forknotify.py:47 in baeecbbb08 outdated

41@@ -41,11 +42,17 @@ def run_test(self):
42         self.nodes[1].generate(1)
43         self.sync_all()
44 
45-        with open(self.alert_filename, 'r', encoding='utf8') as f:
46-            alert_text = f.read()
47+        # Give bitcoind 10 seconds to write the alert notification
48+        timeout = 10
49+        while True:

JeremyRubin commented at 6:04 pm on March 28, 2017:

Maybe a bit cleaner to do something like (a couple of changes, feel free to pick and choose – I was torn on the os.path.exists+getsize v.s. continual reading with open).

0        for t in xrange(100):
1            if os.path.exists(self.alert_filename) and os.path.getsize(self.alert_filename):
2                break
3            if t != 99: time.sleep(0.1) 
4        else:
5            raise AssertionError("-alertnotify did not warn of up-version blocks")
6        with open(self.alert_filename, 'r', encoding='utf8') as f:
7            alert_text = f.read()

jnewbery commented at 6:51 pm on March 28, 2017:

I think this is equivalent.

JeremyRubin commented at 7:57 pm on March 28, 2017:

yeah; mostly this was motivated by being able to get rid of the stateful timeout = 10; assert timeout > 0; timeout -= 0.1 combo. This is also fine.

0        for t in xrange(100):
1            with open(self.alert_filename, 'r', encoding='utf8') as f:
2                alert_text = f.read()
3            if alert_text:
4                break
5            time.sleep(0.1) 
6        else:
7            raise AssertionError("-alertnotify did not warn of up-version blocks")

in test/functional/forknotify.py:46 in baeecbbb08 outdated

41@@ -41,11 +42,17 @@ def run_test(self):
42         self.nodes[1].generate(1)
43         self.sync_all()
44 
45-        with open(self.alert_filename, 'r', encoding='utf8') as f:
46-            alert_text = f.read()
47+        # Give bitcoind 10 seconds to write the alert notification
48+        timeout = 10

JeremyRubin commented at 6:07 pm on March 28, 2017:

This should rarely actually take 10 seconds, if the code is correct, right? Maybe 1 second will be a bit better in the case where it is actually broken & you’re trying to fix it.

jnewbery commented at 6:49 pm on March 28, 2017:

Depends. Travis catches a lot of timing edge cases. I don’t think there’s any problem making the timeout something high like 10 seconds since the while loop will break as soon as the file is written.

JeremyRubin approved

JeremyRubin commented at 6:09 pm on March 28, 2017: contributor

utack! A couple suggestions but nothing major.

Wait for connection to open in bip9-softforks.py

bip9-sofforks.py stop-starts the bitcoind node twice during the test
run, but it doesn't wait for the connection from mininode to open before
continuing with the test. This leads to race conditions where the test
can fail getblocktemplate() because it has no p2p connections.

1f3d78b4e0

Make forknotify.py more robust

forknotify would intermittently fail because the alert file was not
being written fast enough. This commit adds a timeout so the test does
not fail immediately.

a4fd89fddb

jnewbery force-pushed on Mar 28, 2017

jnewbery commented at 8:23 pm on March 28, 2017: member

Pushed a new version using while/else and not using assert for control flow.

MarcoFalke commented at 10:51 am on April 2, 2017: member

utACK a4fd89f. Going to merge this, so that the failures are a thing of the past.

in test/functional/forknotify.py:54 in a4fd89fddb

49+            if os.path.exists(self.alert_filename) and os.path.getsize(self.alert_filename):
50+                break
51+            time.sleep(0.1)
52+            timeout -= 0.1
53+        else:
54+            assert False, "-alertnotify did not warn of up-version blocks"

MarcoFalke commented at 10:53 am on April 2, 2017:

@jnewbery nit: Any reason you changed the raise AssertionError to assert False?

jnewbery commented at 1:12 pm on April 2, 2017:

No good reason. Equivalent behaviour but you’re probably right that raise AssertionError is better style here.

MarcoFalke merged this on Apr 2, 2017

MarcoFalke closed this on Apr 2, 2017

MarcoFalke referenced this in commit 12af74b289 on Apr 2, 2017

jnewbery commented at 7:53 pm on April 2, 2017: member

🎉 first successful daily run of extended tests on Travis: https://travis-ci.org/bitcoin/bitcoin/builds/217786785

Thanks for merging @MarcoFalke

PastaPastaPasta referenced this in commit 8113a72283 on May 10, 2019

PastaPastaPasta referenced this in commit 5286026b71 on May 15, 2019

PastaPastaPasta referenced this in commit 9fa51cc667 on May 20, 2019

PastaPastaPasta referenced this in commit dc91b44a76 on May 21, 2019

barrystyle referenced this in commit df4f399602 on Jan 22, 2020

DrahtBot locked this on Sep 8, 2021

Remove sources of unreliablility in extended functional tests #10072