Open JssDWt opened 1 year ago
JssDWt
commented
1 year ago 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
commented
1 year ago 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
commented
1 year ago 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
commented
1 year ago 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
commented
1 year ago 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.
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
commented
1 year ago Cool š.
I wonder if you can recreate it more easily if you put the CPU under heavy load while it's running
JssDWt
commented
1 year ago @ddustin it doesn't help. Currently running v22.11.1 with those changes you suggested.
Here's a case with a 'normal' channel open:
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
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 fdsJust a wild guess, but could it have something to do with that block coming in?
JssDWt
commented
1 year ago @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
commented
4 months ago 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.
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.
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
Accepting peer
Succesful flow
Channel funder
Accepting peer