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.

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

calc_forwarding_channel can pick a channel that is offline, leading to unilateral closure #7917

Open
whitslack opened this issue Dec 7, 2024 · 4 comments · May be fixed by #7935
Open

calc_forwarding_channel can pick a channel that is offline, leading to unilateral closure #7917

whitslack opened this issue Dec 7, 2024 · 4 comments · May be fixed by #7935
Milestone

Comments

@whitslack
Copy link
Collaborator

Issue and Steps to Reproduce

I had an open channel #255525 with peer 03…ee, but the peer had been disconnected for some time. (The peer is Tor-only, and I don't have Tor connectivity, so there was no way for my node to connect outbound to the peer.)

2024-12-06T03:59:19.568Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T03:59:19.568Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds

An HTLC came in over a different channel, #255563, with a different peer, 02…9d, and evidently CLN "decided" to forward the payment over channel #255525 with the offline peer 03…ee:

2024-12-06T03:59:49.934Z DEBUG   02…9d-channeld-chan#255563: peer_in WIRE_UPDATE_ADD_HTLC
2024-12-06T03:59:49.934Z DEBUG   02…9d-channeld-chan#255563: NEW:: HTLC REMOTE 5272 = RCVD_ADD_HTLC/SENT_ADD_HTLC
2024-12-06T03:59:49.989Z DEBUG   02…9d-channeld-chan#255563: peer_in WIRE_COMMITMENT_SIGNED
2024-12-06T03:59:49.989Z DEBUG   02…9d-channeld-chan#255563: handle_peer_commit_sig(splice: 0, remote_splice: 0)
2024-12-06T03:59:49.990Z DEBUG   02…9d-channeld-chan#255563: Received commit
2024-12-06T03:59:49.990Z DEBUG   02…9d-channeld-chan#255563: htlc 5272: RCVD_ADD_HTLC->RCVD_ADD_COMMIT
2024-12-06T03:59:49.990Z DEBUG   02…9d-channeld-chan#255563: htlc added LOCAL: local 4819031033 remote 5180968967
2024-12-06T03:59:49.990Z DEBUG   02…9d-channeld-chan#255563: -> local 4819031033 remote 5170968947
2024-12-06T03:59:49.990Z DEBUG   02…9d-channeld-chan#255563: rcvd_commit: HTLC REMOTE 5272 = RCVD_ADD_COMMIT/SENT_ADD_COMMIT
2024-12-06T03:59:49.990Z DEBUG   02…9d-channeld-chan#255563: Feerates are 2269/2269
2024-12-06T03:59:49.990Z DEBUG   02…9d-channeld-chan#255563: Committed 1, removing 0, adding 0
2024-12-06T03:59:49.990Z DEBUG   02…9d-channeld-chan#255563: We need 103600sat at feerate 2269 for 1 untrimmed htlcs: we have 5170968947msat/5180968967msat (will have 5170968947msat)
2024-12-06T03:59:49.990Z DEBUG   02…9d-channeld-chan#255563: Derived key 03…95 from basepoint 03…a6, point 03…66
2024-12-06T03:59:49.991Z DEBUG   02…9d-channeld-chan#255563: Received commit_sig with 1 htlc sigs
2024-12-06T03:59:49.991Z DEBUG   02…9d-hsmd: Got WIRE_HSMD_VALIDATE_COMMITMENT_TX
2024-12-06T03:59:49.991Z DEBUG   02…9d-channeld-chan#255563: Sending revoke_and_ack
2024-12-06T03:59:49.991Z DEBUG   02…9d-channeld-chan#255563: htlc 5272: RCVD_ADD_COMMIT->SENT_ADD_REVOCATION
2024-12-06T03:59:49.991Z DEBUG   02…9d-channeld-chan#255563: sending_revoke_and_ack: HTLC REMOTE 5272 = SENT_ADD_REVOCATION/RCVD_ADD_REVOCATION
2024-12-06T03:59:49.992Z DEBUG   02…9d-channeld-chan#255563: revoke_and_ack made pending: commit timer
2024-12-06T03:59:49.992Z DEBUG   02…9d-channeld-chan#255563: Sending master 1021
2024-12-06T03:59:49.992Z DEBUG   02…9d-chan#255563: got commitsig 10855: feerate 2269, blockheight: 0, 1 added, 0 fulfilled, 0 failed, 0 changed. 0 splice commitments.
2024-12-06T03:59:49.993Z DEBUG   02…9d-chan#255563: Adding their HTLC 5272
2024-12-06T03:59:49.993Z DEBUG   02…9d-chan#255563: HTLC in 5272 RCVD_ADD_COMMIT->SENT_ADD_REVOCATION
2024-12-06T03:59:50.005Z DEBUG   02…9d-channeld-chan#255563: ... , awaiting 1121
2024-12-06T03:59:50.005Z DEBUG   02…9d-channeld-chan#255563: Got it!
2024-12-06T03:59:50.006Z DEBUG   02…9d-hsmd: Got WIRE_HSMD_REVOKE_COMMITMENT_TX
2024-12-06T03:59:50.006Z DEBUG   02…9d-channeld-chan#255563: peer_out WIRE_REVOKE_AND_ACK
2024-12-06T03:59:50.006Z DEBUG   02…9d-channeld-chan#255563: Trying commit
2024-12-06T03:59:50.006Z DEBUG   02…9d-channeld-chan#255563: htlc 5272: SENT_ADD_REVOCATION->SENT_ADD_ACK_COMMIT
2024-12-06T03:59:50.006Z DEBUG   02…9d-channeld-chan#255563: htlc added REMOTE: local 4819031033 remote 5180968967
2024-12-06T03:59:50.006Z DEBUG   02…9d-channeld-chan#255563: -> local 4819031033 remote 5170968947
2024-12-06T03:59:50.006Z DEBUG   02…9d-channeld-chan#255563: sending_commit: HTLC REMOTE 5272 = SENT_ADD_ACK_COMMIT/RCVD_ADD_ACK_COMMIT
2024-12-06T03:59:50.008Z DEBUG   02…9d-hsmd: Got WIRE_HSMD_SIGN_REMOTE_COMMITMENT_TX
2024-12-06T03:59:50.008Z DEBUG   02…9d-channeld-chan#255563: Creating commit_sig signature 10854 30…01 for tx 02…20 wscript 52…ae key 03…34
2024-12-06T03:59:50.009Z DEBUG   02…9d-hsmd: Got WIRE_HSMD_SIGN_REMOTE_HTLC_TX
2024-12-06T03:59:50.009Z DEBUG   02…9d-channeld-chan#255563: Creating HTLC signature 30…83 for tx 02…00 wscript 76…68 key 03…54
2024-12-06T03:59:50.009Z DEBUG   02…9d-channeld-chan#255563: Telling master we're about to commit...
2024-12-06T03:59:50.009Z DEBUG   02…9d-channeld-chan#255563: Sending master 1020
2024-12-06T03:59:50.009Z DEBUG   02…9d-chan#255563: HTLC in 5272 SENT_ADD_REVOCATION->SENT_ADD_ACK_COMMIT
2024-12-06T03:59:50.018Z DEBUG   02…9d-channeld-chan#255563: ... , awaiting 1120
2024-12-06T03:59:50.018Z DEBUG   02…9d-channeld-chan#255563: Got it!
2024-12-06T03:59:50.018Z DEBUG   02…9d-channeld-chan#255563: Sending commit_sig with 1 htlc sigs
2024-12-06T03:59:50.022Z DEBUG   02…9d-channeld-chan#255563: peer_out WIRE_COMMITMENT_SIGNED
2024-12-06T03:59:50.029Z DEBUG   02…9d-channeld-chan#255563: Can't send commit: waiting for revoke_and_ack
2024-12-06T03:59:50.448Z DEBUG   02…9d-channeld-chan#255563: peer_in WIRE_REVOKE_AND_ACK
2024-12-06T03:59:50.448Z DEBUG   02…9d-channeld-chan#255563: Received revoke_and_ack
2024-12-06T03:59:50.448Z DEBUG   02…9d-channeld-chan#255563: htlc 5272: SENT_ADD_ACK_COMMIT->RCVD_ADD_ACK_REVOCATION
2024-12-06T03:59:50.448Z DEBUG   02…9d-channeld-chan#255563: rcvd_revoke_and_ack: HTLC REMOTE 5272 = RCVD_ADD_ACK_REVOCATION/SENT_ADD_ACK_REVOCATION
2024-12-06T03:59:50.448Z DEBUG   02…9d-channeld-chan#255563: No commits outstanding after recv revoke_and_ack
2024-12-06T03:59:50.448Z DEBUG   02…9d-channeld-chan#255563: HTLC 5272[REMOTE] => RCVD_ADD_ACK_REVOCATION
2024-12-06T03:59:50.449Z DEBUG   02…9d-hsmd: Got WIRE_HSMD_VALIDATE_REVOCATION
2024-12-06T03:59:50.450Z DEBUG   02…9d-hsmd: Got WIRE_HSMD_SIGN_PENALTY_TO_US
2024-12-06T03:59:50.450Z DEBUG   02…9d-channeld-chan#255563: Sending master 1022
2024-12-06T03:59:50.450Z DEBUG   02…9d-chan#255563: got revoke 10853: 1 changed
2024-12-06T03:59:50.450Z DEBUG   02…9d-chan#255563: HTLC in 5272 SENT_ADD_ACK_COMMIT->RCVD_ADD_ACK_REVOCATION
2024-12-06T03:59:50.451Z DEBUG   02…9d-chan#255563: Looking up channel by scid=…54x…27x1 to forward htlc_id=5272
2024-12-06T03:59:50.451Z DEBUG   02…9d-chan#255563: Decided to forward htlc_id=5272 over channel with scid=…54x…27x1 with peer 03…ee
2024-12-06T03:59:50.462Z DEBUG   02…9d-channeld-chan#255563: ... , awaiting 1122
2024-12-06T03:59:50.463Z DEBUG   02…9d-channeld-chan#255563: Got it!
2024-12-06T03:59:50.463Z DEBUG   02…9d-channeld-chan#255563: revoke_and_ack REMOTE: remote_per_commit = 03…0d, old_remote_per_commit = 03…6d
2024-12-06T03:59:50.465Z DEBUG   03…ee-channeld-chan#255525: NEW:: HTLC LOCAL 172 = SENT_ADD_HTLC/RCVD_ADD_HTLC
2024-12-06T03:59:50.465Z DEBUG   03…ee-channeld-chan#255525: Adding HTLC 172 amount=10000000msat cltv=873499 gave CHANNEL_ERR_ADD_OK
2024-12-06T03:59:50.465Z DEBUG   03…ee-channeld-chan#255525: peer_out WIRE_UPDATE_ADD_HTLC

