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

strange corner case while sending a commit #6077

Closed
vincenzopalazzo opened this issue Mar 7, 2023 · 4 comments · Fixed by #6107
Closed

strange corner case while sending a commit #6077

vincenzopalazzo opened this issue Mar 7, 2023 · 4 comments · Fixed by #6107
Assignees
Labels
in diagnostic issue under diagnostic
Milestone

Comments

@vincenzopalazzo
Copy link
Contributor

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"
   }
}
@vincenzopalazzo vincenzopalazzo added the in diagnostic issue under diagnostic label Mar 7, 2023
@vincenzopalazzo vincenzopalazzo changed the title strange corner care while sending a commit strange corner case while sending a commit Mar 7, 2023
@whitslack
Copy link
Collaborator

whitslack commented Mar 14, 2023

"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
Copy link
Contributor Author

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

@rustyrussell rustyrussell self-assigned this Mar 20, 2023
@rustyrussell rustyrussell added this to the v23.05 milestone Mar 20, 2023
@instagibbs
Copy link
Collaborator

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
Copy link
Contributor

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.

rustyrussell added a commit to rustyrussell/lightning that referenced this issue Mar 20, 2023
We would sleep for 10msec (default) and try again, spamming the logs
every second.  But we're waiting for revoke_and_ack, and that handler
already sets off the timer, so there's no need to spin at all!

Fixes: ElementsProject#6077
Changelog-Fixed: `channeld`: no longer spin and spam logs when waiting for revoke_and_ack.
Signed-off-by: Rusty Russell <[email protected]>
rustyrussell added a commit that referenced this issue Mar 22, 2023
We would sleep for 10msec (default) and try again, spamming the logs
every second.  But we're waiting for revoke_and_ack, and that handler
already sets off the timer, so there's no need to spin at all!

Fixes: #6077
Changelog-Fixed: `channeld`: no longer spin and spam logs when waiting for revoke_and_ack.
Signed-off-by: Rusty Russell <[email protected]>
ddustin pushed a commit to ddustin/lightning that referenced this issue Apr 11, 2023
We would sleep for 10msec (default) and try again, spamming the logs
every second.  But we're waiting for revoke_and_ack, and that handler
already sets off the timer, so there's no need to spin at all!

Fixes: ElementsProject#6077
Changelog-Fixed: `channeld`: no longer spin and spam logs when waiting for revoke_and_ack.
Signed-off-by: Rusty Russell <[email protected]>
gkrizek pushed a commit to voltagecloud/lightning that referenced this issue Apr 26, 2023
We would sleep for 10msec (default) and try again, spamming the logs
every second.  But we're waiting for revoke_and_ack, and that handler
already sets off the timer, so there's no need to spin at all!

Fixes: ElementsProject#6077
Changelog-Fixed: `channeld`: no longer spin and spam logs when waiting for revoke_and_ack.
Signed-off-by: Rusty Russell <[email protected]>
ddustin pushed a commit to ddustin/lightning that referenced this issue May 12, 2023
We would sleep for 10msec (default) and try again, spamming the logs
every second.  But we're waiting for revoke_and_ack, and that handler
already sets off the timer, so there's no need to spin at all!

Fixes: ElementsProject#6077
Changelog-Fixed: `channeld`: no longer spin and spam logs when waiting for revoke_and_ack.
Signed-off-by: Rusty Russell <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
in diagnostic issue under diagnostic
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants