search

MutinyWallet / mutiny-node

SDK behind Mutiny Wallet
https://mutinywallet.com
MIT License
189 stars 35 forks source link

Force close with LSP #568

Closed benthecarman closed 1 year ago

benthecarman commented 1 year ago

Steps to reproduce:

  1. Initiate swap to lightning to LSP
  2. Immediately force close app after the success screen
  3. Wait 10 seconds
  4. Reopen app
  5. Channel should be force closed
benthecarman commented 1 year ago

Probably a CLN bug, just documenting here

TonyGiorgio commented 1 year ago

Got some logs: 

2023-06-05T22:30:24.208Z DEBUG   031f2669adab71548fad4432277a0d90233e3bc07ac29cfb0b3e01bd3fb26cb9fa-gossipd: Received channel_update for channel 770238x1321x3/0 now ACTIVE
2023-06-05T22:30:26.662Z DEBUG   020b1784f40ab854e9a5bdd2a57b8ffef4981f5422b7b66d7c78b9b7841a39ef41-gossipd: Received channel_update for channel 760223x2695x0/1 now DISABLED
2023-06-05T22:30:26.663Z DEBUG   020b1784f40ab854e9a5bdd2a57b8ffef4981f5422b7b66d7c78b9b7841a39ef41-gossipd: Received channel_update for channel 722673x1409x1/0 now ACTIVE
2023-06-05T22:30:28.591Z DEBUG   03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0-hsmd: Got WIRE_HSMD_ECDH_REQ
2023-06-05T22:30:28.591Z DEBUG   hsmd: Client: Received message 1 from client
2023-06-05T22:30:28.684Z DEBUG   0273f11a7b6ac79a606b586966b172304c4185009cb5b1f71ff7ae6be19145e711-connectd: Connect IN
2023-06-05T22:30:28.684Z DEBUG   0273f11a7b6ac79a606b586966b172304c4185009cb5b1f71ff7ae6be19145e711-connectd: peer_out WIRE_INIT
2023-06-05T22:30:28.751Z DEBUG   0273f11a7b6ac79a606b586966b172304c4185009cb5b1f71ff7ae6be19145e711-connectd: peer_in WIRE_INIT
2023-06-05T22:30:28.751Z DEBUG   0273f11a7b6ac79a606b586966b172304c4185009cb5b1f71ff7ae6be19145e711-lightningd: Peer says it sees our address as: 52.88.33.119:9735
2023-06-05T22:30:28.751Z DEBUG   0273f11a7b6ac79a606b586966b172304c4185009cb5b1f71ff7ae6be19145e711-connectd: Handed peer, entering loop
2023-06-05T22:30:28.758Z DEBUG   03c1f2781c735c0538745657447f546f50d401ae44cbd9d0fbbe6538337be14ba3-gossipd: Received channel_update for channel 791564x1747x7/0 now ACTIVE
2023-06-05T22:30:28.759Z DEBUG   03c1f2781c735c0538745657447f546f50d401ae44cbd9d0fbbe6538337be14ba3-gossipd: Spammy update for 731184x1893x0/1 flagged (last 1686001103, now 1686004099)
2023-06-05T22:30:28.759Z DEBUG   03c1f2781c735c0538745657447f546f50d401ae44cbd9d0fbbe6538337be14ba3-gossipd: Received channel_update for channel 731184x1893x0/1 now ACTIVE
2023-06-05T22:30:28.860Z DEBUG   0273f11a7b6ac79a606b586966b172304c4185009cb5b1f71ff7ae6be19145e711-connectd: Activating for message WIRE_CHANNEL_REESTABLISH
2023-06-05T22:30:28.861Z UNUSUAL 0273f11a7b6ac79a606b586966b172304c4185009cb5b1f71ff7ae6be19145e711-lightningd: Unknown channel bdff33c1175ccd5b8b4c041da57a4cdf9212e9ce8a679627bace9f9403a5f955 for WIRE_CHANNEL_REESTABLISH
2023-06-05T22:30:28.862Z DEBUG   0273f11a7b6ac79a606b586966b172304c4185009cb5b1f71ff7ae6be19145e711-lightningd: Telling connectd to send error 0011bdff33c1175ccd5b8b4c041da57a4cdf9212e9ce8a679627bace9f9403a5f955002c556e6b6e6f776e206368616e6e656c20666f7220574952455f4348414e4e454c5f524545535441424c495348
2023-06-05T22:30:28.862Z DEBUG   0273f11a7b6ac79a606b586966b172304c4185009cb5b1f71ff7ae6be19145e711-connectd: peer_out WIRE_ERROR
2023-06-05T22:30:28.862Z DEBUG   connectd: drain_peer
2023-06-05T22:30:28.862Z DEBUG   0273f11a7b6ac79a606b586966b172304c4185009cb5b1f71ff7ae6be19145e711-lightningd: peer_disconnect_done
2023-06-05T22:30:28.862Z DEBUG   0273f11a7b6ac79a606b586966b172304c4185009cb5b1f71ff7ae6be19145e711-lightningd: Not reconnecting: no active channel
2023-06-05T22:30:28.865Z DEBUG   plugin-funder: Cleaning up inflights for peer id 0273f11a7b6ac79a606b586966b172304c4185009cb5b1f71ff7ae6be19145e711
2023-06-05T22:30:28.929Z DEBUG   connectd: maybe_free_peer freeing peer!
2023-06-05T22:30:29.223Z DEBUG   031f2669adab71548fad4432277a0d90233e3bc07ac29cfb0b3e01bd3fb26cb9fa-gossipd: Bad gossip order: WIRE_CHANNEL_UPDATE before announcement 759095x599x1/1
2023-06-05T22:30:31.644Z DEBUG   020b1784f40ab854e9a5bdd2a57b8ffef4981f5422b7b66d7c78b9b7841a39ef41-gossipd: Received channel_update for channel 705751x541x0/1 now DISABLED
2023-06-05T22:30:31.644Z DEBUG   020b1784f40ab854e9a5bdd2a57b8ffef4981f5422b7b66d7c78b9b7841a39ef41-gossipd: Received channel_update for channel 787130x2278x1/1 now DISABLED
2023-06-05T22:30:33.760Z DEBUG   03c1f2781c735c0538745657447f546f50d401ae44cbd9d0fbbe6538337be14ba3-gossipd: Spammy update for 789862x3321x1/0 flagged (last 1685995083, now 1686004083)
2023-06-05T22:30:33.760Z DEBUG   03c1f2781c735c0538745657447f546f50d401ae44cbd9d0fbbe6538337be14ba3-gossipd: Received channel_update for channel 789862x3321x1/0 now ACTIVE
2023-06-05T22:30:33.760Z DEBUG   03c1f2781c735c0538745657447f546f50d401ae44cbd9d0fbbe6538337be14ba3-gossipd: Spammy update for 777146x544x1/1 flagged (last 1686001196, now 1686004167)
2023-06-05T22:30:33.760Z DEBUG   03c1f2781c735c0538745657447f546f50d401ae44cbd9d0fbbe6538337be14ba3-gossipd: Received channel_update for channel 777146x544x1/1 now ACTIVE
2023-06-05T22:30:33.761Z DEBUG   03c1f2781c735c0538745657447f546f50d401ae44cbd9d0fbbe6538337be14ba3-gossipd: Received channel_update for channel 753706x746x1/0 now DISABLED
2023-06-05T22:30:34.263Z DEBUG   031f2669adab71548fad4432277a0d90233e3bc07ac29cfb0b3e01bd3fb26cb9fa-gossipd: Spammy update for 789567x3714x1/1 flagged (last 1686000597, now 1686004101)
2023-06-05T22:30:34.263Z DEBUG   031f2669adab71548fad4432277a0d90233e3bc07ac29cfb0b3e01bd3fb26cb9fa-gossipd: Received channel_update for channel 789567x3714x1/1 now ACTIVE
2023-06-05T22:30:34.574Z DEBUG   03aefa43fbb4009b21a4129d05953974b7dbabbbfb511921410080860fca8ee1f0-hsmd: Got WIRE_HSMD_ECDH_REQ
2023-06-05T22:30:34.574Z DEBUG   hsmd: Client: Received message 1 from client

From the sounds of it yesterday, it's just due to the app closing before the channel_pending message came through? And the protocol for that really is a force closure? I did a channel open and it was pretty instant that it returned. Should we wait longer for the channel_update message to come across?

TonyGiorgio commented 1 year ago

The temp solution to this was to make the channel open flow wait one second before returning but a longer term fix is going to be by being reactive to the EventManager.

https://github.com/MutinyWallet/mutiny-node/issues/594