CHANNELD_AWAITING_LOCKIN after 65+ confirms

[fixone]

very recent client (compiled earlier today)

{
  "id": "0360a66958608a187e7d0c3e9f26ad445c60b9b649fc2674c0d25fc83ce82d850b",
  "port": 9735,
  "address": [
    {
      "type": "ipv4",
      "address": "188.166.99.121",
      "port": 9735
    }
  ],
  "version": "v0.5.2-2016-11-21-2037-g1192f16",
  "blockheight": 1284267,
  "network": "testnet"
}

with in-sync blockchain (bitcoin-cli getinfo shows the same height "blocks": 1284267)

peer channel funded and long confirmed, but state still AWAITING_LOCKIN

{
      "id": "0214187473a79a4f32590f645481a944ac7507cb7801d6cfa0671be4e17806e109",
      "connected": true,
      "netaddr": [
        "180.181.208.42:9735"
      ],
      "channels": [
        {
          "state": "CHANNELD_AWAITING_LOCKIN",
          "owner": "lightning_channeld",
          "short_channel_id": "1284202:80:0",
          "funding_txid": "8655516a362e39560a592aee24f653b8f649294b5f219231a59dc298a3658637",
          "msatoshi_to_us": 10000000000,
          "msatoshi_total": 10000000000,
          "dust_limit_satoshis": 546,
          "max_htlc_value_in_flight_msat": 18446744073709552000,
          "channel_reserve_satoshis": 0,
          "htlc_minimum_msat": 0,
          "to_self_delay": 6,
          "max_accepted_htlcs": 483
        }
      ]
    },

[cdecker]

Can you grep the logs for funding_locked? You should have received one (peer_in) and sent one (peer_out).

[fixone]

Here are all the occurences of funding locked

2018-02-21T11:47:37.344Z lightningd(3929): lightning_channeld-0214187473a79a4f32590f645481a944ac7507cb7801d6cfa0671be4e17806e109 chan #8: funding_locked: sending commit index 1: 0322064bf298e3caccb4c3881b175f183ca0c504bac65ccdb4a5455a017c5ddf8c
2018-02-21T12:30:20.117Z lightningd(3929): lightning_channeld-0231eee2441073c86d38f6085aedaf2bb7ad3d43af4c0e2669c1edd1a7d566ce31 chan #10: funding_locked: sending commit index 1: 03ee41378136e20322a86d234087cebe6fbe395b2f685496057a1fd33691d0319d
2018-02-21T12:30:27.461Z lightningd(3929): 0231eee2441073c86d38f6085aedaf2bb7ad3d43af4c0e2669c1edd1a7d566ce31 chan #10: Got funding_locked
2018-02-21T12:31:53.267Z lightningd(3929): 0315c5d0d75a6557d6378afe948911983d48886fe1542478a7493e8685dc7b5ef8 chan #13: Got funding_locked
2018-02-21T12:32:00.236Z lightningd(3929): lightning_channeld-0315c5d0d75a6557d6378afe948911983d48886fe1542478a7493e8685dc7b5ef8 chan #13: funding_locked: sending commit index 1: 0341e0d3b261a95fed42b4e1ed53d12afcf2c78a1d33cfb461c1b48661ddce5c09
2018-02-21T20:02:31.077Z lightningd(22080): lightning_channeld-0214187473a79a4f32590f645481a944ac7507cb7801d6cfa0671be4e17806e109 chan #8: funding_locked: sending commit index 1: 0322064bf298e3caccb4c3881b175f183ca0c504bac65ccdb4a5455a017c5ddf8c
2018-02-21T20:43:35.929Z lightningd(22080): 027e92b4fa1988ae5b0d44b87da80ab8875312fdae6631a8896851bc41857e66aa chan #22: Got funding_locked
2018-02-21T20:43:43.366Z lightningd(22080): lightning_channeld-033dd7f388fdbf33915c68b548883b899516a8ed7da14ae5eff03ad9f9ab1fe7ad chan #17: funding_locked: sending commit index 1: 038a89dcd4439348d45eb6dcc9d30d68b30e12a2bed3b6a0aac2766021f1de4324
2018-02-21T20:43:43.367Z lightningd(22080): lightning_channeld-027e92b4fa1988ae5b0d44b87da80ab8875312fdae6631a8896851bc41857e66aa chan #22: funding_locked: sending commit index 1: 0372ecc4d1c1a0b14515d840a432e001dd2f5956951a28a4eda2105a49f9979155
2018-02-21T20:43:43.530Z lightningd(22080): 033dd7f388fdbf33915c68b548883b899516a8ed7da14ae5eff03ad9f9ab1fe7ad chan #17: Got funding_locked
2018-02-21T21:02:01.706Z lightningd(22080): 03e103d5679dc41b96a0d11d8a9c359f9ee6f2eb3ba0e14e72d2b1918d03439d72 chan #16: Got funding_locked
2018-02-21T21:02:01.767Z lightningd(22080): 0316b3d2fac93a0638994b198ef19a548ad141874dc102c4b779feb3930bc46e20 chan #18: Got funding_locked
2018-02-21T21:02:04.362Z lightningd(22080): lightning_channeld-03e103d5679dc41b96a0d11d8a9c359f9ee6f2eb3ba0e14e72d2b1918d03439d72 chan #16: funding_locked: sending commit index 1: 020f2ccc8016e79a3874fcec7a390381da9c5fc246d86ea4df27277947fc9fedc2
2018-02-21T21:02:04.363Z lightningd(22080): lightning_channeld-0316b3d2fac93a0638994b198ef19a548ad141874dc102c4b779feb3930bc46e20 chan #18: funding_locked: sending commit index 1: 0326fbd37fdd4d10c2cace194f7758d365811593ab4cd7924649e3b02722d431ad

I have multiple channels and for reference here's the full listpeers

{
  "peers": [
    {
      "id": "0214187473a79a4f32590f645481a944ac7507cb7801d6cfa0671be4e17806e109",
      "connected": true,
      "netaddr": [
        "180.181.208.42:9735"
      ],
      "channels": [
        {
          "state": "CHANNELD_AWAITING_LOCKIN",
          "owner": "lightning_channeld",
          "short_channel_id": "1284202:80:0",
          "funding_txid": "8655516a362e39560a592aee24f653b8f649294b5f219231a59dc298a3658637",
          "msatoshi_to_us": 10000000000,
          "msatoshi_total": 10000000000,
          "dust_limit_satoshis": 546,
          "max_htlc_value_in_flight_msat": 18446744073709552000,
          "channel_reserve_satoshis": 0,
          "htlc_minimum_msat": 0,
          "to_self_delay": 6,
          "max_accepted_htlcs": 483
        }
      ]
    },
    {
      "id": "0231eee2441073c86d38f6085aedaf2bb7ad3d43af4c0e2669c1edd1a7d566ce31",
      "connected": true,
      "netaddr": [
        "77.251.249.36:9735"
      ],
      "channels": [
        {
          "state": "CHANNELD_NORMAL",
          "owner": "lightning_channeld",
          "short_channel_id": "1284205:31:0",
          "funding_txid": "f43f941d5e42683a2ee2f6bcfb5de7457380db5fff2ea6f982c33de66a4d0536",
          "msatoshi_to_us": 1000000000,
          "msatoshi_total": 1000000000,
          "dust_limit_satoshis": 546,
          "max_htlc_value_in_flight_msat": 18446744073709552000,
          "channel_reserve_satoshis": 0,
          "htlc_minimum_msat": 0,
          "to_self_delay": 6,
          "max_accepted_htlcs": 483
        }
      ]
    },
    {
      "id": "0315c5d0d75a6557d6378afe948911983d48886fe1542478a7493e8685dc7b5ef8",
      "connected": true,
      "netaddr": [
        "73.217.109.197:9735"
      ],
      "channels": [
        {
          "state": "CHANNELD_NORMAL",
          "owner": "lightning_channeld",
          "short_channel_id": "1284206:15:0",
          "funding_txid": "7a90d275f40ac8cc8f9299caa39e2c9d50fbc954c423a0b1e7a54af185de8801",
          "msatoshi_to_us": 10000000000,
          "msatoshi_total": 10000000000,
          "dust_limit_satoshis": 546,
          "max_htlc_value_in_flight_msat": 18446744073709552000,
          "channel_reserve_satoshis": 0,
          "htlc_minimum_msat": 0,
          "to_self_delay": 6,
          "max_accepted_htlcs": 483
        }
      ]
    },
    {
      "id": "03e103d5679dc41b96a0d11d8a9c359f9ee6f2eb3ba0e14e72d2b1918d03439d72",
      "connected": true,
      "netaddr": [
        "188.166.39.247:9735"
      ],
      "channels": [
        {
          "state": "CHANNELD_NORMAL",
          "owner": "lightning_channeld",
          "short_channel_id": "1284270:174:0",
          "funding_txid": "40cc700b1dd51f1eb5ed16f3fbc0de21807946b77ab0e4cca057b45bc379a281",
          "msatoshi_to_us": 1000000000,
          "msatoshi_total": 1000000000,
          "dust_limit_satoshis": 546,
          "max_htlc_value_in_flight_msat": 18446744073709552000,
          "channel_reserve_satoshis": 0,
          "htlc_minimum_msat": 0,
          "to_self_delay": 6,
          "max_accepted_htlcs": 483
        }
      ]
    },
    {
      "id": "033dd7f388fdbf33915c68b548883b899516a8ed7da14ae5eff03ad9f9ab1fe7ad",
      "connected": true,
      "netaddr": [
        "67.180.192.3:9735"
      ],
      "channels": [
        {
          "state": "CHANNELD_NORMAL",
          "owner": "lightning_channeld",
          "short_channel_id": "1284270:175:0",
          "funding_txid": "ec84b4163e6ccf0a0859fb57d441fcb9b99d4abb18dc28fd8d14413cb45a7351",
          "msatoshi_to_us": 1000000000,
          "msatoshi_total": 1000000000,
          "dust_limit_satoshis": 546,
          "max_htlc_value_in_flight_msat": 18446744073709552000,
          "channel_reserve_satoshis": 0,
          "htlc_minimum_msat": 0,
          "to_self_delay": 6,
          "max_accepted_htlcs": 483
        }
      ]
    },
    {
      "id": "0316b3d2fac93a0638994b198ef19a548ad141874dc102c4b779feb3930bc46e20",
      "connected": true,
      "netaddr": [
        "142.4.213.42:9736"
      ],
      "channels": [
        {
          "state": "CHANNELD_NORMAL",
          "owner": "lightning_channeld",
          "short_channel_id": "1284270:176:0",
          "funding_txid": "e1dbd7017e58a2bab7599fe80793c748ab8441a6cbe3821724bbdfbd9e51b92c",
          "msatoshi_to_us": 1000000000,
          "msatoshi_total": 1000000000,
          "dust_limit_satoshis": 546,
          "max_htlc_value_in_flight_msat": 18446744073709552000,
          "channel_reserve_satoshis": 0,
          "htlc_minimum_msat": 0,
          "to_self_delay": 6,
          "max_accepted_htlcs": 483
        }
      ]
    },
    {
      "id": "027e92b4fa1988ae5b0d44b87da80ab8875312fdae6631a8896851bc41857e66aa",
      "connected": true,
      "netaddr": [
        "133.18.23.0:9735"
      ],
      "channels": [
        {
          "state": "CHANNELD_NORMAL",
          "owner": "lightning_channeld",
          "short_channel_id": "1284270:177:0",
          "funding_txid": "c590a2cde116c74cd04facd2364ee6b8b9b667b92f56cc52bec5d1b5c724bb87",
          "msatoshi_to_us": 1000000000,
          "msatoshi_total": 1000000000,
          "dust_limit_satoshis": 546,
          "max_htlc_value_in_flight_msat": 18446744073709552000,
          "channel_reserve_satoshis": 0,
          "htlc_minimum_msat": 0,
          "to_self_delay": 6,
          "max_accepted_htlcs": 483
        }
      ]
    }
  ]
}

