I'm suspicious about this line in test_direct_sync():
while self.conductor.spv_node.server.session_manager.notified_height < initial_height + 99: # off by 1
The comment recognizes that it's off by one, but I don't understand why it's there.
If we exit the loop when hub is at block 299, and the initial_headers_sync() runs fast enough to complete before hub updates to block 300, then the assertion fails.
Most of the time, the hub updates to block 300 before initial_headers_sync() finishes. By changing the loop condition, we can make it more likely to fail.
Captured this behavior with test modifications, logging level changes:
--- a/tests/integration/blockchain/test_network.py
+++ b/tests/integration/blockchain/test_network.py
@@ -102,7 +102,7 @@ class ReconnectTests(IntegrationTestCase):
await self.ledger.stop()
initial_height = self.ledger.local_height_including_downloaded_height
await self.blockchain.generate(100)
- while self.conductor.spv_node.server.session_manager.notified_height < initial_height + 99: # off by 1
+ while self.conductor.spv_node.server.session_manager.notified_height < initial_height + 98:
await asyncio.sleep(0.1)
self.assertEqual(initial_height, self.ledger.local_height_including_downloaded_height)
await self.ledger.headers.open()
2022-09-07 06:43:36,510 - hub.service.ElasticSyncService - WARNING - Indexing block 280 done. 0/0 successful
2022-09-07 06:43:36,512 - hub.service.HubServerService - WARNING - received es notification block 280
2022-09-07 06:43:36,512 - hub.service.HubServerService - WARNING - es and reader are in sync at block 280
2022-09-07 06:43:36,663 - hub.service.ElasticSyncService - WARNING - Indexing block 283 done. 0/0 successful
2022-09-07 06:43:36,664 - hub.service.HubServerService - WARNING - received es notification block 283
2022-09-07 06:43:36,664 - hub.service.HubServerService - WARNING - es and reader are in sync at block 283
2022-09-07 06:43:36,885 - hub.service.ElasticSyncService - WARNING - Indexing block 286 done. 0/0 successful
2022-09-07 06:43:36,886 - hub.service.HubServerService - WARNING - received es notification block 286
2022-09-07 06:43:36,886 - hub.service.HubServerService - WARNING - es and reader are in sync at block 286
2022-09-07 06:43:37,010 - hub.service.ElasticSyncService - WARNING - Indexing block 288 done. 0/0 successful
2022-09-07 06:43:37,010 - hub.service.HubServerService - WARNING - received es notification block 288
2022-09-07 06:43:37,011 - hub.service.HubServerService - WARNING - es and reader are in sync at block 288
2022-09-07 06:43:37,171 - hub.service.ElasticSyncService - WARNING - Indexing block 291 done. 0/0 successful
2022-09-07 06:43:37,172 - hub.service.HubServerService - WARNING - received es notification block 291
2022-09-07 06:43:37,172 - hub.service.HubServerService - WARNING - es and reader are in sync at block 291
2022-09-07 06:43:37,310 - hub.service.ElasticSyncService - WARNING - Indexing block 294 done. 0/0 successful
2022-09-07 06:43:37,311 - hub.service.HubServerService - WARNING - received es notification block 294
2022-09-07 06:43:37,311 - hub.service.HubServerService - WARNING - es and reader are in sync at block 294
2022-09-07 06:43:37,455 - hub.service.ElasticSyncService - WARNING - Indexing block 297 done. 0/0 successful
2022-09-07 06:43:37,456 - hub.service.HubServerService - WARNING - received es notification block 297
2022-09-07 06:43:37,456 - hub.service.HubServerService - WARNING - es and reader are in sync at block 297
2022-09-07 06:43:37,620 - hub.service.ElasticSyncService - WARNING - Indexing block 299 done. 0/0 successful
2022-09-07 06:43:37,620 - hub.service.HubServerService - WARNING - received es notification block 299
2022-09-07 06:43:37,621 - hub.service.HubServerService - WARNING - es and reader are in sync at block 299
/opt/homebrew/Cellar/python@3.9/3.9.13_2/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/events.py:80: DeprecationWarning: The explicit passing of coroutine objects to asyncio.wait() is deprecated since Python 3.8, and scheduled for removal in Python 3.11.
self._context.run(self._callback, *self._args)
2022-09-07 06:43:37,757 - hub.service.ElasticSyncService - WARNING - Indexing block 300 done. 0/0 successful
FAIL
======================================================================
FAIL: test_direct_sync (tests.integration.blockchain.test_network.ReconnectTests)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/Users/swdev1/lbry-sdk/lbry/testcase.py", line 145, in run
self.loop.run_until_complete(maybe_coroutine)
File "/opt/homebrew/Cellar/python@3.9/3.9.13_2/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/base_events.py", line 647, in run_until_complete
return future.result()
File "/Users/swdev1/lbry-sdk/tests/integration/blockchain/test_network.py", line 112, in test_direct_sync
self.assertEqual(initial_height + 100, self.ledger.local_height_including_downloaded_height)
AssertionError: 300 != 299
----------------------------------------------------------------------
Ran 1 test in 34.198s
FAILED (failures=1)
I'm suspicious about this line in
test_direct_sync()
:while self.conductor.spv_node.server.session_manager.notified_height < initial_height + 99: # off by 1
The comment recognizes that it's off by one, but I don't understand why it's there.
If we exit the loop when hub is at block 299, and the
initial_headers_sync()
runs fast enough to complete before hub updates to block 300, then the assertion fails.Most of the time, the hub updates to block 300 before
initial_headers_sync()
finishes. By changing the loop condition, we can make it more likely to fail.Captured this behavior with test modifications, logging level changes: