tests: xpay issue and fixes

[daywalker90]

I noticed this in one of my plugin's tests.

        # BOLT 12, direct peer
        offer = l2.rpc.offer('any')['bolt12']
        b12 = l1.rpc.fetchinvoice(offer, '10000msat')['invoice']
        ret = l1.rpc.xpay(invstring=b12)
        assert ret['failed_parts'] == 0
        assert ret['successful_parts'] == 1
        assert ret['amount_msat'] == 10000
>       assert ret['amount_sent_msat'] == 10000
E       assert 10001 == 10000

tests/test_xpay.py:187: AssertionError

This is also quite flaky on my local tests with this result instead:

>       ret = l1.rpc.xpay(invstring=b12)

tests/test_xpay.py:183:

pyln.client.lightning.RpcError: RPC call failed: method: xpay, payload: {'invstring': '<removed>'}, error: {'code': 205, 'message': 'Failed: We could not find a usable set of paths. The shortest path is 103x1x0->103x2x0->0x0x0, but 0x0x0/1 exceeds htlc_maximum_msat ~0msat'}

[daywalker90]

This also happens with pay btw with even weirder results:

l1-cli pay "<removed>"
{
   "destination": "035ed467e11a1990fd4fc7d98dafbc3c49abcf8d2a48fb24f914e909e95a6737cb",
   "payment_hash": "b461b5fae962473ad0d198c0a69e458cbd6a9ef959918ea5cd6c434e75422ff4",
   "created_at": 1774304621.999080537,
   "parts": 1,
   "amount_msat": 10001,
   "amount_sent_msat": 10001,
   "payment_preimage": "a70a45a55d5121b9ba54daeb62a8cb0bb31fcaeda643974ef3ed8952c0c83f55",
   "status": "complete"
}

This is a direct pay from l1 to l2 with an "any" offer aswell and a fetched invoice for 10000msat. Notice how both amount_msat and amount_sent_msat include a fee.

[Lagrang3]

Weird. Some line above in the same test there is a BOLT11 test payment to a direct peer

        # BOLT 11, direct peer
        b11 = l2.rpc.invoice('10000msat', 'test_xpay_simple', 'test_xpay_simple bolt11')['bolt11']
        ret = l1.rpc.xpay(b11)
        assert ret['failed_parts'] == 0
        assert ret['successful_parts'] == 1
        assert ret['amount_msat'] == 10000
        assert ret['amount_sent_msat'] == 10000

with no weird fees.

Could it be the blinded path adding this fee?

[daywalker90]

Very possible, look at the path from the other error i sometimes get above: 103x1x0->103x2x0->0x0x0. That could explain it.

[Lagrang3]

I am able to reproduce the flaky test locally

pyln.client.lightning.RpcError: RPC call failed: method: xpay, payload: {'invstring': '<removed>'}, error: {'code': 205, 'message': 'Failed: We could not find a usable set of paths.  The shortest path is 103x1x0->103x2x0->0x0x0, but 0x0x0/1 exceeds htlc_maximum_msat ~0msat'}

I am looking into it. It looks like some memory un-initialized in the bolt12 decoded structure.
One of the decoded fields is called payinfo which contains the htlc_maximum_msat for the blinded path.
Sometimes we read 0 and sometimes we read some other value there. That's weird.
Furthermore debugging would be easier if decode RPC would also shown htlc_maximum_msat in the response, it doesn't.

[rustyrussell]

OK, so l2 gives a blinded path to l1, which starts with l1. l1 should realize that and not charge itself fees, but doesn't. Diagnosing now.

[rustyrussell]

Ah, this is cool!

So, xpay specifies layers like so:

1. auto.localchans
2. auto.sourcefree
3. xpay global layer
4. per-payment temporary layer

This means we don't set zero fees on the blinded path, since we apply layers in order (as documented).

More interestingly, if you "fix" this, the payment fails:

pyln.client.lightning.RpcError: RPC call failed: method: xpay, payload: {'invstring': 'lni1qqgpydqs7v2tvcagxe3hjfdmpmtp6q3qqc3xu3s3rg94nj40zfsy866mhu5vxne6tcej5878k2mneuvgjy83pmsrsx2ttuetmu92txqjepkyaaad9u55zp86qf734n5mg6dmd7yv7das9gyzx6nru5rnk63r2rytcajmhh6pj3hjxjzgw8zpx528wr4zulj8qgpry78qzse0fsxqyqt2cny0rk62ec88w8k2tvvn2hlu0s0gcf83mqgqxdv3zcmg9964yw30648fqaea7q2pr9u9h5zuc4jkqny9hzp6rn84tgvavct76pjlz7pulcx6gfecut7kyncsynjqf8eza33dhgzcfvcq2hhn4z38vmwamep7r2kv3ttq7fu5wzysqqe24akse2k5hndly934he0mvz6tyty904ujayfznh8yt05xk6rf706qagd4y7kfw8pl56wze3trz80685zpvggr8pzcqtf9kns8fn8a0nvtxwdyrhr4h7vh3gp5sqzyfdgag2c80xd9qgqxyfhyvyg6pdvu4tcjvpp7kkal9rp57wj7xv4pl3ajku70rzy3pafqyfcs2sq9sggrjrya2te7jnnnhrqjrpxjrzk76028y9fheacmxp4q9ps46kc00wq2plgql5pcr9947v4a7z49nqfvsmzw77kj722pqnaqylg6e6d5dxaklzx0x7cz49fmkr3eq50zhln30j7h5p49ajp09annwk66kt6dj0mjgml4lresyqem4qcvxj7dakxxynvcz8sf0w0pvqn0zsadum84u9qqdad7ke9ylsqyy5g8stg6yw6ljl9rgaj0meu4nq8nm2eak6dm4gnp03ykes2jq0fhcjw3ts237072hqstrsr0mhkttrr5nm3pnr5tvejxr92hwpcmamj5lksr83ytznav5pwp6dfym5jqg475rq4rvx374t7yncgstan8zukhhzrsqvh95sal4n8vg9gfeur0cjf8wcsh63lmsrjdflp3fc5nnnv6xpttnf0jawdrp6zzmzcj6wdpg8xchvz8yrazrsqqqqqpqqqqqzsqpvqqqqqqqqqqqqqqqqqqqwjcqqqqqq9yq35uk8g64qszza9777w4ua0pgtc6zjkgeqa4gvshfuf8k82434d05lr2kdx05592qgn3ptsrqgqqpvppqvuytqpdyk6wqaxvl47d3vee5swuwklej79qxjqqg394r4ptqaue4uzqj4p9mp3xku9a7dw4gwej0ah75et3mfwgn585qhx5knp7005ty6wp9wedpw43lell4svkhckxqd6hpvs48k2myjq2cp624226g5yaj4s'}, error: {'code': 209, 'message': "Failed after 1 attempts. Unexpected error (invalid_onion_blinding) from final node: disabling the invoice's blinded path (0x0x0/1) for this payment. Then routing failed: We could not find a usable set of paths. The destination has disabled 1 of 1 channels, leaving capacity only 0msat of 1515000msat."}

This is because, to avoid probing, the (encrypted) inside of the blinded path insists that the fee be paid, for important obfuscation reasons.

In summary, this is weird behavior, but we shouldn't fix it. If we override this check for local payments, it would allow any user of the node (who may not be privileged with the ability to use the node keys to decrypt the onion) to probe the next hop in this case.

[rustyrussell]

Oh, and the reason this changed? We use blinded paths for the case where our node doesn't advertize addresses: since l2's addresses are all localhost, they don't get advertized. So it uses an incoming node, and that's l1. This can be fixed by using dev-allow-localhost.

[rustyrussell]

I am able to reproduce the flaky test locally

pyln.client.lightning.RpcError: RPC call failed: method: xpay, payload: {'invstring': '<removed>'}, error: {'code': 205, 'message': 'Failed: We could not find a usable set of paths.  The shortest path is 103x1x0->103x2x0->0x0x0, but 0x0x0/1 exceeds htlc_maximum_msat ~0msat'}

I am looking into it. It looks like some memory un-initialized in the bolt12 decoded structure. One of the decoded fields is called payinfo which contains the htlc_maximum_msat for the blinded path. Sometimes we read 0 and sometimes we read some other value there. That's weird. Furthermore debugging would be easier if decode RPC would also shown htlc_maximum_msat in the response, it doesn't.

This is, fascinatingly, a different bug! I've got a reproduce for exactly this, and as you suggested, I fixed decode to print it. I'll get to the bottom of this too...

[Lagrang3]

@daywalker90, @rustyrussell: false alarm this is not an issue it was just missing liquidity and expected behavior (see #9009).
The flip-flop happens because we don't control which node l2 will use as entry point for it's blinded path. So when l2 chooses the blinded path l1->l2, the liquidity is present and payment goes through, when l2 chooses l3->l2, the liquidity is not there and htlc_max is set to 0msat in the payinfo field, then xpay correctly sets the htlc_max=0 into 0x0x0 and askrene correctly fails because 0x0x0 cannot forward the payment.

[rustyrussell]

Your diagnosis is correct, but it should always choose l1 (which has incoming capacity) not l3 (which does not). It is a corner case, though.

The final commit here fixes this.