Stuck htlc after payment

[grunch]

Background

I had two nodes on testnet, a neutrino node (0.10.0-beta.rc2 commit=v0.10.0-beta.rc2-4-g9c4f9416d53b523b00ee34e5cb1dcd834c33e1e0) and a lnd full node (0.9.0-beta commit=v0.9.0-beta-469-gd04bc200e75ff47e41e6298d610221d44cb94058)

I opened a channel from neutrino to lnd for 4000000 sats, after confirmations the channels was working properly, then I created an invoice on lnd and it was paid by the neutrino node, after the payment the channel between both nodes changed to "active": false, showing the htlc in pending_htlcs.

This is the channel info

        {
            "active": false,
            "remote_pubkey": "022cfd97528beb47c1684c81b97137915f9f20b64187a3bee80532d4d09976774c",
            "channel_point": "7bd908fbb2237ca4964b9cbe78b39bc85b5ee2864a182434605a1d798eedf8c6:1",
            "chan_id": "1891407389894377473",
            "capacity": "4000000",
            "local_balance": "2999774",
            "remote_balance": "0",
            "commit_fee": "226",
            "commit_weight": "772",
            "fee_per_kw": "253",
            "unsettled_balance": "1000000",
            "total_satoshis_sent": "0",
            "total_satoshis_received": "0",
            "num_updates": "1",
            "pending_htlcs": [
                {
                    "incoming": false,
                    "amount": "1000000",
                    "hash_lock": "c92938ac68134ac1784299f5e3e9e229a3373aeb2d9b08de5d55271fee492c6b",
                    "expiration_height": 1720530
                }
            ],
            "csv_delay": 480,
            "private": false,
            "initiator": true,
            "chan_status_flags": "ChanStatusDefault",
            "local_chan_reserve_sat": "40000",
            "remote_chan_reserve_sat": "40000",
            "static_remote_key": true,
            "commitment_type": "STATIC_REMOTE_KEY",
            "lifetime": "80354",
            "uptime": "80354",
            "close_address": "",
            "push_amount_sat": "0",
            "thaw_height": 0
        },

This are the logs at the moment of failuer

2020-04-19 20:01:54.784 [INF] DISC: GossipSyncer(038863cf8ab91046230f561cd5b386cbff8309fa02e3f0c3ed161a3aeb64a643b9): applying gossipFilter(start=0001-01-01 00:00:00 +0000 UTC, end=0001-01-01 00:00:00 +0000 UTC)
2020-04-19 20:01:54.785 [INF] DISC: GossipSyncer(02ec788f53255a5998a06eb0f89372737b93dc22926c5cd7e471e1930999c9830a): applying gossipFilter(start=2020-04-19 20:01:54.78575313 +0000 UTC m=+174478.374459307, end=2156-05-27 02:30:09.78575313 +0000 UTC m=+4295141773.374459307)
2020-04-19 20:02:54.784 [INF] DISC: Broadcasting 1 new announcements in 1 sub batches
2020-04-19 20:04:10.721 [INF] CRTR: Processed channels=0 updates=24 nodes=0 in last 2m58.390322798s
2020-04-19 20:04:24.784 [INF] DISC: Broadcasting 23 new announcements in 3 sub batches
2020-04-19 20:05:06.853 [ERR] HSWC: ChannelLink(1720225:52:1): failing link: ChannelPoint(7bd908fbb2237ca4964b9cbe78b39bc85b5ee2864a182434605a1d798eedf8c6:1): received error from peer: chan_id=c6f8ed8e791d5a603424184a86e25e5bc89bb378be9c4b96a47c23b2fb08d97a, err=internal error with error: remote error
2020-04-19 20:05:06.855 [ERR] HSWC: ChannelLink(1720225:52:1): link failed, exiting htlcManager
2020-04-19 20:05:06.856 [INF] HSWC: ChannelLink(1720225:52:1): exited
2020-04-19 20:05:06.857 [INF] HSWC: Removing channel link with ChannelID(c6f8ed8e791d5a603424184a86e25e5bc89bb378be9c4b96a47c23b2fb08d97a)
2020-04-19 20:05:06.858 [INF] HSWC: ChannelLink(1720225:52:1): stopping
2020-04-19 20:05:06.859 [INF] SRVR: Adding preimage=fe874da69e7b3f0737a380a2f0b5d498af69d9e4b03769853bb177946b9fe972 to witness cache
2020-04-19 20:05:10.721 [INF] CRTR: Processed channels=0 updates=0 nodes=1 in last 59.997862486s
2020-04-19 20:05:13.006 [INF] BTCN: Processed 1 block in the last 12m49.78s (height 1720488, 2020-04-19 20:04:44 +0000 UTC)
2020-04-19 20:05:13.011 [INF] BTCN: Attempting to fetch set of un-checkpointed filters at height=1720488, hash=00000000000001271109250d32383cca75dcea3c78956190421732b4e60af1dd
2020-04-19 20:05:23.016 [INF] BTCN: Verified 1 filter header in the last 12m49.78s (height 1720488, 2020-04-19 20:04:44 +0000 UTC)
2020-04-19 20:05:23.104 [INF] NTFN: New block: height=1720488, sha=00000000000001271109250d32383cca75dcea3c78956190421732b4e60af1dd
2020-04-19 20:05:23.105 [INF] UTXN: Attempting to graduate height=1720488: num_kids=0, num_babies=0
2020-04-19 20:05:54.784 [INF] DISC: Broadcasting 4 new announcements in 1 sub batches
2020-04-19 20:06:10.721 [INF] CRTR: Processed channels=0 updates=3 nodes=0 in last 59.998157874s

