search

lbryio / lbry-sdk

The LBRY SDK for building decentralized, censorship resistant, monetized, digital content apps.
https://lbry.com
MIT License
7.2k stars 483 forks source link

test_trending intermittent failures due to trending_score (e.g. AssertionError: 5.157053472135866 != 2.2437974397778886) #3653

Closed moodyjon closed 1 year ago

moodyjon commented 1 year ago

I think I've got it captured here with enhanced/customized logging hacked into hub. The issue is that IntegrationTestCase.generate() checks that hub (herald + es_sync) is synchronized, but the expected terminal height is incorrect. Furthermore, herald _es_height is not checked though maybe correcting height is enough.

IntegrationTestCase.generate_and_wait() calculates expected terminal height after calling generate() so blockchain.block_expected is the correct terminal height. 

2022-09-06 09:37:27,597 - hub.service.HubServerService - WARNING - received es notification block 290
2022-09-06 09:37:27,597 - hub.service.HubServerService - WARNING - es and reader are not yet in sync (block 290 vs 288)
2022-09-06 09:37:27,726 - hub.service.ElasticSyncService - WARNING - Indexing block 293 done. 0/0 successful
2022-09-06 09:37:27,726 - hub.service.HubServerService - WARNING - received es notification block 293
2022-09-06 09:37:27,726 - hub.service.HubServerService - WARNING - es and reader are not yet in sync (block 293 vs 291)
2022-09-06 09:37:27,846 - hub.service.ElasticSyncService - WARNING - Indexing block 296 done. 0/0 successful
2022-09-06 09:37:27,846 - hub.service.HubServerService - WARNING - received es notification block 296
2022-09-06 09:37:27,846 - hub.service.HubServerService - WARNING - es and reader are not yet in sync (block 296 vs 294)
2022-09-06 09:37:27,991 - hub.service.ElasticSyncService - WARNING - Indexing block 299 done. 0/0 successful
2022-09-06 09:37:27,991 - hub.service.HubServerService - WARNING - received es notification block 299
2022-09-06 09:37:27,992 - hub.service.HubServerService - WARNING - es and reader are not yet in sync (block 299 vs 297)
2022-09-06 09:37:28,113 - hub.service.ElasticSyncService - WARNING - Indexing block 302 done. 0/0 successful
2022-09-06 09:37:28,114 - hub.service.HubServerService - WARNING - received es notification block 302
2022-09-06 09:37:28,114 - hub.service.HubServerService - WARNING - es and reader are not yet in sync (block 302 vs 300)
2022-09-06 09:37:28,237 - hub.service.ElasticSyncService - WARNING - Indexing block 305 done. 0/0 successful
2022-09-06 09:37:28,238 - hub.service.HubServerService - WARNING - received es notification block 305
2022-09-06 09:37:28,238 - hub.service.HubServerService - WARNING - es and reader are not yet in sync (block 305 vs 303)
2022-09-06 09:37:28,379 - hub.service.ElasticSyncService - WARNING - Indexing block 308 done. 0/0 successful
2022-09-06 09:37:28,379 - hub.service.HubServerService - WARNING - received es notification block 308
2022-09-06 09:37:28,380 - hub.service.HubServerService - WARNING - es and reader are not yet in sync (block 308 vs 306)
claim: 961e7ca9 trending_score: 2.2437974397778886
/Users/swdev1/lbry-sdk/lbry/extras/daemon/componentmanager.py:134: DeprecationWarning: The explicit passing of coroutine objects to asyncio.wait() is deprecated since Python 3.8, and scheduled for removal in Python 3.11.
  await asyncio.wait(needing_stop)
2022-09-06 09:37:28,490 - hub.service.ElasticSyncService - WARNING - claim: 961e7ca9 trending nofication: TrendingNotification(height=309, prev_amount=10000000000, new_amount=100000000000000)
2022-09-06 09:37:28,715 - hub.service.ElasticSyncService - WARNING - Indexing block 309 done. 1/1 successful
FAIL

======================================================================
FAIL: test_trending (tests.integration.takeovers.test_resolve_command.ResolveClaimTakeovers)
----------------------------------------------------------------------
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/takeovers/test_resolve_command.py", line 1535, in test_trending
    self.assertEqual(5.157053472135866, claim1['trending_score'], str(claim1))
AssertionError: 5.157053472135866 != 2.2437974397778886 : {'claim_id': '961e7ca98aec78c40d7ebb9be39a4173c5627649', 'claim_name': 'derp', 'normalized_name': 'derp', 'tx_id': '4a02052b40172c75967c64fbefea1207ec8bc89df37990a1f72de3058abcb9e1', 'tx_num': 209, 'tx_nout': 0, 'amount': 100000000, 'timestamp': 1662475047, 'creation_timestamp': 1662475047, 'height': 207, 'creation_height': 207, 'activation_height': 207, 'expiration_height': 707, 'effective_amount': 100000000, 'support_amount': 0, 'is_controlling': True, 'last_take_over_height': 207, 'short_url': 'derp#9', 'canonical_url': 'derp#9', 'title': '', 'author': '', 'description': '', 'claim_type': 1, 'has_source': True, 'sd_hash': '379fe84f22ad62ddc0080ae60cd9826959f0ca5ea110dd43a47199d04e8653f382e011183122cdd96a30d2514535bd72', 'stream_type': 5, 'media_type': 'application/octet-stream', 'fee_amount': 0, 'fee_currency': None, 'reposted_claim_id': None, 'reposted_claim_type': None, 'channel_id': None, 'public_key_id': None, 'signature': None, 'tags': [], 'languages': ['none'], 'censor_type': 0, 'censoring_channel_id': None, 'claims_in_channel': None, 'reposted_tx_id': None, 'reposted_tx_position': None, 'reposted_height': None, 'channel_tx_id': None, 'channel_tx_position': None, 'channel_height': None, 'release_time': 1662475047, 'trending_score': 2.2437974397778886, 'claim_hash': b'Ivb\xc5sA\x9a\xe3\x9b\xbb~\r\xc4x\xec\x8a\xa9|\x1e\x96', 'reposted_claim_hash': None, 'channel_hash': None, 'txo_hash': b'\xe1\xb9\xbc\x8a\x05\xe3-\xf7\xa1\x90y\xf3\x9d\xc8\x8b\xec\x07\x12\xea\xef\xfbd|\x96u,\x17@+\x05\x02J\x00\x00\x00\x00', 'tx_hash': b'\xe1\xb9\xbc\x8a\x05\xe3-\xf7\xa1\x90y\xf3\x9d\xc8\x8b\xec\x07\x12\xea\xef\xfbd|\x96u,\x17@+\x05\x02J', 'reposted': 0, 'signature_valid': False}

----------------------------------------------------------------------
Ran 1 test in 42.374s
moodyjon commented 1 year ago

This could also explain test_remove_controlling_support &test_delay_takeover_with_update_then_update_to_lower_on_takeover failures, as they use generate(N) a lot.

======================================================================
[480](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:481)
FAIL: test_remove_controlling_support (integration.takeovers.test_resolve_command.ResolveClaimTakeovers)
[481](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:482)
----------------------------------------------------------------------
[482](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:483)
Traceback (most recent call last):
[483](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:484)
  File "/home/runner/work/lbry-sdk/lbry-sdk/lbry/testcase.py", line 145, in run
[484](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:485)
    self.loop.run_until_complete(maybe_coroutine)
[485](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:486)
  File "/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py", line 587, in run_until_complete
[486](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:487)
    return future.result()
[487](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:488)
  File "/home/runner/work/lbry-sdk/lbry-sdk/tests/integration/takeovers/test_resolve_command.py", line 1436, in test_remove_controlling_support
[488](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:489)
    ClaimStateValue(second_claim_id, activation_height=538, active_in_lbrycrd=True)
[489](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:490)
  File "/home/runner/work/lbry-sdk/lbry-sdk/tests/integration/takeovers/test_resolve_command.py", line 719, in assertNameState
[490](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:491)
    await self.assertMatchClaimIsWinning(name, winning_claim_id)
[491](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:492)
  File "/home/runner/work/lbry-sdk/lbry-sdk/tests/integration/takeovers/test_resolve_command.py", line 123, in assertMatchClaimIsWinning
[492](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:493)
    await self.assertMatchClaimsForName(name)
[493](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:494)
  File "/home/runner/work/lbry-sdk/lbry-sdk/tests/integration/takeovers/test_resolve_command.py", line 166, in assertMatchClaimsForName
[494](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:495)
    self.assertMatchESClaim(claim_from_es[0][0], claim)
[495](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:496)
  File "/home/runner/work/lbry-sdk/lbry-sdk/tests/integration/takeovers/test_resolve_command.py", line 32, in assertMatchESClaim
[496](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:497)
    self.assertEqual(claim_from_es['effective_amount'], claim_from_db.effective_amount, f'ES: {str(claim_from_es)} DB: {str(claim_from_db)}')
[497](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:498)
AssertionError: 0 != 10000000 : ES: {'claim_id': 'd867d65bbaa6cd6d5d63aa518263a6ec3c5c47d5', 'claim_name': 'derp', 'normalized_name': 'derp', 'tx_id': '9e0fa7483203cccc80e8c8c6aa41a2add98806876738381a1e8cdef818905e64', 'tx_num': 532, 'tx_nout': 0, 'amount': 10000000, 'timestamp': 1662391077, 'creation_timestamp': 1662391077, 'height': 528, 'creation_height': 528, 'activation_height': 538, 'expiration_height': 1028, 'effective_amount': 0, 'support_amount': 150000000, 'is_controlling': False, 'last_take_over_height': 207, 'short_url': 'derp#d', 'canonical_url': 'derp#d', 'title': '', 'author': '', 'description': '', 'claim_type': 1, 'has_source': True, 'sd_hash': '73b5dc228f81747e73acb4e37916ad361e47fe5cd52f5647b5c9eb480540d9c68ed4af604cc7618edafb0946a0b2b862', 'stream_type': 5, 'media_type': 'application/octet-stream', 'fee_amount': 0, 'fee_currency': None, 'reposted_claim_id': None, 'reposted_claim_type': None, 'channel_id': None, 'public_key_id': None, 'signature': None, 'tags': [], 'languages': ['none'], 'censor_type': 0, 'censoring_channel_id': None, 'claims_in_channel': None, 'reposted_tx_id': None, 'reposted_tx_position': None, 'reposted_height': None, 'channel_tx_id': None, 'channel_tx_position': None, 'channel_height': None, 'release_time': 1662391077, 'trending_score': 1.4694401309623295, 'claim_hash': b'\xd5G\\<\xec\xa6c\x82Q\xaac]m\xcd\xa6\xba[\xd6g\xd8', 'reposted_claim_hash': None, 'channel_hash': None, 'txo_hash': b'd^\x90\x18\xf8\xde\x8c\x1e\x1a88g\x87\x06\x88\xd9\xad\xa2A\xaa\xc6\xc8\xe8\x80\xcc\xcc\x032H\xa7\x0f\x9e\x00\x00\x00\x00', 'tx_hash': b'd^\x90\x18\xf8\xde\x8c\x1e\x1a88g\x87\x06\x88\xd9\xad\xa2A\xaa\xc6\xc8\xe8\x80\xcc\xcc\x032H\xa7\x0f\x9e', 'reposted': 0, 'signature_valid': False} DB: ResolveResult(name='derp', normalized_name='derp', claim_hash=b'\xd8g\xd6[\xba\xa6\xcdm]c\xaaQ\x82c\xa6\xec<\\G\xd5', tx_num=532, position=0, tx_hash=b'd^\x90\x18\xf8\xde\x8c\x1e\x1a88g\x87\x06\x88\xd9\xad\xa2A\xaa\xc6\xc8\xe8\x80\xcc\xcc\x032H\xa7\x0f\x9e', height=528, amount=10000000, short_url='derp#d', is_controlling=False, canonical_url='derp#d', creation_height=528, activation_height=538, expiration_height=1028, effective_amount=10000000, support_amount=150000000, reposted=0, last_takeover_height=207, claims_in_channel=0, channel_hash=None, reposted_claim_hash=None, signature_valid=None, reposted_tx_hash=None, reposted_tx_position=None, reposted_height=None, channel_tx_hash=None, channel_tx_position=None, channel_height=None)
[498](https://github.com/moodyjon/lbry-sdk/runs/8191563422?check_suite_focus=true#step:11:499)
======================================================================
[690](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:691)
FAIL: test_delay_takeover_with_update_then_update_to_lower_on_takeover (integration.takeovers.test_resolve_command.ResolveClaimTakeovers)
[691](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:692)
----------------------------------------------------------------------
[692](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:693)
Traceback (most recent call last):
[693](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:694)
  File "/home/runner/work/lbry-sdk/lbry-sdk/lbry/testcase.py", line 145, in run
[694](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:695)
    self.loop.run_until_complete(maybe_coroutine)
[695](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:696)
  File "/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py", line 587, in run_until_complete
[696](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:697)
    return future.result()
[697](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:698)
  File "/home/runner/work/lbry-sdk/lbry-sdk/tests/integration/takeovers/test_resolve_command.py", line 937, in test_delay_takeover_with_update_then_update_to_lower_on_takeover
[698](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:699)
    ClaimStateValue(third_claim_id, activation_height=560, active_in_lbrycrd=True)
[699](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:700)
  File "/home/runner/work/lbry-sdk/lbry-sdk/tests/integration/takeovers/test_resolve_command.py", line 719, in assertNameState
[700](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:701)
    await self.assertMatchClaimIsWinning(name, winning_claim_id)
[701](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:702)
  File "/home/runner/work/lbry-sdk/lbry-sdk/tests/integration/takeovers/test_resolve_command.py", line 123, in assertMatchClaimIsWinning
[702](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:703)
    await self.assertMatchClaimsForName(name)
[703](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:704)
  File "/home/runner/work/lbry-sdk/lbry-sdk/tests/integration/takeovers/test_resolve_command.py", line 166, in assertMatchClaimsForName
[704](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:705)
    self.assertMatchESClaim(claim_from_es[0][0], claim)
[705](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:706)
  File "/home/runner/work/lbry-sdk/lbry-sdk/tests/integration/takeovers/test_resolve_command.py", line 32, in assertMatchESClaim
[706](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:707)
    self.assertEqual(claim_from_es['effective_amount'], claim_from_db.effective_amount, f'ES: {str(claim_from_es)} DB: {str(claim_from_db)}')
[707](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:708)
AssertionError: 0 != 9000000 : ES: {'claim_id': '8065a618c89715137973964d7a510f0872add0cb', 'claim_name': 'derp', 'normalized_name': 'derp', 'tx_id': '8a65f0f1655963b3758f855bcaf91bb7ac1d01bad705cc361ba58c721462d8ba', 'tx_num': 556, 'tx_nout': 0, 'amount': 9000000, 'timestamp': 1662390563, 'creation_timestamp': 1662390559, 'height': 550, 'creation_height': 529, 'activation_height': 560, 'expiration_height': 1050, 'effective_amount': 0, 'support_amount': 0, 'is_controlling': False, 'last_take_over_height': 207, 'short_url': 'derp#8', 'canonical_url': 'derp#8', 'title': '', 'author': '', 'description': '', 'claim_type': 1, 'has_source': True, 'sd_hash': '7bed9a4e8f588927534e7ac05ca1a4bfe7d003ad7aa17f8b820c5b3aab6607bcf76730299034bc0fd2bd0a7ba6dba126', 'stream_type': 5, 'media_type': 'application/octet-stream', 'fee_amount': 0, 'fee_currency': None, 'reposted_claim_id': None, 'reposted_claim_type': None, 'channel_id': None, 'public_key_id': None, 'signature': None, 'tags': [], 'languages': ['none'], 'censor_type': 0, 'censoring_channel_id': None, 'claims_in_channel': None, 'reposted_tx_id': None, 'reposted_tx_position': None, 'reposted_height': None, 'channel_tx_id': None, 'channel_tx_position': None, 'channel_height': None, 'release_time': 1662390559, 'trending_score': 0.7433045085709724, 'claim_hash': b'\xcb\xd0\xadr\x08\x0fQzM\x96sy\x13\x15\x97\xc8\x18\xa6e\x80', 'reposted_claim_hash': None, 'channel_hash': None, 'txo_hash': b'\xba\xd8b\x14r\x8c\xa5\x1b6\xcc\x05\xd7\xba\x01\x1d\xac\xb7\x1b\xf9\xca[\x85\x8fu\xb3cYe\xf1\xf0e\x8a\x00\x00\x00\x00', 'tx_hash': b'\xba\xd8b\x14r\x8c\xa5\x1b6\xcc\x05\xd7\xba\x01\x1d\xac\xb7\x1b\xf9\xca[\x85\x8fu\xb3cYe\xf1\xf0e\x8a', 'reposted': 0, 'signature_valid': False} DB: ResolveResult(name='derp', normalized_name='derp', claim_hash=b'\x80e\xa6\x18\xc8\x97\x15\x13ys\x96MzQ\x0f\x08r\xad\xd0\xcb', tx_num=556, position=0, tx_hash=b'\xba\xd8b\x14r\x8c\xa5\x1b6\xcc\x05\xd7\xba\x01\x1d\xac\xb7\x1b\xf9\xca[\x85\x8fu\xb3cYe\xf1\xf0e\x8a', height=550, amount=9000000, short_url='derp#8', is_controlling=False, canonical_url='derp#8', creation_height=529, activation_height=560, expiration_height=1050, effective_amount=9000000, support_amount=0, reposted=0, last_takeover_height=207, claims_in_channel=0, channel_hash=None, reposted_claim_hash=None, signature_valid=None, reposted_tx_hash=None, reposted_tx_position=None, reposted_height=None, channel_tx_hash=None, channel_tx_position=None, channel_height=None)
[708](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:709)

[709](https://github.com/moodyjon/lbry-sdk/runs/8191561442?check_suite_focus=true#step:11:710)
----------------------------------------------------------------------