bitromortac/lndmanage

channel disappears although tx has > 100 confirmations, possibly because peer disconnected before tx was confirmed

xmrk-btc opened this issue · 4 comments

See lightningnetwork/lnd#6717 for more info.
Opening issue here because it seems lndmanage openchannels sent funds to the address even though lnd logged unable to open channel to NodeKey...

Hey, could you provide logs? Look into ~/.lndmanage/lndmanage.log. We can also communicate via email bitromortac@protonmail.com.

Sure, here it is , didn't know lndmanage had its own logs. The lnd logs are in the linked lnd issue.


[2022-07-09 16:24:26 DEBUG] Using selector: EpollSelector
[2022-07-09 16:24:26 DEBUG] Node interface starting.
[2022-07-09 16:24:27 DEBUG] Connecting async rpcs.
[2022-07-09 16:24:27 DEBUG] Using AsyncIOEngine.POLLER as I/O engine
[2022-07-09 16:24:27 INFO] Cached graph is too old. Fetching new one.
[2022-07-09 16:24:46 DEBUG] Network.set_graph_and_edges 18.2389 s
[2022-07-09 16:24:51 DEBUG] Network.load_graph 23.8341 s
[2022-07-09 16:24:51 DEBUG] Network.load_liquidity_hints 0.0004 s
[2022-07-09 16:24:54 INFO] >>> Checking node pubkeys and address information.
[2022-07-09 16:24:54 INFO] >>> Connecting to channel peer candidates.
[2022-07-09 16:24:54 INFO]     trying to connect to 021cc722c97eaaeb7649e2a88301b2b0826060f3ebbd008bcd2d23ba2798dcc850@zul6k2zgi5tprvrk3kx3qo6lfch5ohir3ogg2henzvk3zq3znqkossyd.onion:9735
[2022-07-09 16:24:54 INFO]     > already connected
[2022-07-09 16:24:54 INFO] >>> Available UTXOs:
[2022-07-09 16:24:54 DEBUG]     d26aa7514db96f5ef90413d8cdadf11c1811a5fc7e0904d401197f33a24a7d12:0 9872936 sat
[2022-07-09 16:24:54 DEBUG]     Transaction size calculation for 1 (p2wkh) + 0 (np2wkh) inputs, 1channels, change False: 153 vbytes
[2022-07-09 16:24:54 INFO] >>> Used UTXOs:
[2022-07-09 16:24:54 INFO]     d26aa7514db96f5ef90413d8cdadf11c1811a5fc7e0904d401197f33a24a7d12:0 9872936 sat
[2022-07-09 16:24:54 INFO] >>> Channels will be public.
[2022-07-09 16:24:54 INFO]     Channel capacities: [9870476] sat (9870476 sat total).
[2022-07-09 16:24:54 INFO]     Fees: 2460 sat (16 sat/vbyte).
[2022-07-09 16:24:54 INFO]     Change: 0 sat.
[2022-07-09 16:24:54 INFO] >>> Asking peers for channel opening.
[2022-07-09 16:28:56 DEBUG]    > peer 021cc722c9...: got address: bc1q6chtu402x9yhj4upkussry4vy5vxhcu8rhncsarmdg0cajh3ndvsw57kvr
[2022-07-09 16:28:56 INFO] >>> Funding PSBT.
[2022-07-09 16:28:56 DEBUG]     given inputs: [UTXO(txid='d26aa7514db96f5ef90413d8cdadf11c1811a5fc7e0904d401197f33a24a7d12', output_index=0, amount_sat=9872936, transaction_type=<AddressType.WITNESS_PUBKEY_HASH
: 0>)]
[2022-07-09 16:28:56 DEBUG]     inputs (psbt): 1
[2022-07-09 16:28:56 DEBUG]     outputs (psbt): 1
[2022-07-09 16:28:56 DEBUG]     amounts (psbt): [9870476]
[2022-07-09 16:28:56 INFO] >>> WARNING: this is a relatively new feature, so please check the generated PSBT by the following command:
[2022-07-09 16:28:56 INFO] bitcoin-cli decodepsbt "cHNidP8BAF4CAAAAARJ9SqIzfxkB1AQJfvylERgc8a3N2BME+V5vuU1Rp2rSAAAAAAAAAAAAAYyclgAAAAAAIgAg1i6+VeoxSXlXgbchAZKsJRhr44cd54h0e2ofjsrxm1kAAAAAAAEA7AIAAAAAAQG8tvNRy39
zyQfwWFXaPcLCLWupt6xjVIfd8B59sxYCAgEAAAAAsQQAAAEoppYAAAAAABYAFLeKaqyyQc6J2uqITJW2+dU/4eVOA0cwRAIgeuLZ1nF0u1Ou5RqOALpX7lHjKAV6xsRzH90g4Clp9sQCIBMRT5mL5cnNm3scNMyxFexzEsj2PNYUCuBYrGoraY0bAQBNYyEDygsVzi/1jOyGyHc26
kETAJGxTNE7y2snUt29NP+Jj7tnArEEsnUhA0Pcgdn7Vb2P1dXf0m/xzxt+cqWBhksmgYROa9JcDfAnaKziVgsAAQEfKKaWAAAAAAAWABS3imqsskHOidrqiEyVtvnVP+HlTgEDBAEAAAAiBgMPR4Flxt2YfbazgdYDujepOCSygJJJ5BpFQrg7kNRjQxgAAAAAVAAAgAAAAIAAAAC
AAAAAAAwKAAAAAA=="
[2022-07-09 16:28:56 INFO] >>> You have 8 minutes from now to decide.

