Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

zero conf channel stuck in CHANNELD_AWAITING_LOCKIN sometimes: Owning subdaemon channeld died #5808

Open
JssDWt opened this issue Dec 10, 2022 · 9 comments
Open

zero conf channel stuck in CHANNELD_AWAITING_LOCKIN sometimes: Owning subdaemon channeld died #5808

JssDWt opened this issue Dec 10, 2022 · 9 comments

Comments

@JssDWt
Copy link
Contributor

JssDWt commented Dec 10, 2022 •
edited
Loading

Issue and Steps to Reproduce

There is a CLN v22.11 node that opens a zero conf channel to another CLN v22.11 node. When running my integration tests on regtest, regularly the opened channel is stuck in CHANNELD_AWAITING_LOCKIN. The most relevant log line is:
2022-12-10T20:46:28.159Z INFO 036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-chan#2: Peer transient failure in CHANNELD_AWAITING_LOCKIN: channeld: Owning subdaemon channeld died (0)

There appears to be no recovery from the dying channeld subdaemon at this point.

Here's the relevant logs:

Failing flow

Channel funder

2022-12-10T20:46:28.113Z DEBUG   plugin-spenderp: mfc 50: multiconnect.
2022-12-10T20:46:28.113Z DEBUG   plugin-spenderp: mfc 50, dest 0: connect 036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894.
2022-12-10T20:46:28.113Z DEBUG   lightningd: Already connected via 127.0.0.1:63328
2022-12-10T20:46:28.113Z DEBUG   plugin-spenderp: mfc 50, dest 0: connect done.
2022-12-10T20:46:28.113Z DEBUG   plugin-spenderp: mfc 50: multiconnect done.
2022-12-10T20:46:28.115Z DEBUG   plugin-spenderp: mfc 50: 'parsefeerate' done
2022-12-10T20:46:28.115Z DEBUG   plugin-spenderp: mfc 50: fundpsbt.
2022-12-10T20:46:28.116Z DEBUG   plugin-spenderp: mfc 50: fundpsbt done.
2022-12-10T20:46:28.117Z DEBUG   plugin-spenderp: mfc 50: fundchannel_start parallel with PSBT cHNidP8BADMCAAAAARPcNOkysvYut5ReANK9TgyXmxmXbBHH39pdFoMUbfrMAQAAAAD9////AG0AAAAAAQDeAgAAAAABAbMOpwAWjSzI6is3S0e7xgFb0MjI4TRnZqXv76yEfHaJAAAAAAD+////AubD1CgBAAAAFgAUXIDDCoWo/7s2zydpDQWRQk5exMWAlpgAAAAAABYAFKTaT/DpgOneP8xgQlOdynyGXwEoAkcwRAIgY5CQKsBTQJF0XH3cn/82ZMm+Kex6+UPgVp9+8chTFacCICQIcHZSINMuy/4hSGKVf/RRrf7Mtcv6hTlX/mqH3CY/ASECyLhFsZvHqwbNloUg10uM/2wyIG9ez5uABodBdxJW+H9mAAAAAQEfgJaYAAAAAAAWABSk2k/w6YDp3j/MYEJTncp8hl8BKAz8CWxpZ2h0bmluZwEIs3emJLA0mfgM/AlsaWdodG5pbmcCAgABAA==
2022-12-10T20:46:28.117Z DEBUG   plugin-spenderp: mfc 50, dest 0: fundchannel_start 036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894.
2022-12-10T20:46:28.117Z DEBUG   lightningd: fundchannel_start: allocating uncommitted_channel
2022-12-10T20:46:28.117Z INFO    lightningd: Will open private channel with node 036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894
2022-12-10T20:46:28.120Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-openingd-chan#2: pid 30849, msgfd 70
2022-12-10T20:46:28.120Z DEBUG   hsmd: Client: Received message 30 from client
2022-12-10T20:46:28.120Z DEBUG   hsmd: Client: Received message 10 from client
2022-12-10T20:46:28.120Z DEBUG   hsmd: new_client: 2
2022-12-10T20:46:28.124Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2022-12-10T20:46:28.124Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-openingd-chan#2: funder_channel_start
2022-12-10T20:46:28.124Z DEBUG   hsmd: Client: Received message 18 from client
2022-12-10T20:46:28.125Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-openingd-chan#2: Setting their reserve to 0sat
2022-12-10T20:46:28.125Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-openingd-chan#2: peer_out WIRE_OPEN_CHANNEL
2022-12-10T20:46:28.125Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-openingd-chan#2: billboard: Funding channel start: offered, now waiting for accept_channel
2022-12-10T20:46:28.134Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-openingd-chan#2: peer_in WIRE_ACCEPT_CHANNEL
2022-12-10T20:46:28.134Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-openingd-chan#2: accept_channel: max_htlc_value_in_flight=18446744073709551615msat, channel_reserve=1021sat, htlc_minimum=0msat, minimum_depth=1
2022-12-10T20:46:28.134Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-openingd-chan#2: We negotiated option_zeroconf, using our minimum_depth=0
2022-12-10T20:46:28.134Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-openingd-chan#2: billboard: Funding channel start: awaiting funding_txid with output to 0020d6036a171ff01fc7f094d9f6c4552a5c3002601c05d29180dad41981cd61f472
2022-12-10T20:46:28.135Z DEBUG   plugin-spenderp: mfc 50, dest 0: fundchannel_start 036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894 done.
2022-12-10T20:46:28.135Z DEBUG   plugin-spenderp: mfc 50: parallel channel starts done.
2022-12-10T20:46:28.135Z DEBUG   plugin-spenderp: mfc 50: Creating funding tx.
2022-12-10T20:46:28.135Z DEBUG   plugin-spenderp: mfc 50: funding tx 573811fc7a69ab21b0475f56687b492fabdc9e10de3f63e4c9d4f6467af8ede4: 036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894: 102100sat, change: 9897746sat
2022-12-10T20:46:28.135Z DEBUG   plugin-spenderp: mfc 50: parallel fundchannel_complete.
2022-12-10T20:46:28.135Z DEBUG   plugin-spenderp: mfc 50, dest 0: fundchannel_complete 036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894.
2022-12-10T20:46:28.135Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-openingd-chan#2: billboard: Funding channel con't: continuing with funding_txid 573811fc7a69ab21b0475f56687b492fabdc9e10de3f63e4c9d4f6467af8ede4
2022-12-10T20:46:28.135Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-hsmd: Got WIRE_HSMD_READY_CHANNEL
2022-12-10T20:46:28.135Z DEBUG   hsmd: Client: Received message 31 from client
2022-12-10T20:46:28.138Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-hsmd: Got WIRE_HSMD_SIGN_REMOTE_COMMITMENT_TX
2022-12-10T20:46:28.138Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-openingd-chan#2: signature 3044022077fa0b4dad77d2c96d1fda4641b44e241bc3298894a8ea09520749769482bdd102205629ed37b65642833f252bf9dfa5d6148589d5c783be0bc29a8ac6c090bdafb401 on tx 0200000001e4edf87a46f6d4c9e4633fde109edcab2f497b68565f47b021ab697afc11385700000000003c740580011d8e010000000000160014dad6e943e05148c1e8b157e57f237ccee4dcc76ac3de3c20 using key 02abeb3d4492e44f800aceed0e3f507333ea5f20b0a9c986b0c49f6a02e889862e
2022-12-10T20:46:28.139Z DEBUG   hsmd: Client: Received message 19 from client
2022-12-10T20:46:28.139Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-openingd-chan#2: peer_out WIRE_FUNDING_CREATED
2022-12-10T20:46:28.139Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-openingd-chan#2: billboard: Funding channel: create first tx, now waiting for their signature
2022-12-10T20:46:28.149Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-openingd-chan#2: peer_in WIRE_FUNDING_SIGNED
2022-12-10T20:46:28.150Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-hsmd: Got WIRE_HSMD_VALIDATE_COMMITMENT_TX
2022-12-10T20:46:28.150Z DEBUG   hsmd: Client: Received message 35 from client
2022-12-10T20:46:28.150Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-openingd-chan#2: billboard: Funding channel: opening negotiation succeeded
2022-12-10T20:46:28.151Z DEBUG   lightningd: 0379e9853582eca69ea52e3368a788edbe5ae55cc0793c8b47546e5877247911b6
2022-12-10T20:46:28.154Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-channeld-chan#2: pid 30852, msgfd 72
2022-12-10T20:46:28.154Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-chan#2: Waiting for funding confirmations
2022-12-10T20:46:28.154Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-chan#2: Ignoring fee limits!
2022-12-10T20:46:28.154Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-chan#2: attempting update blockheight e4edf87a46f6d4c9e4633fde109edcab2f497b68565f47b021ab697afc113857
2022-12-10T20:46:28.154Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-openingd-chan#2: Status closed, but not exited. Killing
2022-12-10T20:46:28.156Z DEBUG   hsmd: new_client: 2
2022-12-10T20:46:28.157Z DEBUG   plugin-spenderp: mfc 50, dest 0: fundchannel_complete 036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894 done.
2022-12-10T20:46:28.157Z DEBUG   plugin-spenderp: mfc 50: parallel fundchannel_complete  done.
2022-12-10T20:46:28.157Z DEBUG   plugin-spenderp: mfc 50: signpsbt.
2022-12-10T20:46:28.157Z DEBUG   hsmd: Client: Received message 7 from client
2022-12-10T20:46:28.157Z DEBUG   lightningd: sendrawtransaction: 0200000000010113dc34e932b2f62eb7945e00d2bd4e0c979b19976c11c7dfda5d1683146dfacc0100000000fdffffff02d48e010000000000220020d6036a171ff01fc7f094d9f6c4552a5c3002601c05d29180dad41981cd61f4721207970000000000160014add75f3fa7f82f0d2c52d88c5ea8ed5c23fc267d024730440220499e4745b44e5dedc9dd13eb08f807b5dd6497ffefbfec9db4c03640a63211e20220019aaf72c77a071b600f4aa1df5819ae68bf8fcd27a1a818b9d03399ef21c7f5012103fa8b3f76f38950651f026ccd40d0024d2912c96579098780d9ac7928b29308a26d000000
2022-12-10T20:46:28.159Z DEBUG   plugin-spenderp: mfc 50: signpsbt done.
2022-12-10T20:46:28.159Z DEBUG   plugin-spenderp: mfc 50: sendpsbt.
2022-12-10T20:46:28.159Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-channeld-chan#2: option_static_remotekey = 1, option_anchor_outputs = 0
2022-12-10T20:46:28.159Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-channeld-chan#2: init LOCAL: remote_per_commit = 0379e9853582eca69ea52e3368a788edbe5ae55cc0793c8b47546e5877247911b6, old_remote_per_commit = 0379e9853582eca69ea52e3368a788edbe5ae55cc0793c8b47546e5877247911b6 next_idx_local = 1 next_idx_remote = 1 revocations_received = 0 feerates { SENT_ADD_ACK_REVOCATION:253 } range 253-4294967295 blockheights { SENT_ADD_ACK_REVOCATION:0 }, our current 109
2022-12-10T20:46:28.159Z INFO    036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-chan#2: Peer transient failure in CHANNELD_AWAITING_LOCKIN: channeld: Owning subdaemon channeld died (0)
2022-12-10T20:46:28.159Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2022-12-10T20:46:28.159Z DEBUG   hsmd: Client: Received message 18 from client
2022-12-10T20:46:28.165Z DEBUG   plugin-bcli: sendrawtx exit 0 (bitcoin-cli -regtest -datadir=miner2503483624 -rpcport=61949 -rpcuser=... -stdinrpcpass sendrawtransaction 0200000000010113dc34e932b2f62eb7945e00d2bd4e0c979b19976c11c7dfda5d1683146dfacc0100000000fdffffff02d48e010000000000220020d6036a171ff01fc7f094d9f6c4552a5c3002601c05d29180dad41981cd61f4721207970000000000160014add75f3fa7f82f0d2c52d88c5ea8ed5c23fc267d024730440220499e4745b44e5dedc9dd13eb08f807b5dd6497ffefbfec9db4c03640a63211e20220019aaf72c77a071b600f4aa1df5819ae68bf8fcd27a1a818b9d03399ef21c7f5012103fa8b3f76f38950651f026ccd40d0024d2912c96579098780d9ac7928b29308a26d000000) 
2022-12-10T20:46:28.166Z DEBUG   wallet: Owning output 1 9897746sat (SEGWIT) txid 573811fc7a69ab21b0475f56687b492fabdc9e10de3f63e4c9d4f6467af8ede4
2022-12-10T20:46:28.167Z DEBUG   plugin-spenderp: mfc 50: sendpsbt done.
2022-12-10T20:46:28.167Z DEBUG   plugin-spenderp: mfc 50: done.
2022-12-10T20:46:28.167Z DEBUG   plugin-spenderp: mfc 50: cleanup!
2022-12-10T20:46:28.167Z DEBUG   plugin-spenderp: mfc 50: cleanup done, finishing command.

Accepting peer

2022-12-10T20:46:28.036Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-connectd: Connected out, starting crypto
2022-12-10T20:46:28.037Z DEBUG   036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-hsmd: Got WIRE_HSMD_ECDH_REQ
2022-12-10T20:46:28.037Z DEBUG   hsmd: Client: Received message 1 from client
2022-12-10T20:46:28.037Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-connectd: Connect OUT
2022-12-10T20:46:28.037Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-connectd: peer_out WIRE_INIT
2022-12-10T20:46:28.037Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-connectd: peer_in WIRE_INIT
2022-12-10T20:46:28.037Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-gossipd: seeker: chosen as startup peer
2022-12-10T20:46:28.038Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-connectd: Handed peer, entering loop
2022-12-10T20:46:28.038Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-gossipd: seeker: starting gossip
2022-12-10T20:46:28.038Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-connectd: peer_out WIRE_GOSSIP_TIMESTAMP_FILTER
2022-12-10T20:46:28.038Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-gossipd: Received channel_announcement for channel 104x1x0
2022-12-10T20:46:28.038Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-gossipd: Updated pending announce with update 104x1x0/0
2022-12-10T20:46:28.038Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-gossipd: Updated pending announce with update 104x1x0/1
2022-12-10T20:46:28.038Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-gossipd: Updated pending announce with update 104x1x0/0
2022-12-10T20:46:28.038Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-gossipd: Updated pending announce with update 104x1x0/1
2022-12-10T20:46:28.039Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-gossipd: Received node_announcement for node 02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6
2022-12-10T20:46:28.039Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-gossipd: Received channel_update for channel 104x1x0/0 now ACTIVE
2022-12-10T20:46:28.039Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-gossipd: Received channel_update for channel 104x1x0/1 now ACTIVE
2022-12-10T20:46:28.125Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-connectd: Activating for message WIRE_OPEN_CHANNEL
2022-12-10T20:46:28.128Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-openingd-chan#1: pid 30850, msgfd 69
2022-12-10T20:46:28.128Z DEBUG   hsmd: Client: Received message 30 from client
2022-12-10T20:46:28.128Z DEBUG   hsmd: Client: Received message 10 from client
2022-12-10T20:46:28.128Z DEBUG   hsmd: new_client: 1
2022-12-10T20:46:28.133Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2022-12-10T20:46:28.133Z DEBUG   hsmd: Client: Received message 18 from client
2022-12-10T20:46:28.133Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-openingd-chan#1: peer_in WIRE_OPEN_CHANNEL
2022-12-10T20:46:28.133Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-openingd-chan#1: Setting their reserve to 1021sat
2022-12-10T20:46:28.133Z DEBUG   lightningd: Calling openchannel hook of plugin start_zero_conf_plugin.sh
2022-12-10T20:46:28.133Z INFO    plugin-start_zero_conf_plugin.sh: {'id': '02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6', 'funding_msat': 102100000, 'push_msat': 0, 'dust_limit_msat': 546000, 'max_htlc_value_in_flight_msat': 18446744073709551615, 'channel_reserve_msat': 0, 'htlc_minimum_msat': 0, 'feerate_per_kw': 253, 'to_self_delay': 6, 'max_accepted_htlcs': 30, 'channel_flags': 0}
2022-12-10T20:46:28.133Z INFO    plugin-start_zero_conf_plugin.sh: This peer is in the zeroconf allowlist, setting mindepth=0
2022-12-10T20:46:28.133Z DEBUG   lightningd: Plugin start_zero_conf_plugin.sh returned from openchannel hook call
2022-12-10T20:46:28.133Z DEBUG   lightningd: Setting mindepth=0 for this channel as requested by the openchannel hook
2022-12-10T20:46:28.134Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-openingd-chan#1: peer_out WIRE_ACCEPT_CHANNEL
2022-12-10T20:46:28.134Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-openingd-chan#1: billboard: Incoming channel: accepted, now waiting for them to create funding tx
2022-12-10T20:46:28.139Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-openingd-chan#1: peer_in WIRE_FUNDING_CREATED
2022-12-10T20:46:28.139Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-hsmd: Got WIRE_HSMD_READY_CHANNEL
2022-12-10T20:46:28.139Z DEBUG   hsmd: Client: Received message 31 from client
2022-12-10T20:46:28.140Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-hsmd: Got WIRE_HSMD_VALIDATE_COMMITMENT_TX
2022-12-10T20:46:28.140Z DEBUG   hsmd: Client: Received message 35 from client
2022-12-10T20:46:28.141Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-hsmd: Got WIRE_HSMD_SIGN_REMOTE_COMMITMENT_TX
2022-12-10T20:46:28.141Z DEBUG   hsmd: Client: Received message 19 from client
2022-12-10T20:46:28.141Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-chan#1: Got opening_fundee_finish_response
2022-12-10T20:46:28.142Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-chan#1: Watching funding tx 573811fc7a69ab21b0475f56687b492fabdc9e10de3f63e4c9d4f6467af8ede4
2022-12-10T20:46:28.145Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-channeld-chan#1: pid 30851, msgfd 70
2022-12-10T20:46:28.145Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-chan#1: Waiting for funding confirmations
2022-12-10T20:46:28.145Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-chan#1: Ignoring fee limits!
2022-12-10T20:46:28.145Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-openingd-chan#1: Status closed, but not exited. Killing
2022-12-10T20:46:28.146Z DEBUG   hsmd: new_client: 1
2022-12-10T20:46:28.149Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-channeld-chan#1: option_static_remotekey = 1, option_anchor_outputs = 0
2022-12-10T20:46:28.149Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-channeld-chan#1: init REMOTE: remote_per_commit = 02e51997030304788e534c0cb4ccfe04408d295df3e0e23a2b98c57c341d67b62c, old_remote_per_commit = 02e51997030304788e534c0cb4ccfe04408d295df3e0e23a2b98c57c341d67b62c next_idx_local = 1 next_idx_remote = 1 revocations_received = 0 feerates { RCVD_ADD_ACK_REVOCATION:253 } range 253-4294967295 blockheights { RCVD_ADD_ACK_REVOCATION:0 }, our current 109
2022-12-10T20:46:28.149Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2022-12-10T20:46:28.149Z DEBUG   hsmd: Client: Received message 18 from client
2022-12-10T20:46:28.149Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-channeld-chan#1: peer_out WIRE_FUNDING_SIGNED
2022-12-10T20:46:28.149Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-channeld-chan#1: billboard: Funding needs 0 more confirmations to be ready.
2022-12-10T20:46:28.149Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-channeld-chan#1: channel_ready: sending commit index 1: 031afd03afb19b487e9d0bc5aed1c2687a4c3dd40b6ee3a909d47e1e372a0b3960
2022-12-10T20:46:28.149Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2022-12-10T20:46:28.149Z DEBUG   hsmd: Client: Received message 18 from client
2022-12-10T20:46:28.149Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-channeld-chan#1: peer_out WIRE_CHANNEL_READY
2022-12-10T20:46:28.149Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-channeld-chan#1: billboard: We've confirmed channel ready, they haven't yet.
2022-12-10T20:46:28.563Z DEBUG   lightningd: ... feerate estimate for opening hit floor 253
2022-12-10T20:46:28.563Z DEBUG   lightningd: ... feerate estimate for mutual_close hit floor 253
2022-12-10T20:46:28.563Z DEBUG   lightningd: ... feerate estimate for unilateral_close hit floor 253
2022-12-10T20:46:28.563Z DEBUG   lightningd: ... feerate estimate for delayed_to_us hit floor 253
2022-12-10T20:46:28.563Z DEBUG   lightningd: ... feerate estimate for htlc_resolution hit floor 253
2022-12-10T20:46:28.564Z DEBUG   lightningd: ... feerate estimate for penalty hit floor 253
2022-12-10T20:46:28.564Z DEBUG   lightningd: ... polled feerate estimate for min_acceptable (125) smoothed to 250 (alpha=0.02)
2022-12-10T20:46:28.564Z DEBUG   lightningd: ... feerate estimate for min_acceptable hit floor 253
2022-12-10T20:46:29.039Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-gossipd: Received node_announcement for node 02d0928b9effc19197ae42b0aa027e6f9b8cb7691dbb7e4076b80e90830049db62
2022-12-10T20:46:29.594Z DEBUG   lightningd: ... feerate estimate for opening hit floor 253
2022-12-10T20:46:29.594Z DEBUG   lightningd: ... feerate estimate for mutual_close hit floor 253
2022-12-10T20:46:29.594Z DEBUG   lightningd: ... feerate estimate for unilateral_close hit floor 253
2022-12-10T20:46:29.594Z DEBUG   lightningd: ... feerate estimate for delayed_to_us hit floor 253
2022-12-10T20:46:29.595Z DEBUG   lightningd: ... feerate estimate for htlc_resolution hit floor 253
2022-12-10T20:46:29.595Z DEBUG   lightningd: ... feerate estimate for penalty hit floor 253
2022-12-10T20:46:29.595Z DEBUG   lightningd: ... polled feerate estimate for min_acceptable (125) smoothed to 250 (alpha=0.02)
2022-12-10T20:46:29.595Z DEBUG   lightningd: ... feerate estimate for min_acceptable hit floor 253
2022-12-10T20:46:30.624Z DEBUG   lightningd: ... feerate estimate for opening hit floor 253
2022-12-10T20:46:30.624Z DEBUG   lightningd: ... feerate estimate for mutual_close hit floor 253
2022-12-10T20:46:30.624Z DEBUG   lightningd: ... feerate estimate for unilateral_close hit floor 253
2022-12-10T20:46:30.624Z DEBUG   lightningd: ... feerate estimate for delayed_to_us hit floor 253
2022-12-10T20:46:30.624Z DEBUG   lightningd: ... feerate estimate for htlc_resolution hit floor 253
2022-12-10T20:46:30.624Z DEBUG   lightningd: ... feerate estimate for penalty hit floor 253
2022-12-10T20:46:30.624Z DEBUG   lightningd: ... polled feerate estimate for min_acceptable (125) smoothed to 250 (alpha=0.02)
2022-12-10T20:46:30.624Z DEBUG   lightningd: ... feerate estimate for min_acceptable hit floor 253
2022-12-10T20:46:31.653Z DEBUG   lightningd: ... feerate estimate for opening hit floor 253
2022-12-10T20:46:31.653Z DEBUG   lightningd: ... feerate estimate for mutual_close hit floor 253
2022-12-10T20:46:31.653Z DEBUG   lightningd: ... feerate estimate for unilateral_close hit floor 253
2022-12-10T20:46:31.653Z DEBUG   lightningd: ... feerate estimate for delayed_to_us hit floor 253
2022-12-10T20:46:31.653Z DEBUG   lightningd: ... feerate estimate for htlc_resolution hit floor 253
2022-12-10T20:46:31.653Z DEBUG   lightningd: ... feerate estimate for penalty hit floor 253
2022-12-10T20:46:31.653Z DEBUG   lightningd: ... polled feerate estimate for min_acceptable (125) smoothed to 250 (alpha=0.02)
2022-12-10T20:46:31.653Z DEBUG   lightningd: ... feerate estimate for min_acceptable hit floor 253
2022-12-10T20:46:32.676Z DEBUG   lightningd: ... feerate estimate for opening hit floor 253
2022-12-10T20:46:32.676Z DEBUG   lightningd: ... feerate estimate for mutual_close hit floor 253
2022-12-10T20:46:32.676Z DEBUG   lightningd: ... feerate estimate for unilateral_close hit floor 253
2022-12-10T20:46:32.676Z DEBUG   lightningd: ... feerate estimate for delayed_to_us hit floor 253
2022-12-10T20:46:32.676Z DEBUG   lightningd: ... feerate estimate for htlc_resolution hit floor 253
2022-12-10T20:46:32.676Z DEBUG   lightningd: ... feerate estimate for penalty hit floor 253
2022-12-10T20:46:32.676Z DEBUG   lightningd: ... polled feerate estimate for min_acceptable (125) smoothed to 250 (alpha=0.02)
2022-12-10T20:46:32.676Z DEBUG   lightningd: ... feerate estimate for min_acceptable hit floor 253
2022-12-10T20:46:33.414Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-gossipd: seeker: startup peer finished
2022-12-10T20:46:33.414Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-gossipd: seeker: state = PROBING_SCIDS Seeking scids 1 - 109
2022-12-10T20:46:33.414Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-gossipd: sending query_channel_range for blocks 1+109
2022-12-10T20:46:33.417Z DEBUG   02c3212fb660988b1aac3b5cd3d4223cc254e61af0e9818ee0d192a574c3616ec6-gossipd: reply_channel_range 1+109 (of 1+109) 1 scids

Succesful flow

Channel funder

2022-12-10T20:47:50.054Z DEBUG   plugin-spenderp: mfc 50: multiconnect.
2022-12-10T20:47:50.054Z DEBUG   lightningd: Already connected via 127.0.0.1:49382
2022-12-10T20:47:50.054Z DEBUG   plugin-spenderp: mfc 50, dest 0: connect 031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1.
2022-12-10T20:47:50.054Z DEBUG   plugin-spenderp: mfc 50, dest 0: connect done.
2022-12-10T20:47:50.054Z DEBUG   plugin-spenderp: mfc 50: multiconnect done.
2022-12-10T20:47:50.056Z DEBUG   plugin-spenderp: mfc 50: 'parsefeerate' done
2022-12-10T20:47:50.056Z DEBUG   plugin-spenderp: mfc 50: fundpsbt.
2022-12-10T20:47:50.056Z DEBUG   plugin-spenderp: mfc 50: fundpsbt done.
2022-12-10T20:47:50.058Z DEBUG   plugin-spenderp: mfc 50: fundchannel_start parallel with PSBT cHNidP8BADMCAAAAAW4PQSxCmP6RPhOf0f3fH4NjiAJJS729v07TVUlFXdnkAAAAAAD9////AGsAAAAAAQDeAgAAAAABAd1pi/9wcweiiOexIPqIdMGv3iweCPK3+pZ0wHKWrBkXAQAAAAD+////AoCWmAAAAAAAFgAURrTIj7cogzYIoCBUtl6b1szsKXPmw9QoAQAAABYAFJooDqzauCxFClWsUYWqnMtu0sAkAkcwRAIgUVNuIrwncLREX2hQAxB3ZSk17NRuvD4tB3uVY65Gv1gCICU1KJN9iVbBvVMsjDoYsCSjxJ88y5FNr/9EPhzeklTPASECo9hB5N0iOpLcnCntzcFLEt8o/8IDcOGpMtS8ENoxDiNmAAAAAQEfgJaYAAAAAAAWABRGtMiPtyiDNgigIFS2XpvWzOwpcwz8CWxpZ2h0bmluZwEIJu+CEQ4VUBgM/AlsaWdodG5pbmcCAgABAA==
2022-12-10T20:47:50.058Z DEBUG   lightningd: fundchannel_start: allocating uncommitted_channel
2022-12-10T20:47:50.058Z INFO    lightningd: Will open private channel with node 031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1
2022-12-10T20:47:50.062Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-openingd-chan#2: pid 32339, msgfd 70
2022-12-10T20:47:50.062Z DEBUG   plugin-spenderp: mfc 50, dest 0: fundchannel_start 031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1.
2022-12-10T20:47:50.062Z DEBUG   hsmd: Client: Received message 30 from client
2022-12-10T20:47:50.062Z DEBUG   hsmd: Client: Received message 10 from client
2022-12-10T20:47:50.063Z DEBUG   hsmd: new_client: 2
2022-12-10T20:47:50.069Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2022-12-10T20:47:50.069Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-openingd-chan#2: funder_channel_start
2022-12-10T20:47:50.069Z DEBUG   hsmd: Client: Received message 18 from client
2022-12-10T20:47:50.069Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-openingd-chan#2: Setting their reserve to 0sat
2022-12-10T20:47:50.069Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-openingd-chan#2: peer_out WIRE_OPEN_CHANNEL
2022-12-10T20:47:50.069Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-openingd-chan#2: billboard: Funding channel start: offered, now waiting for accept_channel
2022-12-10T20:47:50.081Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-openingd-chan#2: peer_in WIRE_ACCEPT_CHANNEL
2022-12-10T20:47:50.082Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-openingd-chan#2: accept_channel: max_htlc_value_in_flight=18446744073709551615msat, channel_reserve=1021sat, htlc_minimum=0msat, minimum_depth=1
2022-12-10T20:47:50.082Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-openingd-chan#2: We negotiated option_zeroconf, using our minimum_depth=0
2022-12-10T20:47:50.082Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-openingd-chan#2: billboard: Funding channel start: awaiting funding_txid with output to 002071c0505062dca4cf58ac4d11c3a661473445812a2f592b8c59dc0d27b728ffde
2022-12-10T20:47:50.082Z DEBUG   plugin-spenderp: mfc 50, dest 0: fundchannel_start 031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1 done.
2022-12-10T20:47:50.082Z DEBUG   plugin-spenderp: mfc 50: parallel channel starts done.
2022-12-10T20:47:50.082Z DEBUG   plugin-spenderp: mfc 50: Creating funding tx.
2022-12-10T20:47:50.082Z DEBUG   plugin-spenderp: mfc 50: funding tx 8ec4ee4dd01e079a1e79e74dbd578d9b5ac89705141dbac2f9733bb6d93f1fe5: change: 9897746sat, 031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1: 102100sat
2022-12-10T20:47:50.082Z DEBUG   plugin-spenderp: mfc 50: parallel fundchannel_complete.
2022-12-10T20:47:50.082Z DEBUG   plugin-spenderp: mfc 50, dest 0: fundchannel_complete 031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1.
2022-12-10T20:47:50.083Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-openingd-chan#2: billboard: Funding channel con't: continuing with funding_txid 8ec4ee4dd01e079a1e79e74dbd578d9b5ac89705141dbac2f9733bb6d93f1fe5
2022-12-10T20:47:50.083Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-hsmd: Got WIRE_HSMD_READY_CHANNEL
2022-12-10T20:47:50.083Z DEBUG   hsmd: Client: Received message 31 from client
2022-12-10T20:47:50.085Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-hsmd: Got WIRE_HSMD_SIGN_REMOTE_COMMITMENT_TX
2022-12-10T20:47:50.086Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-openingd-chan#2: signature 3044022007c4e7044d537aa3c7f05f7f97194181c2ba2a3efc84b8ffe007f2c8cb0f179f022006c0219871d1321378e07258fc0790d95d712ae40344c02bd0fa99739b035e5901 on tx 0200000001e51f3fd9b63b73f9c2ba1d140597c85a9b8d57bd4de7791e9a071ed04deec48e01000000003d6ebb80011d8e0100000000001600146ad6a73a69c1febacc793f77d19d6e0aee1b8b8a9a9e1420 using key 03141b9199751b1ba31bc2fd37b872f7fad7d7f5936e94ca2dfb67fbaf76b46399
2022-12-10T20:47:50.086Z DEBUG   hsmd: Client: Received message 19 from client
2022-12-10T20:47:50.086Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-openingd-chan#2: peer_out WIRE_FUNDING_CREATED
2022-12-10T20:47:50.086Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-openingd-chan#2: billboard: Funding channel: create first tx, now waiting for their signature
2022-12-10T20:47:50.099Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-openingd-chan#2: peer_in WIRE_FUNDING_SIGNED
2022-12-10T20:47:50.099Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-hsmd: Got WIRE_HSMD_VALIDATE_COMMITMENT_TX
2022-12-10T20:47:50.099Z DEBUG   hsmd: Client: Received message 35 from client
2022-12-10T20:47:50.100Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-openingd-chan#2: billboard: Funding channel: opening negotiation succeeded
2022-12-10T20:47:50.100Z DEBUG   lightningd: 02c028c3be3eba1509e6f5e67e490a898e59541e430aa91bdfd2bdbd204454e63d
2022-12-10T20:47:50.104Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-channeld-chan#2: pid 32346, msgfd 72
2022-12-10T20:47:50.104Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-chan#2: Waiting for funding confirmations
2022-12-10T20:47:50.104Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-chan#2: Ignoring fee limits!
2022-12-10T20:47:50.104Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-chan#2: attempting update blockheight e51f3fd9b63b73f9c2ba1d140597c85a9b8d57bd4de7791e9a071ed04deec48f
2022-12-10T20:47:50.104Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-openingd-chan#2: Status closed, but not exited. Killing
2022-12-10T20:47:50.105Z DEBUG   hsmd: new_client: 2
2022-12-10T20:47:50.107Z DEBUG   plugin-spenderp: mfc 50, dest 0: fundchannel_complete 031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1 done.
2022-12-10T20:47:50.107Z DEBUG   plugin-spenderp: mfc 50: parallel fundchannel_complete  done.
2022-12-10T20:47:50.107Z DEBUG   plugin-spenderp: mfc 50: signpsbt.
2022-12-10T20:47:50.107Z DEBUG   hsmd: Client: Received message 7 from client
2022-12-10T20:47:50.107Z DEBUG   lightningd: sendrawtransaction: 020000000001016e0f412c4298fe913e139fd1fddf1f83638802494bbdbdbf4ed35549455dd9e40000000000fdffffff021207970000000000160014226e0a0d45a01e73493fed542d2975a0ba6f37abd48e01000000000022002071c0505062dca4cf58ac4d11c3a661473445812a2f592b8c59dc0d27b728ffde024730440220789cba9f4d60c3abb32653ba1f08731838d9ea81d94d11f6c79fe8e4e34298b302206809fd4f0713baa322407be06be3e2a393cc109ba9bb85f4d141ef03f5b294320121023b197858ca96b84051d4770b0e26af9dbd303ca12571e68dc01bcbfdbc47d42c6b000000
2022-12-10T20:47:50.109Z DEBUG   plugin-spenderp: mfc 50: signpsbt done.
2022-12-10T20:47:50.109Z DEBUG   plugin-spenderp: mfc 50: sendpsbt.
2022-12-10T20:47:50.109Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-channeld-chan#2: option_static_remotekey = 1, option_anchor_outputs = 0
2022-12-10T20:47:50.109Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-channeld-chan#2: init LOCAL: remote_per_commit = 02c028c3be3eba1509e6f5e67e490a898e59541e430aa91bdfd2bdbd204454e63d, old_remote_per_commit = 02c028c3be3eba1509e6f5e67e490a898e59541e430aa91bdfd2bdbd204454e63d next_idx_local = 1 next_idx_remote = 1 revocations_received = 0 feerates { SENT_ADD_ACK_REVOCATION:253 } range 253-4294967295 blockheights { SENT_ADD_ACK_REVOCATION:0 }, our current 115
2022-12-10T20:47:50.109Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2022-12-10T20:47:50.109Z DEBUG   hsmd: Client: Received message 18 from client
2022-12-10T20:47:50.109Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-channeld-chan#2: billboard: Funding needs 0 more confirmations to be ready.
2022-12-10T20:47:50.110Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-channeld-chan#2: channel_ready: sending commit index 1: 03cb761529f8b62d0f0f38035fcdeea74fc79ac61da08c5850ff25e2a1a97a3926
2022-12-10T20:47:50.110Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2022-12-10T20:47:50.110Z DEBUG   hsmd: Client: Received message 18 from client
2022-12-10T20:47:50.110Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-channeld-chan#2: peer_out WIRE_CHANNEL_READY
2022-12-10T20:47:50.110Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-channeld-chan#2: billboard: We've confirmed channel ready, they haven't yet.
2022-12-10T20:47:50.110Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-channeld-chan#2: peer_in WIRE_CHANNEL_READY
2022-12-10T20:47:50.110Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-channeld-chan#2: Peer told us that they'll use alias=2739350x10579728x65251 for this channel
2022-12-10T20:47:50.110Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-chan#2: Got channel_ready
2022-12-10T20:47:50.111Z INFO    031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-chan#2: State changed from CHANNELD_AWAITING_LOCKIN to CHANNELD_NORMAL
2022-12-10T20:47:50.111Z DEBUG   lightningd: update_feerates: feerate = 253, min=253, max=4294967295, penalty=253
2022-12-10T20:47:50.111Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-chan#2: attempting update blockheight e51f3fd9b63b73f9c2ba1d140597c85a9b8d57bd4de7791e9a071ed04deec48f
2022-12-10T20:47:50.113Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-channeld-chan#2: billboard: Channel ready for use.
2022-12-10T20:47:50.113Z DEBUG   plugin-funder: Cleaning up datastore for channel_id e51f3fd9b63b73f9c2ba1d140597c85a9b8d57bd4de7791e9a071ed04deec48f
2022-12-10T20:47:50.114Z INFO    plugin-chanbackup: Updating the SCB
2022-12-10T20:47:50.114Z DEBUG   plugin-chanbackup: Updating the SCB file...
2022-12-10T20:47:50.114Z DEBUG   plugin-bookkeeper: coin_move 2 (channel_proposed) 102100000msat -0msat chain_mvt 1670705270
2022-12-10T20:47:50.116Z DEBUG   plugin-bcli: sendrawtx exit 0 (bitcoin-cli -regtest -datadir=miner2454834833 -rpcport=64271 -rpcuser=... -stdinrpcpass sendrawtransaction 020000000001016e0f412c4298fe913e139fd1fddf1f83638802494bbdbdbf4ed35549455dd9e40000000000fdffffff021207970000000000160014226e0a0d45a01e73493fed542d2975a0ba6f37abd48e01000000000022002071c0505062dca4cf58ac4d11c3a661473445812a2f592b8c59dc0d27b728ffde024730440220789cba9f4d60c3abb32653ba1f08731838d9ea81d94d11f6c79fe8e4e34298b302206809fd4f0713baa322407be06be3e2a393cc109ba9bb85f4d141ef03f5b294320121023b197858ca96b84051d4770b0e26af9dbd303ca12571e68dc01bcbfdbc47d42c6b000000) 
2022-12-10T20:47:50.117Z DEBUG   wallet: Owning output 0 9897746sat (SEGWIT) txid 8ec4ee4dd01e079a1e79e74dbd578d9b5ac89705141dbac2f9733bb6d93f1fe5
2022-12-10T20:47:50.119Z DEBUG   plugin-spenderp: mfc 50: sendpsbt done.
2022-12-10T20:47:50.119Z DEBUG   plugin-spenderp: mfc 50: done.
2022-12-10T20:47:50.119Z DEBUG   plugin-spenderp: mfc 50: cleanup!
2022-12-10T20:47:50.119Z DEBUG   plugin-spenderp: mfc 50: cleanup done, finishing command.

Accepting peer

2022-12-10T20:47:49.967Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-connectd: Connected out, starting crypto
2022-12-10T20:47:49.968Z DEBUG   031ce6de13373c3768e0e94f216ed212f52b19d2fc41f16568b38f09d9361ea0c1-hsmd: Got WIRE_HSMD_ECDH_REQ
2022-12-10T20:47:49.968Z DEBUG   hsmd: Client: Received message 1 from client
2022-12-10T20:47:49.968Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-connectd: Connect OUT
2022-12-10T20:47:49.968Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-connectd: peer_out WIRE_INIT
2022-12-10T20:47:49.969Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-connectd: peer_in WIRE_INIT
2022-12-10T20:47:49.969Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-connectd: Handed peer, entering loop
2022-12-10T20:47:49.969Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-gossipd: seeker: chosen as startup peer
2022-12-10T20:47:49.970Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-gossipd: seeker: starting gossip
2022-12-10T20:47:49.970Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-gossipd: Received channel_announcement for channel 104x1x0
2022-12-10T20:47:49.970Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-connectd: peer_out WIRE_GOSSIP_TIMESTAMP_FILTER
2022-12-10T20:47:49.970Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-gossipd: Updated pending announce with update 104x1x0/0
2022-12-10T20:47:49.970Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-gossipd: Updated pending announce with update 104x1x0/1
2022-12-10T20:47:49.971Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-gossipd: Received node_announcement for node 02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102
2022-12-10T20:47:49.971Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-gossipd: Received channel_update for channel 104x1x0/0 now ACTIVE
2022-12-10T20:47:49.971Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-gossipd: Received channel_update for channel 104x1x0/1 now ACTIVE
2022-12-10T20:47:50.069Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-connectd: Activating for message WIRE_OPEN_CHANNEL
2022-12-10T20:47:50.073Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-openingd-chan#1: pid 32341, msgfd 69
2022-12-10T20:47:50.074Z DEBUG   hsmd: Client: Received message 30 from client
2022-12-10T20:47:50.074Z DEBUG   hsmd: Client: Received message 10 from client
2022-12-10T20:47:50.074Z DEBUG   hsmd: new_client: 1
2022-12-10T20:47:50.079Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2022-12-10T20:47:50.079Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-openingd-chan#1: peer_in WIRE_OPEN_CHANNEL
2022-12-10T20:47:50.079Z DEBUG   hsmd: Client: Received message 18 from client
2022-12-10T20:47:50.079Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-openingd-chan#1: Setting their reserve to 1021sat
2022-12-10T20:47:50.079Z DEBUG   lightningd: Calling openchannel hook of plugin start_zero_conf_plugin.sh
2022-12-10T20:47:50.080Z INFO    plugin-start_zero_conf_plugin.sh: {'id': '02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102', 'funding_msat': 102100000, 'push_msat': 0, 'dust_limit_msat': 546000, 'max_htlc_value_in_flight_msat': 18446744073709551615, 'channel_reserve_msat': 0, 'htlc_minimum_msat': 0, 'feerate_per_kw': 253, 'to_self_delay': 6, 'max_accepted_htlcs': 30, 'channel_flags': 0}
2022-12-10T20:47:50.081Z INFO    plugin-start_zero_conf_plugin.sh: This peer is in the zeroconf allowlist, setting mindepth=0
2022-12-10T20:47:50.081Z DEBUG   lightningd: Plugin start_zero_conf_plugin.sh returned from openchannel hook call
2022-12-10T20:47:50.081Z DEBUG   lightningd: Setting mindepth=0 for this channel as requested by the openchannel hook
2022-12-10T20:47:50.081Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-openingd-chan#1: peer_out WIRE_ACCEPT_CHANNEL
2022-12-10T20:47:50.081Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-openingd-chan#1: billboard: Incoming channel: accepted, now waiting for them to create funding tx
2022-12-10T20:47:50.086Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-openingd-chan#1: peer_in WIRE_FUNDING_CREATED
2022-12-10T20:47:50.086Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-hsmd: Got WIRE_HSMD_READY_CHANNEL
2022-12-10T20:47:50.086Z DEBUG   hsmd: Client: Received message 31 from client
2022-12-10T20:47:50.087Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-hsmd: Got WIRE_HSMD_VALIDATE_COMMITMENT_TX
2022-12-10T20:47:50.087Z DEBUG   hsmd: Client: Received message 35 from client
2022-12-10T20:47:50.089Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-hsmd: Got WIRE_HSMD_SIGN_REMOTE_COMMITMENT_TX
2022-12-10T20:47:50.089Z DEBUG   hsmd: Client: Received message 19 from client
2022-12-10T20:47:50.089Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-chan#1: Got opening_fundee_finish_response
2022-12-10T20:47:50.091Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-chan#1: Watching funding tx 8ec4ee4dd01e079a1e79e74dbd578d9b5ac89705141dbac2f9733bb6d93f1fe5
2022-12-10T20:47:50.093Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-channeld-chan#1: pid 32345, msgfd 70
2022-12-10T20:47:50.093Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-chan#1: Waiting for funding confirmations
2022-12-10T20:47:50.093Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-chan#1: Ignoring fee limits!
2022-12-10T20:47:50.093Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-openingd-chan#1: Status closed, but not exited. Killing
2022-12-10T20:47:50.095Z DEBUG   hsmd: new_client: 1
2022-12-10T20:47:50.097Z DEBUG   lightningd: ... feerate estimate for opening hit floor 253
2022-12-10T20:47:50.097Z DEBUG   lightningd: ... feerate estimate for mutual_close hit floor 253
2022-12-10T20:47:50.097Z DEBUG   lightningd: ... feerate estimate for unilateral_close hit floor 253
2022-12-10T20:47:50.097Z DEBUG   lightningd: ... feerate estimate for delayed_to_us hit floor 253
2022-12-10T20:47:50.097Z DEBUG   lightningd: ... feerate estimate for htlc_resolution hit floor 253
2022-12-10T20:47:50.097Z DEBUG   lightningd: ... feerate estimate for penalty hit floor 253
2022-12-10T20:47:50.097Z DEBUG   lightningd: ... polled feerate estimate for min_acceptable (125) smoothed to 250 (alpha=0.02)
2022-12-10T20:47:50.097Z DEBUG   lightningd: ... feerate estimate for min_acceptable hit floor 253
2022-12-10T20:47:50.098Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-channeld-chan#1: option_static_remotekey = 1, option_anchor_outputs = 0
2022-12-10T20:47:50.098Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-channeld-chan#1: init REMOTE: remote_per_commit = 02518a5db9ad66bada347cc4bc69dbd3eacca70042a7c7b2102e00cdbaa51ae75c, old_remote_per_commit = 02518a5db9ad66bada347cc4bc69dbd3eacca70042a7c7b2102e00cdbaa51ae75c next_idx_local = 1 next_idx_remote = 1 revocations_received = 0 feerates { RCVD_ADD_ACK_REVOCATION:253 } range 253-4294967295 blockheights { RCVD_ADD_ACK_REVOCATION:0 }, our current 115
2022-12-10T20:47:50.098Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2022-12-10T20:47:50.098Z DEBUG   hsmd: Client: Received message 18 from client
2022-12-10T20:47:50.098Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-channeld-chan#1: peer_out WIRE_FUNDING_SIGNED
2022-12-10T20:47:50.098Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-channeld-chan#1: billboard: Funding needs 0 more confirmations to be ready.
2022-12-10T20:47:50.098Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-channeld-chan#1: channel_ready: sending commit index 1: 02d7fdc7447d3885b8a4ec23f2da7f9291ceeeeaecbf8c7c215ddbdaa992cdf5ec
2022-12-10T20:47:50.099Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2022-12-10T20:47:50.099Z DEBUG   hsmd: Client: Received message 18 from client
2022-12-10T20:47:50.099Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-channeld-chan#1: peer_out WIRE_CHANNEL_READY
2022-12-10T20:47:50.099Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-channeld-chan#1: billboard: We've confirmed channel ready, they haven't yet.
2022-12-10T20:47:50.110Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-channeld-chan#1: peer_in WIRE_CHANNEL_READY
2022-12-10T20:47:50.110Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-channeld-chan#1: Peer told us that they'll use alias=7054100x15544350x62801 for this channel
2022-12-10T20:47:50.110Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-chan#1: Got channel_ready
2022-12-10T20:47:50.111Z INFO    02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-chan#1: State changed from CHANNELD_AWAITING_LOCKIN to CHANNELD_NORMAL
2022-12-10T20:47:50.111Z DEBUG   lightningd: update_feerates: feerate = 253, min=253, max=4294967295, penalty=253
2022-12-10T20:47:50.111Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-chan#1: attempting update blockheight e51f3fd9b63b73f9c2ba1d140597c85a9b8d57bd4de7791e9a071ed04deec48f
2022-12-10T20:47:50.113Z DEBUG   plugin-funder: Cleaning up datastore for channel_id e51f3fd9b63b73f9c2ba1d140597c85a9b8d57bd4de7791e9a071ed04deec48f
2022-12-10T20:47:50.113Z DEBUG   02a428a7fbfecfac8b7e252813fa240a1203895cb0cb4ad13192ca2f39c9c63102-channeld-chan#1: billboard: Channel ready for use.
@JssDWt JssDWt mentioned this issue Dec 12, 2022
Closed
@JssDWt
Copy link
Contributor Author

JssDWt commented Dec 16, 2022

I had this issue on macOS. CLN was running in a directory that was not indexed by Spotlight. Putting back file indexing on the directory CLN was running in seems to have resolved the problem for me. So I guess the channeld daemon dying had something to do with unindexed file access.

@cdecker
Copy link
Member

cdecker commented Dec 30, 2022

Channeld dying is a badly phrased log that stems from us losing the connection with the peer. This case is strange since you seem to be controlling both endpoints.

Maybe this is related to the FD mixup we are hunting down on MacOS @ddustin ?

@JssDWt
Copy link
Contributor Author

JssDWt commented Dec 30, 2022 •
edited
Loading

It appears to happen more often when spotlight decides to index files, mds_stores being actively consuming a lot of CPU and disk reads/writes. I don't know whether that helps. I think it must be a race somewhere. Not necessarily the log line, but the fact that the channel is stuck in CHANNELD_AWAITING_LOCKIN.

@ddustin
Copy link
Collaborator

ddustin commented Dec 30, 2022 •
edited
Loading

Channeld dying is a badly phrased log that stems from us losing the connection with the peer. This case is strange since you seem to be controlling both endpoints.

Maybe this is related to the FD mixup we are hunting down on MacOS @ddustin ?

It definitely rhymes

2022-12-10T20:46:28.154Z DEBUG 036cf43e0ede57d72dfeabd0795fdc5f76244b396c9f19333e2ed1d89fcce90894-openingd-chan#2: Status closed, but not exited. Killing