[fixone]

The relevant lines seem to be these, right?

2018-02-21T11:47:37.344Z lightningd(3929): lightning_channeld-0214187473a79a4f32590f645481a944ac7507cb7801d6cfa0671be4e17806e109 chan #8: funding_locked: sending commit index 1: 0322064bf298e3caccb4c3881b175f183ca0c504bac65ccdb4a5455a017c5ddf8c
2018-02-21T20:02:31.077Z lightningd(22080): lightning_channeld-0214187473a79a4f32590f645481a944ac7507cb7801d6cfa0671be4e17806e109 chan #8: funding_locked: sending commit index 1: 0322064bf298e3caccb4c3881b175f183ca0c504bac65ccdb4a5455a017c5ddf8c
2018-02-22T08:58:20.090Z lightningd(32119): lightning_channeld-0214187473a79a4f32590f645481a944ac7507cb7801d6cfa0671be4e17806e109 chan #8: funding_locked: sending commit index 1: 0322064bf298e3caccb4c3881b175f183ca0c504bac65ccdb4a5455a017c5ddf8c

but there's not "Got funding_locked" for this peer

[cdecker]

Yeah, that's likely the issue, we never get a funding locked, so we can't proceed. The remote node may be faulty. Not much we can do on our side, other than just dev-failing it 😞

[daldwinc]

