Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

CI Complaint about spend_tag in test_onchain_their_unilateral_out[True] #7526

Open
rustyrussell opened this issue Aug 5, 2024 · 1 comment · May be fixed by #7593
Open

CI Complaint about spend_tag in test_onchain_their_unilateral_out[True] #7526

rustyrussell opened this issue Aug 5, 2024 · 1 comment · May be fixed by #7593
Assignees
@niftynei
Labels
bookkeeper
Milestone
v24.11

Comments

@rustyrussell
Copy link
Contributor

From splicing tests:
job-logs.txt

2024-08-05T05:54:48.6779834Z ___________________ test_onchain_their_unilateral_out[True] ____________________
2024-08-05T05:54:48.6781639Z [gw5] linux -- Python 3.8.18 /home/runner/.cache/pypoetry/virtualenvs/cln-meta-project-AqJ9wMix-py3.8/bin/python
2024-08-05T05:54:48.6783030Z 
2024-08-05T05:54:48.6783579Z node_factory = <pyln.testing.utils.NodeFactory object at 0x7fcbb7cef1f0>
2024-08-05T05:54:48.6784841Z bitcoind = <pyln.testing.utils.BitcoinD object at 0x7fcbb7cd7970>
2024-08-05T05:54:48.6787874Z chainparams = {'bip173_prefix': 'bcrt', 'chain_hash': '06226e46111a0b59caaf126043eb5bbf28c34f3a5e332a1fc7b2b73cf188910f', 'elements': False, 'example_addr': 'bcrt1qeyyk6sl5pr49ycpqyckvmttus5ttj25pd0zpvg', ...}
2024-08-05T05:54:48.6789821Z anchors = True
2024-08-05T05:54:48.6790109Z 
2024-08-05T05:54:48.6790457Z     @pytest.mark.parametrize("anchors", [False, True])
2024-08-05T05:54:48.6791580Z     def test_onchain_their_unilateral_out(node_factory, bitcoind, chainparams, anchors):
2024-08-05T05:54:48.6792985Z         """ Very similar to the test_onchain_middleman, except there's no
2024-08-05T05:54:48.6794050Z             middleman, we simply want to check that our offered htlc
2024-08-05T05:54:48.6795050Z             on their unilateral returns to us (and is accounted
2024-08-05T05:54:48.6795943Z             for correctly) """
2024-08-05T05:54:48.6796542Z     
2024-08-05T05:54:48.6797221Z         if chainparams['elements'] and anchors:
2024-08-05T05:54:48.6798238Z             pytest.skip('elementsd anchors unsupported')
2024-08-05T05:54:48.6798912Z     
2024-08-05T05:54:48.6799587Z         # We track channel balances, to verify that accounting is ok.
2024-08-05T05:54:48.6800721Z         coin_mvt_plugin = os.path.join(os.getcwd(), 'tests/plugins/coin_movements.py')
2024-08-05T05:54:48.6801685Z         opts = {'plugin': coin_mvt_plugin}
2024-08-05T05:54:48.6802338Z         if anchors is False:
2024-08-05T05:54:48.6802972Z             opts['dev-force-features'] = "-23"
2024-08-05T05:54:48.6803570Z     
2024-08-05T05:54:48.6804201Z         disconnects = ['-WIRE_UPDATE_FAIL_HTLC', 'permfail']
2024-08-05T05:54:48.6804873Z     
2024-08-05T05:54:48.6805360Z         l1, l2 = node_factory.line_graph(2, opts=[opts,
2024-08-05T05:54:48.6806295Z                                                   {**opts, **{'disconnect': disconnects}}])
2024-08-05T05:54:48.6807333Z         channel_id = first_channel_id(l1, l2)
2024-08-05T05:54:48.6807931Z     
2024-08-05T05:54:48.6808648Z         route = l1.rpc.getroute(l2.info['id'], 10**8, 1)["route"]
2024-08-05T05:54:48.6809591Z         assert len(route) == 1
2024-08-05T05:54:48.6810219Z     
2024-08-05T05:54:48.6810663Z         q = queue.Queue()
2024-08-05T05:54:48.6811245Z     
2024-08-05T05:54:48.6811785Z         def try_pay():
2024-08-05T05:54:48.6812502Z             try:
2024-08-05T05:54:48.6813207Z                 # rhash is fake (so is payment_secret)
2024-08-05T05:54:48.6814105Z                 rhash = 'B1' * 32
2024-08-05T05:54:48.6815008Z                 l1.rpc.sendpay(route, rhash, payment_secret=rhash)
2024-08-05T05:54:48.6815880Z                 q.put(None)
2024-08-05T05:54:48.6816617Z             except Exception as err:
2024-08-05T05:54:48.6817338Z                 q.put(err)
2024-08-05T05:54:48.6817970Z     
2024-08-05T05:54:48.6818554Z         t = threading.Thread(target=try_pay)
2024-08-05T05:54:48.6819211Z         t.daemon = True
2024-08-05T05:54:48.6819835Z         t.start()
2024-08-05T05:54:48.6820355Z     
2024-08-05T05:54:48.6820873Z         # l2 will drop to chain.
2024-08-05T05:54:48.6821755Z         l2.daemon.wait_for_log(' to AWAITING_UNILATERAL')
2024-08-05T05:54:48.6822618Z         l2.daemon.wait_for_log('sendrawtx exit 0')
2024-08-05T05:54:48.6823600Z         l2.bitcoin.generate_block(1)
2024-08-05T05:54:48.6824405Z         l1.daemon.wait_for_log(' to ONCHAIN')
2024-08-05T05:54:48.6825188Z         l2.daemon.wait_for_log(' to ONCHAIN')
2024-08-05T05:54:48.6826260Z         l1.daemon.wait_for_log('THEIR_UNILATERAL/OUR_HTLC')
2024-08-05T05:54:48.6827376Z         _, txid, blocks = l1.wait_for_onchaind_tx('OUR_HTLC_TIMEOUT_TO_US',
2024-08-05T05:54:48.6828416Z                                                   'THEIR_UNILATERAL/OUR_HTLC')
2024-08-05T05:54:48.6829711Z         assert blocks == 9
2024-08-05T05:54:48.6830303Z     
2024-08-05T05:54:48.6830951Z         # l1 should wait til to_self_delay (10), then fulfill onchain
2024-08-05T05:54:48.6831953Z         l2.bitcoin.generate_block(9)
2024-08-05T05:54:48.6832973Z         l2.daemon.wait_for_log('Ignoring output .*_UNILATERAL/THEIR_HTLC')
2024-08-05T05:54:48.6833950Z     
2024-08-05T05:54:48.6834528Z         err = q.get(timeout=10)
2024-08-05T05:54:48.6835121Z         if err:
2024-08-05T05:54:48.6835734Z             print("Got err from sendpay thread")
2024-08-05T05:54:48.6836522Z             raise err
2024-08-05T05:54:48.6837122Z         t.join(timeout=1)
2024-08-05T05:54:48.6837767Z         assert not t.is_alive()
2024-08-05T05:54:48.6838494Z     
2024-08-05T05:54:48.6839155Z         # 100 blocks after last spend, l1+l2 should be done.
2024-08-05T05:54:48.6839927Z         # Could be RBF!
2024-08-05T05:54:48.6840652Z         l1.mine_txid_or_rbf(txid, numblocks=100)
2024-08-05T05:54:48.6841693Z         l1.daemon.wait_for_log('onchaind complete, forgetting peer')
2024-08-05T05:54:48.6842771Z         l2.daemon.wait_for_log('onchaind complete, forgetting peer')
2024-08-05T05:54:48.6843576Z     
2024-08-05T05:54:48.6844053Z         # Verify accounting for l1 & l2
2024-08-05T05:54:48.6844741Z         assert account_balance(l2, channel_id) == 0
2024-08-05T05:54:48.6845498Z         assert account_balance(l1, channel_id) == 0
2024-08-05T05:54:48.6846151Z     
2024-08-05T05:54:48.6846617Z         # Graph of coin_move events we expect
2024-08-05T05:54:48.6847274Z         expected_1 = {
2024-08-05T05:54:48.6847986Z             '0': [('wallet', ['deposit'], ['withdrawal'], 'A')],
2024-08-05T05:54:48.6848874Z             # This is ugly, but this wallet deposit is either unspent or used
2024-08-05T05:54:48.6849774Z             # in the next channel open
2024-08-05T05:54:48.6850825Z             'A': [('wallet', ['deposit'], None, None), ('cid1', ['channel_open', 'opener'], ['channel_close'], 'B')],
2024-08-05T05:54:48.6852409Z             'B': [('wallet', ['deposit'], None, None), ('cid1', ['htlc_timeout'], ['to_wallet'], 'C')],
2024-08-05T05:54:48.6853696Z             'C': [('wallet', ['deposit'], None, None)],
2024-08-05T05:54:48.6854445Z         }
2024-08-05T05:54:48.6854871Z     
2024-08-05T05:54:48.6855259Z         expected_2 = {
2024-08-05T05:54:48.6856054Z             'A': [('cid1', ['channel_open'], ['channel_close'], 'B')],
2024-08-05T05:54:48.6857212Z             'B': [('external', ['to_them'], None, None), ('external', ['htlc_timeout'], None, None)],
2024-08-05T05:54:48.6858067Z         }
2024-08-05T05:54:48.6858528Z     
2024-08-05T05:54:48.6858965Z         if anchors:
2024-08-05T05:54:48.6859696Z             expected_1['B'].append(('external', ['anchor'], None, None))
2024-08-05T05:54:48.6860763Z             expected_2['B'].append(('external', ['anchor'], None, None))
2024-08-05T05:54:48.6861807Z             expected_1['B'].append(('wallet', ['anchor', 'ignored'], None, None))
2024-08-05T05:54:48.6862825Z             expected_2['B'].append(('wallet', ['anchor', 'ignored'], None, None))
2024-08-05T05:54:48.6863610Z     
2024-08-05T05:54:48.6864075Z         # FIXME: Why does this fail?
2024-08-05T05:54:48.6864673Z         if not anchors:
2024-08-05T05:54:48.6865390Z             tags = check_utxos_channel(l1, [channel_id], expected_1)
2024-08-05T05:54:48.6866273Z             check_utxos_channel(l2, [channel_id], expected_2, tags)
2024-08-05T05:54:48.6866988Z     
2024-08-05T05:54:48.6867631Z         # Check 'bkpr-inspect' and 'bkpr-listbalances'
2024-08-05T05:54:48.6868498Z         # The wallet events aren't in the channel's events
2024-08-05T05:54:48.6869254Z         del expected_1['0']
2024-08-05T05:54:48.6870088Z         expected_1['A'] = expected_1['A'][1:]
2024-08-05T05:54:48.6870808Z >       check_inspect_channel(l1, channel_id, expected_1)
2024-08-05T05:54:48.6871286Z 
2024-08-05T05:54:48.6871524Z tests/test_closing.py:2421: 
2024-08-05T05:54:48.6872286Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2024-08-05T05:54:48.6873327Z tests/utils.py:356: in check_inspect_channel
2024-08-05T05:54:48.6874066Z     inspect_check_actual(txids, channel_id, actual, exp)
2024-08-05T05:54:48.6875007Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2024-08-05T05:54:48.6875547Z 
2024-08-05T05:54:48.6876140Z txids = [('B', '7d40a1c42dc00c03071c99e1ae805d6b03ce3df00d58bdcfab388889187e7e80')]
2024-08-05T05:54:48.6877424Z channel_id = '87fa568fb05a23d0832a60937a3a82242f0d7ae2116e86927a7cc95aeced9b11'
2024-08-05T05:54:48.6879794Z actual = {'blockheight': 104, 'fees_paid_msat': 5526000, 'outputs': [{'account': 'external', 'credit_msat': 330000, 'currency':...y': 'bcrt', 'debit_msat': 894474000, ...}], 'txid': '7d40a1c42dc00c03071c99e1ae805d6b03ce3df00d58bdcfab388889187e7e80'}
2024-08-05T05:54:48.6882477Z exp = [('wallet', ['deposit'], None, None), ('cid1', ['htlc_timeout'], ['to_wallet'], 'C'), ('external', ['anchor'], None, None), ('wallet', ['anchor', 'ignored'], None, None)]
2024-08-05T05:54:48.6883511Z 
2024-08-05T05:54:48.6883870Z     def inspect_check_actual(txids, channel_id, actual, exp):
2024-08-05T05:54:48.6884830Z         assert len(actual['outputs']) == len(exp)
2024-08-05T05:54:48.6885480Z         for e in exp:
2024-08-05T05:54:48.6885985Z             # find the event in actual that matches
2024-08-05T05:54:48.6886708Z             found = False
2024-08-05T05:54:48.6887327Z             for a in actual['outputs']:
2024-08-05T05:54:48.6887999Z                 if e[0].startswith('cid'):
2024-08-05T05:54:48.6888761Z                     if a['account'] != channel_id:
2024-08-05T05:54:48.6889398Z                         continue
2024-08-05T05:54:48.6890015Z                 elif a['account'] != e[0]:
2024-08-05T05:54:48.6890654Z                     continue
2024-08-05T05:54:48.6891165Z     
2024-08-05T05:54:48.6891728Z                 if e[1][0] != a['output_tag']:
2024-08-05T05:54:48.6892571Z                     continue
2024-08-05T05:54:48.6893081Z                 if e[2]:
2024-08-05T05:54:48.6893709Z                     assert e[2][0] == a['spend_tag']
2024-08-05T05:54:48.6894817Z                     txids.append((e[3], a['spending_txid']))
2024-08-05T05:54:48.6895543Z                 else:
2024-08-05T05:54:48.6896155Z >                   assert 'spend_tag' not in a
2024-08-05T05:54:48.6896890Z E                   AssertionError
2024-08-05T05:54:48.6897261Z 
2024-08-05T05:54:48.6897460Z tests/utils.py:327: AssertionError
@rustyrussell rustyrussell added this to the v24.08 milestone Aug 5, 2024
@rustyrussell
Copy link
Contributor Author

job-logs.txt

@rustyrussell rustyrussell modified the milestones: v24.08, v24.11 Aug 12, 2024
niftynei added a commit to niftynei/lightning that referenced this issue Aug 20, 2024
@niftynei
anchors: dont make anchorspend txs for in-chain commitments
6e6a143 
We were seeing occassional spends of commitment tx utxos in
anchorspend txs, which was causing occasional test fails.

We shouldn't be sending anchorspends at all for onchain funding-spends.
The logic is in place for this, but the ordering of the state update to
channel was incorrect, which lead to loglines as follows
(we'd expect to see failure in ONCHAIN not NORMAL), given that the
reason=onchain...

"Peer permanent failure in CHANNELD_NORMAL: Funding transaction spent (reason=onchain)"

A quick reordering of the state change + firing of `drop_to_chain` fixes
the issue of sending the anchorspend tx, which removes the race case
of onchaind adding utxos from the commitment tx to the utxoset, where
the anchorspend construction was picking them up.

Fixes ElementsProject#7526
niftynei added a commit to niftynei/lightning that referenced this issue Aug 20, 2024
@niftynei
anchors: dont make anchorspend txs for in-chain commitments
84f55b1 
We were seeing occassional spends of commitment tx utxos in
anchorspend txs, which was causing occasional test fails.

We shouldn't be sending anchorspends at all for onchain funding-spends.
The logic is in place for this, but the ordering of the state update to
channel was incorrect, which lead to loglines as follows
(we'd expect to see failure in ONCHAIN not NORMAL), given that the
reason=onchain...

"Peer permanent failure in CHANNELD_NORMAL: Funding transaction spent (reason=onchain)"

A quick reordering of the state change + firing of `drop_to_chain` fixes
the issue of sending the anchorspend tx, which removes the race case
of onchaind adding utxos from the commitment tx to the utxoset, where
the anchorspend construction was picking them up.

Fixes ElementsProject#7526
@niftynei niftynei linked a pull request Aug 20, 2024 that will close this issue
Open
rustyrussell pushed a commit to niftynei/lightning that referenced this issue Sep 20, 2024
@niftynei @rustyrussell
anchors: dont make anchorspend txs for in-chain commitments
a7c25bf 
We were seeing occassional spends of commitment tx utxos in
anchorspend txs, which was causing occasional test fails.

We shouldn't be sending anchorspends at all for onchain funding-spends.
The logic is in place for this, but the ordering of the state update to
channel was incorrect, which lead to loglines as follows
(we'd expect to see failure in ONCHAIN not NORMAL), given that the
reason=onchain...

"Peer permanent failure in CHANNELD_NORMAL: Funding transaction spent (reason=onchain)"

A quick reordering of the state change + firing of `drop_to_chain` fixes
the issue of sending the anchorspend tx, which removes the race case
of onchaind adding utxos from the commitment tx to the utxoset, where
the anchorspend construction was picking them up.

Fixes ElementsProject#7526
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@niftynei niftynei

Labels
bookkeeper
Projects
None yet
Milestone
v24.11
Development

Successfully merging a pull request may close this issue.

Fix: don't send anchorspends for onchain commitment txs niftynei/lightning
2 participants
@rustyrussell @niftynei