^ this makes me think it's related.

Are you able to recreate the problem easily?

It would be nice to see if changing some constants effects how often it fails.

In subd.c around line 602 change
switch (waitpid(sd->pid, &status, WNOHANG))
to
switch (waitpid(sd->pid, &status, 0))

ie. Remove the WNOHANG

In openingd.c around line 1557 change

	/* Give master a chance to pass the fd along */
	sleep(1);

to

	/* Give master a chance to pass the fd along */
	sleep(5);

In dualopen.c around line 4076 change

	/* Give master a chance to pass the fd along */
	sleep(1);

to

	/* Give master a chance to pass the fd along */
	sleep(5);

Are you opening a legacy v1 channel with this? Would be nice to know if the problem happens for both dualopen and the legacy open.

@JssDWt
Copy link
Contributor Author

JssDWt commented Dec 30, 2022

I can't exactly reproduce the issue in any controlled way. I can only say 'it happens sometimes'. It does appear that when it does happen, it happens quite often in that period.

I'm using cln v22.11 currently
I'm opening channels in two ways in my integration tests, it appears to happen for both cases.

  • regular open with fundchannel, specifying id, amount and annouce.
  • fundchannel with zero conf + zero reserve open

I'm not sure whether that's a legacy v1 channel? Is it?

There's some timing options set:
--dev-bitcoind-poll=1 --dev-fast-gossip