Unfortunately, this just happened to me as well. One is a channel that I opened, and one is a channel that was opened by the peer.

@cdecker if there is no "got funding_locked" for the peers, is there any point in waiting or has it failed permanently?

lightning-cli listpeers
<trimmed for brevity>

		{ "id" : "0235447c7485ff2b945bac5fbc366d54a87389bab8cacf1b64b26ec01e96bd165a", "connected" : true, "netaddr" : 
			[ "34.236.113.58:9735" ], "channels" : 
			[ 
				{ "state" : "CHANNELD_AWAITING_LOCKIN", "owner" : "lightning_channeld", "short_channel_id" : "510205:1239:0", "funding_txid" : "23f465879f6ab5b6d6ace
b8e4c2c77932ebee6ff7f231adc932e01bd2e89e31c", "msatoshi_to_us" : 0, "msatoshi_total" : 200000000, "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" : "02dcdd7e18b80dc7fd51af34e871901c13f574e4b82325dc74c0beeada5771e8e9", "connected" : true, "netaddr" : 
			[ "[::ffff:138.68.14.201]:43130" ], "channels" : 
			[ 
				{ "state" : "CHANNELD_AWAITING_LOCKIN", "owner" : "lightning_channeld", "short_channel_id" : "510258:1222:1", "funding_txid" : "4c9fc865927891b429c5e
fe2b8b0ea709291f9820f2381f800c052be72fdc376", "msatoshi_to_us" : 175000000, "msatoshi_total" : 175000000, "dust_limit_satoshis" : 546, "max_htlc_value_in_flight_msat" : 184467440737
09551615, "channel_reserve_satoshis" : 0, "htlc_minimum_msat" : 0, "to_self_delay" : 144, "max_accepted_htlcs" : 483 } ] } ] }

... and off-topic, why does @fixone have such well-formatted output and mine looks like mashed potatoes?

lightning-cli getinfo
{ "id" : "03e72d70b4e015bb3bee8a50deb32b6316a35d52b2333b5df66e36ed5e48ed102e", "port" : 9735, "address" : 
	[ 
		{ "type" : "ipv4", "address" : "129.97.243.18", "port" : 9735 } ], "version" : "v0.5.2-2016-11-21-2040-g3dbace3", "blockheight" : 510401, "network" : "bitcoin" }

[cdecker]

