Lightning: Closing signature negotiation fails and causes unilateral closes

[cdecker]

Investigating the failures of signature negotiation that leads to channels being unilaterally closed. The closing side (also the funder of the channel) gets the following logs messages:

lightning_channeld(21422): TRACE: peer_out WIRE_SHUTDOWN
lightningd(1):jcon fd 14: Closing (No such file or directory)
lightning_channeld(21422): TRACE: Read decrypt 0026e0a522d6de65a062217c70cf8502ab1d31fa6275aa072f44d16c6503f38fb5d400160014565f424bbf08e369561cd012b12a0623a451806e
lightning_channeld(21422): TRACE: peer_in WIRE_SHUTDOWN
lightning_channeld(21422): UPDATE WIRE_CHANNEL_GOT_SHUTDOWN
lightning_channeld(21422): UPDATE WIRE_CHANNEL_SHUTDOWN_COMPLETE
lightning_channeld(21422): UPDATE WIRE_CHANNEL_SHUTDOWN_COMPLETE
lightning_closingd(32056): pid 32056, msgfd 16
lightningd(1): Forcing fee rate, ignoring estimate
lightningd(1): Forcing fee rate, ignoring estimate
lightningd(1): Forcing fee rate, ignoring estimate
lightningd(1): peer 02f6725f9c1c40333b67faea92fd211c183050f28df32cac3f9d69685fe9665432: state: CHANNELD_SHUTTING_DOWN -> CLOSINGD_SIGEXCHANGE
lightning_closingd(32056): TRACE: satoshi_out = 189998/10002
lightning_closingd(32056): TRACE: dustlimit = 546
lightning_closingd(32056): TRACE: fee = 7602
lightning_closingd(32056): TRACE: Making close tx at = 189998/10002 fee 7602
lightning_closingd(32056): TRACE: sending fee offer 7602
lightning_closingd(32056): TRACE: Read decrypt 0027e0a522d6de65a062217c70cf8502ab1d31fa6275aa072f44d16c6503f38fb5d40000000000000b9e07b165b9696519bbae26cadd12993293e2a7fa042f336f243e464f0e70e315fb60e9c27cb907cbd7d4719966502d513e80d4a5a9b02f31f862be32ea5d2ae210
lightning_closingd(32056): TRACE: Making close tx at = 189998/10002 fee 2974
lightning_closingd(32056): TRACE: Making close tx at = 189998/0 fee 2974
lightning_closingd(32056): STATUS_FAIL_PEER_BAD: Bad closing_signed signature for 0200000001e0a522d6de65a062217c70cf8502ab1d31fa6275aa072f44d16c6503f38fb5d50100000000ffffffff021227000000000000160014565f424bbf08e369561cd012b12a0623a451806e90da02000000000016001444d084aa6aed3aa4b4c8c5d8e33a18585a7d89b400000000 (and trimmed version 0200000001e0a522d6de65a062217c70cf8502ab1d31fa6275aa072f44d16c6503f38fb5d50100000000ffffffff0190da02000000000016001444d084aa6aed3aa4b4c8c5d8e33a18585a7d89b400000000)
lightningd(1): peer 02f6725f9c1c40333b67faea92fd211c183050f28df32cac3f9d69685fe9665432: Peer permanent failure in CLOSINGD_SIGEXCHANGE: lightning_closingd: Bad closing_signed signature for 0200000001e0a522d6de65a062217c70cf8502ab1d31fa6275aa072f44d16c6503f38fb5d50100000000ffffffff021227000000000000160014565f424bbf08e369561cd012b12a0623a451806e90da02000000000016001444d084aa6aed3aa4b4c8c5d8e33a18585a7d89b400000000 (and trimmed version 0200000001e0a522d6de65a062217c70cf8502ab1d31fa6275aa072f44d16c6503f38fb5d50100000000ffffffff0190da02000000000016001444d084aa6aed3aa4b4c8c5d8e33a18585a7d89b400000000)
lightningd(1):   (tx 6d28e0e5a23c7b25b4551b78bb1bcf22dec321b118ac719842043f6eb6119a62)
lightningd(1): sendrawtransaction: 02000000000101e0a522d6de65a062217c70cf8502ab1d31fa6275aa072f44d16c6503f38fb5d50100000000c4853080021127000000000000160014ce82454ac392f7b39de84c853e6f0cb47beee91d7a9f020000000000220020b65bfbc5b80ea52e667a4f2aa654d50f49b0597f6a94a22428d7c3af380a6e56040048304502210088097e4851ccee19789468e510ec305354d6af0f0560a957a96079974cfd5bd1022065a2942865bb1668d41f7dffd58939b00e143ae26a0377e415eb3e0aa79ca5f80147304402201bb538ce0d4416a4cd8423a989f55adcf2f9189422c0b238b88a1b532f562b5702205a5abd94b0b2a461e993ac0ad93ef556d53bd58cd0aa3388dc0d41d6537c881d01475221022753ddacaba541d185ebab78cd41c78c5cb160ae92b09c6398fda885e822b7192103aca784f6ec506180a2dd8f1e3d3da2cdfdcdfa1e063191f979bfb3314857e59252ae34f2c520
lightning_gossipd(13): TRACE: Forgetting remote peer 02f6725f9c1c40333b67faea92fd211c183050f28df32cac3f9d69685fe9665432
lightningd(1): sendrawtx exit 0, gave 6d28e0e5a23c7b25b4551b78bb1bcf22dec321b118ac719842043f6eb6119a62