I'll change those values in subd.c openingd.c and dualopen.c and run my tests with those values for a while to see whether it helps. I guess I can say it helps if I haven't had this problem in a week or so.

@ddustin
Copy link
Collaborator

ddustin commented Dec 30, 2022

Cool 👍.

I wonder if you can recreate it more easily if you put the CPU under heavy load while it's running

@JssDWt
Copy link
Contributor Author

JssDWt commented Jan 5, 2023 •
edited
Loading

@ddustin it doesn't help. Currently running v22.11.1 with those changes you suggested.

Here's a case with a 'normal' channel open:

Accepting side

2023-01-05T14:39:05.064Z DEBUG   lightningd: Adding block 103: 63dd4f99f7b2f61cf09318ab3d966f18807a5145013c3b4841dbc36cea7c663c
2023-01-05T14:39:05.068Z DEBUG   wallet: Owning output 1 10000000sat (SEGWIT) txid 6de92d089581cdead20428b395a822c518038f1d85d2fc862a967ccf3c223949 CONFIRMED
2023-01-05T14:39:05.071Z DEBUG   plugin-bookkeeper: coin_move 2 (deposit) 10000000000msat -0msat chain_mvt 1672929545
2023-01-05T14:39:05.077Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_NEW_BLOCKHEIGHT_REPLY with 0 fds
2023-01-05T14:39:05.149Z DEBUG   0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7-hsmd: Got WIRE_HSMD_ECDH_REQ
2023-01-05T14:39:05.150Z DEBUG   hsmd: Client: Received message 1 from client
2023-01-05T14:39:05.150Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-connectd: Connect IN
2023-01-05T14:39:05.151Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-connectd: peer_out WIRE_INIT
2023-01-05T14:39:05.151Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-connectd: peer_in WIRE_INIT
2023-01-05T14:39:05.151Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-gossipd: seeker: chosen as startup peer
2023-01-05T14:39:05.151Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-connectd: Handed peer, entering loop
2023-01-05T14:39:05.151Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-gossipd: seeker: starting gossip
2023-01-05T14:39:05.151Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-connectd: peer_out WIRE_GOSSIP_TIMESTAMP_FILTER
2023-01-05T14:39:05.151Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-connectd: peer_in WIRE_GOSSIP_TIMESTAMP_FILTER
2023-01-05T14:39:05.163Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-connectd: Activating for message WIRE_OPEN_CHANNEL
2023-01-05T14:39:05.166Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-openingd-chan#1: pid 77728, msgfd 71
2023-01-05T14:39:05.166Z DEBUG   hsmd: Client: Received message 30 from client
2023-01-05T14:39:05.166Z DEBUG   hsmd: Client: Received message 10 from client
2023-01-05T14:39:05.166Z DEBUG   hsmd: new_client: 1
2023-01-05T14:39:05.170Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2023-01-05T14:39:05.170Z DEBUG   hsmd: Client: Received message 18 from client
2023-01-05T14:39:05.170Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-openingd-chan#1: peer_in WIRE_OPEN_CHANNEL
2023-01-05T14:39:05.170Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-openingd-chan#1: Setting their reserve to 10001sat
2023-01-05T14:39:05.170Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-openingd-chan#1: peer_out WIRE_ACCEPT_CHANNEL
2023-01-05T14:39:05.170Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-openingd-chan#1: billboard: Incoming channel: accepted, now waiting for them to create funding tx
2023-01-05T14:39:05.177Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-openingd-chan#1: peer_in WIRE_FUNDING_CREATED
2023-01-05T14:39:05.177Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-hsmd: Got WIRE_HSMD_READY_CHANNEL
2023-01-05T14:39:05.177Z DEBUG   hsmd: Client: Received message 31 from client
2023-01-05T14:39:05.178Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-hsmd: Got WIRE_HSMD_VALIDATE_COMMITMENT_TX
2023-01-05T14:39:05.178Z DEBUG   hsmd: Client: Received message 35 from client
2023-01-05T14:39:05.180Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-hsmd: Got WIRE_HSMD_SIGN_REMOTE_COMMITMENT_TX
2023-01-05T14:39:05.180Z DEBUG   hsmd: Client: Received message 19 from client
2023-01-05T14:39:05.180Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-chan#1: Got opening_fundee_finish_response
2023-01-05T14:39:05.181Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-chan#1: Watching funding tx 40b9d8070864d520ded0d7ea854af3c7d85f7ce098e307aed1ee0a53aa74ff56
2023-01-05T14:39:05.184Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-channeld-chan#1: pid 77729, msgfd 72
2023-01-05T14:39:05.184Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-chan#1: Waiting for funding confirmations
2023-01-05T14:39:05.184Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-chan#1: Ignoring fee limits!
2023-01-05T14:39:10.187Z DEBUG   hsmd: new_client: 1
2023-01-05T14:39:10.188Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-channeld-chan#1: option_static_remotekey = 1, option_anchor_outputs = 0
2023-01-05T14:39:10.188Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-channeld-chan#1: init REMOTE: remote_per_commit = 034ab499d08d34f4ac881622185a5d240bd3e01d3ef73375ba88f1e4fa536589a7, old_remote_per_commit = 034ab499d08d34f4ac881622185a5d240bd3e01d3ef73375ba88f1e4fa536589a7 next_idx_local = 1 next_idx_remote = 1 revocations_received = 0 feerates { RCVD_ADD_ACK_REVOCATION:253 } range 253-4294967295 blockheights { RCVD_ADD_ACK_REVOCATION:0 }, our current 103
2023-01-05T14:39:10.189Z INFO    03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-chan#1: Peer transient failure in CHANNELD_AWAITING_LOCKIN: channeld: Owning subdaemon channeld died (0)
2023-01-05T14:39:10.189Z DEBUG   03d578375badeee27690f4948f67682c915cd779815d7d9e03106eb7e0abac08db-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2023-01-05T14:39:10.189Z DEBUG   hsmd: Client: Received message 18 from client

Opening side

2023-01-05T14:39:05.153Z DEBUG   plugin-spenderp: mfc 49: multiconnect.
2023-01-05T14:39:05.153Z DEBUG   plugin-spenderp: mfc 49, dest 0: connect 0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7.
2023-01-05T14:39:05.153Z DEBUG   lightningd: Already connected via 127.0.0.1:63889
2023-01-05T14:39:05.153Z DEBUG   plugin-spenderp: mfc 49, dest 0: connect done.
2023-01-05T14:39:05.153Z DEBUG   plugin-spenderp: mfc 49: multiconnect done.
2023-01-05T14:39:05.153Z DEBUG   plugin-spenderp: mfc 49: 'parsefeerate' done
2023-01-05T14:39:05.153Z DEBUG   plugin-spenderp: mfc 49: fundpsbt.
2023-01-05T14:39:05.155Z DEBUG   plugin-spenderp: mfc 49: fundpsbt done.
2023-01-05T14:39:05.156Z DEBUG   plugin-spenderp: mfc 49: fundchannel_start parallel with PSBT cHNidP8BADMCAAAAAWeat36o+fsULfm8O92SpuG8kkgYlR6CYyvxWoHgv4emAQAAAAD9////AGYAAAAAAQDeAgAAAAABAQITc1Uh61nszWjamNTx7MT/3udnjaJWpcSw7hT2yg8UAAAAAAD+////AvNabSkBAAAAFgAUKak3RFxMUU9UXyXsmjDNSZ270m2AlpgAAAAAABYAFMy/G+GDYIDC0gTuCxRMTpids0I8AkcwRAIgXNBfosyMbpJhiF+ys8aX0bf9vrdamiuCdNEu8EwH9A0CIDoaFcXKVU2mVOXAqSxEOtpzC1ZwOwotq7fNjZz9hG3tASECk/oIUsMXZbL32llCB3QnanfgRIE6L9UbVq4p9OirITxlAAAAAQEfgJaYAAAAAAAWABTMvxvhg2CAwtIE7gsUTE6YnbNCPAz8CWxpZ2h0bmluZwEIccmpBwYkP6QM/AlsaWdodG5pbmcCAgABAA==
2023-01-05T14:39:05.156Z DEBUG   plugin-spenderp: mfc 49, dest 0: fundchannel_start 0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7.
2023-01-05T14:39:05.156Z DEBUG   lightningd: fundchannel_start: allocating uncommitted_channel
2023-01-05T14:39:05.157Z INFO    lightningd: Will open private channel with node 0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7
2023-01-05T14:39:05.159Z DEBUG   0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7-openingd-chan#1: pid 77727, msgfd 69
2023-01-05T14:39:05.159Z DEBUG   hsmd: Client: Received message 30 from client
2023-01-05T14:39:05.159Z DEBUG   hsmd: Client: Received message 10 from client
2023-01-05T14:39:05.159Z DEBUG   hsmd: new_client: 1
2023-01-05T14:39:05.163Z DEBUG   0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2023-01-05T14:39:05.163Z DEBUG   hsmd: Client: Received message 18 from client
2023-01-05T14:39:05.163Z DEBUG   0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7-openingd-chan#1: funder_channel_start
2023-01-05T14:39:05.163Z DEBUG   0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7-openingd-chan#1: Setting their reserve to 10001sat
2023-01-05T14:39:05.163Z DEBUG   0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7-openingd-chan#1: peer_out WIRE_OPEN_CHANNEL
2023-01-05T14:39:05.163Z DEBUG   0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7-openingd-chan#1: billboard: Funding channel start: offered, now waiting for accept_channel
2023-01-05T14:39:05.170Z DEBUG   0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7-openingd-chan#1: peer_in WIRE_ACCEPT_CHANNEL
2023-01-05T14:39:05.170Z DEBUG   0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7-openingd-chan#1: accept_channel: max_htlc_value_in_flight=18446744073709551615msat, channel_reserve=10001sat, htlc_minimum=0msat, minimum_depth=1
2023-01-05T14:39:05.171Z DEBUG   0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7-openingd-chan#1: We negotiated option_zeroconf, using our minimum_depth=1
2023-01-05T14:39:05.171Z DEBUG   0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7-openingd-chan#1: billboard: Funding channel start: awaiting funding_txid with output to 0020684dd80ff34afd4f04626df9d60fe6a83f3e303e7f50d33f027f475d242604be
2023-01-05T14:39:05.171Z DEBUG   plugin-spenderp: mfc 49, dest 0: fundchannel_start 0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7 done.
2023-01-05T14:39:05.171Z DEBUG   plugin-spenderp: mfc 49: parallel channel starts done.
2023-01-05T14:39:05.171Z DEBUG   plugin-spenderp: mfc 49: Creating funding tx.
2023-01-05T14:39:05.171Z DEBUG   plugin-spenderp: mfc 49: funding tx 40b9d8070864d520ded0d7ea854af3c7d85f7ce098e307aed1ee0a53aa74ff56: 0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7: 1000183sat, change: 8999663sat
2023-01-05T14:39:05.171Z DEBUG   plugin-spenderp: mfc 49: parallel fundchannel_complete.
2023-01-05T14:39:05.171Z DEBUG   plugin-spenderp: mfc 49, dest 0: fundchannel_complete 0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7.
2023-01-05T14:39:05.171Z DEBUG   0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7-openingd-chan#1: billboard: Funding channel con't: continuing with funding_txid 40b9d8070864d520ded0d7ea854af3c7d85f7ce098e307aed1ee0a53aa74ff56
2023-01-05T14:39:05.172Z DEBUG   0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7-hsmd: Got WIRE_HSMD_READY_CHANNEL
2023-01-05T14:39:05.172Z DEBUG   hsmd: Client: Received message 31 from client
2023-01-05T14:39:05.176Z DEBUG   0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7-hsmd: Got WIRE_HSMD_SIGN_REMOTE_COMMITMENT_TX
2023-01-05T14:39:05.176Z DEBUG   0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7-openingd-chan#1: signature 3044022012766aa3b43ff668f351e466fc84989423a76e6e1147d7ca130188df1b174bd302206d3090e6cd246271bc20ac065ba56130fad7875bbba931ba07397cab3bd84fd301 on tx 020000000156ff74aa530aeed1ae07e398e07c5fd8c7f34a85ead7d0de20d5640807d8b940000000000046f6d5800140420f0000000000160014e0536620b13e9726162e036c857d6cf634ffa608bb006120 using key 0373c9d0eb0e4a0b23979b11444e56f982098512d6053c02311be94509be4704d5
2023-01-05T14:39:05.176Z DEBUG   hsmd: Client: Received message 19 from client
2023-01-05T14:39:05.177Z DEBUG   0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7-openingd-chan#1: peer_out WIRE_FUNDING_CREATED
2023-01-05T14:39:05.177Z DEBUG   0341c81c2b9f28359a5d86cb68faa40d209c41846d5106a7a204813bffd8ba40b7-openingd-chan#1: billboard: Funding channel: create first tx, now waiting for their signature
2023-01-05T14:39:05.378Z DEBUG   lightningd: Adding block 103: 63dd4f99f7b2f61cf09318ab3d966f18807a5145013c3b4841dbc36cea7c663c
2023-01-05T14:39:05.387Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_NEW_BLOCKHEIGHT_REPLY with 0 fds

Just a wild guess, but could it have something to do with that block coming in?

@JssDWt
Copy link
Contributor Author

JssDWt commented Jan 8, 2023

@ddustin Would it be an idea to use the old debugging technique log(1), log(2), etc? If you can make a commit with a ridiculous amount of log statements I can run that, maybe we can find where this thing is failing?

@evd0kim
Copy link
Contributor

evd0kim commented Mar 25, 2024

I think this is the right place to report. I have the same situation and I've read docs for fundchannel which say that by default feerates are selected as normal. I decided to try feerates command and I discovered that CLN has actually very wrong about mempool situation.

{
   "perkb": {
      "opening": 3124,
      "mutual_close": 3124,
      "unilateral_close": 3460,
      "unilateral_anchor_close": 5000,
      "penalty": 3124,
      "delayed_to_us": 3124,
      "htlc_resolution": 3460,
      "min_acceptable": 1560,
      "max_acceptable": 34600,
      "floor": 1012,
      "estimates": [
         {
            "blockcount": 2,
            "feerate": 3460,
            "smoothed_feerate": 3460
         },
         {
            "blockcount": 6,
            "feerate": 3460,
            "smoothed_feerate": 3460
         },
         {
            "blockcount": 12,
            "feerate": 3124,
            "smoothed_feerate": 3124
         },
         {
            "blockcount": 100,
            "feerate": 3124,
            "smoothed_feerate": 3124
         }
      ]
   },
   "onchain_fee_estimates": {
      "opening_channel_satoshis": 548,
      "mutual_close_satoshis": 525,
      "unilateral_close_satoshis": 1390,
      "unilateral_close_nonanchor_satoshis": 517,
      "htlc_timeout_satoshis": 573,
      "htlc_success_satoshis": 608
   }
}

These levels are actually below the purging threshold.

image

Therefore my conclusion is that CLN has totally unreliable feerate estimation algo and this issue is a result of inability to correctly determine even minimal feerates.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@cdecker @ddustin @evd0kim @JssDWt