xpay: fakenet test: move funds when payment succeeds

[Lagrang3]

Improved the fakenet simulation by moving funds after a payment succeeds. This triggers a bug in xpay.

To-do:

• fix the 1msat xpay bug that fails the test_xpay_fake_channeld

[Lagrang3]

This is an extract of the logs

...
PAYING Node #0
PAYING Node #1
PAYING Node #2
PAYING Node #3
PAYING Node #4
PAYING Node #5
PAYING Node #6
PAYING Node #7
PAYING Node #8
...
        for n in range(0, 9):
            if n in canned_gossmap_badnodes:
                continue
    
            print(f"PAYING Node #{n}")
    
            preimage_hex = bytes([n]).hex() + '00' * 31
            hash_hex = sha256(bytes.fromhex(preimage_hex)).hexdigest()
            inv = subprocess.check_output(["devtools/bolt11-cli",
                                           "encode",
                                           n.to_bytes(length=8, byteorder=sys.byteorder).hex() + '01' * 24,
                                           f"currency={chainparams['bip173_prefix']}",
                                           f"p={hash_hex}",
                                           f"s={'00' * 32}",
                                           "9=020000",  # option_basic_mpp
                                           f"d=Paying node {n}",
                                           f"amount={AMOUNT}msat"]).decode('utf-8').strip()
            assert l1.rpc.decode(inv)['payee'] == nodeids[n]
