"invalid commitment signature" with Eclair channel

[wtogami]

Previous version: v23.05.2
Shortly after upgrading to v23.08rc1 this channel with ACINQ's Eclair node force closed with these errors. Note the Adding HTLC 20 too slow: killing connection and invalid commitment signature.

2023-08-03T15:24:40.737Z UNUSUAL 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#7226: Adding HTLC 20 too slow: killing connection
2023-08-03T15:24:40.738Z INFO    03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-chan#7226: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (9)
2023-08-03T16:01:46.995Z INFO    03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-chan#7226: Attempt to send HTLC but unowned (CHANNELD_NORMAL)
2023-08-03T16:24:15.467Z UNUSUAL 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-chan#7226: Peer permanent failure in CHANNELD_NORMAL: channeld: received ERROR error channel 2277ce04dedd46a578e420a2841d8ec46a49133e093bc541d151bf7bd3589fc3: invalid commitment signature: txId=85f9be357b4879d3e96ef499e5e267f7709df3606a765b5826e183e1099e9651
2023-08-03T16:24:15.468Z INFO    03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-chan#7226: State changed from CHANNELD_NORMAL to AWAITING_UNILATERAL
2023-08-03T17:38:34.076Z UNUSUAL 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-chan#7226: Peer permanent failure in AWAITING_UNILATERAL: Funding transaction spent
2023-08-03T17:38:34.077Z INFO    03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-chan#7226: State changed from AWAITING_UNILATERAL to FUNDING_SPEND_SEEN
2023-08-03T17:38:34.880Z INFO    03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-chan#7226: State changed from FUNDING_SPEND_SEEN to ONCHAIN

@grubles reported the same happening with v23.08rc1 and the ACINQ node.

[pm47]

From ACINQ side here is what we have:

     ACINQ              BLOCKSTREAM
       |                     |
       |--- reestablish ---->|
       |<-- reestablish -----|
       |                     |
       |<----- ann_sigs -----|
       |------ ann_sigs ---->|
       |                     |
       |------ add-120 ----->|
       |-------- sig ------->|
       |<------- rev --------|
       |                     |
       |------ add-121 ----->|
       |-------- sig ------->|
       |<------- rev --------|
       |                     |
       |------ add-122 ----->|
       |-------- sig ------->|
       |<------- rev --------|
       |                     |
       |------ add-123 ----->|
       |-------- sig ------->|
       |<------- rev --------|
       |                     |
       |<----- add-20 -------|
       |                     |
       |   (an hour elapses) |
       |                     |
       |------ add-124 ----->|
       |-------- sig ------->|
       |                     | <-- no rev received from cln in 20s, eclair disconnects
       |                     |
       |--- reestablish ---->|
       |<-- reestablish -----|
       |                     |
       |<------- sig --------| <-- invalid sig
       |------ add-124 ----->|
       |-------- sig ------->|
       |<----- ann_sigs -----|
       |                     |

It seems cln wasn't sending signatures.

[grubles]

Here are the logs that @wtogami mentioned (also reported in the Eclair repo).

2023-07-27T13:58:33.812Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: peer_out WIRE_COMMITMENT_SIGNED
2023-07-27T13:58:33.812Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-hsmd: Got WIRE_HSMD_CANNOUNCEMENT_SIG_REQ
2023-07-27T13:58:33.812Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14324: billboard: Channel ready for use. Channel announced.
2023-07-27T13:58:33.812Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: No upgrade: we retransmitted
2023-07-27T13:58:33.812Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: billboard perm: Reconnected, and reestablished.
2023-07-27T13:58:33.812Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-hsmd: Got WIRE_HSMD_CANNOUNCEMENT_SIG_REQ
2023-07-27T13:58:33.822Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14324: billboard: Channel ready for use. Channel announced.
2023-07-27T13:58:33.822Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: Exchanging announcement signatures.
2023-07-27T13:58:33.822Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14324: billboard: Channel ready for use. Channel announced.
2023-07-27T13:58:33.822Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: peer_out WIRE_ANNOUNCEMENT_SIGNATURES
2023-07-27T13:58:33.822Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: billboard: Channel ready for use. Channel announced.
2023-07-27T13:58:33.822Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14324: Can't send commit: waiting for revoke_and_ack
2023-07-27T13:58:33.833Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: billboard: Channel ready for use. Channel announced.
2023-07-27T13:58:33.833Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: billboard: Channel ready for use. Channel announced.
2023-07-27T13:58:33.833Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: Can't send commit: waiting for revoke_and_ack
2023-07-27T13:59:23.929Z INFO    03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14324: Peer connection lost
2023-07-27T13:59:23.929Z INFO    03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-chan#14324: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
2023-07-27T13:59:23.929Z INFO    03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: Peer connection lost
2023-07-27T13:59:23.929Z INFO    03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-chan#14429: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
2023-07-27T13:59:23.929Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-lightningd: peer_disconnect_done
2023-07-27T13:59:23.929Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-lightningd: Will try reconnect in 300 seconds

The above seemed to continue for a few days until the invalid commitment signature error:

2023-08-01T22:29:32.186Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: pid 2319607, msgfd 135                         
2023-08-01T22:29:32.187Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: option_static_remotekey = 1, option_anchor_outputs = 0 option_anchors_zero_fee_htlc_tx = 0                                                                                                                             
2023-08-01T22:29:32.187Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: init LOCAL: remote_per_commit = 0210ca3fef8d35b96309bbb73da0cac604ec523233d1fabb4ab7fd4449d85cb224, old_remote_per_commit = 02c3a2e53124735b9fc1b4055dd0fcc73daf39177670ac8c73779442fec243a315 next_idx_local = 6023 next_idx_remote = 6021 revocations_received = 6019 feerates { SENT_ADD_COMMIT:1999 SENT_ADD_ACK_REVOCATION:1791 } range 901-34340 blockheights { SENT_ADD_ACK_REVOCATION:0 }, our current 801263                                                                                                                                                  
2023-08-01T22:29:32.187Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: Restoring HTLC 0/1: id=192 amount=501500msat cl
tv=801400 payment_hash=b9fdc7e632ec974f8ec2361b0aec53ec25b7a2a2a45350f1d456924fbed8fb15                                                                                 
2023-08-01T22:29:32.188Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: NEW:: HTLC REMOTE 192 = SENT_ADD_REVOCATION/RCVD_ADD_REVOCATION                                                                                                                                                        
2023-08-01T22:29:32.188Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: peer_out WIRE_CHANNEL_REESTABLISH              
2023-08-01T22:29:32.188Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: billboard: Sent reestablish, waiting for theirs2023-08-01T22:29:32.255Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: peer_in WIRE_CHANNEL_REESTABLISH               
2023-08-01T22:29:32.255Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: Got reestablish commit=6020 revoke=6022        
2023-08-01T22:29:32.256Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: next_revocation_number = 6022                  
2023-08-01T22:29:32.256Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: option_static_remotekey: fields are correct    
2023-08-01T22:29:32.256Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: Retransmitting commitment, feerate LOCAL=1791 REMOTE=1999, blockheight LOCAL=0 REMOTE=0                                                                                                                                
2023-08-01T22:29:32.256Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: peer_out WIRE_UPDATE_FEE                       
2023-08-01T22:29:32.257Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: Creating commit_sig signature 6020 304402202c85e99c75767586eb70ec60c5a92a8ce04d9cf4868a51fe2d79d053c42a46c502203c456f7f70c0d34275e7fba046b3b3313f7075b5d47c22215bb16bc08908f63f01 for tx 020000000187d7f9ac5cecfa54e910e48518e8ed83de52cd93511f4665c9dd7b02a451cfb0000000000070517d8002c2b90400000000001600148ceef863fb13e1823224475a29b0d0108c349cf799f2a70100000000220020f0009947e5f9d9324ba24798a468de5a1a119b931df9d0251cb9e6893ebea9bb5b196d20 wscript 52210221f5d1b34d96c05efb418ca13affc2cf7b45d7f376f081ea5f8749cfeef921902103bf54062b869771a2b66559d90173c870b40df7890b7a62c5bb119588026ea08b52ae key 03bf54062b869771a2b66559d90173c870b40df7890b7a62c5bb119588026ea08b                                                              
2023-08-01T22:29:32.257Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: peer_out WIRE_COMMITMENT_SIGNED                
2023-08-01T22:29:32.257Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: No upgrade: we retransmitted                   
2023-08-01T22:29:32.257Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: billboard perm: Reconnected, and reestablished.
2023-08-01T22:29:32.257Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: Exchanging announcement signatures.            
2023-08-01T22:29:32.258Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: peer_out WIRE_ANNOUNCEMENT_SIGNATURES          
2023-08-01T22:29:32.258Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: billboard: Channel ready for use. Channel announced.                                                                                                                                                                   
2023-08-01T22:29:32.277Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: billboard: Channel ready for use. Channel announced.                                                                                                                                                                   
2023-08-01T22:29:32.277Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: billboard: Channel ready for use. Channel announced.                                                                                                                                                                   
2023-08-01T22:29:32.280Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: Can't send commit: waiting for revoke_and_ack  
2023-08-01T22:29:32.690Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: peer_in WIRE_ERROR                             
2023-08-01T22:29:32.690Z DEBUG   03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-channeld-chan#14429: billboard perm: Received error channel 87d7f9ac5cecfa54e910e48518e8ed83de52cd93511f4665c9dd7b02a451cfb0: invalid commitment signature: txId=9a84de0ccb4eb4168e33d5bf07fdecb59533d1f2c4d2bacd42fdf915706d4e4b   