[2022-07-09 16:28:56 INFO] 
>>> Do you want to open the channel(s) (y/n)?
[2022-07-09 16:31:01 INFO] >>> Verifying PSBT.
[2022-07-09 16:31:02 INFO] >>> Signing PSBT.
[2022-07-09 16:31:02 INFO]     Signed transaction:
    02000000000101127d4aa2337f1901d404097efca511181cf1adcdd81304f95e6fb94d51a76ad2000000000000000000018c9c960000000000220020d62ebe55ea3149795781b7210192ac25186be3871de788747b6a1f8ecaf19b590247304402204108c15be67552ad6acb12651c472e3e03c9c839fad0e348d438b072e29df6bb022031755c5509b31b99bf515df02e198804ecbe6f2b1fae004e1ddb1383c2de44080121030f478165c6dd987db6b381d603ba37a93824b2809249e41a4542b83b90d4634300000000
[2022-07-09 16:31:02 INFO]     Signed psbt:
    cHNidP8BAF4CAAAAARJ9SqIzfxkB1AQJfvylERgc8a3N2BME+V5vuU1Rp2rSAAAAAAAAAAAAAYyclgAAAAAAIgAg1i6+VeoxSXlXgbchAZKsJRhr44cd54h0e2ofjsrxm1kAAAAAAAEA7AIAAAAAAQG8tvNRy39zyQfwWFXaPcLCLWupt6xjVIfd8B59sxYCAgEAAAAAsQQAAAEoppYAAAAAABYAFLeKaqyyQc6J2uqITJW2+dU/4eVOA0cwRAIgeuLZ1nF0u1Ou5RqOALpX7lHjKAV6xsRzH90g4Clp9sQCIBMRT5mL5cnNm3scNMyxFexzEsj2PNYUCuBYrGoraY0bAQBNYyEDygsVzi/1jOyGyHc26kETAJGxTNE7y2snUt29NP+Jj7tnArEEsnUhA0Pcgdn7Vb2P1dXf0m/xzxt+cqWBhksmgYROa9JcDfAnaKziVgsAAQEfKKaWAAAAAAAWABS3imqsskHOidrqiEyVtvnVP+HlTgEIawJHMEQCIEEIwVvmdVKtassSZRxHLj4Dycg5+tDjSNQ4sHLinfa7AiAxdVxVCbMbmb9RXfAuGYgE7L5vKx+uAE4d2xODwt5ECAEhAw9HgWXG3Zh9trOB1gO6N6k4JLKAkknkGkVCuDuQ1GNDAAA=
[2022-07-09 16:31:02 INFO]     Final transaction size: 203 bytes
[2022-07-09 16:31:02 INFO] >>> Publishing transaction.
[2022-07-09 16:31:03 DEBUG] Disconnecting rpcs.
[2022-07-09 16:24:27 DEBUG] Using AsyncIOEngine.POLLER as I/O engine
[2022-07-09 16:24:27 INFO] Cached graph is too old. Fetching new one.
[2022-07-09 16:24:46 DEBUG] Network.set_graph_and_edges 18.2389 s
[2022-07-09 16:24:51 DEBUG] Network.load_graph 23.8341 s
[2022-07-09 16:24:51 DEBUG] Network.load_liquidity_hints 0.0004 s
[2022-07-09 16:24:54 INFO] >>> Checking node pubkeys and address information.
[2022-07-09 16:24:54 INFO] >>> Connecting to channel peer candidates.
[2022-07-09 16:24:54 INFO]     trying to connect to 021cc722c97eaaeb7649e2a88301b2b0826060f3ebbd008bcd2d23ba2798dcc850@zul6k2zgi5tprvrk3kx3qo6lfch5ohir3ogg2henzvk3zq3znqkossyd.onion:9735
[2022-07-09 16:24:54 INFO]     > already connected
[2022-07-09 16:24:54 INFO] >>> Available UTXOs:
[2022-07-09 16:24:54 DEBUG]     d26aa7514db96f5ef90413d8cdadf11c1811a5fc7e0904d401197f33a24a7d12:0 9872936 sat
[2022-07-09 16:24:54 DEBUG]     Transaction size calculation for 1 (p2wkh) + 0 (np2wkh) inputs, 1channels, change False: 153 vbytes
[2022-07-09 16:24:54 INFO] >>> Used UTXOs:
[2022-07-09 16:24:54 INFO]     d26aa7514db96f5ef90413d8cdadf11c1811a5fc7e0904d401197f33a24a7d12:0 9872936 sat
[2022-07-09 16:24:54 INFO] >>> Channels will be public.
[2022-07-09 16:24:54 INFO]     Channel capacities: [9870476] sat (9870476 sat total).
[2022-07-09 16:24:54 INFO]     Fees: 2460 sat (16 sat/vbyte).
[2022-07-09 16:24:54 INFO]     Change: 0 sat.
[2022-07-09 16:24:54 INFO] >>> Asking peers for channel opening.
[2022-07-09 16:28:56 DEBUG]    > peer 021cc722c9...: got address: bc1q6chtu402x9yhj4upkussry4vy5vxhcu8rhncsarmdg0cajh3ndvsw57kvr
[2022-07-09 16:28:56 INFO] >>> Funding PSBT.
[2022-07-09 16:28:56 DEBUG]     given inputs: [UTXO(txid='d26aa7514db96f5ef90413d8cdadf11c1811a5fc7e0904d401197f33a24a7d12', output_index=0, amount_sat=9872936, transaction_type=<AddressType.WITNESS_PUBKEY_HASH
: 0>)]
[2022-07-09 16:28:56 DEBUG]     inputs (psbt): 1
[2022-07-09 16:28:56 DEBUG]     outputs (psbt): 1
[2022-07-09 16:28:56 DEBUG]     amounts (psbt): [9870476]
[2022-07-09 16:28:56 INFO] >>> WARNING: this is a relatively new feature, so please check the generated PSBT by the following command:
[2022-07-09 16:28:56 INFO] bitcoin-cli decodepsbt "cHNidP8BAF4CAAAAARJ9SqIzfxkB1AQJfvylERgc8a3N2BME+V5vuU1Rp2rSAAAAAAAAAAAAAYyclgAAAAAAIgAg1i6+VeoxSXlXgbchAZKsJRhr44cd54h0e2ofjsrxm1kAAAAAAAEA7AIAAAAAAQG8tvNRy39
zyQfwWFXaPcLCLWupt6xjVIfd8B59sxYCAgEAAAAAsQQAAAEoppYAAAAAABYAFLeKaqyyQc6J2uqITJW2+dU/4eVOA0cwRAIgeuLZ1nF0u1Ou5RqOALpX7lHjKAV6xsRzH90g4Clp9sQCIBMRT5mL5cnNm3scNMyxFexzEsj2PNYUCuBYrGoraY0bAQBNYyEDygsVzi/1jOyGyHc26
kETAJGxTNE7y2snUt29NP+Jj7tnArEEsnUhA0Pcgdn7Vb2P1dXf0m/xzxt+cqWBhksmgYROa9JcDfAnaKziVgsAAQEfKKaWAAAAAAAWABS3imqsskHOidrqiEyVtvnVP+HlTgEDBAEAAAAiBgMPR4Flxt2YfbazgdYDujepOCSygJJJ5BpFQrg7kNRjQxgAAAAAVAAAgAAAAIAAAAC
AAAAAAAwKAAAAAA=="
[2022-07-09 16:28:56 INFO] >>> You have 8 minutes from now to decide.

[2022-07-09 16:28:56 INFO] 
>>> Do you want to open the channel(s) (y/n)?
[2022-07-09 16:31:01 INFO] >>> Verifying PSBT.
[2022-07-09 16:31:02 INFO] >>> Signing PSBT.
[2022-07-09 16:31:02 INFO]     Signed transaction:
    02000000000101127d4aa2337f1901d404097efca511181cf1adcdd81304f95e6fb94d51a76ad2000000000000000000018c9c960000000000220020d62ebe55ea3149795781b7210192ac25186be3871de788747b6a1f8ecaf19b590247304402204108c15be67552ad6acb12651c472e3e03c9c839fad0e348d438b072e29df6bb022031755c5509b31b99bf515df02e198804ecbe6f2b1fae004e1ddb1383c2de44080121030f478165c6dd987db6b381d603ba37a93824b2809249e41a4542b83b90d4634300000000
[2022-07-09 16:31:02 INFO]     Signed psbt:
    cHNidP8BAF4CAAAAARJ9SqIzfxkB1AQJfvylERgc8a3N2BME+V5vuU1Rp2rSAAAAAAAAAAAAAYyclgAAAAAAIgAg1i6+VeoxSXlXgbchAZKsJRhr44cd54h0e2ofjsrxm1kAAAAAAAEA7AIAAAAAAQG8tvNRy39zyQfwWFXaPcLCLWupt6xjVIfd8B59sxYCAgEAAAAAsQQAAAEoppYAAAAAABYAFLeKaqyyQc6J2uqITJW2+dU/4eVOA0cwRAIgeuLZ1nF0u1Ou5RqOALpX7lHjKAV6xsRzH90g4Clp9sQCIBMRT5mL5cnNm3scNMyxFexzEsj2PNYUCuBYrGoraY0bAQBNYyEDygsVzi/1jOyGyHc26kETAJGxTNE7y2snUt29NP+Jj7tnArEEsnUhA0Pcgdn7Vb2P1dXf0m/xzxt+cqWBhksmgYROa9JcDfAnaKziVgsAAQEfKKaWAAAAAAAWABS3imqsskHOidrqiEyVtvnVP+HlTgEIawJHMEQCIEEIwVvmdVKtassSZRxHLj4Dycg5+tDjSNQ4sHLinfa7AiAxdVxVCbMbmb9RXfAuGYgE7L5vKx+uAE4d2xODwt5ECAEhAw9HgWXG3Zh9trOB1gO6N6k4JLKAkknkGkVCuDuQ1GNDAAA=
[2022-07-09 16:31:02 INFO]     Final transaction size: 203 bytes
[2022-07-09 16:31:02 INFO] >>> Publishing transaction.
[2022-07-09 16:31:03 DEBUG] Disconnecting rpcs.

But note that lnd fails to open the channel at 16:38:28, when lndmanage already ended. (Not sure what it means, not going to speculate.)

Thank you, the issue seems to be that the peer disconnected during the funding flow and that was not caught. I am replacing the internal channel funding of lndmanage with a wrapper around the batchopen api of lnd in #137.

Fixed by #137.