>           failed_parts.append(l1.rpc.xpay(inv)['failed_parts'])
...
>           raise RpcError(method, payload, resp['error'])
E           pyln.client.lightning.RpcError: RPC call failed: method: xpay, payload: {'invstring': 'lnbcrt5m1p4yhz30sp5qqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqpp5qe7ud2qsrqlfq60k8sszpd5jcy3v34vzv0kh7hqw2v2sfhpmdcrqdq42pshj6twvusxummyv5srscqpj9qyyqqqzmuns0mernvj9rzhsa07vh8p87rmrywxk6744wsjjxsu8x5j5vq4zaharev330qc9k3qgderuw8xh8phykajy8nwkl9ve83f4weau7sqd7675n'},
error: {'code': 209, 'message': "Timed out after after 842 attempts.
We got temporary_channel_failure for 45210x2134x44171/0, assuming it can't carry 198102199msat.
We got temporary_channel_failure for 45210x2134x44171/0, assuming it can't carry 198102197msat.
We got temporary_channel_failure for 45210x2134x44171/0, assuming it can't carry 198102196msat.
We got temporary_channel_failure for 45210x2134x44171/0, assuming it can't carry 198102195msat.
We got temporary_channel_failure for 45210x2134x44171/0, assuming it can't carry 198102194msat.
We got temporary_channel_failure for 45210x2134x44171/0, assuming it can't carry 198102193msat.
We got temporary_channel_failure for 45210x2134x44171/0, assuming it can't carry 198102192msat.
We got temporary_channel_failure for 45210x2134x44171/0, assuming it can't carry 198102191msat.
We got temporary_channel_failure for 45210x2134x44171/0, assuming it can't carry 198102190msat
...
We got temporary_channel_failure for 45210x2134x44171/0, assuming it can't carry 198101779msat.
Payment of 9996982msat reached destination, but timed out before the rest arrived..
Payment of 998000msat reached destination, but timed out before the rest arrived..
Payment of 3000000msat reached destination, but timed out before the rest arrived..
Payment of 197000000msat reached destination, but timed out before the rest arrived..
Payment of 91005018msat reached destination, but timed out before the rest arrived..
Payment of 1msat reached destination, but timed out before the rest arrived..
Payment of 1msat reached destination, but timed out before the rest arrived..
Payment of 1msat reached destination, but timed out before the rest arrived..
Payment of 1msat reached destination, but timed out before the rest arrived..
Payment of 1msat reached destination, but timed out before the rest arrived..
Payment of 1msat reached destination, but timed out before the rest arrived..
Payment of 1msat reached destination, but timed out before the rest arrived..
Payment of 1msat reached destination, but timed out before the rest arrived..
Payment of 1msat reached destination, but timed out before the rest arrived.. 
...
Payment of 1msat reached destination, but timed out before the rest arrived..
Payment of 1msat reached destination, but timed out before the rest arrived.. "}

[Lagrang3]

Going through the logs of this test.
First thing to notice is that payments are numbered with odd integers, there must be calls to check xpay before
the actual xpay execution, that is increasing the counter.

Next, the payment that breaks the test is xpay-17, this is also where the 1msat flows appear.

Next is that the cause of failure is a bottleneck channel 45210x2134x44171/0 at xpay-17. It turns useful to
search in the logs for instances of that channel and analyze what askrene learns from it.

At xpay-1 askrene knowledge of 45210x2134x44171/0 is min=0msat,max=2763030000msat
then a route is computed and 289148239msat are reserved.
The simulator receives the htlc and logs

Capacity for 45210x2134x44171/0 is 2763030000msat, dynamic capacity is 2531905168msat

The payment succeeds and 289148239msat reservation is released.

 xpay-1
 min=0msat,max=2763030000msat
 reserve: 289148239
 Capacity for 45210x2134x44171/0 is 2763030000msat, dynamic capacity is 2531905168msat
 success: 289148239

For xpay-3, 3 paths go through 45210x2134x44171/0 therefore the reservation is the sum of three values.

 xpay-3
 min=0msat,max=2763030000msat
 reserve: 182397312 + 5505755 + 101582575
 Capacity for 45210x2134x44171/0 is 2763030000msat, dynamic capacity is 2242742663msat
 success and unreserve: 182397312 + 5505755 + 101582575

A similar pattern is observed for the following payments

 xpay-5
 min=0msat,max=2763030000msat
 reserve: 289148799
 Capacity for 45210x2134x44171/0 is 2763030000msat, dynamic capacity is 1953242544msat
 success and unreserve: 289148799

 xpay-7
 min=0msat,max=2763030000msat
 reserve: 289196253
 Capacity for 45210x2134x44171/0 is 2763030000msat, dynamic capacity is 1664079479msat
 success and unreserve: 289196253

 xpay-9
 min=0msat,max=2763030000msat
 reserve: 66037133 + 74538175 + 148575101
 Capacity for 45210x2134x44171/0 is 2763030000msat, dynamic capacity is 1374868958msat
 success and unreserve: 66037133 + 74538175 + 148575101

At xpay-11 there is another path through 45210x2134x44171/0 but this time the payment
fails at a channel in some hop after it. So xpay informs askrene that this channel is unconstrained, ie. it has
at least this amount. In a second attempt min is no longer 0, and this time the payment succeeds.

 xpay-11
 min=0msat,max=2763030000msat
 reserve: 289153519
 Capacity for 45210x2134x44171/0 is 2763030000msat, dynamic capacity is 1085704088msat
 failure at a further hop, unconstrained and unreserve: 289153519
 
 min=289153519msat,max=2763030000msat
 reserve: 869380 + 5209772 + 279909714 + 3763797
 Capacity for 45210x2134x44171/0 is 2763030000msat, dynamic capacity is 1085704088msat
 success and unreserve: 869380 + 5209772 + 279909714 + 3763797

xpay-13 and xpay-15 keep the usual pattern

 xpay-13
 min=289153519msat,max=2763030000msat
 reserve: 91272856 + 198102199
 Capacity for 45210x2134x44171/0 is 2763030000msat, dynamic capacity is 795936837msat
 success and unreserve: 91272856 + 198102199
 
 xpay-15
 min=289153519msat,max=2763030000msat
 reserve: 289149710
 Capacity for 45210x2134x44171/0 is 2763030000msat, dynamic capacity is 506547407msat
 success and unreserve: 289149710

At xpay-17 the first attempt has 2 paths through 45210x2134x44171/0, the second htlc fails at this channel,
xpay calls askrene inform constrained, this is the first failure we record on it.

 xpay-17
 min=289153519msat,max=2763030000msat
 reserve: 91053612 + 198102199
 Capacity for 45210x2134x44171/0 is 2763030000msat, dynamic capacity is 217383431msat
 We got temporary_channel_failure for 45210x2134x44171/0, assuming it can't carry 198102199msat

In the next attempt the max has been lowered due to the recent constrained observed.

 min=198099907msat,max=198102198msat
 reserve: 198102197
 Capacity for 45210x2134x44171/0 is 2763030000msat, dynamic capacity is 217383431msat

But then getroutes does two weird things. It returns a path through 45210x2134x44171/0 with
an amount is only 1msat below the known maximum bound. This is counter productive by the
same metric of Pickhardt-Richter, with a probability of only 1 in 2291, as getroutes reports
a probability of ~400 ppm. And the other weird behavior is to send the excess 1msat
through another path.

Action points:

• investigate why getroutes is insisting in going through 45210x2134x44171/0 instead of an alternative route,
• prevent refine to produce 1msat payments in any case.
• check should not increase the payment counter.

[Lagrang3]

If I disable 45210x2134x44171/0 after the first failure the payment succeeds, by finding alternative routes.
This is possibly due to an over-optimistic probability cost computation during MCF. We saw that the actual
probability in the final route is very low, while MCF insists it is the best.

If askrene does nothing with unconstrained inform calls the payment also succeeds, which is counter
intuitive, the more knowledge we have the better we results we should obtain.

We should

• review the computation of probability cost for this problem, figure out why do we have over optimistic probability costs here.
• relax constraints not just as time goes by but also after our hypothesis contradicts reality (more knowledge should produce equal or better results, not worse).

[Lagrang3]

Over optimism happens because in theory and with the current knowledge we can route through 45210x2134x44171/0
the remaining amount of 198000000msat at zero cost, while in practice we need to hit that channel with a
higher value due to fees we need to pay downstream.

linearize_channel: mincap=198099907msat, maxcap=198102198msat, accuracy=198000msat
linearize_channel: a=1000, b=1001
linearize_channel: cap_on_capacity=1000
linearize_channel: capacity[0]=1000
linearize_channel: capacity[1]=0
linearize_channel: capacity[2]=0
linearize_channel: capacity[3]=0

So for the payment amount X we pay 0 probability cost (ie. 100% success), for the associated fees we pay a LOT
leading to 0.04% probability of success.

• our assumption that the cost added for incrementing a flow by the fees it pays doesn't hold, we need to be aware of this and have guards in place, maybe a possible solution is to compute the costs pessimistically. Instead of the cost to route X we should look at the cost to route X + fees where the fees represent an upper bound.