App force closes channel when opening position: Invalid commitment tx signature from peer

[da-kami]

App deployed and running on phone from main at commit e224fadfaa8fc611520b9b7ea86b098df81279a9.
App was running against our cloud setup.

Coordinator logs (cloud):

2023-04-05 01:25:42 ERROR coordinator::orderbook::trading: Could not notify maker - we should fail here and get another match if possible
2023-04-05 01:25:42 DEBUG coordinator::orderbook::trading: Successfully notified taker
2023-04-05 01:25:44  INFO coordinator::node: Opening position
2023-04-05 01:25:44 DEBUG coordinator::node: Proposing dlc channel event_id="btcusd1681262742"
2023-04-05 01:25:44 DEBUG reqwest::connect: starting new connection: https://oracle.holzeis.me/
2023-04-05 01:26:10 DEBUG ln_dlc_node::node: Announcing node on [IPv4 { addr: [35, 189, 57, 114], port: 9045 }]
2023-04-05 01:26:10 DEBUG lightning::ln::peer_handler: Broadcasting NodeAnnouncement after passing it to our own RoutingMessageHandler.
2023-04-05 01:26:29 DEBUG lightning::ln::peer_handler: Error handling message from 0283c4cd7a849c1e2ca8781876825745e83b5430d7c9435a3ced5febc9238c657d; ignoring: No existing channels for node_announcement
2023-04-05 01:27:09 DEBUG ln_dlc_node::node: Announcing node on [IPv4 { addr: [35, 189, 57, 114], port: 9045 }]
2023-04-05 01:27:09 DEBUG lightning::ln::peer_handler: Broadcasting NodeAnnouncement after passing it to our own RoutingMessageHandler.
2023-04-05 01:27:17 DEBUG lightning::ln::channelmanager: Marking channels with 0283c4cd7a849c1e2ca8781876825745e83b5430d7c9435a3ced5febc9238c657d disconnected and generating channel_updates. We believe we can make future connections to this peer.
2023-04-05 01:27:21 DEBUG ln_dlc_node::node: Received inbound connection addr=103.135.144.7:58072
2023-04-05 01:27:21 DEBUG lightning::ln::peer_handler: Finished noise handshake for connection with 0283c4cd7a849c1e2ca8781876825745e83b5430d7c9435a3ced5febc9238c657d
2023-04-05 01:27:22  INFO lightning::ln::peer_handler: Received peer Init message from 0283c4cd7a849c1e2ca8781876825745e83b5430d7c9435a3ced5febc9238c657d: DataLossProtect: supported, InitialRoutingSync: not supported, UpfrontShutdownScript: supported, GossipQueries: supported, VariableLengthOnion: required, StaticRemoteKey: required, PaymentSecret: required, BasicMPP: supported, Wumbo: supported, ShutdownAnySegwit: supported, OnionMessages: not supported, ChannelType: supported, SCIDPrivacy: supported, ZeroConf: supported, unknown flags: none
2023-04-05 01:27:22 DEBUG lightning::ln::channelmanager: Generating channel_reestablish events for 0283c4cd7a849c1e2ca8781876825745e83b5430d7c9435a3ced5febc9238c657d
2023-04-05 01:27:22 DEBUG lightning::ln::peer_handler: Handling SendChannelReestablish event in peer_handler for node 0283c4cd7a849c1e2ca8781876825745e83b5430d7c9435a3ced5febc9238c657d for channel 942f51a5bcf0704f62fdea50d25036fe4a4744d578ce41ffd773ffd5e494c765
2023-04-05 01:27:22 DEBUG lightning::ln::peer_handler: Handling SendChannelAnnouncement event in peer_handler for node 0283c4cd7a849c1e2ca8781876825745e83b5430d7c9435a3ced5febc9238c657d for short channel id 713583046492161
2023-04-05 01:27:23 DEBUG lightning::ln::channel: Reconnected channel 942f51a5bcf0704f62fdea50d25036fe4a4744d578ce41ffd773ffd5e494c765 with no loss
2023-04-05 01:27:23 ERROR lightning::ln::channelmanager: Closing channel 942f51a5bcf0704f62fdea50d25036fe4a4744d578ce41ffd773ffd5e494c765 due to close-required error: Invalid commitment tx signature from peer
2023-04-05 01:27:23 DEBUG lightning::ln::channelmanager: Finishing force-closure of channel with 0 HTLCs to fail
2023-04-05 01:27:23  INFO lightning::chain::channelmonitor: Applying update to monitor 942f51a5bcf0704f62fdea50d25036fe4a4744d578ce41ffd773ffd5e494c765, bringing update_id from 5 to 6 with 1 changes.
2023-04-05 01:27:23  INFO lightning::chain::channelmonitor: Broadcasting local commitment tx with txid e307a5bf9ef2fc78ac2f4974aa5da563efac0fd5bb4ad240a80446784a906722
2023-04-05 01:27:23 ERROR lightning::ln::channelmanager: Invalid commitment tx signature from peer
2023-04-05 01:27:23 DEBUG lightning::ln::peer_handler: Error handling message from 0283c4cd7a849c1e2ca8781876825745e83b5430d7c9435a3ced5febc9238c657d; ignoring: Couldn't find channel for update
2023-04-05 01:27:23  INFO ln_dlc_node::ln::event_handler: Received event event=ChannelClosed { channel_id: [148, 47, 81, 165, 188, 240, 112, 79, 98, 253, 234, 80, 210, 80, 54, 254, 74, 71, 68, 213, 120, 206, 65, 255, 215, 115, 255, 213, 228, 148, 199, 101], user_channel_id: 0, reason: ProcessingError { err: "Invalid commitment tx signature from peer" } }
2023-04-05 01:27:23  INFO ln_dlc_node::ln::event_handler:
Channel closed channel=942f51a5bcf0704f62fdea50d25036fe4a4744d578ce41ffd773ffd5e494c765 reason=ProcessingError { err: "Invalid commitment tx signature from peer" }
2023-04-05 01:27:23 DEBUG ln_dlc_node::ln::event_handler: Successfully handled event event="ChannelClosed { channel_id: [148, 47, 81, 165, 188, 240, 112, 79, 98, 253, 234, 80, 210, 80, 54, 254, 74, 71, 68, 213, 120, 206, 65, 255, 215, 115, 255, 213, 228, 148, 199, 101], user_channel_id: 0, reason: ProcessingError { err: \"Invalid commitment tx signature from peer\" } }"

