WIRE_TEMPORARY_CHANNEL_FAILURE from own peer with "UNUSUAL routing_failure"

[hkjn]

Issue and Steps to Reproduce

Built at b3d4e1:

$ env | grep VERSION
LIGHTNING_VERSION=b3d4e1                           
BITCOIN_VERSION=1462bd

Should be built past fixes for #638, #893, which have similar symptoms. Seems like different symptoms from #952, afaict.

Attempting to pay a mainnet.yalls.org article:

$ lightning-cli pay lnbc1500n1pd8cuumpp5cnnc8nrxrx49es67w0g0mahrdevdr28y6p94pl                                                                                                       
qx5e49p6xw75mqdyu0v3xgg36yffx2ctyypqhyarfvdkx2w3qf35hxapqdanzqum9wfmxjcm9wvsxzcmrv4c8g6twvusx6ctfdehzy                                                                                                       
tpzdy3r5g3jxp3njenyxdsj6ctrxajz6dp5v5uz6c3kvfsj6wrrxgerydf4v4nr2c33yf7scqzys4erahl43ezpxr4mra5cycehxte                                                                                                       
js49tpqkv7plfzvy5pyc0xejnn7jtq0jgj68hk0tuensld0pace9ws5vesmhy5dak3cdrdlhdu54cpmtzjve                  
{ "code" : 204, "message" : "failed: WIRE_TEMPORARY_CHANNEL_FAILURE (First peer not ready)", "data" : { "erring_index" : 0, "failcode" : 4103, "erring_node" : "10b51d2e2b63b76c7856b7fb83077f9b893de0720d74871b67deafa4c39b08642ed3b9941c74478333126740127b5c811b5ba19b9ae6a914d76bd7e53fe554cd", "erring_channel" : "507981:1093:0" } }                                                                                 

In logs with --log-level=debug:

2018-02-08T15:58:43.500Z lightning_gossipd(54): req: type WIRE_GOSSIP_GETROUTE_REQUEST len 78         
2018-02-08T15:58:43.500Z lightning_gossipd(54): Trying to find a route from 0264089bc3a4afde671b87740d72e03d899b7f0783fbb756786cb7632b2e1db510 to 02669e1e43577c14a4ae796a38e0cfdadb548615058e367bd96bf825e62c0932ce for 150000 msatoshi                        
2018-02-08T15:58:43.500Z lightning_gossipd(54): find_route: via 039514e5d704c59a0eba65d25fc5fe559a1641243ccdf80c980b1fc10ca9c30ca2                                                                           
2018-02-08T15:58:43.501Z lightning_gossipd(54):  02669e1e43577c14a4ae796a38e0cfdadb548615058e367bd96bf825e62c0932ce (1000+1=1000)                                                                            
2018-02-08T15:58:43.501Z lightning_gossipd(54):  =150000(+1000)                                       
2018-02-08T15:58:43.502Z lightning_gossipd(54): REPLY WIRE_GOSSIP_GETROUTE_REPLY with 0 fds            
2018-02-08T15:58:43.531Z lightningd(46): Sending 151000 over 2 hops to deliver 150000                 
2018-02-08T15:58:43.531Z lightningd(46): peer 039514e5d704c59a0eba65d25fc5fe559a1641243ccdf80c980b1fc10ca9c30ca2: Attempt to send HTLC but unowned (CHANNELD_NORMAL)                                         
2018-02-08T15:58:43.534Z lightningd(46): Reporting route failure to gossipd: 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE) node 0264089bc3a4afde671b87740d72e03d899b7f0783fbb756786cb7632b2e1db510 channel 507981:1093:0 update                                        
2018-02-08T15:58:43.535Z lightningd(46):jcon fd 14: Failing: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (First peer not ready)                                                                                   
2018-02-08T15:58:43.537Z lightning_gossipd(54): req: type WIRE_GOSSIP_ROUTING_FAILURE len 47          
2018-02-08T15:58:43.539Z lightning_gossipd(54): Received routing failure 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE), erring node 0264089bc3a4afde671b87740d72e03d899b7f0783fbb756786cb7632b2e1db510, channel 507981:1093:0                                         
2018-02-08T15:58:43.539Z lightning_gossipd(54): UNUSUAL routing_failure: UPDATE bit set, no channel_update. failcode: 0x1007    

If I'm reading the output right, the "erring node" is ourselves:

$ lightning-cli listnodes | grep 0264089bc3a4afde671b87740d72e03d899b7f0783fbb756786cb7632b2e1db510
                { "nodeid" : "0264089bc3a4afde671b87740d72e03d899b7f0783fbb756786cb7632b2e1db510", "alias" : "ln.hkjn.me", "color" : "003366", "last_timestamp" : 1518099430, "addresses" :

Retrying pay repeatedly as suggested by @ZmnSCPxj on #952 (comment) leads to a different failure symptom after 5+ tries (may be legitimate, haven't looked):

$ lightning-cli pay lnbc1500n1pd8cuumpp5cnnc8nrxrx49es67w0g0mahrdevdr28y6p94plqx5e49p6xw75mqdyu0v3xgg36yffx2ctyypqhyarfvdkx2w3qf35hxapqdanzqum9wfmxjcm9wvsxzcmrv4c8g6twvusx6ctfdehzytpzdy3r5g3jxp3njenyxdsj6ctrxajz6dp5v5uz6c3kvfsj6wrrxgerydf4v4nr2c33yf7scqzys4erahl43ezpxr4mra5cycehxtejs49tpqkv7plfzvy5pyc0xejnn7jtq0jgj68hk0tuensld0pace9ws5vesmhy5dak3cdrdlhdu54cpmtzjve
{ "code" : 204, "message" : "failed: WIRE_FEE_INSUFFICIENT (reply from remote)", "data" : { "erring_index" : 1, "failcode" : 4108, "erring_node" : "e16f593a1de837dbf53332da89800e0f0af0d3b947c9063fe30b3068b098f2cbcd369fe4e42e87fe1445ed1aa932983f8b43edf328a05a69955c21ff4c728733", "erring_channel" : "508211:1437:0", "channel_update" : "9b437cadaadb56871aebc12c3907ce790d508b86b1f41427d4be02b3ce3f58c1651ae800ddaa5159549c77450345877b79f55cc572233dc093bfb5f035894e956fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d619000000000007ba0b0005f000015a7c59010000000e00000000000003e8000003e80000000a" } }

getinfo output

$ lightning-cli getinfo
{ "id" : "0264089bc3a4afde671b87740d72e03d899b7f0783fbb756786cb7632b2e1db510", "port" : 9735, "address" :
        [
                { "type" : "ipv4", "address" : "163.172.162.18", "port" : 9735 } ], "version" : "v0.5.2-2016-11-21-1886-gb3d4e161", "blockheight" : 508265, "network" : "bitcoin" }

[ZmnSCPxj]

Yes, routing does not pay attention to the state of the local channels, it simply selects a short route. Currently routing depends on sendpay reporting failures, including local ones, so that it has an opportunity to temporarily mark routes unroutable on failure (open issue #611). If you have a lot of local channels, that cannot be used for routing (e.g. exhausted on your side) then it will take a lot of pay commands to disable all of them.

(routes are marked unroutable for only 20 seconds, in the optimistic hope that the condition changes within that time, so your pay loop probably needs to be automated)

Just keep retrying until you get a code 205 routing failure or a code 203 permanent failure at destination.

The UNUSUAL routing_failure is normal for local failures. It would be unusual for remote failures. I should probably change that...

[ZmnSCPxj]

"erring node" means the one that reported the error, not the node that is somehow erroneous. In your particular case "First peer not ready" means it is the communication with the peer that is problematic; it would be WIRE_UNKNOWN_NEXT_PEER if that peer is not yet in CHANNELD_NORMAL, and WIRE_TEMPORARY_CHANNEL_FAILURE if connection to the peer is down.

[hkjn]

Thanks for the reply and info, @ZmnSCPxj.

After rebuilding at d5effc (and closing some small channels, as well as waiting for others in weird closing states to go away, which might be related), failure shifted to:

{ "code" : 206, "message" : "Fee 1000 is 0.666667% of payment 150000; max fee requested is 0.500000%", "data" : { "fee" : 1000, "feepercent" : 0.666667, "msatoshi" : 150000, "maxfeepercent" : 0.500000 } } 

But overriding the maxfeepercent when making the payment allowed it to go through:

$ lightning-cli pay <bolt11> null null 1.0 0.8
{ "preimage" : [...] }

Since pay according to my understanding is supposed to be a relatively high-level command, is it planned to have it handle the mark-routes-as-unusable-and-retry logic itself, to avoid needing an external loop around pay?

I'll leave the ticket open based on your comment about UNUSUAL routing_failure message perhaps being inappropriate for local failures, but since there's no current issue with failing to send here, feel free to close at your discretion.

[ZmnSCPxj]

Since pay according to my understanding is supposed to be a relatively high-level command, is it planned to have it handle the mark-routes-as-unusable-and-retry logic itself, to avoid needing an external loop around pay?

Yes, that is #863, sorry I am somewhat blocked about it...

I'll leave the ticket open based on your comment about UNUSUAL routing_failure message perhaps being inappropriate for local failures, but since there's no current issue with failing to send here, feel free to close at your discretion.

Fixed by #962, so already done.

@cdecker, close please?

[hkjn]

Cool, thanks again. Closing.