(How could 03…ee-channeld-chan#255525 possibly have sent WIRE_UPDATE_ADD_HTLC to peer 03…ee while the peer was disconnected?)

2024-12-06T03:59:50.465Z DEBUG   03…ee-channeld-chan#255525: REPLY WIRE_CHANNELD_OFFER_HTLC_REPLY with 0 fds
2024-12-06T03:59:50.473Z DEBUG   02…9d-channeld-chan#255563: Trying commit
2024-12-06T03:59:50.473Z DEBUG   02…9d-channeld-chan#255563: Can't send commit: nothing to send, feechange not wanted ({ RCVD_ADD_ACK_REVOCATION:2269 }) blockheight not wanted ({ RCVD_ADD_ACK_REVOCATION:0 })
2024-12-06T03:59:50.475Z DEBUG   03…ee-channeld-chan#255525: Trying commit
2024-12-06T03:59:50.476Z DEBUG   03…ee-channeld-chan#255525: htlc 172: SENT_ADD_HTLC->SENT_ADD_COMMIT
2024-12-06T03:59:50.476Z DEBUG   03…ee-channeld-chan#255525: htlc added REMOTE: local 2430597531 remote 69402469
2024-12-06T03:59:50.476Z DEBUG   03…ee-channeld-chan#255525: -> local 2420597531 remote 69402469
2024-12-06T03:59:50.476Z DEBUG   03…ee-channeld-chan#255525: sending_commit: HTLC LOCAL 172 = SENT_ADD_COMMIT/RCVD_ADD_COMMIT
2024-12-06T03:59:50.477Z DEBUG   03…ee-hsmd: Got WIRE_HSMD_SIGN_REMOTE_COMMITMENT_TX
2024-12-06T03:59:50.477Z DEBUG   03…ee-channeld-chan#255525: Creating commit_sig signature 1017 30…01 for tx 02…20 wscript 52…ae key 02…e5
2024-12-06T03:59:50.478Z DEBUG   03…ee-hsmd: Got WIRE_HSMD_SIGN_REMOTE_HTLC_TX
2024-12-06T03:59:50.478Z DEBUG   03…ee-channeld-chan#255525: Creating HTLC signature 30…83 for tx 02…00 wscript 76…68 key 03…c2
2024-12-06T03:59:50.478Z DEBUG   03…ee-channeld-chan#255525: Telling master we're about to commit...
2024-12-06T03:59:50.478Z DEBUG   03…ee-channeld-chan#255525: Sending master 1020
2024-12-06T03:59:50.480Z DEBUG   03…ee-chan#255525: HTLC out 172 SENT_ADD_HTLC->SENT_ADD_COMMIT
2024-12-06T03:59:50.489Z DEBUG   03…ee-channeld-chan#255525: ... , awaiting 1120
2024-12-06T03:59:50.489Z DEBUG   03…ee-channeld-chan#255525: Got it!
2024-12-06T03:59:50.489Z DEBUG   03…ee-channeld-chan#255525: Sending commit_sig with 1 htlc sigs
2024-12-06T03:59:50.492Z DEBUG   03…ee-channeld-chan#255525: peer_out WIRE_COMMITMENT_SIGNED
2024-12-06T03:59:50.499Z DEBUG   03…ee-channeld-chan#255525: Can't send commit: waiting for revoke_and_ack

Eventually the downstream HTLC 172 hit its deadline, causing CLN to unilaterally close the downstream channel #255525:

2024-12-06T10:14:40.581Z UNUSUAL 03…ee-chan#255525: Peer permanent failure in CHANNELD_NORMAL: Offered HTLC 172 SENT_ADD_COMMIT cltv 873499 hit deadline (reason=protocol)
2024-12-06T10:14:40.581Z DEBUG   03…ee-channeld-chan#255525: Status closed, but not exited. Killing
2024-12-06T10:14:40.585Z DEBUG   03…ee-chan#255525: We have 3 anchor points to use
2024-12-06T10:14:40.585Z DEBUG   lightningd: Broadcasting txid c9…39
2024-12-06T10:14:40.586Z DEBUG   lightningd: sendrawtransaction: 02…20
2024-12-06T10:14:40.586Z INFO    03…ee-chan#255525: State changed from CHANNELD_NORMAL to AWAITING_UNILATERAL
2024-12-06T10:14:40.730Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:14:40.730Z DEBUG   03…ee-chan#255525: Anchorspend for local commit tx fee 7705sat (w=714), commit_tx fee 2345sat (w=1112): package feerate 5503 perkw
2024-12-06T10:14:40.743Z INFO    03…ee-chan#255525: Creating anchor spend for local commit tx 13…32: we're paying fee 7705sat
2024-12-06T10:15:27.844Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy.
2024-12-06T10:15:27.844Z DEBUG   03…ee-lightningd: Not reconnecting: no active channel
2024-12-06T10:15:33.291Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:16:31.909Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:17:29.653Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:18:10.323Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:19:02.954Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:19:34.623Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:20:18.261Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:20:50.893Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:21:42.576Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:22:39.258Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:23:37.918Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:24:25.639Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:25:13.268Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:25:45.888Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:26:39.491Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:27:39.138Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:28:23.733Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:29:16.352Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:30:14.959Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:30:51.655Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:31:24.069Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:32:07.663Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:32:42.256Z DEBUG   03…ee-chan#255525: Worth fee 7705sat for local commit tx to get 10000000msat in 873499 blocks at feerate 4219perkw
2024-12-06T10:33:12.294Z DEBUG   03…ee-chan#255525: Got UTXO spend for 82…c2:1: c9…39
2024-12-06T10:33:12.295Z UNUSUAL 03…ee-chan#255525: Peer permanent failure in AWAITING_UNILATERAL: Funding transaction spent (reason=onchain)
2024-12-06T10:33:12.296Z DEBUG   03…ee-chan#255525: We have 3 anchor points to use
2024-12-06T10:33:12.296Z DEBUG   lightningd: Broadcasting txid c9…39
2024-12-06T10:33:12.297Z DEBUG   lightningd: sendrawtransaction: 02…20
2024-12-06T10:33:12.297Z INFO    03…ee-chan#255525: State changed from AWAITING_UNILATERAL to FUNDING_SPEND_SEEN
2024-12-06T10:33:12.323Z DEBUG   03…ee-onchaind-chan#255525: pid 5514, msgfd 1
2024-12-06T10:33:12.323Z DEBUG   03…ee-chan#255525: channel->static_remotekey_start[LOCAL] 0
2024-12-06T10:33:12.325Z DEBUG   03…ee-chan#255525: Got UTXO spend for c9…39:1: 13…32
2024-12-06T10:33:19.644Z DEBUG   wallet: Owning output 0 1736347sat (SEGWIT) txid 13…32 CONFIRMED
2024-12-06T10:33:19.727Z DEBUG   03…ee-onchaind-chan#255525: Tracking output 82…c2:1: FUNDING_TRANSACTION/FUNDING_OUTPUT
2024-12-06T10:33:19.727Z DEBUG   03…ee-onchaind-chan#255525: Remote per-commit point: 03…f1
2024-12-06T10:33:19.728Z DEBUG   03…ee-onchaind-chan#255525: Old remote per-commit point: 03…28
2024-12-06T10:33:19.728Z DEBUG   03…ee-onchaind-chan#255525: reducing max_possible_feerate from 2500...
2024-12-06T10:33:19.729Z DEBUG   03…ee-onchaind-chan#255525: ... to 2255
2024-12-06T10:33:19.729Z DEBUG   03…ee-onchaind-chan#255525: commitnum = 1016, revocations_received = 1016
2024-12-06T10:33:19.729Z INFO    03…ee-chan#255525: State changed from FUNDING_SPEND_SEEN to ONCHAIN
2024-12-06T10:33:19.995Z DEBUG   03…ee-chan#255525: We want to know if htlc 172 is missing (later)
2024-12-06T10:33:19.999Z DEBUG   03…ee-onchaind-chan#255525: billboard perm: Tracking our own unilateral close
2024-12-06T10:33:20.011Z DEBUG   03…ee-onchaind-chan#255525: Resolved FUNDING_TRANSACTION/FUNDING_OUTPUT by OUR_UNILATERAL (c9…39)
2024-12-06T10:33:20.011Z DEBUG   03…ee-onchaind-chan#255525: Deconstructing unilateral tx: 1016 using keyset:  self_revocation_key: 03…2e self_delayed_payment_key: 03…0b self_payment_key: 02…62 other_payment_key: 02…4d self_htlc_key: 03…88 other_htlc_key: 02…21
2024-12-06T10:33:20.011Z DEBUG   03…ee-onchaind-chan#255525: Script to-me: 300: 00…0f (63…ac)
2024-12-06T10:33:20.011Z DEBUG   03…ee-onchaind-chan#255525: Script to-them: 00…c4
2024-12-06T10:33:20.011Z DEBUG   03…ee-onchaind-chan#255525: Output 0: 00…a8
2024-12-06T10:33:20.011Z DEBUG   03…ee-onchaind-chan#255525: Output 1: 00…cd
2024-12-06T10:33:20.011Z DEBUG   03…ee-onchaind-chan#255525: Output 2: 00…c4
2024-12-06T10:33:20.011Z DEBUG   03…ee-onchaind-chan#255525: Output 3: 00…0f
2024-12-06T10:33:20.011Z DEBUG   03…ee-onchaind-chan#255525: Tracking output c9…39:0: OUR_UNILATERAL/ANCHOR_TO_THEM
2024-12-06T10:33:20.012Z DEBUG   03…ee-onchaind-chan#255525: Ignoring output c9…39:0: OUR_UNILATERAL/ANCHOR_TO_THEM
2024-12-06T10:33:20.012Z DEBUG   03…ee-onchaind-chan#255525: Tracking output c9…39:1: OUR_UNILATERAL/ANCHOR_TO_US
2024-12-06T10:33:20.012Z DEBUG   03…ee-onchaind-chan#255525: Ignoring output c9…39:1: OUR_UNILATERAL/ANCHOR_TO_US
2024-12-06T10:33:20.012Z DEBUG   03…ee-onchaind-chan#255525: Tracking output c9…39:2: OUR_UNILATERAL/OUTPUT_TO_THEM
2024-12-06T10:33:20.012Z DEBUG   03…ee-onchaind-chan#255525: Ignoring output c9…39:2: OUR_UNILATERAL/OUTPUT_TO_THEM
2024-12-06T10:33:20.012Z DEBUG   03…ee-onchaind-chan#255525: Tracking output c9…39:3: OUR_UNILATERAL/DELAYED_OUTPUT_TO_US
2024-12-06T10:33:20.012Z DEBUG   03…ee-onchaind-chan#255525: Telling lightningd about OUR_DELAYED_RETURN_TO_WALLET to resolve OUR_UNILATERAL/DELAYED_OUTPUT_TO_US after block 873800 (299 more blocks)
2024-12-06T10:33:20.016Z DEBUG   03…ee-chan#255525: Feerate for target 873801 (+300 blocks) is 253, fee 122sat of 2430597sat
2024-12-06T10:33:20.016Z DEBUG   03…ee-chan#255525: Broadcast for onchaind tx 02…00
2024-12-06T10:33:20.018Z DEBUG   03…ee-onchaind-chan#255525: billboard: 5 outputs unresolved: in 300 blocks will spend DELAYED_OUTPUT_TO_US (c9…39:3) using OUR_DELAYED_RETURN_TO_WALLET
2024-12-06T10:33:20.018Z DEBUG   03…ee-onchaind-chan#255525: Got new message WIRE_ONCHAIND_SPENT
2024-12-06T10:33:20.019Z DEBUG   03…ee-onchaind-chan#255525: Notified about tx c9…39 output 1 spend, but we don't care
2024-12-06T10:33:20.019Z DEBUG   03…ee-onchaind-chan#255525: billboard: 5 outputs unresolved: in 300 blocks will spend DELAYED_OUTPUT_TO_US (c9…39:3) using OUR_DELAYED_RETURN_TO_WALLET
2024-12-06T10:33:20.019Z DEBUG   03…ee-onchaind-chan#255525: Got new message WIRE_ONCHAIND_DEPTH
2024-12-06T10:33:20.020Z DEBUG   03…ee-onchaind-chan#255525: billboard: 5 outputs unresolved: in 300 blocks will spend DELAYED_OUTPUT_TO_US (c9…39:3) using OUR_DELAYED_RETURN_TO_WALLET
2024-12-06T10:33:20.020Z DEBUG   03…ee-onchaind-chan#255525: Got new message WIRE_ONCHAIND_DEPTH
2024-12-06T10:33:20.020Z DEBUG   03…ee-onchaind-chan#255525: FUNDING_TRANSACTION/FUNDING_OUTPUT->OUR_UNILATERAL depth 1
2024-12-06T10:33:20.020Z DEBUG   03…ee-onchaind-chan#255525: OUR_UNILATERAL/ANCHOR_TO_THEM->SELF depth 1
2024-12-06T10:33:20.021Z DEBUG   03…ee-onchaind-chan#255525: OUR_UNILATERAL/ANCHOR_TO_US->SELF depth 1
2024-12-06T10:33:20.021Z DEBUG   03…ee-onchaind-chan#255525: OUR_UNILATERAL/OUTPUT_TO_THEM->SELF depth 1
2024-12-06T10:33:20.021Z DEBUG   03…ee-onchaind-chan#255525: billboard: 5 outputs unresolved: in 299 blocks will spend DELAYED_OUTPUT_TO_US (c9…39:3) using OUR_DELAYED_RETURN_TO_WALLET
2024-12-06T10:55:02.789Z DEBUG   03…ee-onchaind-chan#255525: Got new message WIRE_ONCHAIND_DEPTH
2024-12-06T10:55:02.789Z DEBUG   03…ee-onchaind-chan#255525: FUNDING_TRANSACTION/FUNDING_OUTPUT->OUR_UNILATERAL depth 2
2024-12-06T10:55:02.789Z DEBUG   03…ee-onchaind-chan#255525: OUR_UNILATERAL/ANCHOR_TO_THEM->SELF depth 2
2024-12-06T10:55:02.789Z DEBUG   03…ee-onchaind-chan#255525: OUR_UNILATERAL/ANCHOR_TO_US->SELF depth 2
2024-12-06T10:55:02.789Z DEBUG   03…ee-onchaind-chan#255525: OUR_UNILATERAL/OUTPUT_TO_THEM->SELF depth 2
2024-12-06T10:55:02.789Z DEBUG   03…ee-onchaind-chan#255525: billboard: 5 outputs unresolved: in 298 blocks will spend DELAYED_OUTPUT_TO_US (c9…39:3) using OUR_DELAYED_RETURN_TO_WALLET
2024-12-06T11:00:06.164Z DEBUG   03…ee-onchaind-chan#255525: Got new message WIRE_ONCHAIND_DEPTH
2024-12-06T11:00:06.164Z DEBUG   03…ee-onchaind-chan#255525: Sending 1 missing htlc messages
2024-12-06T11:00:06.164Z DEBUG   03…ee-chan#255525: onchain_failed_our_htlc
2024-12-06T11:00:06.169Z DEBUG   03…ee-chan#255525: HTLC id 172 has incoming

CLN noticed that the deadlined downstream HTLC 172 was related to an upstream HTLC 5272 in channel #525563 and correctly failed that upstream HTLC, saving the upstream channel from also hitting its deadline. (Kudos! This used to not work.)

2024-12-06T11:00:06.169Z DEBUG   02…9d-chan#255563: HTLC in 5272 RCVD_ADD_ACK_REVOCATION->SENT_REMOVE_HTLC
2024-12-06T11:00:06.184Z DEBUG   03…ee-onchaind-chan#255525: FUNDING_TRANSACTION/FUNDING_OUTPUT->OUR_UNILATERAL depth 3
2024-12-06T11:00:06.185Z DEBUG   03…ee-onchaind-chan#255525: OUR_UNILATERAL/ANCHOR_TO_THEM->SELF depth 3
2024-12-06T11:00:06.185Z DEBUG   03…ee-onchaind-chan#255525: OUR_UNILATERAL/ANCHOR_TO_US->SELF depth 3
2024-12-06T11:00:06.185Z DEBUG   03…ee-onchaind-chan#255525: OUR_UNILATERAL/OUTPUT_TO_THEM->SELF depth 3
2024-12-06T11:00:06.185Z DEBUG   03…ee-onchaind-chan#255525: billboard: 5 outputs unresolved: in 297 blocks will spend DELAYED_OUTPUT_TO_US (c9…39:3) using OUR_DELAYED_RETURN_TO_WALLET
2024-12-06T11:00:06.186Z DEBUG   02…9d-channeld-chan#255563: FAIL:: HTLC REMOTE 5272 = SENT_REMOVE_HTLC/RCVD_REMOVE_HTLC
2024-12-06T11:00:06.186Z DEBUG   02…9d-channeld-chan#255563: peer_out WIRE_UPDATE_FAIL_HTLC
2024-12-06T11:00:06.687Z DEBUG   02…9d-hsmd: Got WIRE_HSMD_SIGN_REMOTE_COMMITMENT_TX
2024-12-06T11:00:06.687Z DEBUG   02…9d-channeld-chan#255563: Trying commit
2024-12-06T11:00:06.687Z DEBUG   02…9d-channeld-chan#255563: htlc 5272: SENT_REMOVE_HTLC->SENT_REMOVE_COMMIT
2024-12-06T11:00:06.687Z DEBUG   02…9d-channeld-chan#255563: htlc added REMOTE: local 4819031033 remote 5170968947
2024-12-06T11:00:06.687Z DEBUG   02…9d-channeld-chan#255563: -> local 4819031033 remote 5180968967
2024-12-06T11:00:06.687Z DEBUG   02…9d-channeld-chan#255563: sending_commit: HTLC REMOTE 5272 = SENT_REMOVE_COMMIT/RCVD_REMOVE_COMMIT FAILED
2024-12-06T11:00:06.687Z DEBUG   02…9d-channeld-chan#255563: Creating commit_sig signature 10978 30…01 for tx 02…20 wscript 52…ae key 03…34
2024-12-06T11:00:06.687Z DEBUG   02…9d-channeld-chan#255563: Telling master we're about to commit...
2024-12-06T11:00:06.688Z DEBUG   02…9d-channeld-chan#255563: Sending master 1020
2024-12-06T11:00:06.688Z DEBUG   02…9d-chan#255563: HTLC in 5272 SENT_REMOVE_HTLC->SENT_REMOVE_COMMIT
2024-12-06T11:00:06.703Z DEBUG   02…9d-channeld-chan#255563: ... , awaiting 1120
2024-12-06T11:00:06.712Z DEBUG   02…9d-channeld-chan#255563: Got it!
2024-12-06T11:00:06.712Z DEBUG   02…9d-channeld-chan#255563: Sending commit_sig with 0 htlc sigs
2024-12-06T11:00:06.715Z DEBUG   02…9d-channeld-chan#255563: peer_out WIRE_COMMITMENT_SIGNED
2024-12-06T11:00:06.716Z DEBUG   02…9d-channeld-chan#255563: Can't send commit: waiting for revoke_and_ack
2024-12-06T11:00:07.116Z DEBUG   02…9d-channeld-chan#255563: peer_in WIRE_REVOKE_AND_ACK
2024-12-06T11:00:07.116Z DEBUG   02…9d-hsmd: Got WIRE_HSMD_VALIDATE_REVOCATION
2024-12-06T11:00:07.116Z DEBUG   02…9d-channeld-chan#255563: Received revoke_and_ack
2024-12-06T11:00:07.117Z DEBUG   02…9d-channeld-chan#255563: htlc 5272: SENT_REMOVE_COMMIT->RCVD_REMOVE_REVOCATION
2024-12-06T11:00:07.117Z DEBUG   02…9d-channeld-chan#255563: rcvd_revoke_and_ack: HTLC REMOTE 5272 = RCVD_REMOVE_REVOCATION/SENT_REMOVE_REVOCATION FAILED
2024-12-06T11:00:07.117Z DEBUG   02…9d-channeld-chan#255563: Commits outstanding after recv revoke_and_ack
2024-12-06T11:00:07.117Z DEBUG   02…9d-channeld-chan#255563: HTLC 5272[REMOTE] => RCVD_REMOVE_REVOCATION
2024-12-06T11:00:07.118Z DEBUG   02…9d-hsmd: Got WIRE_HSMD_SIGN_PENALTY_TO_US
2024-12-06T11:00:07.118Z DEBUG   02…9d-channeld-chan#255563: Sending master 1022
2024-12-06T11:00:07.118Z DEBUG   02…9d-chan#255563: got revoke 10977: 1 changed
2024-12-06T11:00:07.118Z DEBUG   02…9d-chan#255563: HTLC in 5272 SENT_REMOVE_COMMIT->RCVD_REMOVE_REVOCATION
2024-12-06T11:00:07.126Z DEBUG   02…9d-channeld-chan#255563: ... , awaiting 1122
2024-12-06T11:00:07.126Z DEBUG   02…9d-channeld-chan#255563: Got it!
2024-12-06T11:00:07.126Z DEBUG   02…9d-channeld-chan#255563: revoke_and_ack REMOTE: remote_per_commit = 03…0b, old_remote_per_commit = 03…88
2024-12-06T11:00:07.127Z DEBUG   02…9d-channeld-chan#255563: peer_in WIRE_COMMITMENT_SIGNED
2024-12-06T11:00:07.127Z DEBUG   02…9d-channeld-chan#255563: handle_peer_commit_sig(splice: 0, remote_splice: 0)
2024-12-06T11:00:07.127Z DEBUG   02…9d-channeld-chan#255563: Received commit
2024-12-06T11:00:07.127Z DEBUG   02…9d-channeld-chan#255563: htlc 5272: RCVD_REMOVE_REVOCATION->RCVD_REMOVE_ACK_COMMIT
2024-12-06T11:00:07.127Z DEBUG   02…9d-channeld-chan#255563: htlc added LOCAL: local 4819031033 remote 5170968947
2024-12-06T11:00:07.127Z DEBUG   02…9d-channeld-chan#255563: -> local 4819031033 remote 5180968967
2024-12-06T11:00:07.127Z DEBUG   02…9d-channeld-chan#255563: rcvd_commit: HTLC REMOTE 5272 = RCVD_REMOVE_ACK_COMMIT/SENT_REMOVE_ACK_COMMIT FAILED
2024-12-06T11:00:07.127Z DEBUG   02…9d-channeld-chan#255563: Feerates are 2682/2682
2024-12-06T11:00:07.127Z DEBUG   02…9d-channeld-chan#255563: Committed 0, removing 0, adding 0
2024-12-06T11:00:07.127Z DEBUG   02…9d-channeld-chan#255563: We need 103674sat at feerate 2682 for 0 untrimmed htlcs: we have 5180968967msat/5180968967msat (will have 5180968967msat)
2024-12-06T11:00:07.127Z DEBUG   02…9d-channeld-chan#255563: Derived key 03…ff from basepoint 03…a6, point 02…eb
2024-12-06T11:00:07.127Z DEBUG   02…9d-channeld-chan#255563: Received commit_sig with 0 htlc sigs
2024-12-06T11:00:07.128Z DEBUG   02…9d-hsmd: Got WIRE_HSMD_VALIDATE_COMMITMENT_TX
2024-12-06T11:00:07.128Z DEBUG   02…9d-channeld-chan#255563: Sending revoke_and_ack
2024-12-06T11:00:07.128Z DEBUG   02…9d-channeld-chan#255563: htlc 5272: RCVD_REMOVE_ACK_COMMIT->SENT_REMOVE_ACK_REVOCATION
2024-12-06T11:00:07.128Z DEBUG   02…9d-channeld-chan#255563: sending_revoke_and_ack: HTLC REMOTE 5272 = SENT_REMOVE_ACK_REVOCATION/RCVD_REMOVE_ACK_REVOCATION FAILED
2024-12-06T11:00:07.128Z DEBUG   02…9d-channeld-chan#255563: Sending master 1021
2024-12-06T11:00:07.128Z DEBUG   02…9d-chan#255563: got commitsig 10979: feerate 2682, blockheight: 0, 0 added, 0 fulfilled, 0 failed, 1 changed. 0 splice commitments.
2024-12-06T11:00:07.128Z DEBUG   02…9d-chan#255563: HTLC in 5272 RCVD_REMOVE_REVOCATION->RCVD_REMOVE_ACK_COMMIT
2024-12-06T11:00:07.129Z DEBUG   02…9d-chan#255563: HTLC in 5272 RCVD_REMOVE_ACK_COMMIT->SENT_REMOVE_ACK_REVOCATION
2024-12-06T11:00:07.133Z DEBUG   02…9d-chan#255563: Removing in HTLC 5272 state SENT_REMOVE_ACK_REVOCATION REMOTEFAIL
2024-12-06T11:00:07.139Z DEBUG   02…9d-channeld-chan#255563: ... , awaiting 1121
2024-12-06T11:00:07.139Z DEBUG   02…9d-channeld-chan#255563: Got it!
2024-12-06T11:00:07.140Z DEBUG   02…9d-channeld-chan#255563: peer_out WIRE_REVOKE_AND_ACK
2024-12-06T11:00:07.140Z DEBUG   02…9d-channeld-chan#255563: Trying commit
2024-12-06T11:00:07.140Z DEBUG   02…9d-channeld-chan#255563: Can't send commit: nothing to send, feechange not wanted ({ RCVD_ADD_ACK_REVOCATION:2682 }) blockheight not wanted ({ RCVD_ADD_ACK_REVOCATION:0 })
2024-12-06T11:00:07.140Z DEBUG   02…9d-hsmd: Got WIRE_HSMD_REVOKE_COMMITMENT_TX

So, the question is: why did CLN add an HTLC to a channel with a disconnected peer? That's just asking to hit a deadline and to be forced to unilaterally close that channel, when that could have been avoided simply by refusing to add an HTLC to a disconnected channel. Moreover, this behavior causes a bad user experience because it creates a stuck payment that only unsticks when the HTLC in the disconnected channel eventually hits its deadline (or the downstream peer comes back online).

getinfo output

This happened with CLN v24.08.2.

@rustyrussell
Copy link
Contributor

It absolutely seems the peer was connected. As your logs show, we were talking to it. We don't create a channeld for it until after it has connected to us.

Look for 03…ee-connectd in the logs: I anticipate you should see it connecting...

@whitslack
Copy link
Collaborator Author

whitslack commented Dec 9, 2024

Of course, I had been connected to the peer previously, as I had an active channel with them. However, at the time when CLN added an HTLC to the channel, the peer was disconnected. I'll show you…

For reference, here is an example of what I expect to happen when a forward comes in while the peer is disconnected:

2024-12-01T09:01:39.177Z DEBUG   02…9a-chan#255546: Decided to forward htlc_id=3950 over channel with scid=…54x…27x1 with peer 03…ee
2024-12-01T09:01:39.189Z INFO    03…ee-chan#255525: Attempt to send HTLC but unowned (CHANNELD_NORMAL)

And what follows is what actually happened. This is a grep for the peer's node ID with no lines filtered out or manually elided. You can see the last message exchange I had with them, wherein they updated the fee at 16:34:47 and then disconnected about ten minutes later at 16:44:33. My node attempted to reconnect to them every five minutes until eventually it added an HTLC to the channel at 03:59:50, even though it was disconnected at the time.

2024-12-05T16:34:47.457Z DEBUG   03…ee-channeld-chan#255525: peer_in WIRE_UPDATE_FEE
2024-12-05T16:34:47.458Z DEBUG   03…ee-channeld-chan#255525: update_fee 2086, range 775-20870
2024-12-05T16:34:47.458Z DEBUG   03…ee-channeld-chan#255525: Committed 0, removing 0, adding 0
2024-12-05T16:34:47.458Z DEBUG   03…ee-channeld-chan#255525: We need 28004sat at feerate 2086 for 0 untrimmed htlcs: we have 69402469msat/69402469msat (will have 69402469msat)
2024-12-05T16:34:47.459Z DEBUG   03…ee-channeld-chan#255525: Setting LOCAL feerate to 2086
2024-12-05T16:34:47.459Z DEBUG   03…ee-channeld-chan#255525: peer updated fee to 2086
2024-12-05T16:34:47.462Z DEBUG   03…ee-channeld-chan#255525: peer_in WIRE_COMMITMENT_SIGNED
2024-12-05T16:34:47.462Z DEBUG   03…ee-channeld-chan#255525: handle_peer_commit_sig(splice: 0, remote_splice: 0)
2024-12-05T16:34:47.462Z DEBUG   03…ee-channeld-chan#255525: Received commit
2024-12-05T16:34:47.462Z DEBUG   03…ee-channeld-chan#255525: Feerate: RCVD_ADD_HTLC->RCVD_ADD_COMMIT LOCAL now 2086
2024-12-05T16:34:47.462Z DEBUG   03…ee-channeld-chan#255525: Feerates are 2086/1794
2024-12-05T16:34:47.463Z DEBUG   03…ee-channeld-chan#255525: Committed 0, removing 0, adding 0
2024-12-05T16:34:47.463Z DEBUG   03…ee-channeld-chan#255525: We need 28004sat at feerate 2086 for 0 untrimmed htlcs: we have 69402469msat/69402469msat (will have 69402469msat)
2024-12-05T16:34:47.466Z DEBUG   03…ee-channeld-chan#255525: Derived key 02…21 from basepoint 02…a9, point 02…c5
2024-12-05T16:34:47.466Z DEBUG   03…ee-channeld-chan#255525: Received commit_sig with 0 htlc sigs
2024-12-05T16:34:47.467Z DEBUG   03…ee-hsmd: Got WIRE_HSMD_VALIDATE_COMMITMENT_TX
2024-12-05T16:34:47.467Z DEBUG   03…ee-channeld-chan#255525: Sending revoke_and_ack
2024-12-05T16:34:47.467Z DEBUG   03…ee-channeld-chan#255525: Feerate: RCVD_ADD_COMMIT->SENT_ADD_REVOCATION REMOTE now 2086
2024-12-05T16:34:47.467Z DEBUG   03…ee-channeld-chan#255525: revoke_and_ack made pending: commit timer
2024-12-05T16:34:47.467Z DEBUG   03…ee-channeld-chan#255525: Sending master 1021
2024-12-05T16:34:47.468Z DEBUG   03…ee-chan#255525: got commitsig 1016: feerate 2086, blockheight: 0, 0 added, 0 fulfilled, 0 failed, 0 changed. 0 splice commitments.
2024-12-05T16:34:47.487Z DEBUG   03…ee-channeld-chan#255525: ... , awaiting 1121
2024-12-05T16:34:47.487Z DEBUG   03…ee-channeld-chan#255525: Got it!
2024-12-05T16:34:47.487Z DEBUG   03…ee-hsmd: Got WIRE_HSMD_REVOKE_COMMITMENT_TX
2024-12-05T16:34:47.488Z DEBUG   03…ee-channeld-chan#255525: peer_out WIRE_REVOKE_AND_ACK
2024-12-05T16:34:47.488Z DEBUG   03…ee-channeld-chan#255525: Trying commit
2024-12-05T16:34:47.488Z DEBUG   03…ee-channeld-chan#255525: Feerate: SENT_ADD_REVOCATION->SENT_ADD_ACK_COMMIT REMOTE now 2086
2024-12-05T16:34:47.489Z DEBUG   03…ee-hsmd: Got WIRE_HSMD_SIGN_REMOTE_COMMITMENT_TX
2024-12-05T16:34:47.490Z DEBUG   03…ee-channeld-chan#255525: Creating commit_sig signature 1016 30…01 for tx 02…20 wscript 52…ae key 02…e5
2024-12-05T16:34:47.490Z DEBUG   03…ee-channeld-chan#255525: Telling master we're about to commit...
2024-12-05T16:34:47.490Z DEBUG   03…ee-channeld-chan#255525: Sending master 1020
2024-12-05T16:34:47.499Z DEBUG   03…ee-channeld-chan#255525: ... , awaiting 1120
2024-12-05T16:34:47.499Z DEBUG   03…ee-channeld-chan#255525: Got it!
2024-12-05T16:34:47.500Z DEBUG   03…ee-channeld-chan#255525: Sending commit_sig with 0 htlc sigs
2024-12-05T16:34:47.503Z DEBUG   03…ee-channeld-chan#255525: peer_out WIRE_COMMITMENT_SIGNED
2024-12-05T16:34:47.510Z DEBUG   03…ee-channeld-chan#255525: Can't send commit: waiting for revoke_and_ack
2024-12-05T16:34:48.032Z DEBUG   03…ee-channeld-chan#255525: peer_in WIRE_REVOKE_AND_ACK
2024-12-05T16:34:48.033Z DEBUG   03…ee-channeld-chan#255525: Received revoke_and_ack
2024-12-05T16:34:48.033Z DEBUG   03…ee-channeld-chan#255525: Feerate: SENT_ADD_ACK_COMMIT->RCVD_ADD_ACK_REVOCATION LOCAL now 2086
2024-12-05T16:34:48.033Z DEBUG   03…ee-channeld-chan#255525: No commits outstanding after recv revoke_and_ack
2024-12-05T16:34:48.033Z DEBUG   03…ee-hsmd: Got WIRE_HSMD_VALIDATE_REVOCATION
2024-12-05T16:34:48.035Z DEBUG   03…ee-hsmd: Got WIRE_HSMD_SIGN_PENALTY_TO_US
2024-12-05T16:34:48.035Z DEBUG   03…ee-channeld-chan#255525: Sending master 1022
2024-12-05T16:34:48.035Z DEBUG   03…ee-chan#255525: got revoke 1015: 0 changed
2024-12-05T16:34:48.047Z DEBUG   03…ee-channeld-chan#255525: ... , awaiting 1122
2024-12-05T16:34:48.048Z DEBUG   03…ee-channeld-chan#255525: Got it!
2024-12-05T16:34:48.048Z DEBUG   03…ee-channeld-chan#255525: revoke_and_ack REMOTE: remote_per_commit = 03…f1, old_remote_per_commit = 03…28
2024-12-05T16:34:48.058Z DEBUG   03…ee-channeld-chan#255525: Trying commit
2024-12-05T16:34:48.058Z DEBUG   03…ee-channeld-chan#255525: Can't send commit: nothing to send, feechange not wanted ({ RCVD_ADD_ACK_REVOCATION:2086 }) blockheight not wanted ({ RCVD_ADD_ACK_REVOCATION:0 })
2024-12-05T16:44:33.548Z DEBUG   03…ee-lightningd: peer_disconnect_done
2024-12-05T16:44:33.548Z DEBUG   03…ee-lightningd: Will try reconnect in 1 seconds
2024-12-05T16:44:33.549Z DEBUG   plugin-funder: Cleaning up inflights for peer id 03…ee
2024-12-05T16:44:34.872Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T16:44:34.872Z DEBUG   03…ee-lightningd: Will try reconnect in 2 seconds
2024-12-05T16:44:37.251Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T16:44:37.251Z DEBUG   03…ee-lightningd: Will try reconnect in 4 seconds
2024-12-05T16:44:41.484Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T16:44:41.484Z DEBUG   03…ee-lightningd: Will try reconnect in 8 seconds
2024-12-05T16:44:49.661Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T16:44:49.661Z DEBUG   03…ee-lightningd: Will try reconnect in 16 seconds
2024-12-05T16:45:06.654Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T16:45:06.654Z DEBUG   03…ee-lightningd: Will try reconnect in 32 seconds
2024-12-05T16:45:38.962Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T16:45:38.962Z DEBUG   03…ee-lightningd: Will try reconnect in 64 seconds
2024-12-05T16:46:43.182Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T16:46:43.182Z DEBUG   03…ee-lightningd: Will try reconnect in 128 seconds
2024-12-05T16:48:51.251Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T16:48:51.251Z DEBUG   03…ee-lightningd: Will try reconnect in 256 seconds
2024-12-05T16:53:08.205Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T16:53:08.205Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T16:58:10.298Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T16:58:10.298Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T17:03:10.443Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T17:03:10.444Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T17:08:11.057Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T17:08:11.057Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T17:13:11.779Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T17:13:11.779Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T17:18:12.391Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T17:18:12.391Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T17:23:13.313Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T17:23:13.313Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T17:28:14.072Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T17:28:14.072Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T17:33:14.236Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T17:33:14.236Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T17:38:14.723Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T17:38:14.723Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T17:43:15.428Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T17:43:15.428Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T17:48:16.382Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T17:48:16.382Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T17:53:17.331Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T17:53:17.331Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T17:58:17.638Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T17:58:17.638Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T18:03:18.521Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T18:03:18.521Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T18:08:19.022Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T18:08:19.022Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T18:13:19.521Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T18:13:19.521Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T18:18:19.849Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T18:18:19.850Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T18:23:20.046Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T18:23:20.046Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T18:28:20.579Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T18:28:20.579Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T18:33:21.129Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T18:33:21.129Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T18:38:21.161Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T18:38:21.162Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T18:43:21.923Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T18:43:21.923Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T18:48:22.645Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T18:48:22.645Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T18:53:23.640Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T18:53:23.640Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T18:58:24.395Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T18:58:24.395Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T19:03:24.816Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T19:03:24.816Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T19:08:25.247Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T19:08:25.247Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T19:13:25.313Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T19:13:25.313Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T19:18:26.251Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T19:18:26.251Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T19:23:26.776Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T19:23:26.776Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T19:28:26.963Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T19:28:26.963Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T19:33:27.395Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T19:33:27.395Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T19:38:27.713Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T19:38:27.713Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T19:43:28.111Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T19:43:28.111Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T19:48:28.862Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T19:48:28.862Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T19:53:29.503Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T19:53:29.503Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T19:58:29.675Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T19:58:29.675Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T20:03:29.702Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T20:03:29.702Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T20:08:30.670Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T20:08:30.670Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T20:13:31.406Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T20:13:31.406Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T20:18:31.743Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T20:18:31.743Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T20:23:31.827Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T20:23:31.827Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T20:28:32.392Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T20:28:32.392Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T20:33:32.673Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T20:33:32.673Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T20:38:33.798Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T20:38:33.798Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T20:43:34.063Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T20:43:34.063Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T20:48:34.394Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T20:48:34.394Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T20:53:35.120Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T20:53:35.120Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T20:58:35.703Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T20:58:35.703Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T21:03:36.150Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T21:03:36.150Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T21:08:36.278Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T21:08:36.278Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T21:13:36.771Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T21:13:36.771Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T21:18:37.719Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T21:18:37.719Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T21:23:38.142Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T21:23:38.142Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T21:28:38.252Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T21:28:38.252Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T21:33:38.481Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T21:33:38.481Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T21:38:38.620Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T21:38:38.620Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T21:43:38.911Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T21:43:38.911Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T21:48:39.899Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T21:48:39.899Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T21:53:40.235Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T21:53:40.235Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T21:58:40.752Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T21:58:40.752Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T22:03:41.138Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T22:03:41.138Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T22:08:41.145Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T22:08:41.146Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T22:13:41.995Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T22:13:41.995Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T22:18:42.333Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T22:18:42.333Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T22:23:43.255Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T22:23:43.255Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T22:28:43.705Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T22:28:43.705Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T22:33:43.853Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T22:33:43.853Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T22:38:44.063Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T22:38:44.063Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T22:43:44.562Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T22:43:44.563Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T22:48:45.347Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T22:48:45.347Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T22:53:45.558Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T22:53:45.558Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T22:58:45.660Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T22:58:45.660Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T23:03:45.920Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T23:03:45.920Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T23:08:46.866Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T23:08:46.866Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T23:13:47.263Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T23:13:47.263Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T23:18:47.890Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T23:18:47.890Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T23:23:48.406Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T23:23:48.407Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T23:28:48.518Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T23:28:48.518Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T23:33:48.859Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T23:33:48.859Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T23:38:49.073Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T23:38:49.073Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T23:43:49.814Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T23:43:49.814Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T23:48:50.460Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T23:48:50.461Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T23:53:50.902Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T23:53:50.902Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-05T23:58:51.728Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-05T23:58:51.729Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T00:03:51.879Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T00:03:51.879Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T00:08:52.143Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T00:08:52.143Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T00:13:53.145Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T00:13:53.145Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T00:18:53.914Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T00:18:53.914Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T00:23:54.115Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T00:23:54.116Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T00:28:55.111Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T00:28:55.111Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T00:33:56.102Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T00:33:56.102Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T00:38:56.660Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T00:38:56.660Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T00:43:57.322Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T00:43:57.322Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T00:48:59.050Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T00:48:59.050Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T00:53:59.480Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T00:53:59.480Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T00:58:59.699Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T00:58:59.699Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T01:03:59.814Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T01:03:59.814Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T01:09:00.443Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T01:09:00.444Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T01:14:00.677Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T01:14:00.677Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T01:19:01.463Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T01:19:01.463Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T01:24:01.849Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T01:24:01.849Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T01:29:02.164Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T01:29:02.164Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T01:34:02.253Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T01:34:02.254Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T01:39:03.214Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T01:39:03.214Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T01:44:03.404Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T01:44:03.405Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T01:49:03.749Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T01:49:03.749Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T01:54:04.372Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T01:54:04.372Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T01:59:05.337Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T01:59:05.337Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T02:04:05.461Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T02:04:05.461Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T02:09:05.824Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T02:09:05.824Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T02:14:07.830Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T02:14:07.830Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T02:19:09.342Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T02:19:09.342Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T02:24:09.760Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T02:24:09.760Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T02:29:10.628Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T02:29:10.628Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T02:34:10.630Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T02:34:10.630Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T02:39:10.748Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T02:39:10.748Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T02:44:11.139Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T02:44:11.139Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T02:49:11.904Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T02:49:11.904Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T02:54:12.584Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T02:54:12.584Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T02:59:13.126Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T02:59:13.126Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T03:04:14.069Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T03:04:14.069Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T03:09:14.801Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T03:09:14.801Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T03:14:15.111Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T03:14:15.111Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T03:19:15.995Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T03:19:15.995Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T03:24:16.061Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T03:24:16.061Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T03:29:16.991Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T03:29:16.991Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T03:34:17.577Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T03:34:17.577Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T03:39:17.848Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T03:39:17.849Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T03:44:18.084Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T03:44:18.084Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T03:49:18.843Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T03:49:18.843Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T03:54:18.926Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T03:54:18.926Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T03:59:19.568Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy. 
2024-12-06T03:59:19.568Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T03:59:50.451Z DEBUG   02…9d-chan#255563: Decided to forward htlc_id=5272 over channel with scid=…54x…27x1 with peer 03…ee
2024-12-06T03:59:50.465Z DEBUG   03…ee-channeld-chan#255525: NEW:: HTLC LOCAL 172 = SENT_ADD_HTLC/RCVD_ADD_HTLC 
2024-12-06T03:59:50.465Z DEBUG   03…ee-channeld-chan#255525: Adding HTLC 172 amount=10000000msat cltv=873499 gave CHANNEL_ERR_ADD_OK
2024-12-06T03:59:50.465Z DEBUG   03…ee-channeld-chan#255525: peer_out WIRE_UPDATE_ADD_HTLC

For completeness, here are all log lines that contain the string "connect" (not filtered to only those containing the node ID in question) from a little before the incident to a little after it:

2024-12-06T03:58:40.267Z DEBUG   03…f7-channeld-chan#147665: billboard perm: Reconnected, and reestablished.
2024-12-06T03:58:47.264Z INFO    plugin-sling: …18x…21x2/1: not connected. Taking a break...
2024-12-06T03:59:18.894Z DEBUG   03…83-connectd: peer_in WIRE_WARNING
2024-12-06T03:59:18.894Z INFO    03…83-connectd: Received WIRE_WARNING: WARNING: channel_announcement: no unspent txout …50x…97x1
2024-12-06T03:59:19.568Z DEBUG   03…ee-connectd: Failed connected out: All addresses failed: ise…d.onion:9735: need a proxy.
2024-12-06T03:59:19.568Z DEBUG   03…ee-lightningd: Will try reconnect in 300 seconds
2024-12-06T03:59:28.653Z DEBUG   02…0d-connectd: Failed connected out: All addresses failed: 46.…1:16431: Connection establishment: No route to host. qeg…d.onion:9735: need a proxy.
2024-12-06T03:59:28.654Z DEBUG   02…0d-lightningd: Will try reconnect in 300 seconds
2024-12-06T03:59:32.319Z INFO    plugin-sling: …86x…85x1/1: not connected. Taking a break...
2024-12-06T03:59:38.239Z DEBUG   03…8f-connectd: peer_in INVALID 39409
2024-12-06T03:59:47.337Z INFO    plugin-sling: …18x…21x2/1: not connected. Taking a break...
2024-12-06T04:00:05.563Z DEBUG   02…8b-connectd: Failed connected out: All addresses failed: [::…5.…2]:42077: Connection establishment: Connection refused. 68.…8:9735: Connection establishment: Connection timed out. dt7…d.onion:9735: need a proxy.
2024-12-06T04:00:05.563Z DEBUG   02…8b-lightningd: Will try reconnect in 300 seconds

@rustyrussell
Copy link
Contributor

Wow, neat. We have a phantom channeld (which should only be created once we have a connection). Connectd is still trying to connect, so it doesn't believe we're connected. So maybe channeld is hanging around but shouldn't be? connectd gives subds 5 seconds before closing on them, and channeld should shutdown once that happens, worst case.

Hmm, OK, grep for '#255525': you should see channeld getting created, something like this from my own logs:

2024-11-29T02:07:36.804Z DEBUG   03..8f-chan#70780: Peer has reconnected, state CHANNELD_NORMAL: connecting subd
2024-11-29T02:07:36.813Z DEBUG   03..8f-channeld-chan#70780: pid 1891, msgfd 86
2024-11-29T02:07:36.814Z DEBUG   03..8f-chan#70780: Already have funding locked in
2024-11-29T02:07:36.825Z DEBUG   03..8f-channeld-chan#70780: option_static_remotekey = 1, op

Also, just check for 'messages suppressed' in case that's dropping stuff.

@whitslack
Copy link
Collaborator Author

Here's everything from December 1-6:

$ tail -c"$((5<<30))" /var/log/lightningd.log | grep '^2024-12-0[1-6]' | grep -F -e '#255525' -e 'messages suppressed' | grep -Fv 'gossipd:' | redact | tee /tmp/log.redacted.txt
log.redacted.txt

Lots of "messages suppressed". That's supremely unhelpful. I would have thought that that misfeature would apply only to the in-memory log, which I actually have patched out of my CLN to save RAM. How can I tell CLN never to "suppress" any log messages?

@rustyrussell rustyrussell added this to the v25.02 milestone Dec 13, 2024
rustyrussell added a commit to rustyrussell/lightning that referenced this issue Dec 13, 2024
We ratelimited DEBUG messages, but that can be annoying and cause us to miss things.
We demoted the worst offenders in the last release, to TRACE level.

Now, only log trace if it's wanted, and never suppress DEBUG.

Changelog-Changed: Logging: we no longer suppress DEBUG messages from subdaemons.
Signed-off-by: Rusty Russell <[email protected]>
Fixes: ElementsProject#7917
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants