failed: WIRE_EXPIRY_TOO_SOON (reply from remote)

[sfmcnally]

while attempting to send a payment I get the following error:

lightning-cli pay lnbc565992510p1pd8xucypp58k5h2ajge5cvhjvyj4ffx38g59ha9k8s49neh42lpwg834t2gsfqdzsgfkx7cmtwd68yetpd5azqdpw8yujq42ngssxvmeqv9hxggzvd9nksarwd9hxwgznw35kx6m9wgs8sgp3cqpgd922x80d34ayxl46ff9a5uv6qzu9ca9cfy9ts7mernq47pam8jfr9rzlu3wn7zfcrtrf0rg7wj754tre20ty3yzc6mek6h9q70ng0pgqc7r7aa
lightningd(22294): Sending 56600873 over 2 hops to deliver 56599251
lightningd(22294): peer 029efce538a7f6ba7873b1bd00e0028ca39a658b96af326d349fa45bfa34226073: htlc 11 failed from 0th node with code 0x100e (WIRE_EXPIRY_TOO_SOON)
{ "code" : -1, "message" : "failed: WIRE_EXPIRY_TOO_SOON (reply from remote)" }

[cdecker]

Was your blockchain up to date? The expiry time is computed from the current block height, so if lightningd or bitcoind lags behind the current block height then the expiry will be wrong.

[sfmcnally]

It looks like bitcoind is up to date and lightningd is behind. I'll wait for it to catch up and try again.

[cdecker]

Notice that we recently fixed a bug that caused lightningd to lag behind bitcoind indefinitely. You might need to update to latest master

[sfmcnally]

I updated around 10am. Was it that recent?

[cdecker]

No, you should have it then ^^

[sfmcnally]

well, that error cleared, but it's just a different error now. WIRE_TEMPORARY_CHANNEL_FAILURE

[sfmcnally]

It's alternating between that error and WIRE_UNKNOWN_NEXT_PEER despite two channeld_normal channels.

[sfmcnally]

I'm starting to think I need to close everything, wait for funds to settle, and start from scratch. I fear I have compounded errors in my database. If it will help with development, I will continue to troubleshoot. Otherwise I'm gonna delete everything c-lightning start from a clean slate tomorrow.

[cdecker]

Are both hops yours? Those error might be coming from the intermediate node, not your own.

[sfmcnally]

no, both hops are not mine. I'm connected to two nodes (other people's nodes) with state channeld_normal. getroute works correctly, but pay fails every time.

I'm connected to
029efce538a7f6ba7873b1bd00e0028ca39a658b96af326d349fa45bfa34226073@173.71.149.66:9735

and

035f1498c929d4cefba4701ae36a554691f526ff60b1766badd5a49b3c8b68e1d8@78.63.23.25:9735

[cdecker]

I can't see the route you would have taken, but I think that simply the intermediate hop lost connection (or closed the channel) with the destination, hence the WIRE_UNKNOWN_NEXT_PEER. With #638 merged the channel should be disabled and you should be able to try again.

[darkobodnaruk]

I'm having the same problem.

• cli/lightning-cli dev-blockheight shows the right height (compared to blockchain.info)
• I get WIRE_EXPIRY_TOO_SOON, as far as I can tell it's from the first node in route
• first node is one of the best connected public nodes: (rompert.com) 03cbf298b068300be33f06c947b9d3f00a0f0e8089da3233f5db37e81d3a596fe1@45.55.47.17:9735 (found on https://lnmainnet.gaben.win)

Maybe there's an issue with that node and I should close the channel and try opening another one to a different node?

[cdecker]

Can you show us the result of a getroute [dest] [amount] 1 call? That should tell us more about the expiry delta that is given to the route.

[darkobodnaruk]

@cdecker sure:

{ "route" :
	[
		{ "id" : "03cbf298b068300be33f06c947b9d3f00a0f0e8089da3233f5db37e81d3a596fe1", "channel" : "507501:605:1", "msatoshi" : 122212514, "delay" : 17 },
		{ "id" : "03447c9f9d17a6f082dcf4cf97e8949e3fe6fd704baa54560aef0d742593659d15", "channel" : "505728:647:0", "msatoshi" : 122212392, "delay" : 13 },
		{ "id" : "02f6725f9c1c40333b67faea92fd211c183050f28df32cac3f9d69685fe9665432", "channel" : "505888:1513:1", "msatoshi" : 122212270, "delay" : 9 } ] }

[darkobodnaruk]

Also, here's the debug output from lightningd (for the pay command) https://gist.github.com/darkobodnaruk/0f1c41ee877369878cc1c76b15528171

I'd be happy to take a hint on how to begin reading this ;)

[darkobodnaruk]

I am now getting WIRE_FEE_INSUFFICIENT, even though there seems to be plenty in the channel?

listpeers

{ "peers" :
	[
		{ "id" : "03cbf298b068300be33f06c947b9d3f00a0f0e8089da3233f5db37e81d3a596fe1", "connected" : true, "netaddr" :
			[ "45.55.47.17:9735" ], "channels" :
			[
				{ "state" : "CHANNELD_NORMAL", "owner" : "lightning_channeld", "short_channel_id" : "507501:605:1", "funding_txid" : "a0aa584d4368d23d773042ee738e7a50fe32f23caf2586073df1f484299b5c13", "msatoshi_to_us" : 190000000, "msatoshi_total" : 190000000, "dust_limit_satoshis" : 546, "max_htlc_value_in_flight_msat" : 18446744073709551615, "channel_reserve_satoshis" : 0, "htlc_minimum_msat" : 0, "to_self_delay" : 144, "max_accepted_htlcs" : 483 } ] },
		{ "state" : "GOSSIPING", "id" : "0273cc3eb00a38faa0900c8df609ae7075846c80d256b93a30bb8fe601140ecdcf", "netaddr" :
			[ "[::ffff:62.210.36.166]:34176" ], "connected" : true, "owner" : "lightning_gossipd" },
		{ "state" : "GOSSIPING", "id" : "0327cfb815071450a424aa791431e53d25b5fe7b7b18f80729af88316eeeff5423", "netaddr" :
			[ "[::ffff:62.210.252.112]:54108" ], "connected" : true, "owner" : "lightning_gossipd" } ] }

getroute

{ "route" :
	[
		{ "id" : "03cbf298b068300be33f06c947b9d3f00a0f0e8089da3233f5db37e81d3a596fe1", "channel" : "507501:605:1", "msatoshi" : 106748189, "delay" : 167 },
		{ "id" : "030b63bb79bfe2731bccf3ca753224db31a6486ed5fc69c4e5f355263b9b4fd195", "channel" : "508272:1742:1", "msatoshi" : 106747083, "delay" : 23 },
		{ "id" : "02f6725f9c1c40333b67faea92fd211c183050f28df32cac3f9d69685fe9665432", "channel" : "508272:1740:0", "msatoshi" : 106745016, "delay" : 9 } ] }

[cdecker]

Sorry for the delay in looking at this. Checking the routing table it seems that we are indeed chosing a delay that is too small:

$ lightning-cli listchannels | jq '.channels[] | select(.short_channel_id == "507501:605:1")' {
  "source": "021177240c2ec0f9ad564fffb76a810dcb0b21b1136380014689accd307c4e1c1c",
  "destination": "03cbf298b068300be33f06c947b9d3f00a0f0e8089da3233f5db37e81d3a596fe1",
  "short_channel_id": "507501:605:1",
  "flags": 0,
  "active": true,
  "public": true,
  "last_update": 1518125932,
  "base_fee_millisatoshi": 1000,
  "fee_per_millionth": 10,
  "delay": 14
}
{
  "source": "03cbf298b068300be33f06c947b9d3f00a0f0e8089da3233f5db37e81d3a596fe1",
  "destination": "021177240c2ec0f9ad564fffb76a810dcb0b21b1136380014689accd307c4e1c1c",
  "short_channel_id": "507501:605:1",
  "flags": 1,
  "active": true,
  "public": true,
  "last_update": 1518120127,
  "base_fee_millisatoshi": 1100,
  "fee_per_millionth": 12000000,
  "delay": 144
}

Which if I'm not mistake requires the delay difference between hop1 and hop2 to be at least 14, but it is only 4. Could you try to run the above command as well and see if your node also sees the channel like this? The deltas seem to be generally a bit off.

[cdecker]

For reference, when I try to route from your node 021177240c2ec0f9ad564fffb76a810dcb0b21b1136380014689accd307c4e1c1c to the second hop 03447c9f9d17a6f082dcf4cf97e8949e3fe6fd704baa54560aef0d742593659d15 I get the following:

lightning-cli getroute 03447c9f9d17a6f082dcf4cf97e8949e3fe6fd704baa54560aef0d742593659d15 1 1 9 021177240c2ec0f9ad564fffb76a810dcb0b21b1136380014689accd307c4e1c1c
{ "route" : 
	[ 
		{ "id" : "03cbf298b068300be33f06c947b9d3f00a0f0e8089da3233f5db37e81d3a596fe1", "channel" : "507501:605:1", "msatoshi" : 1113, "delay" : 153 }, 
		{ "id" : "03447c9f9d17a6f082dcf4cf97e8949e3fe6fd704baa54560aef0d742593659d15", "channel" : "505728:647:0", "msatoshi" : 1, "delay" : 9 } ] }

Notice the much higher expiry delta of 144 as per routing table.

[darkobodnaruk]

Hey, thanks for the response. Yes, I'm getting the same result for getroute:

cli/lightning-cli listchannels | jq '.channels[] | select(.short_channel_id == "507501:605:1")'
{
  "source": "03cbf298b068300be33f06c947b9d3f00a0f0e8089da3233f5db37e81d3a596fe1",
  "destination": "021177240c2ec0f9ad564fffb76a810dcb0b21b1136380014689accd307c4e1c1c",
  "short_channel_id": "507501:605:1",
  "flags": 1,
  "active": true,
  "public": true,
  "last_update": 1518120127,
  "base_fee_millisatoshi": 1100,
  "fee_per_millionth": 12000000,
  "delay": 144
}
{
  "source": "021177240c2ec0f9ad564fffb76a810dcb0b21b1136380014689accd307c4e1c1c",
  "destination": "03cbf298b068300be33f06c947b9d3f00a0f0e8089da3233f5db37e81d3a596fe1",
  "short_channel_id": "507501:605:1",
  "flags": 0,
  "active": true,
  "public": true,
  "last_update": 1518196785,
  "base_fee_millisatoshi": 1000,
  "fee_per_millionth": 10,
  "delay": 14
}

If I understand correctly, the delay is something that my node should calculate and set it according to what the channels in the route require (e.g. 144), but it's actually setting it to lower values (e.g. 4)?

[darkobodnaruk]

Meanwhile, I've opened another channel and succesfully bought myself a few stickers so I'm a happy camper :)

But I'm still interested in this so I'm trying to recreate the previous situation. But now I have another problem.

My listpeers is this:

{ "peers" :
  [
    { "id" : "03cbf298b068300be33f06c947b9d3f00a0f0e8089da3233f5db37e81d3a596fe1", "connected" : true, "netaddr" :
      [ "[::ffff:45.55.47.17]:41464" ], "channels" :
      [
        { "state" : "CHANNELD_NORMAL", "owner" : "lightning_channeld", "short_channel_id" : "507501:605:1", "funding_txid" : "a0aa584d4368d23d773042ee738e7a50fe32f23caf2586073df1f484299b5c13", "msatoshi_to_us" : 190000000, "msatoshi_total" : 190000000, "dust_limit_satoshis" : 546, "max_htlc_value_in_flight_msat" : 18446744073709551615, "channel_reserve_satoshis" : 0, "htlc_minimum_msat" : 0, "to_self_delay" : 144, "max_accepted_htlcs" : 483 } ] },
    { "id" : "02d202d2d50a7da4730eb3d91c389906e5c4506dac78622d2714bc6daa7daa3700", "connected" : true, "netaddr" :
      [ "89.166.109.218:9735" ], "channels" :
      [
        { "state" : "CHANNELD_NORMAL", "owner" : "lightning_channeld", "short_channel_id" : "508293:1330:1", "funding_txid" : "5b35fded170e2b6a95d858f537198d5f99745ac4c81222aebc5bd0a4f15c37fa", "msatoshi_to_us" : 30540962, "msatoshi_total" : 138790000, "dust_limit_satoshis" : 546, "max_htlc_value_in_flight_msat" : 18446744073709551615, "channel_reserve_satoshis" : 0, "htlc_minimum_msat" : 0, "to_self_delay" : 144, "max_accepted_htlcs" : 483 } ] },
    { "id" : "034a5fdb2df3ce1bfd2c2aca205ce9cfeef1a5f4af21b0b5e81c453080c30d7683", "connected" : true, "netaddr" :
      [ "[::ffff:24.86.243.10]:37608" ], "channels" :
      [
        { "state" : "CHANNELD_NORMAL", "owner" : "lightning_channeld", "short_channel_id" : "508320:2071:0", "funding_txid" : "eefbbc885c64037ada5c3a3dd7c0c8a6eeb56f51e918e8513ff3e67a78a5b048", "msatoshi_to_us" : 0, "msatoshi_total" : 1050000, "dust_limit_satoshis" : 546, "max_htlc_value_in_flight_msat" : 18446744073709551615, "channel_reserve_satoshis" : 0, "htlc_minimum_msat" : 0, "to_self_delay" : 144, "max_accepted_htlcs" : 483 } ] },
    { "state" : "GOSSIPING", "id" : "0327cfb815071450a424aa791431e53d25b5fe7b7b18f80729af88316eeeff5423", "netaddr" :
      [ "[::ffff:62.210.252.112]:60402" ], "connected" : true, "owner" : "lightning_gossipd" },
    { "state" : "GOSSIPING", "id" : "0273cc3eb00a38faa0900c8df609ae7075846c80d256b93a30bb8fe601140ecdcf", "netaddr" :
      [ "[::ffff:62.210.36.166]:34770" ], "connected" : true, "owner" : "lightning_gossipd" },
    { "state" : "GOSSIPING", "id" : "03a3c1fc0a489e2872a2afe8fa16c2714b5fe80d52d8c1ce8ecc4361a77391da82", "netaddr" :
      [ "[::ffff:138.68.252.183]:36068" ], "connected" : true, "owner" : "lightning_gossipd" },
    { "state" : "GOSSIPING", "id" : "031c527494f295220d26a1814c18e7db3f4f03203ce1a53a0b74b52ed570a3972a", "netaddr" :
      [ "[::ffff:24.4.228.213]:42418" ], "connected" : true, "owner" : "lightning_gossipd" } ] }

If I now try to find a route for 100M msatoshi, it should only be able to through channel 507501:605:1 - the one I was debugging before - because it's the only one with enough funds (190M msat).

But getroute shows a route through another peer/channel with only 30M msat:

cli/lightning-cli getroute 03447c9f9d17a6f082dcf4cf97e8949e3fe6fd704baa54560aef0d742593659d15 100000000 1 9
{ "route" :
  [
    { "id" : "02d202d2d50a7da4730eb3d91c389906e5c4506dac78622d2714bc6daa7daa3700", "channel" : "508293:1330:1", "msatoshi" : 100002000, "delay" : 23 },
    { "id" : "03447c9f9d17a6f082dcf4cf97e8949e3fe6fd704baa54560aef0d742593659d15", "channel" : "507766:1675:0", "msatoshi" : 100000000, "delay" : 9 } ] }

Am I misunderstanding something? (Thanks for your patience :)

[cdecker]

Thanks @darkobodnaruk for the update, glad it worked out with the new channel. It's really strange that the routing algo would choose to set a delta of 4, when it knows about the larger delta required by the channel. At the moment I can't really reproduce it, but I'll keep an eye open for it.

Regarding us choosing the channel with insufficient capacity, that's ok, with #638 merged we now hand back these failures to gossipd which temporarily disables the channel for the next routing attempt, so if you try to pay the first attempt will fail, but retrying should succeed (before the 20 seconds timeout re-enables the channel). We will eventually optimize the first hop of the payment to look for sufficient capacity.