App logs (exported from phone; Pixel 6a):

| 2023-04-04 21:25:44.923 | LogLevel.DEBUG | Found subscriber 
| 2023-04-04 21:25:47.542 | LogLevel.INFO | Sent trade request to coordinator successfully 
| 2023-04-04 21:26:00.604 | LogLevel.DEBUG | lightning::chain::chainmonitor: New best block 2f6764e6daf2bf0a5b77f424cd8c8d556d2091b8c50ec852888655e8292dba8f at height 660 provided via best_block_updated 
| 2023-04-04 21:26:03.541 | LogLevel.DEBUG | Publishing event WalletInfoUpdateNotification(WalletInfo { balances: Balances { on_chain: 0, lightning: 100000 }, history: [WalletHistoryItem { flow: Inbound, amount_sats: 100000, timestamp: 1680657882, status: Confirmed, wallet_type: Lightning { payment_hash: "63e387a979683f5dd5c0835f9d2e06cf4689fffe3c780d17b3a36b9569602baf" } }] }) 
| 2023-04-04 21:26:03.547 | LogLevel.DEBUG | Found subscriber 
| 2023-04-04 21:26:03.555 | LogLevel.DEBUG | Processing DLC channel message 
| 2023-04-04 21:26:03.577 | LogLevel.INFO | Accepting DLC channel offer 
| 2023-04-04 21:26:03.628 | LogLevel.INFO | lightning::chain::channelmonitor: Applying update to monitor 942f51a5bcf0704f62fdea50d25036fe4a4744d578ce41ffd773ffd5e494c765, bringing update_id from 5 to 6 with 1 changes. 
| 2023-04-04 21:26:03.636 | LogLevel.DEBUG | lightning::chain::chainmonitor: Persistence of ChannelMonitorUpdate for channel 942f51a5bcf0704f62fdea50d25036fe4a4744d578ce41ffd773ffd5e494c765 completed 
| 2023-04-04 21:26:03.927 | LogLevel.ERROR | Failed to accept DLC channel offer: Invalid parameters were provided: Computed payout is greater than total collateral. 
| 2023-04-04 21:26:17.161 | LogLevel.DEBUG | New message from orderbook 
| 2023-04-04 21:26:17.168 | LogLevel.DEBUG | Publishing event PriceUpdateNotification({BtcUsd: Price { bid: Some(28654), ask: Some(27991) }}) 
| 2023-04-04 21:26:17.172 | LogLevel.DEBUG | Found subscriber 
| 2023-04-04 21:26:17.565 | LogLevel.DEBUG | New message from orderbook 
| 2023-04-04 21:26:17.574 | LogLevel.DEBUG | Publishing event PriceUpdateNotification({BtcUsd: Price { bid: Some(28654), ask: Some(27991) }}) 
| 2023-04-04 21:26:17.579 | LogLevel.DEBUG | Found subscriber 
| 2023-04-04 21:26:17.587 | LogLevel.DEBUG | New message from orderbook 
| 2023-04-04 21:26:17.591 | LogLevel.DEBUG | Publishing event PriceUpdateNotification({BtcUsd: Price { bid: Some(28654), ask: Some(27991) }}) 
| 2023-04-04 21:26:17.595 | LogLevel.DEBUG | Found subscriber 
| 2023-04-04 21:26:17.601 | LogLevel.DEBUG | New message from orderbook 
| 2023-04-04 21:26:17.604 | LogLevel.DEBUG | Publishing event PriceUpdateNotification({BtcUsd: Price { bid: Some(28654), ask: Some(27991) }}) 
| 2023-04-04 21:26:17.607 | LogLevel.DEBUG | Found subscriber 
| 2023-04-04 21:26:27.803 | LogLevel.DEBUG | lightning::chain::chainmonitor: New best block 2f6764e6daf2bf0a5b77f424cd8c8d556d2091b8c50ec852888655e8292dba8f at height 660 provided via best_block_updated 
| 2023-04-04 21:26:28.510 | LogLevel.DEBUG | lightning::chain::chainmonitor: Transaction aeb01fc976fd178736149be5e63206f185acf99dca7828aa9f3572d798fa6072 reorganized out of chain 
| 2023-04-04 21:26:31.012 | LogLevel.DEBUG | Publishing event WalletInfoUpdateNotification(WalletInfo { balances: Balances { on_chain: 0, lightning: 98188 }, history: [WalletHistoryItem { flow: Inbound, amount_sats: 100000, timestamp: 1680657882, status: Confirmed, wallet_type: Lightning { payment_hash: "63e387a979683f5dd5c0835f9d2e06cf4689fffe3c780d17b3a36b9569602baf" } }] }) 
| 2023-04-04 21:26:31.016 | LogLevel.DEBUG | Found subscriber 
| 2023-04-04 21:26:31.024 | LogLevel.DEBUG | Announcing node on [IPv4 { addr: [0, 0, 0, 0], port: 44043 }] 
| 2023-04-04 21:26:31.032 | LogLevel.DEBUG | lightning::ln::peer_handler: Broadcasting NodeAnnouncement after passing it to our own RoutingMessageHandler. 
| 2023-04-04 21:26:51.988 | LogLevel.DEBUG | lightning::chain::chainmonitor: New best block 2f6764e6daf2bf0a5b77f424cd8c8d556d2091b8c50ec852888655e8292dba8f at height 660 provided via best_block_updated 
| 2023-04-04 21:26:52.428 | LogLevel.DEBUG | lightning::chain::chainmonitor: Transaction aeb01fc976fd178736149be5e63206f185acf99dca7828aa9f3572d798fa6072 reorganized out of chain 
| 2023-04-04 21:26:55.077 | LogLevel.DEBUG | Publishing event WalletInfoUpdateNotification(WalletInfo { balances: Balances { on_chain: 0, lightning: 98188 }, history: [WalletHistoryItem { flow: Inbound, amount_sats: 100000, timestamp: 1680657882, status: Confirmed, wallet_type: Lightning { payment_hash: "63e387a979683f5dd5c0835f9d2e06cf4689fffe3c780d17b3a36b9569602baf" } }] }) 
| 2023-04-04 21:26:55.091 | LogLevel.DEBUG | Found subscriber 
| 2023-04-04 21:27:17.223 | LogLevel.DEBUG | New message from orderbook 
| 2023-04-04 21:27:17.226 | LogLevel.DEBUG | Publishing event PriceUpdateNotification({BtcUsd: Price { bid: Some(28654), ask: Some(27991) }}) 
| 2023-04-04 21:27:17.228 | LogLevel.DEBUG | Found subscriber 
| 2023-04-04 21:27:17.897 | LogLevel.DEBUG | New message from orderbook 
| 2023-04-04 21:27:17.898 | LogLevel.DEBUG | Publishing event PriceUpdateNotification({BtcUsd: Price { bid: Some(28654), ask: Some(27991) }}) 
| 2023-04-04 21:27:17.899 | LogLevel.DEBUG | Found subscriber 
| 2023-04-04 21:27:17.900 | LogLevel.DEBUG | New message from orderbook 
| 2023-04-04 21:27:17.902 | LogLevel.DEBUG | Publishing event PriceUpdateNotification({BtcUsd: Price { bid: Some(28654), ask: Some(27991) }}) 
| 2023-04-04 21:27:17.902 | LogLevel.DEBUG | Found subscriber 
| 2023-04-04 21:27:17.903 | LogLevel.DEBUG | New message from orderbook 
| 2023-04-04 21:27:17.904 | LogLevel.DEBUG | Publishing event PriceUpdateNotification({BtcUsd: Price { bid: Some(28654), ask: Some(27991) }}) 
| 2023-04-04 21:27:17.905 | LogLevel.DEBUG | Found subscriber 
| 2023-04-04 21:27:19.633 | LogLevel.DEBUG | lightning::chain::chainmonitor: New best block 2f6764e6daf2bf0a5b77f424cd8c8d556d2091b8c50ec852888655e8292dba8f at height 660 provided via best_block_updated 
| 2023-04-04 21:27:20.274 | LogLevel.DEBUG | lightning::chain::chainmonitor: Transaction aeb01fc976fd178736149be5e63206f185acf99dca7828aa9f3572d798fa6072 reorganized out of chain 
| 2023-04-04 21:27:22.514 | LogLevel.DEBUG | Publishing event WalletInfoUpdateNotification(WalletInfo { balances: Balances { on_chain: 0, lightning: 98188 }, history: [WalletHistoryItem { flow: Inbound, amount_sats: 100000, timestamp: 1680657882, status: Confirmed, wallet_type: Lightning { payment_hash: "63e387a979683f5dd5c0835f9d2e06cf4689fffe3c780d17b3a36b9569602baf" } }] }) 
| 2023-04-04 21:27:22.519 | LogLevel.DEBUG | Found subscriber 
| 2023-04-04 21:27:22.541 | LogLevel.DEBUG | Announcing node on [IPv4 { addr: [0, 0, 0, 0], port: 44043 }] 
| 2023-04-04 21:27:22.544 | LogLevel.DEBUG | lightning::ln::peer_handler: Broadcasting NodeAnnouncement after passing it to our own RoutingMessageHandler. 
| 2023-04-04 21:27:22.545 | LogLevel.DEBUG | lightning::ln::channelmanager: Marking channels with 026e1de0e76902d71d2c27bfdda9d48c19c4c550f08bb4189d7208246e0e3af97e disconnected and generating channel_updates. We believe we can make future connections to this peer. 
| 2023-04-04 21:27:22.546 | LogLevel.DEBUG | Connection lost 
| 2023-04-04 21:27:22.547 | LogLevel.DEBUG | Attempting to reconnect 
| 2023-04-04 21:27:22.935 | LogLevel.DEBUG | Waiting to establish connection 
| 2023-04-04 21:27:23.475 | LogLevel.DEBUG | lightning::ln::peer_handler: Finished noise handshake for connection with 026e1de0e76902d71d2c27bfdda9d48c19c4c550f08bb4189d7208246e0e3af97e 
| 2023-04-04 21:27:23.970 | LogLevel.DEBUG | Waiting to establish connection 
| 2023-04-04 21:27:24.120 | LogLevel.INFO | lightning::ln::peer_handler: Received peer Init message from 026e1de0e76902d71d2c27bfdda9d48c19c4c550f08bb4189d7208246e0e3af97e: DataLossProtect: supported, InitialRoutingSync: not supported, UpfrontShutdownScript: supported, GossipQueries: supported, VariableLengthOnion: required, StaticRemoteKey: required, PaymentSecret: required, BasicMPP: supported, Wumbo: supported, ShutdownAnySegwit: supported, OnionMessages: not supported, ChannelType: supported, SCIDPrivacy: supported, ZeroConf: supported, unknown flags: none 
| 2023-04-04 21:27:24.122 | LogLevel.DEBUG | lightning::ln::channelmanager: Generating channel_reestablish events for 026e1de0e76902d71d2c27bfdda9d48c19c4c550f08bb4189d7208246e0e3af97e 
| 2023-04-04 21:27:24.123 | LogLevel.DEBUG | lightning::ln::peer_handler: Handling SendChannelReestablish event in peer_handler for node 026e1de0e76902d71d2c27bfdda9d48c19c4c550f08bb4189d7208246e0e3af97e for channel 942f51a5bcf0704f62fdea50d25036fe4a4744d578ce41ffd773ffd5e494c765 
| 2023-04-04 21:27:24.831 | LogLevel.DEBUG | lightning::ln::channel: Reconnected channel 942f51a5bcf0704f62fdea50d25036fe4a4744d578ce41ffd773ffd5e494c765 with only lost remote commitment tx 
| 2023-04-04 21:27:24.857 | LogLevel.DEBUG | lightning::ln::peer_handler: Handling UpdateHTLCs event in peer_handler for node 026e1de0e76902d71d2c27bfdda9d48c19c4c550f08bb4189d7208246e0e3af97e with 0 adds, 0 fulfills, 0 fails for channel 942f51a5bcf0704f62fdea50d25036fe4a4744d578ce41ffd773ffd5e494c765 
| 2023-04-04 21:27:24.941 | LogLevel.INFO | Connection established 
| 2023-04-04 21:27:24.944 | LogLevel.DEBUG | Keeping connection alive 
| 2023-04-04 21:27:25.427 | LogLevel.DEBUG | lightning::ln::channelmanager: Received channel_update for channel 942f51a5bcf0704f62fdea50d25036fe4a4744d578ce41ffd773ffd5e494c765. 
| 2023-04-04 21:27:25.434 | LogLevel.DEBUG | lightning::ln::peer_handler: Error handling message from 026e1de0e76902d71d2c27bfdda9d48c19c4c550f08bb4189d7208246e0e3af97e; ignoring: Couldn't find channel for update 
| 2023-04-04 21:27:26.743 | LogLevel.DEBUG | lightning::ln::peer_handler: Got Err message from 026e1de0e76902d71d2c27bfdda9d48c19c4c550f08bb4189d7208246e0e3af97e: Invalid commitment tx signature from peer 
| 2023-04-04 21:27:26.749 | LogLevel.ERROR | lightning::ln::channelmanager: Force-closing channel 942f51a5bcf0704f62fdea50d25036fe4a4744d578ce41ffd773ffd5e494c765 
| 2023-04-04 21:27:26.752 | LogLevel.DEBUG | lightning::ln::channelmanager: Finishing force-closure of channel with 0 HTLCs to fail 
| 2023-04-04 21:27:26.756 | LogLevel.INFO | lightning::chain::channelmonitor: Applying update to monitor 942f51a5bcf0704f62fdea50d25036fe4a4744d578ce41ffd773ffd5e494c765, bringing update_id from 6 to 7 with 1 changes. 
| 2023-04-04 21:27:26.761 | LogLevel.DEBUG | lightning::chain::channelmonitor: Getting signed latest holder commitment transaction! 
| 2023-04-04 21:27:26.771 | LogLevel.INFO | lightning::chain::channelmonitor: Broadcasting local commitment tx with txid 8fbc9b025e0fa338939cedcc7f45df5477116f534dd9faef60281bc336dd0d1f 
| 2023-04-04 21:27:27.312 | LogLevel.ERROR | Error broadcasting transaction: Electrum(Protocol(String("sendrawtransaction RPC error: {\"code\":-26,\"message\":\"insufficient fee, rejecting replacement 8fbc9b025e0fa338939cedcc7f45df5477116f534dd9faef60281bc336dd0d1f; new feerate 0.00001016 BTC/kvB <= old feerate 0.00001016 BTC/kvB\"}"))) 
| 2023-04-04 21:27:27.318 | LogLevel.INFO | Received event 
| 2023-04-04 21:27:27.322 | LogLevel.INFO | 
Channel closed 

[luckysori]

I see two separate issues in the logs provided:

1. The Invalid commitment tx signature from peer error that leads to the force-closure of the channel by the coordinator is already tracked in Closing channel due to close-required error: Invalid commitment tx signature from peer #352. We raised this issue with Tibo (the maintainer of rust-dlc) and he's looking into it although it might take time to resolve the problem.
2. The Failed to accept DLC channel offer: Invalid parameters were provided: Computed payout is greater than total collateral error on the app, that leads to the DLC channel remaining in the "offered" state. Seeing this error is surprising because we though this was fixed with fix: Compute payout is greater than total collateral #319.

As such, I'm gonna close this issue in favour of #352 and re-opening #289.