Hard to say @daldwinc, it could recover, but it seems unlikely, it seems you are connected to the peer ("connected": true on both peers, that could have been another issue. It could be either an incompatibility between the clients (I hope not...) or the peer simply is lagging behind on the blockchain.

[fixone]

easier said than done, dev-fail seems to do nothing

lnc dev-fail 0214187473a79a4f32590f645481a944ac7507cb7801d6cfa0671be4e17806e109
{  }
lnc dev-fail 0214187473a79a4f32590f645481a944ac7507cb7801d6cfa0671be4e17806e109
{  }
lnc dev-fail 0214187473a79a4f32590f645481a944ac7507cb7801d6cfa0671be4e17806e109
{  }

and listpeers shows it still there

{
      "id": "0214187473a79a4f32590f645481a944ac7507cb7801d6cfa0671be4e17806e109",
      "connected": false,
      "channels": [
        {
          "state": "CHANNELD_AWAITING_LOCKIN",
          "short_channel_id": "1284202:80:0",
          "funding_txid": "8655516a362e39560a592aee24f653b8f649294b5f219231a59dc298a3658637",
          "msatoshi_to_us": 10000000000,
          "msatoshi_total": 10000000000,
          "dust_limit_satoshis": 546,
          "max_htlc_value_in_flight_msat": 18446744073709552000,
          "channel_reserve_satoshis": 0,
          "htlc_minimum_msat": 0,
          "to_self_delay": 6,
          "max_accepted_htlcs": 483
        }
      ]
    }

[cdecker]

@fixone do the logs contain a hex encoded transaction? IIRC onchaind will spawn once that unilateral close transaction gets confirmed and it'll also move the state forward.

[fixone]

yes, there's
2018-02-22T18:12:39.778Z lightningd(32119): 0214187473a79a4f32590f645481a944ac7507cb7801d6cfa0671be4e17806e109 chan #8: Peer internal error CHANNELD_AWAITING_LOCKIN:
2018-02-22T18:12:39.778Z lightningd(32119): 0214187473a79a4f32590f645481a944ac7507cb7801d6cfa0671be4e17806e109 chan #8: ... Failing due to dev-fail command
2018-02-22T18:12:39.778Z lightningd(32119): 0214187473a79a4f32590f645481a944ac7507cb7801d6cfa0671be4e17806e109 chan #8: Peer permanent failure in CHANNELD_AWAITING_LOCKIN: Internal error
2018-02-22T18:12:39.778Z lightningd(32119): (tx 9c4306b8c128e97a8195f0c2689d78793263e9813aa0593baf5d5edee19cfffc)
2018-02-22T18:12:39.778Z lightningd(32119): sendrawtransaction: 02000000000101378665a398c29da53192215f4b2949f6b853f624ee2a590a56392e366a5155860000000000756e988001c9959800000000002200204dfb1
12695b3a28bf7434f1aed58afde2a1e2a00c6e386a343027448544ade1c040047304402205443257d9805f5e1af2601f185c4ac10cd2cb8a9eb9c67376a6b8a768cecc8d902202e79bf2328032dfee2af25d9e79fdba7e718fc74e687d4b3
585a78023afd09c701473044022047d0a1e0ecdadbfad06901c50c0ce195edcc433f695df9bf1722a83044faef3502202fb9dd420d3239983a83a271b1032b9fe2a2fc74ee47e85882b4b1495ac5e46201475221029a6fef726214297e114
9d59fc27580a073eb89e5c477df81da112a663418fa922103bf1356133eeabcdd5e3c4ce987c83597d66706a6f703af1067e871705d64fb5952aef33c8720
2018-02-22T18:12:39.779Z lightningd(32119):jcon fd 16: Success

@daldwinc : the secret lies in jq, which comes in handy when dealing with json output on the command line. And ofc can be used to automate stuff, for instance
list all visible nodes with id, IP and port (just right for connect)

~/lightning/cli/lightning-cli listnodes | jq '.nodes | .[]  | select ((.addresses|length)>0) | select ((.addresses|.[0].type)=="ipv4") |  "\(.nodeid) \(.addresses[0].address):\(.addresses[0].port)"'

or getting a simplified output (just {peer} is in {state}

~/lightning/cli/lightning-cli listpeers | jq -r '.peers | to_entries[] | .value.channels[].state +" with peer "+  .value.id'

[fixone]

@cdecker once the dev-fail transaction (in the example above 9c4306b8c128e97a8195f0c2689d78793263e9813aa0593baf5d5edee19cfffc) is propagated, it needs the 144 confirms until the funds show back up, right?

[cdecker]

@fixone yeah, listpeers should list the channel as ONCHAIND_OUR_UNILATERAL, right? It should be done in 144 blocks 👍

[Alex-CodeLab]

Can confirm. I have a similar situation. Both sides of the channel have recent c-lightning (both mine), and show the same info :

"connected" : true,
...
{ "state" : "CHANNELD_AWAITING_LOCKIN",
"owner" : "lightning_channeld",
"funding_txid" : "d97e76ebc886d95de9d1b796c70b4965f105c3552691c0e79a961499785e3886", "msatoshi_to_us" : 0,
"msatoshi_total" : 1000000000,
"dust_limit_satoshis" : 546,
"max_htlc_value_in_flight_msat" : 18446744073709551615,
"channel_reserve_satoshis" : 0,
"htlc_minimum_msat" : 0,
"to_self_delay" : 2, "max_accepted_htlcs" : 483 }

[update: no change after 144+ blocks ]

[ZmnSCPxj]

Maybe we should have a timeout between funding tx confirmation to receive of funding_locked, then automatically fail the channel if no funding_locked from peer? This will at least reduce our risk from faulty peers.

[bitonic-cjp]

I think I am currently on the "bad" side of such a channel, with C-Lightning: I have a channel that stays on CHANNELD_AWAITING_LOCKIN while it already has 12+ confirms. When I grep for funding_locked, I get (for the relevant channel):

2018-02-23T13:19:52.371Z lightningd(28478): 02ff725de0dca7565b1a2ed6c60790d88e693d6fd7192e4104bc6ada4b32515e00 chan #2: Got funding_locked

Correct me if I'm wrong, but I think this means my peer told me it got locked, but I haven't said the same yet.

Could it be because I'm still getting loads of "Adding block ..." messages in the log? It has been running like that since the morning, and based on the block height it's at now, it won't be finished until the evening. I'll probably shut down my node before that; it'll probably restart the next day.

[cdecker]

@bitonic-cjp yes, you need to be up to date with the blockchain, it should start rescanning at the height you created the first channel, but there are some corner cases in which the rescan height seems to be reset to 0. What blockheight is it currently adding?