search

get10101 / 10101

10101 (Ten-Ten-One): Self-custodial derivative trading at your fingertips.
https://10101.finance
MIT License
127 stars 23 forks source link

Force Closing channel due to close-required error: Invalid commitment tx signature from peer #874

Closed holzeis closed 1 year ago

holzeis commented 1 year ago

Reproduced here https://github.com/get10101/10101/blob/test/force-close-with-reversed-order-in-dlc-setup-with-reconnects/crates/ln-dlc-node/src/tests/dlc/dlc_setup_with_reconnects.rs

Upon reconnecting during opening a position here

https://github.com/get10101/10101/blob/test/force-close-with-reversed-order-in-dlc-setup-with-reconnects/crates/ln-dlc-node/src/tests/dlc/dlc_setup_with_reconnects.rs#L103

or during closing a position here

https://github.com/get10101/10101/blob/test/force-close-with-reversed-order-in-dlc-setup-with-reconnects/crates/ln-dlc-node/src/tests/dlc/dlc_setup_with_reconnects.rs#L182

the channel gets force closed with the following error:

Closing channel 006d235e495a7e034bde6449c04aa55628afb931b2cc6a431958081709326248 due to close-required error: Invalid commitment tx signature from peer
holzeis commented 1 year ago

@luckysori can you check on your machine if this is still not reproducible for you?

luckysori commented 1 year ago

@luckysori can you check on your machine if this is still not reproducible for you?

I've tried to reproduce this by reverting back to https://github.com/p2pderivatives/rust-dlc/commit/d4b69cb, but I've not been able to. Let's close this for now and reopen it if we ever run into it again.

holzeis commented 1 year ago

Still happens to me on my m1 mac. Re-opening.

@bonomat can you give it a try on your m1?

bonomat commented 1 year ago

Unfortunately I can't run tests so I can't reproduce it :/

holzeis commented 1 year ago

Pushed a new version of the test with only reproducing that particular bug. Note, during testing I noticed that this bug is also flaky on my machine. About 95% it fails, but sometimes it succeeds without any changes.

holzeis commented 1 year ago

This bug just happened on the testvm.

My position was expired and got automatically closed. I didn't notice and closed the app at processing the Event:SubChannelCloseOffer. After starting the app again the channel got force-closed wth the following error:

Closing channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f due to close-required error: Invalid commitment tx signature from peer

app logs

