moodyjon
commented
2 years ago Closed moodyjon closed 2 years ago
moodyjon
commented
2 years ago moodyjon
commented
2 years ago The successful runs have a sequence like this after reconnecting to the hub:
157 2022-09-10 16:33:55,042 - lbry.wallet.network - DEBUG - response blockchain.address.subscribe('mxz53icJ1cFwnRr18t5DqNn4JGPj2Dde1r', 'myJZWLw4Y7KXv2qRMrAggBZMknRoTnbDpL', 'mkgkJUvATjuBcpbqNN7TV3Ac6ZQtpjY8uD', 'mqUetgZpp1qQoonG12kcer9LrqaqqXNHma', 'mpN4mcXeMvnWUXY76mGE3xPZS7wV5uFHN6', 'n1F22LL9gN8BbJ9578s9ZPX1vR4D6fyDtw', 'n2nqp5jSLuwtxR5qSLFVUDeE3BHek9itqW', 'mqTUQypVwyV332JPy3YpL1zB4JpgL5xi4G', 'msMs4dcSUP43K2ad9a7PUXLAeBfvHLjQxV', 'n25v1mapwvaaK6Udat6wsbu3fKhf9NA4on', 'mtvdkXoDHQbkYjTtEM91FwudGCqH8GjHmc', 'myvWTXfk7vWN1WLHp2Kg6NJibRfkdWts3x', 'mm96C8qfkBb9M6z5uNGva24Ju1BR9RyPSN', 'mhv7Y3wMs1RUhXi43sZcohxs1h6wnW5JAa', 'mzmshAtC3LuhX1iomr3VnBUii7cnNy4fjw', 'ms6hogVM2VSpmFBiH7ETya2Vi9gJADpysm', 'msCAzJqnwY4ra5aaKCqEHp2HNdgpDW44sz', 'n4NXeVevigtrQH2VbcfYvNtDgHXDEfp2y2', 'mnxbd685JmeQPxGJVkcgGR7RCN2EAwUsCY', 'n4PuP4yyyzA9NdK6KYrcxLS8V7sKjTNWDP') from localhost:50002 (30 timeout) -> [None, None, None, None, None, None, None, None, None, None, None, None, None, None, None, None, None, None, None, None]
[158](https://github.com/moodyjon/lbry-sdk/runs/8285936956?check_suite_focus=true#step:11:159)
2022-09-10 16:33:55,049 - lbry.wallet.ledger - INFO - subscribed to 20/20 addresses on 127.0.0.1:50002
[159](https://github.com/moodyjon/lbry-sdk/runs/8285936956?check_suite_focus=true#step:11:160)
2022-09-10 16:33:55,049 - lbry.wallet.ledger - INFO - finished subscribing to 20 addresses on 127.0.0.1:50002
[160](https://github.com/moodyjon/lbry-sdk/runs/8285936956?check_suite_focus=true#step:11:161)
2022-09-10 16:33:55,058 - lbry.wallet.orchstr8.node.lbcwallet - INFO - 2022-09-10 16:33:55.042 [INF] TMGR: Inserting unconfirmed transaction 9c98c78d76060f70982ea1c582ccdef053387813b5c8b0de88a2610b388b1166
[161](https://github.com/moodyjon/lbry-sdk/runs/8285936956?check_suite_focus=true#step:11:162)
2022-09-10 16:33:55.045 [INF] RPCS: Successfully sent transaction 9c98c78d76060f70982ea1c582ccdef053387813b5c8b0de88a2610b388b1166
[162](https://github.com/moodyjon/lbry-sdk/runs/8285936956?check_suite_focus=true#step:11:163)
[163](https://github.com/moodyjon/lbry-sdk/runs/8285936956?check_suite_focus=true#step:11:164)
2022-09-10 16:33:55,059 - lbry.wallet.network - DEBUG - send blockchain.address.subscribe('mhG1s7Ys3AAT74pYgBXihznjWLZEPV3vn9', 'n33ejxZxApkAK3nHUJKZaJ9x8NKAAWTPAp', 'myutFwGKkp8idngwyQtybfs5LdmwrnGpyU', 'mmc46TfoYaQURhhKbtHcNtK4eipzwjYZua', 'mkUq8YoWTTKgePdv4YSQjx2PAp2gcgxysm', 'mooPF6UoABcUQ6GJwhEJosjnSqNRLRT4zR') to localhost:50002 (30 timeout)
[164](https://github.com/moodyjon/lbry-sdk/runs/8285936956?check_suite_focus=true#step:11:165)
2022-09-10 16:33:55,064 - lbry.wallet.orchstr8.node.lbcwallet - INFO - 9c98c78d76060f70982ea1c582ccdef053387813b5c8b0de88a2610b388b1166
[165](https://github.com/moodyjon/lbry-sdk/runs/8285936956?check_suite_focus=true#step:11:166)
2022-09-10 16:33:55,076 - lbry.wallet.network - DEBUG - response blockchain.address.subscribe('mhG1s7Ys3AAT74pYgBXihznjWLZEPV3vn9', 'n33ejxZxApkAK3nHUJKZaJ9x8NKAAWTPAp', 'myutFwGKkp8idngwyQtybfs5LdmwrnGpyU', 'mmc46TfoYaQURhhKbtHcNtK4eipzwjYZua', 'mkUq8YoWTTKgePdv4YSQjx2PAp2gcgxysm', 'mooPF6UoABcUQ6GJwhEJosjnSqNRLRT4zR') from localhost:50002 (30 timeout) -> [None, None, None, None, None, None]
[166](https://github.com/moodyjon/lbry-sdk/runs/8285936956?check_suite_focus=true#step:11:167)
2022-09-10 16:33:55,078 - lbry.wallet.ledger - INFO - subscribed to 6/6 addresses on 127.0.0.1:50002
[167](https://github.com/moodyjon/lbry-sdk/runs/8285936956?check_suite_focus=true#step:11:168)
2022-09-10 16:33:55,078 - lbry.wallet.ledger - INFO - finished subscribing to 6 addresses on 127.0.0.1:50002
[168](https://github.com/moodyjon/lbry-sdk/runs/8285936956?check_suite_focus=true#step:11:169)
2022-09-10 16:33:55,230 - lbry.wallet.network - DEBUG - send blockchain.address.get_history('n2nqp5jSLuwtxR5qSLFVUDeE3BHek9itqW',) to localhost:50002 (30 timeout)
[169](https://github.com/moodyjon/lbry-sdk/runs/8285936956?check_suite_focus=true#step:11:170)
2022-09-10 16:33:55,234 - lbry.wallet.network - DEBUG - response blockchain.address.get_history('n2nqp5jSLuwtxR5qSLFVUDeE3BHek9itqW',) from localhost:50002 (30 timeout) -> [{'tx_hash': '9c98c78d76060f70982ea1c582ccdef053387813b5c8b0de88a2610b388b1166', 'height': 0, 'fee': 376}]
[170](https://github.com/moodyjon/lbry-sdk/runs/8285936956?check_suite_focus=true#step:11:171)
2022-09-10 16:33:55,234 - lbry.wallet.ledger - DEBUG - request 1 transactions, 0/1 for n2nqp5jSLuwtxR5qSLFVUDeE3BHek9itqW are already synced
[171](https://github.com/moodyjon/lbry-sdk/runs/8285936956?check_suite_focus=true#step:11:172)
2022-09-10 16:33:55,234 - lbry.wallet.network - DEBUG - send blockchain.transaction.get_batch('9c98c78d76060f70982ea1c582ccdef053387813b5c8b0de88a2610b388b1166',) to localhost:50002 (30 timeout)
[172](https://github.com/moodyjon/lbry-sdk/runs/8285936956?check_suite_focus=true#step:11:173)
2022-09-10 16:33:55,239 - lbry.wallet.network - DEBUG - response blockchain.transaction.get_batch('9c98c78d76060f70982ea1c582ccdef053387813b5c8b0de88a2610b388b1166',) from localhost:50002 (30 timeout) -> {'9c98c78d76060f70982ea1c582ccdef053387813b5c8b0de88a2610b388b1166': ['010000000200fe5c65139aa0ebdd39a07ff4e22bcf92f365fa84232beef9d233c6702439b1000000006b483045022100d310445d1a9bb2b21379554048438c4a4a4b7e9d4323fc8fcf223421b05fa86802206feaf9e485d1ebb32d15e4ce92f8fee3ab73e065860f19213afc70a7100555e30121033e68152333aee2004d7e226c27f8b42f6aa568caf31a02bd5c2fbccdbcb17399ffffffff01a7941c074b3800205f5b9af4a5b71214acc3cfdcad1ccc210c2ef71fa13720000000006a47304402202ff9021c1358c84a5d6764a1cf3eb65813d4868d059389e35e3814f6b3c75327022070c47bbf2c84c8c6e685243184bafbd1aa55ce9ce0385f0487eba3acce0333a50121033e68152333aee2004d7e226c27f8b42f6aa568caf31a02bd5c2fbccdbcb17399ffffffff02f8dc2905000000001976a9142d5e3d0953c33b13f21c980f4767e761779ba12988ac90e3c106000000001976a914e95be2bead109a5c9a508b7562c8cd424ad70bd188ac00000000', {'block_height': -1}]}
[173](https://github.com/moodyjon/lbry-sdk/runs/8285936956?check_suite_focus=true#step:11:174)
2022-09-10 16:33:55,244 - lbry.wallet.ledger - INFO - (lbc_regtest) on_transaction: address=n2nqp5jSLuwtxR5qSLFVUDeE3BHek9itqW, height=0, is_verified=False,Unsuccessful ones don't do blockchain.address.get_history, so no on_transaction notification is generated.
moodyjon
commented
2 years ago @eukreign @jackrobison
moodyjon
commented
2 years ago Another: https://github.com/moodyjon/lbry-sdk/actions/runs/3040634276/jobs/4896910797 https://github.com/moodyjon/lbry-sdk/actions/runs/3040632508/jobs/4896907603 https://github.com/moodyjon/lbry-sdk/actions/runs/3044957776/jobs/4905927570
It looks like hub fails to send a status update. In passing runs, Ledger.process_status_update() is called. In failing runs, it's NOT called, leading to the hang.
moodyjon
commented
2 years ago I just dug into how the subscriptions are kept, and the session object id() (memory addr) determines which session gets notified.
moodyjon
commented
2 years ago moodyjon
commented
2 years ago Another: https://github.com/moodyjon/lbry-sdk/actions/runs/3063166402/jobs/4944948913
This one has some more logging. There is an initial pass through the mempool logic to compute notifications. But the subscription has not been made at that moment. An empty notification? is generated.
2022-09-15 20:12:01,791 - lbry.wallet.orchstr8.node.lbcwallet - INFO - 232a4672922da996b2998fae35b42b599a9401998a6b12d41e3a1ee21e15411c
[1182](https://github.com/moodyjon/lbry-sdk/actions/runs/3063166402/jobs/4944948913#step:11:1183)
2022-09-15 20:12:01,791 - lbry.testcase - WARNING - before: done = False, tx_watch = []
[1183](https://github.com/moodyjon/lbry-sdk/actions/runs/3063166402/jobs/4944948913#step:11:1184)
2022-09-15 20:12:01,883 - hub.herald.mempool - INFO - touched hashXs: 3
[1184](https://github.com/moodyjon/lbry-sdk/actions/runs/3063166402/jobs/4944948913#step:11:1185)
2022-09-15 20:12:01,885 - hub.herald.mempool - INFO - touched hashXs with subscription: 0
[1185](https://github.com/moodyjon/lbry-sdk/actions/runs/3063166402/jobs/4944948913#step:11:1186)
2022-09-15 20:12:01,885 - hub.herald.mempool - INFO - sessions with touched hashXs: 0
[1186](https://github.com/moodyjon/lbry-sdk/actions/runs/3063166402/jobs/4944948913#step:11:1187)
2022-09-15 20:12:01,885 - hub.herald.mempool - INFO - notification queued for session ('127.0.0.1', 55032) height_changed=False hashXes: NoneMore context from last update:
n2HX6cy5yQcUfk1s625zB7XnUCbwQk8i2t is the receiving address I think. The order of events is:
1) subscription RPC sent by client 2) lbcctl returns after sending transaction 3) hub runs through notification logic (hub.herald.mempool). no subscription found. 4) hub reply to subscription with hashX status None
2022-09-15T20:12:01.7226863Z [0;37m2022-09-15 20:12:01,722 - lbry.wallet.ledger - INFO - Subscribe to 1 accounts[0m
2022-09-15T20:12:01.7266571Z [30m2022-09-15 20:12:01,726 - lbry.wallet.network - DEBUG - send blockchain.address.subscribe('n2HX6cy5yQcUfk1s625zB7XnUCbwQk8i2t', 'myFydtv4PSRyVXZ4Soi7Y2U6NNh4B9o2w2', 'n2EMYrgpLgn2pdsyjXwm4AjDeksgnn71uQ', 'n3FNqBoSce7uek4Hwj4bkW8PyvC672aeMC', 'mugRn1EdwPMdrEWAqz7ewZ2eg8XavWrr9W', 'n3Y8kNJW8BNxCi6NvDLpfdx6QrgdVo1Fjn', 'n1EC5EZLuTq634sc3j8T2DgUBsa7vu6nS1', 'mqkDXc4Z9jDCxAowLqZF48gSxNipL4ZhEa', 'mw49T2dVkqoMh9rGaG5oJNgZnhFs5dpZqJ', 'mmhgho3cFZ6gixX7Lio7DKJ871faAzC16L', 'mqorh8iAo7bfRuotRva6ZPuERAZYyhvppd', 'mrZsf77QhB2txYTiMZHMUcdwLSQK2nUoUb', 'mznewhHNjGgc74pC9Q8HjkNVpLDdZ1K6FY', 'mxvWUfLUUV4VbvL3s5u2cJLSEvsf1j161G', 'mxKCim8vxJvdoQgXicLzDCSb1NDQKXk4wK', 'mvaFiVctFjtzVw6DzWB1dnUYSr88hFh2uX', 'mzHUKjxzoZbNvsSEJRgbmtb7AwKS2jB39k', 'mqKxsnpgoAy1QgJ21oGKs66EiFfJVL73oK', 'mhXMbDUCGwe33Ch8zG6Qk1PyZ2wbWWKxUG', 'mobPRfdG8CWWjH8YcZVFbYya5Zd3cYWees') to localhost:50002 (30 timeout)[0m
2022-09-15T20:12:01.7296490Z [30m2022-09-15 20:12:01,729 - hub.herald.session - DEBUG - Sending framed message b'{"jsonrpc":"2.0","result":"CiV6IwgBEh9Db3VsZCBub3QgZmluZCBjbGFpbSBhdCAiZGVycCIu","id":571}\n'[0m
2022-09-15T20:12:01.7337391Z [30m2022-09-15 20:12:01,733 - lbry.wallet.network - DEBUG - response blockchain.claimtrie.resolve('derp',) from localhost:50002 (30 timeout) -> CiV6IwgBEh9Db3VsZCBub3QgZmluZCBjbGFpbSBhdCAiZGVycCIu[0m
2022-09-15T20:12:01.7347087Z [0;37m2022-09-15 20:12:01,734 - lbry.wallet.orchstr8.node.lbcwallet - INFO - /home/runner/work/lbry-sdk/lbry-sdk/lbry/wallet/bin/lbcctl --rpcuser=rpcuser --rpcpass=rpcpassword --notls --regtest --wallet sendtoaddress n2HX6cy5yQcUfk1s625zB7XnUCbwQk8i2t 1.1337[0m
2022-09-15T20:12:01.7840435Z [0;37m2022-09-15 20:12:01,783 - lbry.wallet.orchstr8.node.lbcwallet - INFO - 2022-09-15 20:12:01.782 [INF] TMGR: Inserting unconfirmed transaction 232a4672922da996b2998fae35b42b599a9401998a6b12d41e3a1ee21e15411c
2022-09-15T20:12:01.7841648Z [0m
2022-09-15T20:12:01.7890053Z [0;37m2022-09-15 20:12:01,787 - lbry.wallet.orchstr8.node.lbcwallet - INFO - 2022-09-15 20:12:01.787 [INF] RPCS: Successfully sent transaction 232a4672922da996b2998fae35b42b599a9401998a6b12d41e3a1ee21e15411c
2022-09-15T20:12:01.7890902Z [0m
2022-09-15T20:12:01.7913989Z [0;37m2022-09-15 20:12:01,791 - lbry.wallet.orchstr8.node.lbcwallet - INFO - 232a4672922da996b2998fae35b42b599a9401998a6b12d41e3a1ee21e15411c[0m
2022-09-15T20:12:01.7915010Z [33m2022-09-15 20:12:01,791 - lbry.testcase - WARNING - before: done = False, tx_watch = [][0m
2022-09-15T20:12:01.8837571Z [0;37m2022-09-15 20:12:01,883 - hub.herald.mempool - INFO - touched hashXs: 3[0m
2022-09-15T20:12:01.8853363Z [0;37m2022-09-15 20:12:01,885 - hub.herald.mempool - INFO - touched hashXs with subscription: 0[0m
2022-09-15T20:12:01.8854310Z [0;37m2022-09-15 20:12:01,885 - hub.herald.mempool - INFO - sessions with touched hashXs: 0[0m
2022-09-15T20:12:01.8861004Z [0;37m2022-09-15 20:12:01,885 - hub.herald.mempool - INFO - notification queued for session ('127.0.0.1', 55032) height_changed=False hashXes: None[0m
2022-09-15T20:12:01.8979351Z [30m2022-09-15 20:12:01,897 - hub.herald.session - DEBUG - Sending framed message b'{"jsonrpc":"2.0","result":[null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null],"id":572}\n'[0m
2022-09-15T20:12:01.8998519Z [30m2022-09-15 20:12:01,899 - lbry.wallet.network - DEBUG - response blockchain.address.subscribe('n2HX6cy5yQcUfk1s625zB7XnUCbwQk8i2t', 'myFydtv4PSRyVXZ4Soi7Y2U6NNh4B9o2w2', 'n2EMYrgpLgn2pdsyjXwm4AjDeksgnn71uQ', 'n3FNqBoSce7uek4Hwj4bkW8PyvC672aeMC', 'mugRn1EdwPMdrEWAqz7ewZ2eg8XavWrr9W', 'n3Y8kNJW8BNxCi6NvDLpfdx6QrgdVo1Fjn', 'n1EC5EZLuTq634sc3j8T2DgUBsa7vu6nS1', 'mqkDXc4Z9jDCxAowLqZF48gSxNipL4ZhEa', 'mw49T2dVkqoMh9rGaG5oJNgZnhFs5dpZqJ', 'mmhgho3cFZ6gixX7Lio7DKJ871faAzC16L', 'mqorh8iAo7bfRuotRva6ZPuERAZYyhvppd', 'mrZsf77QhB2txYTiMZHMUcdwLSQK2nUoUb', 'mznewhHNjGgc74pC9Q8HjkNVpLDdZ1K6FY', 'mxvWUfLUUV4VbvL3s5u2cJLSEvsf1j161G', 'mxKCim8vxJvdoQgXicLzDCSb1NDQKXk4wK', 'mvaFiVctFjtzVw6DzWB1dnUYSr88hFh2uX', 'mzHUKjxzoZbNvsSEJRgbmtb7AwKS2jB39k', 'mqKxsnpgoAy1QgJ21oGKs66EiFfJVL73oK', 'mhXMbDUCGwe33Ch8zG6Qk1PyZ2wbWWKxUG', 'mobPRfdG8CWWjH8YcZVFbYya5Zd3cYWees') from localhost:50002 (30 timeout) -> [None, None, None, None, None, None, None, None, None, None, None, None, None, None, None, None, None, None, None, None][0mClient did not receive the status update through either path -- neither initial subscribe response nor notification.
It looks like subscription is done right:
async def hashX_subscribe(self, hashX, alias):
self.hashX_subs[hashX] = alias
self.session_manager.hashx_subscriptions_by_session[hashX].add(id(self))
return await self.address_status(hashX)address_status() is called after hash_subscriptions_by_session is updated. So there should not be a window of time where we miss an update.
moodyjon
commented
2 years ago But.... address_subscribe() is not written the same way. It's potentially racy:
if len(addresses) > 1000:
raise RPCError(BAD_REQUEST, f'too many addresses in subscription request: {len(addresses)}')
hashXes = [item async for item in asyncify_for_loop((self.address_to_hashX(address) for address in addresses), 100)]
statuses = await self.get_hashX_statuses(hashXes). <<<<<<<<<<< get status BEFORE subscription
for hashX, alias in zip(hashXes, addresses):
self.hashX_subs[hashX] = alias
self.session_manager.hashx_subscriptions_by_session[hashX].add(id(self))
self.session_manager.address_subscription_metric.inc(len(addresses))
return statusesInserting a 1s sleep after statuses = await self.get_hashX_statuses reproduced the problem 5 of 5 runs. Unfortunately, it disrupts a large number of other tests, so running it in the GitHub workflow is difficult.
The fix should be to retrieve get_hashX_statuses AFTER updating the subscription data structures.
I observed this happen with some extra logging hacked into moodyjon/lbry-sdk. Client is able to reconnect to herald, and get RPC responses ("blockchain.address.subscribe", "ping"). But all is not well because
send_to_address_and_wait()appears to hang.https://github.com/moodyjon/lbry-sdk/runs/8281332230?check_suite_focus=true
Hang here. No further activity until asyncio’s task dump.
Test code: