strange corner case while sending a commit

[vincenzopalazzo]

Issue and Steps to Reproduce

I noted this on my core lightning node after receiving a unilateral close for a channel, and I found the following content in the logs

2023-03-07T15:11:46.722Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1769700 attempts
2023-03-07T15:11:46.802Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1769800 attempts
2023-03-07T15:11:47.815Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1769900 attempts
2023-03-07T15:11:48.828Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1770000 attempts
2023-03-07T15:11:49.844Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1770100 attempts
2023-03-07T15:11:50.863Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1770200 attempts
2023-03-07T15:11:51.877Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1770300 attempts
2023-03-07T15:11:52.890Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1770400 attempts
2023-03-07T15:11:53.904Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1770500 attempts
2023-03-07T15:11:54.918Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1770600 attempts
2023-03-07T15:11:55.950Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1770700 attempts
2023-03-07T15:11:56.963Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1770800 attempts
2023-03-07T15:11:57.974Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1770900 attempts
2023-03-07T15:11:58.985Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1771000 attempts
2023-03-07T15:11:59.998Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1771100 attempts
2023-03-07T15:12:01.009Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1771200 attempts
2023-03-07T15:12:02.021Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1771300 attempts
2023-03-07T15:12:03.034Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1771400 attempts
2023-03-07T15:12:04.049Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1771500 attempts
2023-03-07T15:12:05.064Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1771600 attempts
2023-03-07T15:12:06.081Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1771700 attempts
2023-03-07T15:12:07.097Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1771800 attempts
2023-03-07T15:12:08.111Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1771900 attempts
2023-03-07T15:12:09.123Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1772000 attempts
2023-03-07T15:12:10.135Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1772100 attempts
2023-03-07T15:12:11.150Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1772200 attempts
2023-03-07T15:12:12.163Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1772300 attempts
2023-03-07T15:12:13.175Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1772400 attempts
2023-03-07T15:12:14.188Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1772500 attempts
2023-03-07T15:12:15.203Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1772600 attempts
2023-03-07T15:12:16.218Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-channeld-chan#1037: Can't send commit: waiting for revoke_and_ack with 1772700 attempts
2023-03-07T15:12:20.961Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-chan#1037: Got UTXO spend for 3daaafe51534b39f617b345ba62aa99c0ebed0ea6ef79894d762ff17c15bbcd8:0: 29f3360c849e5cd4e47832a7f21cbfab917627838658be8a58b7a037fa4fbe72

getinfo output

{
   "id": "03e2408a49f07d2f4083a47344138ef89e7617e63919202c92aa8d49b574a560ae",
   "alias": "BRUCEWAINE",
   "color": "02bf81",
   "num_peers": 9,
   "num_pending_channels": 0,
   "num_active_channels": 7,
   "num_inactive_channels": 1,
   "address": [
      {
         "type": "ipv4",
         "address": "65.108.246.14",
         "port": 9735
      },
      {
         "type": "ipv6",
         "address": "2a01:4f9:c012:6356::1",
         "port": 9735
      },
      {
         "type": "torv3",
         "address": "hvq7b3r7zekt2cz5a4o52ae4xbhddj5pplan7godpweyihbdmwuuxiqd.onion",
         "port": 9735
      }
   ],
   "binding": [
      {
         "type": "ipv4",
         "address": "0.0.0.0",
         "port": 9735
      }
   ],
   "version": "v23.02",
   "blockheight": 779767,
   "network": "bitcoin",
   "lightning-dir": "/home/vincent/.lightning/bitcoin",
   "our_features": {
      "init": "08a0800a0269a2",
      "node": "88a0800a0269a2",
      "channel": "",
      "invoice": "02000002024100"
   }
}

[whitslack]

"Corner case"? I have seen this message reported 7,470,648 times for 827 distinct channels so far this month. It seems like quite a common case.

$ sed -Ene 's/^2023-03-.*   ([[:xdigit:]]+)-channeld.*Can'\''t send commit: waiting for revoke_and_ack.*$/\1/p' /var/log/lightningd.log | tee >(wc -l >&2) | sort -u | wc -l
7470648
827

[vincenzopalazzo]

@whitslack you are special guys :) I think you had very big not data that can help to diagnostic this case!

[instagibbs]

Note that this log line was broken for a long time(?): #5881

so this was probably supposed to be there all along but we didn't know.

[rustyrussell]

Ah, @instagibbs fixed the logging, so now we log this! And it's spammy :(

The issue is that we want to send commitment_signed, but we're still waiting for their revoke_and_ack. We do the dumbest possible thing here, which is to retry in commit_time_msec (10 by default). We should actually catch this in the revoke_and_ack path instead.