| 2023-07-30 07:14:03.448 | LogLevel.TRACE | lightning_background_processor: Calling PeerManager's timer_tick_occurred  
| 2023-07-30 07:14:03.463 | LogLevel.INFO | Processing message from: 03507b924dae6595cfb78492489978127c5f1e3877848564de2015cd6d41375802,kind: SubChannelCloseOffer 
| 2023-07-30 07:14:03.474 | LogLevel.INFO | Accepting DLC channel collaborative settlement channel_id: de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f 
| 2023-07-30 07:14:03.477 | LogLevel.TRACE | lightning::ln::channel: Updating HTLC state for a newly-sent commitment_signed...  
| 2023-07-30 07:14:03.478 | LogLevel.TRACE | lightning::ln::channel: Building commitment transaction number 281474976710618 (really 37 xor 272151522750067) for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f for remote, generated by us with fee 253...  
| 2023-07-30 07:14:03.479 | LogLevel.TRACE | lightning::ln::channel:    ...including to_remote output with value 98070  
| 2023-07-30 07:14:03.480 | LogLevel.TRACE | lightning::ln::channel:    ...including to_local output with value 91747  
| 2023-07-30 07:14:03.480 | LogLevel.TRACE | lightning::chain::chainmonitor: Updating ChannelMonitor for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f  
| 2023-07-30 07:14:03.481 | LogLevel.INFO | lightning::chain::channelmonitor: Applying update to monitor de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f, bringing update_id from 95 to 96 with 1 changes.  
| 2023-07-30 07:14:03.481 | LogLevel.TRACE | lightning::chain::channelmonitor: Updating ChannelMonitor with latest counterparty commitment transaction info  
| 2023-07-30 07:14:03.482 | LogLevel.TRACE | lightning::chain::channelmonitor: Tracking new counterparty commitment transaction with txid 0fc441a898126973f433c2016efd635a9522b3cccf95801de551ad1513fa25b4 at commitment number 281474976710618 with 0 HTLC outputs  
| 2023-07-30 07:14:03.485 | LogLevel.DEBUG | lightning::chain::chainmonitor: Persistence of ChannelMonitorUpdate for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f completed  
| 2023-07-30 07:14:03.485 | LogLevel.TRACE | lightning::ln::channel: Creating an announcement_signatures message for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f  
| 2023-07-30 07:14:03.486 | LogLevel.TRACE | lightning::ln::channel: Ignore : Channel is not available for public announcements  
| 2023-07-30 07:14:03.486 | LogLevel.TRACE | lightning::ln::channel: Regenerated latest commitment update in channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f with 0 update_adds, 0 update_fulfills, 0 update_fails, and 0 update_fail_malformeds  
| 2023-07-30 07:14:03.487 | LogLevel.TRACE | lightning::ln::channel: Building commitment transaction number 281474976710618 (really 37 xor 272151522750067) for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f for remote, generated by us with fee 253...  
| 2023-07-30 07:14:03.487 | LogLevel.TRACE | lightning::ln::channel:    ...including to_remote output with value 98070  
| 2023-07-30 07:14:03.488 | LogLevel.TRACE | lightning::ln::channel:    ...including to_local output with value 91747  
| 2023-07-30 07:14:03.488 | LogLevel.TRACE | lightning::ln::channel: Signed remote commitment tx 0200000001de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f00000000003685f780026366010000000000160014fab788e4c1921ace81ad85b16b47527d8857fb92167f0100000000002200205b20f1e7b435ac8dfb7a37d655c5286670c1f062df05d54b0554cd376f17916556aed620 (txid 0fc441a898126973f433c2016efd635a9522b3cccf95801de551ad1513fa25b4) with redeemscript 4752210360bc88fbeeaf34e8a0d225aa23bd54317a9ab7db4833da4501cc9ceffa11dd362103d76d2ca47215e5fa1e36757a911719c5651b0e5c9cfc752b4e976594f8b4843c52ae with value 190000 -> 4f8db3e61399f3be4140cf344a94f9b28c6c443dfe0c1430e2abe970d35ed47203346b9940012f8a51fa8a8e41491bda1566e26477558641e20a23f735561e06 in channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f  
| 2023-07-30 07:14:03.489 | LogLevel.DEBUG | lightning::ln::channel: Restored monitor updating in channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f resulting in a commitment update and no RAA, with RAA first  
| 2023-07-30 07:14:03.489 | LogLevel.TRACE | lightning_background_processor: Persisting ChannelManager...  
| 2023-07-30 07:14:03.493 | LogLevel.TRACE | lightning_background_processor: Done persisting ChannelManager.  
| 2023-07-30 07:14:04.345 | LogLevel.DEBUG | Publishing event ServiceHealthUpdate(ServiceUpdate { service: Coordinator, status: Online })  
| 2023-07-30 07:14:04.347 | LogLevel.DEBUG | Forwarding event to flutter event: ServiceHealthUpdate(ServiceUpdate { service: Coordinator, status: Online }) 
| 2023-07-30 07:14:04.348 | LogLevel.DEBUG | Received event: Event.serviceHealthUpdate(field0: Instance of 'ServiceUpdate') 
| 2023-07-30 07:14:07.633 | LogLevel.INFO | lightning_transaction_sync::esplora: Starting transaction sync.  
| 2023-07-30 07:14:09.897 | LogLevel.INFO | Initialized logger  
| 2023-07-30 07:14:09.898 | LogLevel.INFO | App data will be stored in: /var/mobile/Containers/Data/Application/D0AB85E9-2D8F-47DF-9BDC-8312C48C4EFF/Documents 
| 2023-07-30 07:14:09.898 | LogLevel.INFO | Seed data will be stored in: /var/mobile/Containers/Data/Application/D0AB85E9-2D8F-47DF-9BDC-8312C48C4EFF/Library/Application Support 
| 2023-07-30 07:14:09.899 | LogLevel.DEBUG | Parsing config from flutter config: Config { coordinator_pubkey: "03507b924dae6595cfb78492489978127c5f1e3877848564de2015cd6d41375802", esplora_endpoint: "http://35.189.57.114:3000", host: "35.189.57.114", p2p_port: 9045, http_port: 80, network: "regtest", oracle_endpoint: "http://127.0.0.1:8081", oracle_pubkey: "16f88cf7d21e6c0f46bcbc983a4e3b19726c6c98858cc31c83551a88fde171c0", health_check_interval_secs: 10 } 
| 2023-07-30 07:14:09.906 | LogLevel.DEBUG | Database migration run - db initialized  
| 2023-07-30 07:14:09.906 | LogLevel.DEBUG | Publishing event Init("Starting full ldk node")  
| 2023-07-30 07:14:09.906 | LogLevel.DEBUG | Forwarding event to flutter event: Init("Starting full ldk node") 
| 2023-07-30 07:14:09.930 | LogLevel.INFO | Creating the wallet network: Regtest 
| 2023-07-30 07:14:11.146 | LogLevel.INFO | Found channel manager data on disk. Recovering from stored state  
| 2023-07-30 07:14:11.149 | LogLevel.INFO | lightning::ln::channelmanager: Successfully loaded channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f  
| 2023-07-30 07:14:11.150 | LogLevel.TRACE | lightning::chain::chainmonitor: Got new ChannelMonitor for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f  
| 2023-07-30 07:14:11.161 | LogLevel.INFO | lightning::chain::chainmonitor: Persistence of new ChannelMonitor for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f completed  
| 2023-07-30 07:14:11.162 | LogLevel.INFO | Started on-chain sync  
| 2023-07-30 07:14:11.162 | LogLevel.DEBUG | Getting all non-pending channels  
| 2023-07-30 07:14:11.162 | LogLevel.INFO | lightning_transaction_sync::esplora: Starting transaction sync.  
| 2023-07-30 07:14:11.163 | LogLevel.DEBUG | Got all non-pending channels channels: [Channel { user_channel_id: UserChannelId(594bc62c-93d8-401e-9105-3402e0aff5f4), channel_id: Some([222, 8, 212, 96, 138, 190, 163, 237, 188, 91, 139, 86, 223, 39, 198, 133, 210, 156, 218, 186, 4, 70, 190, 45, 203, 99, 247, 105, 64, 179, 124, 47]), inbound: 25964000, outbound: 71595000, funding_txid: Some(2f7cb34069f763cb2dbe4604bada9cd285c627df568b5bbceda3be8a60d408de), channel_state: Open, counterparty: PublicKey(025837416dcd1520de64858477381e5f7c127899489284b7cf9565ae4d927b503380c813bff475d8fff4ba07f2502e5c14db46571898340e2a37d6f2bb1f4d1a), created_at: 2023-07-26 4:57:57.0 +00:00:00, updated_at: 2023-07-30 5:12:46.0 +00:00:00 }] 
| 2023-07-30 07:14:11.163 | LogLevel.DEBUG | Syncing 1 shadow channels  
| 2023-07-30 07:14:11.163 | LogLevel.DEBUG | Inserting channel channel: Channel { user_channel_id: UserChannelId(594bc62c-93d8-401e-9105-3402e0aff5f4), channel_id: Some([222, 8, 212, 96, 138, 190, 163, 237, 188, 91, 139, 86, 223, 39, 198, 133, 210, 156, 218, 186, 4, 70, 190, 45, 203, 99, 247, 105, 64, 179, 124, 47]), inbound: 96353000, outbound: 89847000, funding_txid: Some(2f7cb34069f763cb2dbe4604bada9cd285c627df568b5bbceda3be8a60d408de), channel_state: Open, counterparty: PublicKey(025837416dcd1520de64858477381e5f7c127899489284b7cf9565ae4d927b503380c813bff475d8fff4ba07f2502e5c14db46571898340e2a37d6f2bb1f4d1a), created_at: 2023-07-26 4:57:57.0 +00:00:00, updated_at: 2023-07-30 5:14:11.162395 +00:00:00 } 
| 2023-07-30 07:14:11.164 | LogLevel.DEBUG | Got all transactions transactions: [] 
| 2023-07-30 07:14:11.164 | LogLevel.DEBUG | Syncing 0 shadow transactions  
| 2023-07-30 07:14:13.085 | LogLevel.INFO | Listening on 0.0.0.0:53904  
| 2023-07-30 07:14:13.086 | LogLevel.INFO | Starting background processor  
| 2023-07-30 07:14:13.087 | LogLevel.TRACE | lightning_background_processor: Calling ChannelManager's timer_tick_occurred on startup  
| 2023-07-30 07:14:13.088 | LogLevel.INFO | Lightning node started with node ID 03fa5268ee1d544f82df15d47cfe615b43b987d891eaba42def17ad0e85d1a69e1@0.0.0.0:53904  
| 2023-07-30 07:14:13.089 | LogLevel.DEBUG | Broadcasting node announcement inc_connection_addresses: [IPv4 { addr: [0, 0, 0, 0], port: 53904 }] 
| 2023-07-30 07:14:13.090 | LogLevel.DEBUG | lightning::ln::peer_handler: Broadcasting NodeAnnouncement after passing it to our own RoutingMessageHandler.  
| 2023-07-30 07:14:13.091 | LogLevel.DEBUG | Setting up connection peer: 03507b924dae6595cfb78492489978127c5f1e3877848564de2015cd6d41375802@35.189.57.114:9045 
| 2023-07-30 07:14:13.091 | LogLevel.DEBUG | Publishing event Init("10101 is ready.")  
| 2023-07-30 07:14:13.092 | LogLevel.DEBUG | Forwarding event to flutter event: Init("10101 is ready.") 
| 2023-07-30 07:14:13.093 | LogLevel.DEBUG | Parsing config from flutter config: Config { coordinator_pubkey: "03507b924dae6595cfb78492489978127c5f1e3877848564de2015cd6d41375802", esplora_endpoint: "http://35.189.57.114:3000", host: "35.189.57.114", p2p_port: 9045, http_port: 80, network: "regtest", oracle_endpoint: "http://127.0.0.1:8081", oracle_pubkey: "16f88cf7d21e6c0f46bcbc983a4e3b19726c6c98858cc31c83551a88fde171c0", health_check_interval_secs: 10 } 
| 2023-07-30 07:14:13.093 | LogLevel.DEBUG | Broadcasting node announcement inc_connection_addresses: [IPv4 { addr: [0, 0, 0, 0], port: 53904 }] 
| 2023-07-30 07:14:13.093 | LogLevel.INFO | Backend started 
| 2023-07-30 07:14:13.094 | LogLevel.DEBUG | lightning::ln::peer_handler: Broadcasting NodeAnnouncement after passing it to our own RoutingMessageHandler.  
| 2023-07-30 07:14:13.095 | LogLevel.DEBUG | Pruning expired orders  
| 2023-07-30 07:14:13.095 | LogLevel.DEBUG | Got all spendable outputs outputs: [] 
| 2023-07-30 07:14:13.096 | LogLevel.DEBUG | Connecting to orderbook API  
| 2023-07-30 07:14:13.096 | LogLevel.DEBUG | Publishing event ServiceHealthUpdate(ServiceUpdate { service: Orderbook, status: Online })  
| 2023-07-30 07:14:13.097 | LogLevel.DEBUG | Forwarding event to flutter event: ServiceHealthUpdate(ServiceUpdate { service: Orderbook, status: Online }) 
| 2023-07-30 07:14:13.097 | LogLevel.DEBUG | Received event: Event.serviceHealthUpdate(field0: Instance of 'ServiceUpdate') 
| 2023-07-30 07:14:13.400 | LogLevel.INFO | Built on commit: 75b4d72042da6d2c23304a3ee0a1acbaab2cccbb 
| 2023-07-30 07:14:13.401 | LogLevel.INFO | Built on branch: main 
| 2023-07-30 07:14:13.401 | LogLevel.DEBUG | Connection setup completed peer: 03507b924dae6595cfb78492489978127c5f1e3877848564de2015cd6d41375802@35.189.57.114:9045 
| 2023-07-30 07:14:13.401 | LogLevel.DEBUG | Waiting to confirm established connection peer: 03507b924dae6595cfb78492489978127c5f1e3877848564de2015cd6d41375802@35.189.57.114:9045 
| 2023-07-30 07:14:13.405 | LogLevel.INFO | Build number: 1726 
| 2023-07-30 07:14:13.405 | LogLevel.INFO | Build version: 1.1.0 
| 2023-07-30 07:14:13.405 | LogLevel.INFO | Network: regtest 
| 2023-07-30 07:14:13.405 | LogLevel.INFO | Esplora endpoint: http://35.189.57.114:3000 
| 2023-07-30 07:14:13.405 | LogLevel.INFO | Coordinator: 03507b924dae6595cfb78492489978127c5f1e3877848564de2015cd6d41375802@35.189.57.114:9045 
| 2023-07-30 07:14:13.406 | LogLevel.INFO | Oracle endpoint: http://127.0.0.1:8081 
| 2023-07-30 07:14:13.406 | LogLevel.INFO | Oracle PK: 16f88cf7d21e6c0f46bcbc983a4e3b19726c6c98858cc31c83551a88fde171c0 
| 2023-07-30 07:14:13.406 | LogLevel.INFO | Node ID: 03fa5268ee1d544f82df15d47cfe615b43b987d891eaba42def17ad0e85d1a69e1 
| 2023-07-30 07:14:13.406 | LogLevel.DEBUG | Last login was at 2023-07-28 18:06:00 +00:00:00 
| 2023-07-30 07:14:13.792 | LogLevel.DEBUG | lightning::ln::peer_handler: Finished noise handshake for connection with 03507b924dae6595cfb78492489978127c5f1e3877848564de2015cd6d41375802  
| 2023-07-30 07:14:13.793 | LogLevel.DEBUG | Publishing event ServiceHealthUpdate(ServiceUpdate { service: Coordinator, status: Online })  
| 2023-07-30 07:14:13.794 | LogLevel.DEBUG | Forwarding event to flutter event: ServiceHealthUpdate(ServiceUpdate { service: Coordinator, status: Online }) 
| 2023-07-30 07:14:13.795 | LogLevel.DEBUG | Received event: Event.serviceHealthUpdate(field0: Instance of 'ServiceUpdate') 
| 2023-07-30 07:14:13.796 | LogLevel.INFO | Connected to orderbook realtime API  
| 2023-07-30 07:14:13.797 | LogLevel.DEBUG | New message from orderbook msg: {"AllOrders":[{"id":"2fa58622-a63d-48d7-b7fc-bdf0a0ff6a5d","price":29313.0,"trader_id":"03f75f318471d32d39be3c86c622e2c51bd5731bf95f98aaa3ed5d6e1c0025927f","taken":false,"direction":"Long","quantity":1000.0,"order_type":"Limit","timestamp":"2023-07-30T05:13:15.266566Z","expiry":"2023-07-30T05:14:15.265798Z"},{"id":"d3f8bcd0-dd12-401b-90aa-3b0295cd0159","price":29358.0,"trader_id":"03f75f318471d32d39be3c86c622e2c51bd5731bf95f98aaa3ed5d6e1c0025927f","taken":false,"direction":"Short","quantity":1000.0,"order_type":"Limit","timestamp":"2023-07-30T05:13:15.268641Z","expiry":"2023-07-30T05:14:15.267978Z"},{"id":"78253c63-de34-4921-9ec5-40bb8b02f2dc","price":29313.0,"trader_id":"03f75f318471d32d39be3c86c622e2c51bd5731bf95f98aaa3ed5d6e1c0025927f","taken":false,"direction":"Long","quantity":1000.0,"order_type":"Limit","timestamp":"2023-07-30T05:13:15.270614Z","expiry":"2023-07-30T05:14:15.270017Z"},{"id":"6d58a661-11e7-43be-99b7-c70ba87f4513","price":29358.0,"trader_id":"03f75f318471d32d39be3c86c622e2c51bd5731bf95f98aaa3ed5d6e1c0025927f","taken":false,"direction":"Short","quantity":1000.0,"order_type":"Limit","timestamp":"2023-07-30T05:13:15.272644Z","expiry":"2023-07-30T05:14:15.272002Z"},{"id":"6df6e03b-3cbb-4cab-a8c9-053e452e89c2","price":29313.0,"trader_id":"03f75f318471d32d39be3c86c622e2c51bd5731bf95f98aaa3ed5d6e1c0025927f","taken":false,"direction":"Long","quantity":1000.0,"order_type":"Limit","timestamp":"2023-07-30T05:13:15.274417Z","expiry":"2023-07-30T05:14:15.273889Z"},{"id":"45926aed-fcef-4882-9edd-b1bb03770c80","price":29358.0,"trader_id":"03f75f318471d32d39be3c86c622e2c51bd5731bf95f98aaa3ed5d6e1c0025927f","taken":false,"direction":"Short","quantity":1000.0,"order_type":"Limit","timestamp":"2023-07-30T05:13:15.276519Z","expiry":"2023-07-30T05:14:15.275968Z"},{"id":"e81ddd74-1660-4501-9371-d7ae6a28d492","price":29313.0,"trader_id":"03f75f318471d32d39be3c86c622e2c51bd5731bf95f98aaa3ed5d6e1c0025927f","taken":false,"direction":"Long","quantity":1000.0,"order_type":"Limit","timestamp":"2023-07-30T05:13:15.278753Z","expiry":"2023-07-30T05:14:15.278109Z"},{"id":"25d3189f-45b9-4a88-a1d5-bfeab9333945","price":29358.0,"trader_id":"03f75f318471d32d39be3c86c622e2c51bd5731bf95f98aaa3ed5d6e1c0025927f","taken":false,"direction":"Short","quantity":1000.0,"order_type":"Limit","timestamp":"2023-07-30T05:13:15.281134Z","expiry":"2023-07-30T05:14:15.280306Z"},{"id":"880a2943-1fb0-4879-8afd-8e8b16633d0f","price":29313.0,"trader_id":"03f75f318471d32d39be3c86c622e2c51bd5731bf95f98aaa3ed5d6e1c0025927f","taken":false,"direction":"Long","quantity":1000.0,"order_type":"Limit","timestamp":"2023-07-30T05:13:15.283569Z","expiry":"2023-07-30T05:14:15.282818Z"},{"id":"5b0af415-9657-49a1-908c-9ab77225e7fd","price":29358.0,"trader_id":"03f75f318471d32d39be3c86c622e2c51bd5731bf95f98aaa3ed5d6e1c0025927f","taken":false,"direction":"Short","quantity":1000.0,"order_type":"Limit","timestamp":"2023-07-30T05:13:15.28595Z","expiry":"2023-07-30T05:14:15.28528Z"}]} 
| 2023-07-30 07:14:13.798 | LogLevel.DEBUG | Received all orders from orderbook orders: [] 
| 2023-07-30 07:14:13.798 | LogLevel.DEBUG | Updating prices prices: {BtcUsd: Price { bid: Some(29313), ask: Some(29358) }} 
| 2023-07-30 07:14:13.799 | LogLevel.DEBUG | Publishing event PriceUpdateNotification({BtcUsd: Price { bid: Some(29313), ask: Some(29358) }})  
| 2023-07-30 07:14:13.800 | LogLevel.DEBUG | Forwarding event to flutter event: PriceUpdateNotification({BtcUsd: Price { bid: Some(29313), ask: Some(29358) }}) 
| 2023-07-30 07:14:14.193 | LogLevel.INFO | lightning::ln::peer_handler: Received peer Init message from 03507b924dae6595cfb78492489978127c5f1e3877848564de2015cd6d41375802: DataLossProtect: supported, InitialRoutingSync: not supported, UpfrontShutdownScript: supported, GossipQueries: supported, VariableLengthOnion: required, StaticRemoteKey: required, PaymentSecret: required, BasicMPP: supported, Wumbo: supported, AnchorsZeroFeeHtlcTx: not supported, ShutdownAnySegwit: supported, OnionMessages: not supported, ChannelType: supported, SCIDPrivacy: supported, ZeroConf: supported, unknown flags: none  
| 2023-07-30 07:14:14.194 | LogLevel.DEBUG | lightning::ln::channelmanager: Generating channel_reestablish events for 03507b924dae6595cfb78492489978127c5f1e3877848564de2015cd6d41375802  
| 2023-07-30 07:14:14.195 | LogLevel.TRACE | lightning::ln::channel: Enough info to generate a Data Loss Protect with per_commitment_secret fc4059cb2a324bbade34d9c9bd6c1a4fe0ecd258475988be8024573083ad99e4 for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f  
| 2023-07-30 07:14:14.196 | LogLevel.TRACE | lightning_background_processor: Persisting ChannelManager...  
| 2023-07-30 07:14:14.197 | LogLevel.DEBUG | New message from orderbook msg: "Authenticated" 
| 2023-07-30 07:14:14.197 | LogLevel.DEBUG | Skipping message from orderbook msg: Authenticated 
| 2023-07-30 07:14:14.199 | LogLevel.DEBUG | lightning::ln::peer_handler: Handling SendChannelReestablish event in peer_handler for node 03507b924dae6595cfb78492489978127c5f1e3877848564de2015cd6d41375802 for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f  
| 2023-07-30 07:14:14.205 | LogLevel.TRACE | lightning_background_processor: Done persisting ChannelManager.  
| 2023-07-30 07:14:14.392 | LogLevel.INFO | Connection established peer: 03507b924dae6595cfb78492489978127c5f1e3877848564de2015cd6d41375802@35.189.57.114:9045 
| 2023-07-30 07:14:15.018 | LogLevel.TRACE | lightning::ln::channel: Creating an announcement_signatures message for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f  
| 2023-07-30 07:14:15.019 | LogLevel.TRACE | lightning::ln::channel: Ignore : Channel is not available for public announcements  
| 2023-07-30 07:14:15.020 | LogLevel.DEBUG | lightning::ln::channel: Reconnected channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f with no loss  
| 2023-07-30 07:14:15.021 | LogLevel.TRACE | lightning::ln::channelmanager: Attempting to generate channel update for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f  
| 2023-07-30 07:14:15.022 | LogLevel.TRACE | lightning::ln::channelmanager: Generating channel update for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f  
| 2023-07-30 07:14:15.022 | LogLevel.TRACE | lightning::ln::channelmanager: Handling channel resumption for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f with no RAA, no commitment update, 0 pending forwards, not broadcasting funding, without channel ready, without announcement  
| 2023-07-30 07:14:15.023 | LogLevel.TRACE | lightning_background_processor: Persisting ChannelManager...  
| 2023-07-30 07:14:15.024 | LogLevel.TRACE | lightning::ln::channel: Updating HTLC state for a newly-sent commitment_signed...  
| 2023-07-30 07:14:15.025 | LogLevel.TRACE | lightning::ln::channel: Building commitment transaction number 281474976710618 (really 37 xor 272151522750067) for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f for remote, generated by us with fee 253...  
| 2023-07-30 07:14:15.026 | LogLevel.TRACE | lightning::ln::channel:    ...including to_remote output with value 98070  
| 2023-07-30 07:14:15.026 | LogLevel.TRACE | lightning::ln::channel:    ...including to_local output with value 91747  
| 2023-07-30 07:14:15.026 | LogLevel.TRACE | lightning::chain::chainmonitor: Updating ChannelMonitor for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f  
| 2023-07-30 07:14:15.027 | LogLevel.INFO | lightning::chain::channelmonitor: Applying update to monitor de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f, bringing update_id from 96 to 97 with 1 changes.  
| 2023-07-30 07:14:15.027 | LogLevel.TRACE | lightning::chain::channelmonitor: Updating ChannelMonitor with latest counterparty commitment transaction info  
| 2023-07-30 07:14:15.028 | LogLevel.TRACE | lightning::chain::channelmonitor: Tracking new counterparty commitment transaction with txid 0fc441a898126973f433c2016efd635a9522b3cccf95801de551ad1513fa25b4 at commitment number 281474976710618 with 0 HTLC outputs  
| 2023-07-30 07:14:15.031 | LogLevel.TRACE | lightning_background_processor: Done persisting ChannelManager.  
| 2023-07-30 07:14:15.032 | LogLevel.DEBUG | lightning::chain::chainmonitor: Persistence of ChannelMonitorUpdate for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f completed  
| 2023-07-30 07:14:15.032 | LogLevel.TRACE | lightning::ln::channel: Creating an announcement_signatures message for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f  
| 2023-07-30 07:14:15.033 | LogLevel.TRACE | lightning::ln::channel: Ignore : Channel is not available for public announcements  
| 2023-07-30 07:14:15.033 | LogLevel.TRACE | lightning::ln::channel: Regenerated latest commitment update in channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f with 0 update_adds, 0 update_fulfills, 0 update_fails, and 0 update_fail_malformeds  
| 2023-07-30 07:14:15.034 | LogLevel.TRACE | lightning::ln::channel: Building commitment transaction number 281474976710618 (really 37 xor 272151522750067) for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f for remote, generated by us with fee 253...  
| 2023-07-30 07:14:15.034 | LogLevel.TRACE | lightning::ln::channel:    ...including to_remote output with value 98070  
| 2023-07-30 07:14:15.034 | LogLevel.TRACE | lightning::ln::channel:    ...including to_local output with value 91747  
| 2023-07-30 07:14:15.035 | LogLevel.TRACE | lightning::ln::channel: Signed remote commitment tx 0200000001de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f00000000003685f780026366010000000000160014fab788e4c1921ace81ad85b16b47527d8857fb92167f0100000000002200205b20f1e7b435ac8dfb7a37d655c5286670c1f062df05d54b0554cd376f17916556aed620 (txid 0fc441a898126973f433c2016efd635a9522b3cccf95801de551ad1513fa25b4) with redeemscript 4752210360bc88fbeeaf34e8a0d225aa23bd54317a9ab7db4833da4501cc9ceffa11dd362103d76d2ca47215e5fa1e36757a911719c5651b0e5c9cfc752b4e976594f8b4843c52ae with value 190000 -> 4f8db3e61399f3be4140cf344a94f9b28c6c443dfe0c1430e2abe970d35ed47203346b9940012f8a51fa8a8e41491bda1566e26477558641e20a23f735561e06 in channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f  
| 2023-07-30 07:14:15.035 | LogLevel.DEBUG | lightning::ln::channel: Restored monitor updating in channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f resulting in a commitment update and no RAA, with RAA first  
| 2023-07-30 07:14:15.036 | LogLevel.TRACE | lightning::ln::channel: Building commitment transaction number 281474976710619 (really 36 xor 272151522750067) for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f for us, generated by remote with fee 253...  
| 2023-07-30 07:14:15.036 | LogLevel.TRACE | lightning::ln::channel:    ...including to_local output with value 91747  
| 2023-07-30 07:14:15.037 | LogLevel.TRACE | lightning::ln::channel:    ...including to_remote output with value 98070  
| 2023-07-30 07:14:15.037 | LogLevel.TRACE | lightning::ln::channel: Checking commitment tx signature 5b5febc89948029ae09baf243baea1443e0b6bfc9f2d6dfd56dde2d0b19da0b6148dbd28cc0bbe940929dab9d98cdc6bb59b1cd9816d49430779254698002420 by key 03d76d2ca47215e5fa1e36757a911719c5651b0e5c9cfc752b4e976594f8b4843c against tx 0200000001de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f00000000003685f78002636601000000000022002000979af0049e96c24baa1f8587760a465452622d9c706513fe479e192d157418167f010000000000160014d8ff4571872efd004c851d1a4f5e8b2c4e90413a57aed620 (sighash ed60195cf8c1c6c52b50286be5fb1db83eb3151cb10f81c5144ec6644cbcd650) with redeemscript 4752210360bc88fbeeaf34e8a0d225aa23bd54317a9ab7db4833da4501cc9ceffa11dd362103d76d2ca47215e5fa1e36757a911719c5651b0e5c9cfc752b4e976594f8b4843c52ae in channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f  
| 2023-07-30 07:14:15.038 | LogLevel.ERROR | lightning::ln::channelmanager: Closing channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f due to close-required error: Invalid commitment tx signature from peer  
| 2023-07-30 07:14:15.038 | LogLevel.DEBUG | lightning::ln::channelmanager: Finishing force-closure of channel with 0 HTLCs to fail  
| 2023-07-30 07:14:15.039 | LogLevel.TRACE | lightning::chain::chainmonitor: Updating ChannelMonitor for channel de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f  
| 2023-07-30 07:14:15.039 | LogLevel.INFO | lightning::chain::channelmonitor: Applying update to monitor de08d4608abea3edbc5b8b56df27c685d29cdaba0446be2dcb63f76940b37c2f, bringing update_id from 97 to 98 with 1 changes.  
| 2023-07-30 07:14:15.039 | LogLevel.TRACE | lightning_background_processor: Persisting ChannelManager...  
| 2023-07-30 07:14:15.040 | LogLevel.TRACE | lightning::chain::channelmonitor: Updating ChannelMonitor: channel force closed, should broadcast: true  
| 2023-07-30 07:14:15.040 | LogLevel.DEBUG | lightning::chain::channelmonitor: Getting signed latest holder commitment transaction!  
| 2023-07-30 07:14:15.040 | LogLevel.INFO | lightning::chain::channelmonitor: Broadcasting local commitment tx with txid 72b4278fff3b6fa1398b794e4307693ecdd7ecc685747b7e94b3c36ac1923cac  
| 2023-07-30 07:14:15.041 | LogLevel.INFO | Broadcasting transaction raw_tx: 0200000000010186ed5436e30e6a021adceaabe791bfa477e24a022151c2a52ee6512bd957c3f000000000003685f78002216c000000000000160014d8ff4571872efd004c851d1a4f5e8b2c4e90413a171f010000000000220020eb31bbee2e4fe796f94166f2541b5b11ad14583440fcbad991b643c936846d74040047304402206eb7c0ac5bbaecd33c73acca164411d3d93310abf875c8c23fc6d144aa7d87de02206723395f2a65c8859fe49109af793467c8b949a0e7dac733f3d0f9c3e81fdc1e014730440220332fde6289db3e70a6434ffe4f3967b17b693818c47645d760f1b9830266f85f0220750da2adad6316b350d67cfdc4b20f4ba595f0ed62838726cf71dbaed669e06a014752210360bc88fbeeaf34e8a0d225aa23bd54317a9ab7db4833da4501cc9ceffa11dd362103d76d2ca47215e5fa1e36757a911719c5651b0e5c9cfc752b4e976594f8b4843c52ae50aed620,txid: 72b4278fff3b6fa1398b794e4307693ecdd7ecc685747b7e94b3c36ac1923cac 
| 2023-07-30 07:14:15.297 | LogLevel.DEBUG | New message from orderbook msg: {"DeleteOrder":"2fa58622-a63d-48d7-b7fc-bdf0a0ff6a5d"}

full logs

bonomat commented 1 year ago

@holzeis : I've taken over your branch and made some changes. The test runs now. I hope I did not change the logic but I think this ticket is no bug anymore and works with latest main.

holzeis commented 1 year ago

@holzeis : I've taken over your branch and made some changes. The test runs now. I hope I did not change the logic but I think this ticket is no bug anymore and works with latest main.

Nice, did you verify that the test fails on an older version. I am curious what commit exactly fixed it 🙂

bonomat commented 1 year ago

Nice, did you verify that the test fails on an older version. I am curious what commit exactly fixed it 🙂

yes, the test was failing on an older version. Check the diff, I left the fixup commit in the PR for you to see what I changed .