While the receiving side (fundee) sees the following (slightly pruned to remove other channels and gossip messages):

lightning_channeld(7243): TRACE: peer_in WIRE_SHUTDOWN
lightning_channeld(7243): UPDATE WIRE_CHANNEL_GOT_SHUTDOWN
lightningd(15103): peer 02227b46bb430bff2ab7774b21a4cb19b1517933f10898cfa51c1cf0121b351313: state: CHANNELD_NORMAL -> CHANNELD_SHUTTING_DOWN
lightning_channeld(7243): TRACE: Trying commit
lightning_channeld(7243): TRACE: Can't send commit: nothing to send
lightning_channeld(7243): TRACE: peer_out WIRE_SHUTDOWN
lightning_channeld(7243): UPDATE WIRE_CHANNEL_SHUTDOWN_COMPLETE
lightning_channeld(7243): UPDATE WIRE_CHANNEL_SHUTDOWN_COMPLETE
lightning_closingd(8787): pid 8787, msgfd 26
lightningd(15103): peer 02227b46bb430bff2ab7774b21a4cb19b1517933f10898cfa51c1cf0121b351313: state: CHANNELD_SHUTTING_DOWN -> CLOSINGD_SIGEXCHANGE
lightning_closingd(8787): TRACE: satoshi_out = 10001/189999
lightning_closingd(8787): TRACE: dustlimit = 546
lightning_closingd(8787): TRACE: fee = 2974
lightning_closingd(8787): TRACE: Making close tx at = 10001/189999 fee 2974
lightning_closingd(8787): TRACE: sending fee offer 2974
03582eb09cb0a0e102ec88ec750349e9f0ce839aeed1b6741bbd6946ec9ddc1a23 from basepoint 02ff054b14efedca043697c328e1b61cb6c0a6dc141e0f064ead1e43a79f0c811d, point 02e99500cbb5c9056a45a744d08d9f9335feaa2c81580cff263627063305a985f7

[cdecker]

Could this really be a rounding error?

lightning_closingd(32056): TRACE: satoshi_out = 189998/10002 vs lightning_closingd(8787): TRACE: satoshi_out = 10001/189999

[ZmnSCPxj]

It is because of this line:

https://github.com/ElementsProject/lightning/blob/master/lightningd/peer_control.c#L1905

Notice that we compute the remote side as:

peer->funding_satoshi
- *peer->our_msatoshi / 1000

Now consider the case where funding_satoshi is 3, side A has 1500 msatoshi, and side B has 1500 msatoshi.

Side A claims is own side as *peer->our_msatoshi / 1000 or 1 satoshi. Then it computes peer->funding_satoshi - *peer->our_msatoshi / 1000, which is 2 satoshi, for side B. So A = 1, B = 2.

Side B claims is own side as *peer->our_msatoshi / 1000 or 1 satoshi. Then it computes peer->funding_satoshi - *peer->our_msatoshi / 1000, which is 2 satoshi, for side A. So A = 2, B = 1.

The correct "other side" computation should be:

((peer->funding_satoshi * 1000) - *peer->our_msatoshi) / 1000