First peer not ready: WIRE_TEMPORARY_CHANNEL_FAILURE

[Stadicus]

Trying to buy some stickers on mainnet without directly connecting to Blockstream, I connected to a few nodes and opened two channels:

From [A]: Stadicus.com
025f2cf835c0ca58be159e32e476a2386d8100d97fabf97e144e8e3e3f4829643e

To [B]: NHCS-Singapore
0371bcbde71d6cc591134e6d95592a9e8baac232a1e975ccd67c111864a5e8d373

To [C]: Wakuta
03e72d70b4e015bb3bee8a50deb32b6316a35d52b2333b5df66e36ed5e48ed102e

First, from [A] -> [B] (no channel to [C] yet), I always got the error
WIRE_TEMPORARY_CHANNEL_FAILURE "(reply from remote)

I then opened the second channel to [C]. Now, I always get the error
First peer not ready: WIRE_TEMPORARY_CHANNEL_FAILURE

I checked issue #751. The problem there seems that the partner node is offline. I am posting this issue, as

• my payment channels [C] is online, while [B] is offline
• the referenced issue Disable channel when losing the underlying connection #756 was merged a week ago (I cloned and compiled today)

lightning-cli getlog debug: https://pastebin.com/34nML1iT
lightning-cli getpeers: https://pastebin.com/VPaZibGe
lightning-cli listchannels: https://pastebin.com/w6usJ3HU

getinfo output

{
  "id": "025f2cf835c0ca58be159e32e476a2386d8100d97fabf97e144e8e3e3f4829643e",
  "port": 9735,
  "address": [
    {
      "type": "ipv4",
      "address": "91.190.22.151",
      "port": 9735
    }
  ],
  "version": "v0.5.2-2016-11-21-1797-gb7856e3",
  "blockheight": 507337,
  "network": "bitcoin"
}

[Stadicus]

After closing the offline channel, the payment is still routed through this channel and I get the error message:
First peer not ready: WIRE_UNKNOWN_NEXT_PEER

$ lightning-cli listpeers | jq
{
      "id": "0371bcbde71d6cc591134e6d95592a9e8baac232a1e975ccd67c111864a5e8d373",
      "connected": false,
      "channels": [
        {
          "state": "CHANNELD_SHUTTING_DOWN",
          "short_channel_id": "507322:1435:1",
          "funding_txid": "218ab9aa638e9c1a9bfca33b5d2aa7fd5728bd3ed4a89960551cfb6977cea980",
          "msatoshi_to_us": 500000000,
          "msatoshi_total": 500000000,
          "dust_limit_satoshis": 546,
          "max_htlc_value_in_flight_msat": 18446744073709552000,
          "channel_reserve_satoshis": 0,
          "htlc_minimum_msat": 0,
          "to_self_delay": 144,
          "max_accepted_htlcs": 483
        }
      ]
    }

$ lightning-cli getlog debug (excerpt)
{ "type" : "INFO", "time" : "5120.053605839", "source" : "lightningd(30697):", "log" : "peer 0371bcbde71d6cc591134e6d95592a9e8baac232a1e975ccd67c111864a5e8d373: State changed from CHANNELD_NORMAL to CHANNELD_SHUTTING_DOWN" }, 
{ "type" : "DEBUG", "time" : "5135.039554340", "source" : "lightning_gossipd(30706):", "log" : "TRACE: Trying to find a route from 025f2cf835c0ca58be159e32e476a2386d8100d97fabf97e144e8e3e3f4829643e to 02f6725f9c1c40333b67faea92fd211c183050f28df32cac3f9d69685fe9665432 for 174555230 msatoshi" }, 
{ "type" : "DEBUG", "time" : "5135.039668245", "source" : "lightning_gossipd(30706):", "log" : "TRACE: find_route: via 0371bcbde71d6cc591134e6d95592a9e8baac232a1e975ccd67c111864a5e8d373" }, 
{ "type" : "INFO", "time" : "5135.042219646", "source" : "lightningd(30697):", "log" : "Sending 174556404 over 2 hops to deliver 174555230" }, 
{ "type" : "INFO", "time" : "5135.042265660", "source" : "lightningd(30697):", "log" : "peer 0371bcbde71d6cc591134e6d95592a9e8baac232a1e975ccd67c111864a5e8d373: Attempt to send HTLC but not ready (CHANNELD_SHUTTING_DOWN)" }, 
{ "type" : "DEBUG", "time" : "5135.042304253", "source" : "lightningd(30697):jcon fd 14:", "log" : "Failing: First peer not ready: WIRE_UNKNOWN_NEXT_PEER" }, 

Full log: https://pastebin.com/gNAAFWX9

getroute still shows the route through the closing node

$ lightning-cli getroute 02f6725f9c1c40333b67faea92fd211c183050f28df32cac3f9d69685fe9665432 168115359 20
{ "route" : 
        [ 
                { "id" : "0371bcbde71d6cc591134e6d95592a9e8baac232a1e975ccd67c111864a5e8d373", "channel" : "507322:1435:1", "msatoshi" : 168116527, "delay" : 153 }, 
                { "id" : "02f6725f9c1c40333b67faea92fd211c183050f28df32cac3f9d69685fe9665432", "channel" : "506581:2015:1", "msatoshi" : 168115359, "delay" : 9 } ] }

[ZmnSCPxj]

Very strange. I am expecting a log message of the form "Reporting route failure to gossipd: ...". And from gossipd side I am expecting a log message of the form "Received routing failure ...". Neither appear in the logs.

So I investigated the message "First peer not ready". And lo, it is not, indeed, reported as a routing failure:

lightning/lightningd/pay.c

Lines 425 to 432 in ddf0529

	failcode = send_htlc_out(peer, route[0].amount,
	base_expiry + route[0].delay,
	rhash, onion, NULL, &hout);
	if (failcode) {
	command_fail(cmd, "First peer not ready: %s",
	onion_type_name(failcode));
	return false;
	}

Rather than calling command_fail directly it should trigger reporting of the failure, so that gossipd can learn it is not supposed to route over the sleeping node.

[Stadicus]

I can confirm: with the new build v0.5.2-2016-11-21-1814-g5f2cd7c and a few minutes of updating routes, the indirect payment [A] -> [C] -> Blockstream went through. Thanks for the incredible response time!