Your environment

• neutrino 0.10.0-beta.rc2 commit=v0.10.0-beta.rc2-4-g9c4f9416d53b523b00ee34e5cb1dcd834c33e1e0
• lnd full node 0.9.0-beta commit=v0.9.0-beta-469-gd04bc200e75ff47e41e6298d610221d44cb94058
• neutrino OS Linux testnet-neutrino-node 4.15.0-66-generic ChainNotifier should consult historical data to check if ntfn can immediately be dispatched  #75-Ubuntu SMP Tue Oct 1 05:24:09 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
• lnd full node OS Linux brokerage-docker 4.15.0-91-generic Some minor fixes #92-Ubuntu SMP Fri Feb 28 11:09:48 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
• Bitcoin Core RPC client version v0.18.0

Steps to reproduce

Just have those two lnd versions running and make a payment from one to another in testnet

Expected behaviour

To have the payment done without a htlc_pending and a active: false channel

[cfromknecht]

@grunch do you have any logs from the full node as well?

It looks like some sort of error was hit on the full node, which caused the link (a per-channel subsystem that handles channel updates) to be shut down even though the connection remained open. My guess is that disconnecting and reconnecting would resolve the issue, but it would be good to figure out the root cause.

[grunch]

Hi @cfromknecht thank you for your response.

Yes, here is the log from the full node, to be sure I replicated the error, all this information is from the second time I get the error.

The lnd full node is working since almost a year without any problem, but the neutrino is brand new, probably the error is comming from the neutrino node.

2020-04-19 20:04:39.200 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: rpc error: code = Internal desc = transport: connection error: desc = "transport is closing"
2020-04-19 20:04:39.200 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: rpc error: code = Internal desc = transport: connection error: desc = "transport is closing"
2020-04-19 20:04:39.203 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: rpc error: code = Internal desc = transport: connection error: desc = "transport is closing"
2020-04-19 20:04:39.200 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: rpc error: code = Unavailable desc = transport is closing
2020-04-19 20:04:39.203 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: rpc error: code = Internal desc = transport: connection error: desc = "transport is closing"
2020-04-19 20:04:39.200 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: rpc error: code = Internal desc = transport: connection error: desc = "transport is closing"
2020-04-19 20:04:39.203 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: rpc error: code = Internal desc = transport: connection error: desc = "transport is closing"
2020-04-19 20:04:39.203 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: rpc error: code = Internal desc = transport: connection error: desc = "transport is closing"
2020-04-19 20:04:39.752 [ERR] BTCN: Can't accept connection: unable to accept connection from 203.132.95.10:16760: chacha20poly1305: message authentication failed
2020-04-19 20:04:41.337 [INF] DISC: Broadcasting 16 new announcements in 2 sub batches
2020-04-19 20:05:06.738 [WRN] INVC: client=777 for invoice notifications missed an update, settle_index=0, new settle event index=18
2020-04-19 20:05:06.739 [INF] HSWC: ChannelLink(1720225:52:1): settling htlc c92938ac68134ac1784299f5e3e9e229a3373aeb2d9b08de5d55271fee492c6b as exit hop
2020-04-19 20:05:06.750 [ERR] HSWC: ChannelLink(1720225:52:1): failing link: unable to update commitment: height=2, for ChannelPoint(7bd908fbb2237ca4964b9cbe78b39bc85b5ee2864a182434605a1d798eedf8c6:1) attempts to create commitment wigh feerate 252 sat/kw: (*lnwallet.unsignedCommitmentTx)(0xc00475ec60)({
 txn: (*wire.MsgTx)(0xc007c684c0)({
  Version: (int32) 2,
  TxIn: ([]*wire.TxIn) (len=1 cap=15) {
   (*wire.TxIn)(0xc0050f7b00)({
    PreviousOutPoint: (wire.OutPoint) 7bd908fbb2237ca4964b9cbe78b39bc85b5ee2864a182434605a1d798eedf8c6:1,
    SignatureScript: ([]uint8) <nil>,
    Witness: (wire.TxWitness) <nil>,
    Sequence: (uint32) 2160399808
   })
  },
  TxOut: ([]*wire.TxOut) (len=2 cap=15) {
   (*wire.TxOut)(0xc00475ec20)({
    Value: (int64) 1000000,
    PkScript: ([]uint8) (len=22 cap=500) {
     00000000  00 14 55 dd 98 62 33 e8  c8 e3 e1 f1 87 c6 6b 1c  |..U..b3.......k.|
     00000010  a3 5d b2 4a ee e1                                 |.].J..|
    }
   }),
   (*wire.TxOut)(0xc00475ec00)({
    Value: (int64) 2999817,
    PkScript: ([]uint8) (len=34 cap=500) {
     00000000  00 20 87 ec 82 5f 3d c5  79 bb 85 e2 d1 a0 27 54  |. ..._=.y.....'T|
     00000010  1c ff eb 91 d0 b9 72 1d  d5 7b 07 54 a3 40 ad 50  |......r..{.T.@.P|
     00000020  5c 22                                             |\"|
    }
   })
  },
  LockTime: (uint32) 553342046
 }),
 fee: (btcutil.Amount) 0.00000183 BTC,
 ourBalance: (lnwire.MilliSatoshi) 1000000000 mSAT,
 theirBalance: (lnwire.MilliSatoshi) 2999817000 mSAT
})
 with error: internal error
2020-04-19 20:05:06.750 [ERR] HSWC: ChannelLink(1720225:52:1): link failed, exiting htlcManager
2020-04-19 20:05:06.751 [INF] HSWC: Removing channel link with ChannelID(c6f8ed8e791d5a603424184a86e25e5bc89bb378be9c4b96a47c23b2fb08d97a)
2020-04-19 20:05:06.751 [INF] HSWC: ChannelLink(1720225:52:1): stopping
2020-04-19 20:05:06.751 [INF] HSWC: ChannelLink(1720225:52:1): exited
2020-04-19 20:05:09.947 [INF] CRTR: Processed channels=0 updates=6 nodes=0 in last 59.996842293s
2020-04-19 20:05:13.064 [INF] CRTR: Pruning channel graph using block 00000000000001271109250d32383cca75dcea3c78956190421732b4e60af1dd (height=1720488)
2020-04-19 20:05:16.399 [INF] CRTR: Block 00000000000001271109250d32383cca75dcea3c78956190421732b4e60af1dd (height=1720488) closed 0 channels
2020-04-19 20:05:16.404 [INF] NTFN: New block: height=1720488, sha=00000000000001271109250d32383cca75dcea3c78956190421732b4e60af1dd
2020-04-19 20:05:16.405 [INF] UTXN: Attempting to graduate height=1720488: num_kids=0, num_babies=0
2020-04-19 20:05:16.406 [ERR] LTND: Unable to lookup witness: no witnesses
2020-04-19 20:06:02.543 [ERR] BTCN: Can't accept connection: unable to accept connection from 13.59.8.6:59958: chacha20poly1305: message authentication failed
2020-04-19 20:06:09.947 [INF] CRTR: Processed channels=0 updates=4 nodes=1 in last 59.999808767s
2020-04-19 20:06:11.337 [INF] DISC: Broadcasting 5 new announcements in 1 sub batches
2020-04-19 20:06:13.811 [ERR] BTCN: Can't accept connection: unable to accept connection from 3.13.29.161:43086: chacha20poly1305: message authentication failed
2020-04-19 20:06:15.148 [ERR] BTCN: Can't accept connection: unable to accept connection from 3.16.119.191:49526: chacha20poly1305: message authentication failed
2020-04-19 20:07:17.011 [ERR] BTCN: Can't accept connection: unable to accept connection from 71.171.85.29:4654: chacha20poly1305: message authentication failed
2020-04-19 20:07:59.347 [ERR] BTCN: Can't accept connection: unable to accept connection from 18.188.244.93:18897: chacha20poly1305: message authentication failed
2020-04-19 20:08:11.336 [INF] DISC: GossipSyncer(02ae2f22b02375e3e9b4b4a2db4f12e1b50752b4062dbefd6e01332acdaf680379): applying gossipFilter(start=0001-01-01 00:00:00 +0000 UTC, end=0001-01-01 00:00:00 +0000 UTC)
2020-04-19 20:08:11.339 [INF] DISC: GossipSyncer(0269a94e8b32c005e4336bfb743c08a6e9beb13d940d57c479d95c8e687ccbdb9f): applying gossipFilter(start=2020-04-19 20:08:11.339650126 +0000 UTC m=+1380165.807658563, end=2156-05-27 02:36:26.339650126 +0000 UTC m=+4296347460.807658563)
2020-04-19 20:09:15.330 [INF] DISC: GossipSyncer(0269a94e8b32c005e4336bfb743c08a6e9beb13d940d57c479d95c8e687ccbdb9f): applying new update horizon: start=2042-07-14 01:04:00 +0000 UTC, end=2042-07-14 01:04:00 +0000 UTC, backlog_size=0

[cfromknecht]

@grunch figured out the issue, see #4211. Restarting with that patch return the channel to normal operation unless any pending htlcs have already timed out and caused the channel to go to chain.

[grunch]

thank you @cfromknecht 😄