[pm47]

Can't send commit: waiting for revoke_and_ack

This explains why cln wasn't sending sigs.

Below is the same diagram as before, starting a little bit earlier and with more details. I believe cln acks rev-334 in its reestablish and the behavior of eclair (not resending rev-334) is correct.

     ACINQ              BLOCKSTREAM
       |                     |
       |<------sig-335-------|
       |-------rev-334------>|
       |                     |
       |--- reestablish ---->| `nextLocalCommitmentNumber`=336, `nextRemoteRevocationNumber`=335
       |<-- reestablish -----| `nextLocalCommitmentNumber`=336, `nextRemoteRevocationNumber`=335
       |                     |
       |<----- ann_sigs -----|
       |------ ann_sigs ---->|
       |                     |
       |------ add-120 ----->|
       |-------- sig ------->|
       |<------- rev --------|
       |                     |
       |------ add-121 ----->|
       |-------- sig ------->|
       |<------- rev --------|
       |                     |
       |------ add-122 ----->|
       |-------- sig ------->|
       |<------- rev --------|
       |                     |
       |------ add-123 ----->|
       |-------- sig ------->|
       |<------- rev --------|
       |                     |
       |<----- add-20 -------|
       |                     |
       |   (an hour elapses) |
       |                     |
       |------ add-124 ----->|
       |-------- sig ------->|
       |                     | <-- no rev received from cln in 20s, eclair disconnects
       |                     |
       |--- reestablish ---->|
       |<-- reestablish -----|
       |                     |
       |<------- sig --------|
       |------ add-124 ----->|
       |-------- sig ------->| <-- invalid sig
       |<----- ann_sigs -----|
       |                     |

[rustyrussell]

When I tried to produce locally, I got a very strange result. I was not seeing a revoke_and_ack from ACINQ at all: on reconnect, it retransmitted and all worked, but the next HTLC had the same issue.

So, is the revoke_and_ack not being sent, or are we somehow not receiving it properly? It seems a pretty fundamental thing, and it's only happening on -rc1 nodes, so I really have to suspect it's us! There were no major demuxing changes, but since I can reproduce this I'll hack something in to log everything we receive to be sure...

Nonetheless, this bad signature Shouldn't Happen; I'll look at that too.

[hMsats]

Yeah, me too and only with ACINQ:

            {
               "timestamp": "2023-08-01T17:48:41.514Z",
               "old_state": "CHANNELD_NORMAL",
               "new_state": "AWAITING_UNILATERAL",
               "cause": "protocol",
               "message": "channeld: received ERROR error channel f0b86bbab1a8a9f00909c3a2a2d5bb179dd8722c30a99e1f791fc832b69ec0ea: invalid commitment signature: txId=5ffc2adae33ebcfb3b926865d7c32fd80cdddc1a195640482661033a26f9aea0"
            },

version": "v23.08rc1-1-g568f277

[rustyrussell]

OK, pretty sure I've figured out the reason ACINQ doesn't reply with revoke_and_ack: we're sending a splice TLV, even if splicing is not negotiated. (It should be ignoring it, since it's odd, but it could be a spec disagreement, so I'm creating a patch to not send that unless negotiated). Could also point to a bug in ACINQ's (unfinished?) splice code (their node doesn't advertize support).

[rustyrussell]

This seems to be fixed by #6517 though it's possible that simply unmasked an existing inconsistency. I've closed for now.