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.

Sign up for GitHub

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

Jump to bottom

Dropped UpdateAddHtlc #198

Closed
robbiehanson opened this issue Feb 9, 2021 · 5 comments
Closed

Dropped UpdateAddHtlc #198

robbiehanson opened this issue Feb 9, 2021 · 5 comments

Comments

@robbiehanson
Copy link
Contributor

robbiehanson commented Feb 9, 2021 •
edited
Loading

The client seems to have dropped an UpdateAddHtlc.

I was testing on an iOS device (iPhone 7):

  • i put the device screen to sleep
  • this causes the app to enter background mode and disconnect from the server (a push notification can wake up the app)
  • then I sent a payment from Android to iOS

The attached logs are taken from the client while it is in background mode. The logs indicates that the client:

  • receives the push notification (which wakes up the device)
  • re-connects to the server
  • receives UpdateAddHtlc (@ 2021-02-09 13:33:55.880222-0500)
  • client then proceeds to drop it on the floor ?

Other notes:

  • At 2021-02-09 13:34:14.521190-0500, the server disconnects the TCP socket. (I was debugging connection issues, and changed the log to read "Fish monger" when the TCP socket receives closure packet. As opposed to a client-initiated closure.)
  • iOS gives the client up to 30 seconds to process the push notification. So at 2021-02-09 13:34:21.826146-0500, our 29 second timer fires, and the client kills the background processing (and sockets).
  • After the client has dropped the UpdateAddHtlc, it continues to get disconnected from the server in a loop. As in, client connects, ~15 seconds later the server kills the TCP connection. Client then re-connects, and the loop starts again. (This is excluded from the logs below. But would commence once the user starts using the app again.)
Client logs

2021-02-09 13:33:52.805180-0500 Phoenix[51564:3822617] [PhoenixBusiness] decrementDisconnectCount()
2021-02-09 13:33:52.805289-0500 Phoenix[51564:3822617] [AppConnectionsDaemon] decrementDisconnectCount()
2021-02-09 13:33:52.806230-0500 Phoenix[51564:3822617] [AppConnectionsDaemon] peerControlFlow = TrafficControl(networkIsAvailable=true, disconnectCount=0)
2021-02-09 13:33:52.806664-0500 Phoenix[51564:3822617] [AppConnectionsDaemon] electrumControlFlow = TrafficControl(networkIsAvailable=true, disconnectCount=0)
2021-02-09 13:33:52.807105-0500 Phoenix[51564:3822617] [AppConnectionsDaemon] httpApiControlFlow = TrafficControl(networkIsAvailable=true, disconnectCount=0)
2021-02-09 13:33:52.809109-0500 Phoenix[51564:3822617] [AppConnectionsDaemon] Wait for 500ms before retrying connection on Peer
2021-02-09 13:33:52.809607-0500 Phoenix[51564:3822617] [AppConnectionsDaemon] Wait for 500ms before retrying connection on Electrum
2021-02-09 13:33:53.314771-0500 Phoenix[51564:3822617] [Peer] Peer.connect()
2021-02-09 13:33:53.316108-0500 Phoenix[51564:3822617] [Peer] {2} n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 connecting to 13.248.222.197
2021-02-09 13:33:53.319957-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 connection state changed: ESTABLISHING
2021-02-09 13:33:53.323847-0500 Phoenix[51564:3822617] [ElectrumClient] connection state changed: ESTABLISHING
2021-02-09 13:33:53.327564-0500 Phoenix[51564:3822617] [ElectrumClient] attempting connection to electrumx instance [host=testnet1.electrum.acinq.co, port=51001, tls=null]
2021-02-09 13:33:53.550930-0500 Phoenix[51564:3822617] [ElectrumClient] connected to electrumx instance
2021-02-09 13:33:53.590441-0500 Phoenix[51564:3822617] [CurrencyManager] Saving price rates: [BitcoinPriceRate(fiatCurrency=AUD, price=61296.06), BitcoinPriceRate(fiatCurrency=BRL, price=254592.7), BitcoinPriceRate(fiatCurrency=CAD, price=60181.2), BitcoinPriceRate(fiatCurrency=CHF, price=42285.44), BitcoinPriceRate(fiatCurrency=CLP, price=3.472750894E7), BitcoinPriceRate(fiatCurrency=CNY, price=304803.61), BitcoinPriceRate(fiatCurrency=DKK, price=290984.32), BitcoinPriceRate(fiatCurrency=EUR, price=39191.57), BitcoinPriceRate(fiatCurrency=GBP, price=34335.11), BitcoinPriceRate(fiatCurrency=HKD, price=367148.8), BitcoinPriceRate(fiatCurrency=INR, price=3451080.55), BitcoinPriceRate(fiatCurrency=ISK, price=6045581.91), BitcoinPriceRate(fiatCurrency=JPY, price=4947760.52), BitcoinPriceRate(fiatCurrency=KRW, price=5.263643338E7), BitcoinPriceRate(fiatCurrency=MXN, price=953008.0), BitcoinPriceRate(fiatCurrency=NZD, price=65491.5), BitcoinPriceRate(fiatCurrency=PLN, price=175095.9), BitcoinPriceRate(fiatCurrency=RUB, price=3506037.28), BitcoinPriceRate(fiatCurrency=SEK, price=394864.6), BitcoinPriceRate(fiatCurrency=SGD, price=62855.77), BitcoinPriceRate(fiatCurrency=THB, price=1416682.13), BitcoinPriceRate(fiatCurrency=TWD, price=1325845.75), BitcoinPriceRate(fiatCurrency=USD, price=47364.32)]
2021-02-09 13:33:53.631587-0500 Phoenix[51564:3822617] [Peer] {2} n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 sending init Init(features=080000002aa201, tlvs=TlvStream(records=[], unknown=[]))
2021-02-09 13:33:53.636775-0500 Phoenix[51564:3822617] [LightningSession] read: cipherlen
2021-02-09 13:33:53.785350-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:33:53.786491-0500 Phoenix[51564:3822617] [LightningSession] read: (length = 43) + 16
2021-02-09 13:33:53.788167-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:33:53.789380-0500 Phoenix[51564:3822617] [LightningSession] decrypted: size = 43
2021-02-09 13:33:53.792249-0500 Phoenix[51564:3822617] [LightningSession] read: cipherlen
2021-02-09 13:33:53.794437-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received Init(features=0aaa8a, tlvs=TlvStream(records=[Networks(chainHashes=[43497fd7f826957108f4a30fd9cec3aeba79972084e90ead01ea330900000000])], unknown=[]))
2021-02-09 13:33:53.798203-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 peer is using features Features(activated=[ActivatedFeature(feature=option_data_loss_protect, support=optional), ActivatedFeature(feature=initial_routing_sync, support=optional), ActivatedFeature(feature=gossip_queries, support=optional), ActivatedFeature(feature=var_onion_optin, support=optional), ActivatedFeature(feature=gossip_queries_ex, support=optional), ActivatedFeature(feature=option_static_remotekey, support=optional), ActivatedFeature(feature=payment_secret, support=optional), ActivatedFeature(feature=basic_mpp, support=optional), ActivatedFeature(feature=option_support_large_channel, support=optional)], unknown=[])
2021-02-09 13:33:53.802398-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba offline processing class fr.acinq.eclair.channel.ChannelEvent.Connected
2021-02-09 13:33:53.804221-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba syncing class fr.acinq.eclair.channel.Normal, waiting fo their channelReestablish message
2021-02-09 13:33:53.816193-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 connection state changed: ESTABLISHED
2021-02-09 13:33:53.907289-0500 Phoenix[51564:3822617] [AppHomeController] model=Model(balanceSat=1649, payments=[IncomingPayment(preimage=539fa2d9295d44fdb27cb6db1cb7a16cda9d14ffc9 (truncated)
2021-02-09 13:33:53.908694-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:33:53.909178-0500 Phoenix[51564:3822617] [LightningSession] read: (length = 26004) + 16
2021-02-09 13:33:53.914488-0500 Phoenix[51564:3822617] [ElectrumClient] connection state changed: ESTABLISHED
2021-02-09 13:33:53.920747-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba syncing processing class fr.acinq.eclair.channel.ChannelEvent.NewBlock
2021-02-09 13:33:53.921950-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba new tip 1934962 86fcf1e7dbedb06c23c9ae433b9c47c9599b96a5c0eb23330c00000000000000
2021-02-09 13:33:53.923226-0500 Phoenix[51564:3822617] [ElectrumWatcher] added watch-spent on output=bbf0bfa67fe56f878bfc31c946f02689e03a77aeb4ace0ae8aacc1f9eba5900e:1 scriptHash=606a8d646823ddb98fa375203601b74a9981f3470a503d5991c37f008d243e9b
2021-02-09 13:33:53.934674-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba syncing processing class fr.acinq.eclair.channel.ChannelEvent.NewBlock
2021-02-09 13:33:53.935699-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba new tip 1934962 86fcf1e7dbedb06c23c9ae433b9c47c9599b96a5c0eb23330c00000000000000
2021-02-09 13:33:53.939482-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba syncing processing class fr.acinq.eclair.channel.ChannelEvent.NewBlock
2021-02-09 13:33:53.940220-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba new tip 1934962 86fcf1e7dbedb06c23c9ae433b9c47c9599b96a5c0eb23330c00000000000000
2021-02-09 13:33:53.949431-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:33:54.021355-0500 Phoenix[51564:3822617] [LightningSession] decrypted: size = 26004
2021-02-09 13:33:54.021726-0500 Phoenix[51564:3822617] [LightningSession] read: cipherlen
2021-02-09 13:33:54.023731-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received ChannelReestablish(channelId=0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba, nextLocalCommitmentNumber=27, nextRemoteRevocationNumber=25, yourLastCommitmentSecret=PrivateKey(value=b7f0a855fe0be31be73b6838019394d8279877102601df91e816b5133ad5447f), myCurrentPerCommitmentPoint=0223d4ed03c40bc2b973559b05a72c3427dd944b5513c4dac2831bdb33267383ab, channelData=f868f6bfcda4ffcef23e (truncated))
2021-02-09 13:33:54.024856-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received class fr.acinq.eclair.wire.ChannelReestablish for channel 0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba
2021-02-09 13:33:54.025422-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba syncing processing class fr.acinq.eclair.channel.ChannelEvent.MessageReceived
2021-02-09 13:33:54.025982-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba channel_reestablish includes a peer backup
2021-02-09 13:33:54.256358-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba ignoring their older backup
2021-02-09 13:33:54.278682-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba syncing processing class fr.acinq.eclair.channel.ChannelEvent.MessageReceived
2021-02-09 13:33:54.283570-0500 Phoenix[51564:3822617] [ChannelState] discarding proposed OUT: []
2021-02-09 13:33:54.283648-0500 Phoenix[51564:3822617] [ChannelState] discarding proposed IN: []
2021-02-09 13:33:54.283747-0500 Phoenix[51564:3822617] [ChannelState] localNextHtlcId=0->0
2021-02-09 13:33:54.284094-0500 Phoenix[51564:3822617] [ChannelState] remoteNextHtlcId=13->13
2021-02-09 13:33:54.284184-0500 Phoenix[51564:3822617] [ChannelState] re-processing signed IN: []
2021-02-09 13:33:54.284341-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba switching to class fr.acinq.eclair.channel.Normal
2021-02-09 13:33:54.285364-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba new state: class fr.acinq.eclair.channel.Normal
2021-02-09 13:33:54.285766-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 sending ChannelReestablish(channelId=0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba, nextLocalCommitmentNumber=27, nextRemoteRevocationNumber=26, yourLastCommitmentSecret=PrivateKey(value=1f0122a268f25aefab6337d4e90492d835ac302c1124ae8d4623eb50b244827d), myCurrentPerCommitmentPoint=02c47e0715c7e4befab3241d3959bfd6fde1cd3db0ed0d0f855a22e459c81febe4, channelData=)
2021-02-09 13:33:54.287998-0500 Phoenix[51564:3822617] [Peer] {2} respond
2021-02-09 13:33:54.344997-0500 Phoenix[51564:3822617] [AppHomeController] model=Model(balanceSat=1649, payments=[IncomingPayment(preimage=539fa2d9295d44fdb27cb6db1cb7a16cda9d14ffc9 (truncated)
2021-02-09 13:33:54.347444-0500 Phoenix[51564:3822617] [ElectrumWatcher] added watch-confirmed on txid=bbf0bfa67fe56f878bfc31c946f02689e03a77aeb4ace0ae8aacc1f9eba5900e scriptHash=606a8d646823ddb98fa375203601b74a9981f3470a503d5991c37f008d243e9b
2021-02-09 13:33:54.387194-0500 Phoenix[51564:3822617] [ElectrumWatcher] scriptHash=606a8d646823ddb98fa375203601b74a9981f3470a503d5991c37f008d243e9b at height=1934962
2021-02-09 13:33:54.391902-0500 Phoenix[51564:3822617] [Peer] on-chain fees: [EstimateFeeResponse(confirmations=2, feerate=FeeratePerKw(feerate=253 sat)), EstimateFeeResponse(confirmations=6, feerate=FeeratePerKw(feerate=253 sat)), EstimateFeeResponse(confirmations=10, feerate=FeeratePerKw(feerate=253 sat))]
2021-02-09 13:33:54.525800-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:33:54.527609-0500 Phoenix[51564:3822617] [LightningSession] read: (length = 138) + 16
2021-02-09 13:33:54.528914-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:33:54.529946-0500 Phoenix[51564:3822617] [LightningSession] decrypted: size = 138
2021-02-09 13:33:54.530994-0500 Phoenix[51564:3822617] [LightningSession] read: cipherlen
2021-02-09 13:33:54.532429-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received ChannelUpdate(signature=f80649f9e8bfa9c7e19744452061892356d6a74d969935ee422b0abed8e8268710a0bf9176f2366dd880c4bff1a89924b64afdd2c3a48dec2f4a4fa869d5cb83, chainHash=43497fd7f826957108f4a30fd9cec3aeba79972084e90ead01ea330900000000, shortChannelId=1934953x154x1, timestampSeconds=1612895605, messageFlags=1, channelFlags=1, cltvExpiryDelta=CltvExpiryDelta(underlying=144), htlcMinimumMsat=1000 msat, feeBaseMsat=1000 msat, feeProportionalMillionths=100, htlcMaximumMsat=101301000 msat, unknownFields=)
2021-02-09 13:33:54.533582-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received class fr.acinq.eclair.wire.ChannelUpdate for channel 1934953x154x1
2021-02-09 13:33:54.535753-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:33:54.536157-0500 Phoenix[51564:3822617] [LightningSession] read: (length = 138) + 16
2021-02-09 13:33:54.537342-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:33:54.538297-0500 Phoenix[51564:3822617] [LightningSession] decrypted: size = 138
2021-02-09 13:33:54.539480-0500 Phoenix[51564:3822617] [LightningSession] read: cipherlen
2021-02-09 13:33:54.540833-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received ChannelUpdate(signature=ea7b18874b47c88c826783b72a4719ece77b1cf9c5beb51c592c2e260115a4ce5f33b466c0d25b776e9f629b2fc623025b71e3a9c4c640f6aad99bcc0cfc1960, chainHash=43497fd7f826957108f4a30fd9cec3aeba79972084e90ead01ea330900000000, shortChannelId=1934953x154x1, timestampSeconds=1612895634, messageFlags=1, channelFlags=1, cltvExpiryDelta=CltvExpiryDelta(underlying=144), htlcMinimumMsat=1000 msat, feeBaseMsat=1000 msat, feeProportionalMillionths=100, htlcMaximumMsat=101301000 msat, unknownFields=)
2021-02-09 13:33:54.541397-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received class fr.acinq.eclair.wire.ChannelUpdate for channel 1934953x154x1
2021-02-09 13:33:54.556852-0500 Phoenix[51564:3822617] [ElectrumWatcher] already have status=a61e44be2e43b7bd108425adbf9efa57ee0ecae5412e8fb816d8b0bffe3fbd8b for scriptHash=606a8d646823ddb98fa375203601b74a9981f3470a503d5991c37f008d243e9b
2021-02-09 13:33:54.942139-0500 Phoenix[51564:3822617] [ElectrumWatcher] txid=bbf0bfa67fe56f878bfc31c946f02689e03a77aeb4ace0ae8aacc1f9eba5900e was confirmed at height=1934953 and now has confirmations=10 (currentHeight=1934962)
2021-02-09 13:33:55.159142-0500 Phoenix[51564:3822617] [ElectrumWatcher] txid=bbf0bfa67fe56f878bfc31c946f02689e03a77aeb4ace0ae8aacc1f9eba5900e had confirmations=10 in block=1934953 pos=154
2021-02-09 13:33:55.167833-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 notification: WatchEventConfirmed(channelId=0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba, event=fr.acinq.eclair.blockchain.BITCOIN_FUNDING_DEEPLYBURIED@8279dc18, blockHeight=1934953, txIndex=154, tx=02000000000102a583759efaf3de22d3dce306236e41cdd2668f9e7a5fb80b3f0599cef47829420000000000feffffffe27343b91b9dc9744250d079ad409992ca3de1b34d3e2d17c8a0e2c362a961450100000000feffffff02774d0f0000000000160014c63a85424eca39826d5c4e3266ccdeeea4659179b58b010000000000220020e551c2accb9e4d4ddea3e15cf3149e532dd1530c877a51687cb575870962f1b702473044022059a9d65001defed80faf11875d58b456f5a3712a26bbf8e09ba0a4d68e22a12a02202ccfd8eca2d1807956d3d0679f77215258356a5a798db35a4d0b9442af1905b6012103e691d627e21edf1fc77d6dc86ef6d737f1022da8c71d0902cecd71657947dfff02473044022069ef713ece02239baefa3c58c1573e2652ab6d48f69acd7c85ee77a152cb83e202204c2482aca6716f344861691acc2cae9518f77df43863df82ad24b520666884d50121025d1c68e55f4850ed835a6d95d8865263c2df44bc2bc06cd8c18ef0297a10b2d700000000)
2021-02-09 13:33:55.174201-0500 Phoenix[51564:3822617] [ChannelState] unhandled event class fr.acinq.eclair.channel.ChannelEvent.WatchReceived in state class fr.acinq.eclair.channel.Normal
2021-02-09 13:33:55.841064-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:33:55.843208-0500 Phoenix[51564:3822617] [LightningSession] read: (length = 1452) + 16
2021-02-09 13:33:55.849700-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:33:55.867295-0500 Phoenix[51564:3822617] [LightningSession] decrypted: size = 1452
2021-02-09 13:33:55.869268-0500 Phoenix[51564:3822617] [LightningSession] read: cipherlen
2021-02-09 13:33:55.880222-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received UpdateAddHtlc(channelId=0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba, id=13, amountMsat=50000 msat, paymentHash=cf28549fd0fadb1c67be57a543b4b3e565f8bb7b4137820074447a3c33236a49, cltvExpiry=CltvExpiry(underlying=1934981), onionRoutingPacket=OnionRoutingPacket(version=0, publicKey=032fdb6aeea6e6723d425f38e6afa9c7f24d193c2baabd00215649d67b9a7f7793, payload=4fcb78f9a878c5e58c2cb0cf6df7d74ad9b0776a17ee8aae00bcd6447ee9abfb5608aeb930ea4fa27098f2d691229c4dc3ab3439d17eaa7bf509f738081f4e97e9a982e539a40af9a5de3f2625d828fabcae2a2ae9e65a4b3519751e02ce0d48a2a7fe3608c826d2521df0e7abc291edc65ead2e993032cbfc6180be1f9ce247ab91d86cc8d43cd67c772de0580ea0d259fc1115edd49959d8c298c588829101e84c7acbfbf8cf9abccd2ceaca3ff96e4dc292b016c27d6b0259cd537b64670951e9ea0f2e80616e5f2b8e4db27eb7d7f4c1f203b7e0ca6f39cc81a477445e2cb85091dd4727684bd3d119874bb86759c02624db46098f1faaf792b1b73e3f00da3dc557217134f90f52f8086116ecbfea2828daa710238fbe776646067920977d286ea44f67f5af9a114026efa99a6aa080fb2f8b27673d26b070eb48a651f13ba468446b7435472e216c3fa479c2aeffe9d08ee118e408844be9e539e2ed9f39681f1e5a451e1d70a789acb353cbb6329d2445cb492961af7298c1ee4b9d71f57024e9ce7935daaf1601f244ae31f7038f9503d7056e216d91c0bb9a3e34948c7c0ab4f566374f423b1683f1c5928fbf1697b9bab8d05f42f5e6b73afa8d263c61536b121e8469c77e11ed60ddebfe2232e1812a24c293e66bb1cb705442dbed7ec7e25d0bf51f1fe7553dae01495962e9f5f1496e645d88dd19659e656e96def4157c37051a91e67c129230b8a002a229ea296ed119f14ce15e5800097aad8f7fce41f5658986e1dfbeb0326dcd3e66a9bb110ac83514318755c9944458bf6cf6f70972ef8bc41d9b6960b6677464de1d223dc38460bc9005c0513a46e489f29b60f78cd96338e8dda5e942fe9a7a8ad5d5615d915f6043a8deab617b6c5a1c0f47779686ba22a03b0f6a94700cf7ee17e3c004755f59b2dea66f995bb9f93148b678bfb525d473d34002e004169d80b19d23b36f6f55a0152b12a98da4b23c49297b83a34953ee8aac33c02747d65a72238f3e48b8e16c167fc9341583e0ded9e18c0b392c4136a0acad21076761ce980575fc4152116e8310d79bbacb4540ae4b31a2c61fc3ccba1b053980b8b607272d835840beadb6ed907455353f405bf5d619e9b76d0f9078125323aa5a4b3a44f3ac154a6081e77987dc8b63630822031b0f4ab7659bbc2903e0919dd3e117fbecb98798a3351bd9f456f85ab76fa849e0701b66ac74ad23d410f63f8da70b3ed886ba406d46f2c5a4eb1af05394bd50e7fa10cff185f4fb961dcd6917e28d866492a449dd44cac99f4f7435805e2a3b084428a210076df1aa09758c1d339db85de7734e25d8f279760ff64a61fc62551f74d9f9f17622033dde4e4104db6eaa69e3eb58222c7e8e1f5186edf723b4419766de8cc3fcdba325d47b60cc98213ac268c51d4572c8504160446f9aec77d84dd1c1e83bd48d04a1002b9dd3a8cffdf471e854e919d9bebbde3c765f8841f062d6af4fef1eff0bf8182f4889ac2814253abb869ad716546503bd90b14e3cab0c5abb89be35462d42e26e36b7dc01a99036066cabfcb2fce9322723c43f8665a36afa2e7fca69485575362b58886e176373bb559fa4b649cd4faec06eb8dcd119ea428202854d68aa2b1be0fc08e24723a49ea90e0324f2c90438592d60d2618bb8b5ed25faf6fcbd63d54039f90da88648f300596895600217d6d2af0d761f658dd44f88109deb7fdd17fcd03724a39261623c153db8f3c5635e4ab5d3d77781c7f792d23addec57e48544c6b9edb05994ee3595c3951fd2532fe1f07350985d5fa23b9e31cf6bee74a67923070e653bbf, hmac=c9cdaf3d6993b15ef40ac295cee256f0c4d096d857bd220e1a17814ceb00198d))
2021-02-09 13:33:55.886990-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received class fr.acinq.eclair.wire.UpdateAddHtlc for channel 0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba
2021-02-09 13:33:55.893332-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba new state: class fr.acinq.eclair.channel.Normal
2021-02-09 13:33:55.980058-0500 Phoenix[51564:3822617] [AppHomeController] model=Model(balanceSat=1649, payments=[IncomingPayment(preimage=539fa2d9295d44fdb27cb6db1cb7a16cda9d14ffc9 (truncated)
2021-02-09 13:34:03.653691-0500 Phoenix[51564:3822617] [Peer] {2} Sending ping
2021-02-09 13:34:03.838296-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:34:03.838527-0500 Phoenix[51564:3822617] [LightningSession] read: (length = 14) + 16
2021-02-09 13:34:03.839143-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:34:03.839437-0500 Phoenix[51564:3822617] [LightningSession] decrypted: size = 14
2021-02-09 13:34:03.839598-0500 Phoenix[51564:3822617] [LightningSession] read: cipherlen
2021-02-09 13:34:03.840125-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received Pong(data=00000000000000000000)
2021-02-09 13:34:03.840421-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received pong
2021-02-09 13:34:13.707236-0500 Phoenix[51564:3822617] [Peer] {2} Sending ping
2021-02-09 13:34:13.900207-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:34:13.902196-0500 Phoenix[51564:3822617] [LightningSession] read: (length = 14) + 16
2021-02-09 13:34:13.904437-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:34:13.906232-0500 Phoenix[51564:3822617] [LightningSession] decrypted: size = 14
2021-02-09 13:34:13.907271-0500 Phoenix[51564:3822617] [LightningSession] read: cipherlen
2021-02-09 13:34:13.909539-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received Pong(data=00000000000000000000)
2021-02-09 13:34:13.910446-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received pong
2021-02-09 13:34:14.521190-0500 Phoenix[51564:3822617] [Peer] {2} n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 TCP receive: Fish monger
2021-02-09 13:34:14.523205-0500 Phoenix[51564:3822617] [Peer] {2} listen.finally: closeSocket()
2021-02-09 13:34:14.525080-0500 Phoenix[51564:3822617] [Peer] {2} n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 closing TCP socket
2021-02-09 13:34:14.534664-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 connection state changed: CLOSED
2021-02-09 13:34:14.536367-0500 Phoenix[51564:3822617] [AppConnectionsDaemon] Wait for 500ms before retrying connection on Peer
2021-02-09 13:34:14.538876-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 disconnecting channels
2021-02-09 13:34:14.628222-0500 Phoenix[51564:3822617] [AppHomeController] model=Model(balanceSat=1649, payments=[IncomingPayment(preimage=539fa2d9295d44fdb27cb6db1cb7a16cda9d14ffc9 (truncated)
2021-02-09 13:34:15.125997-0500 Phoenix[51564:3822617] [Peer] Peer.connect()
2021-02-09 13:34:15.128534-0500 Phoenix[51564:3822617] [Peer] {3} n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 connecting to 13.248.222.197
2021-02-09 13:34:15.131549-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 connection state changed: ESTABLISHING
2021-02-09 13:34:15.939546-0500 Phoenix[51564:3822617] [Peer] {3} n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 sending init Init(features=080000002aa201, tlvs=TlvStream(records=[], unknown=[]))
2021-02-09 13:34:15.943987-0500 Phoenix[51564:3822617] [LightningSession] read: cipherlen
2021-02-09 13:34:16.150570-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:34:16.152615-0500 Phoenix[51564:3822617] [LightningSession] read: (length = 43) + 16
2021-02-09 13:34:16.155027-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:34:16.157212-0500 Phoenix[51564:3822617] [LightningSession] decrypted: size = 43
2021-02-09 13:34:16.158404-0500 Phoenix[51564:3822617] [LightningSession] read: cipherlen
2021-02-09 13:34:16.161722-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received Init(features=0aaa8a, tlvs=TlvStream(records=[Networks(chainHashes=[43497fd7f826957108f4a30fd9cec3aeba79972084e90ead01ea330900000000])], unknown=[]))
2021-02-09 13:34:16.166239-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 peer is using features Features(activated=[ActivatedFeature(feature=option_data_loss_protect, support=optional), ActivatedFeature(feature=initial_routing_sync, support=optional), ActivatedFeature(feature=gossip_queries, support=optional), ActivatedFeature(feature=var_onion_optin, support=optional), ActivatedFeature(feature=gossip_queries_ex, support=optional), ActivatedFeature(feature=option_static_remotekey, support=optional), ActivatedFeature(feature=payment_secret, support=optional), ActivatedFeature(feature=basic_mpp, support=optional), ActivatedFeature(feature=option_support_large_channel, support=optional)], unknown=[])
2021-02-09 13:34:16.203536-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba offline processing class fr.acinq.eclair.channel.ChannelEvent.Connected
2021-02-09 13:34:16.205658-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba syncing class fr.acinq.eclair.channel.Normal, waiting fo their channelReestablish message
2021-02-09 13:34:16.209434-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 connection state changed: ESTABLISHED
2021-02-09 13:34:16.211302-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:34:16.212075-0500 Phoenix[51564:3822617] [LightningSession] read: (length = 26004) + 16
2021-02-09 13:34:16.275622-0500 Phoenix[51564:3822617] [AppHomeController] model=Model(balanceSat=1649, payments=[IncomingPayment(preimage=539fa2d9295d44fdb27cb6db1cb7a16cda9d14ffc9 (truncated)
2021-02-09 13:34:16.302479-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:34:16.392720-0500 Phoenix[51564:3822617] [LightningSession] decrypted: size = 26004
2021-02-09 13:34:16.393113-0500 Phoenix[51564:3822617] [LightningSession] read: cipherlen
2021-02-09 13:34:16.394088-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received ChannelReestablish(channelId=0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba, nextLocalCommitmentNumber=27, nextRemoteRevocationNumber=25, yourLastCommitmentSecret=PrivateKey(value=b7f0a855fe0be31be73b6838019394d8279877102601df91e816b5133ad5447f), myCurrentPerCommitmentPoint=0223d4ed03c40bc2b973559b05a72c3427dd944b5513c4dac2831bdb33267383ab, channelData=f868f6bfcda4ffcef23e (truncated))
2021-02-09 13:34:16.394322-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received class fr.acinq.eclair.wire.ChannelReestablish for channel 0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba
2021-02-09 13:34:16.394941-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba syncing processing class fr.acinq.eclair.channel.ChannelEvent.MessageReceived
2021-02-09 13:34:16.395697-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba channel_reestablish includes a peer backup
2021-02-09 13:34:16.640586-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba ignoring their older backup
2021-02-09 13:34:16.649002-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba syncing processing class fr.acinq.eclair.channel.ChannelEvent.MessageReceived
2021-02-09 13:34:16.653853-0500 Phoenix[51564:3822617] [ChannelState] discarding proposed OUT: []
2021-02-09 13:34:16.656349-0500 Phoenix[51564:3822617] [ChannelState] discarding proposed IN: [UpdateAddHtlc(channelId=0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba, id=13, amountMsat=50000 msat, paymentHash=cf28549fd0fadb1c67be57a543b4b3e565f8bb7b4137820074447a3c33236a49, cltvExpiry=CltvExpiry(underlying=1934981), onionRoutingPacket=OnionRoutingPacket(version=0, publicKey=032fdb6aeea6e6723d425f38e6afa9c7f24d193c2baabd00215649d67b9a7f7793, payload=4fcb78f9a878c5e58c2cb0cf6df7d74ad9b0776a17ee8aae00bcd6447ee9abfb5608aeb930ea4fa27098f2d691229c4dc3ab3439d17eaa7bf509f738081f4e97e9a982e539a40af9a5de3f2625d828fabcae2a2ae9e65a4b3519751e02ce0d48a2a7fe3608c826d2521df0e7abc291edc65ead2e993032cbfc6180be1f9ce247ab91d86cc8d43cd67c772de0580ea0d259fc1115edd49959d8c298c588829101e84c7acbfbf8cf9abccd2ceaca3ff96e4dc292b016c27d6b0259cd537b64670951e9ea0f2e80616e5f2b8e4db27eb7d7f4c1f203b7e0ca6f39cc81a477445e2cb85091dd4727684bd3d119874bb86759c02624db46098f1faaf792b1b73e3f00da3dc557217134f90f52f8086116ecbfea2828daa710238fbe776646067920977d286ea44f67f5af9a114026efa99a6aa080fb2f8b27673d26b070eb48a651f13ba468446b7435472e216c3fa479c2aeffe9d08ee118e408844be9e539e2ed9f39681f1e5a451e1d70a789acb353cbb6329d2445cb492961af7298c1ee4b9d71f57024e9ce7935daaf1601f244ae31f7038f9503d7056e216d91c0bb9a3e34948c7c0ab4f566374f423b1683f1c5928fbf1697b9bab8d05f42f5e6b73afa8d263c61536b121e8469c77e11ed60ddebfe2232e1812a24c293e66bb1cb705442dbed7ec7e25d0bf51f1fe7553dae01495962e9f5f1496e645d88dd19659e656e96def4157c37051a91e67c129230b8a002a229ea296ed119f14ce15e5800097aad8f7fce41f5658986e1dfbeb0326dcd3e66a9bb110ac83514318755c9944458bf6cf6f70972ef8bc41d9b6960b6677464de1d223dc38460bc9005c0513a46e489f29b60f78cd96338e8dda5e942fe9a7a8ad5d5615d915f6043a8deab617b6c5a1c0f47779686ba22a03b0f6a94700cf7ee17e3c004755f59b2dea66f995bb9f93148b678bfb525d473d34002e004169d80b19d23b36f6f55a0152b12a98da4b23c49297b83a34953ee8aac33c02747d65a72238f3e48b8e16c167fc9341583e0ded9e18c0b392c4136a0acad21076761ce980575fc4152116e8310d79bbacb4540ae4b31a2c61fc3ccba1b053980b8b607272d835840beadb6ed907455353f405bf5d619e9b76d0f9078125323aa5a4b3a44f3ac154a6081e77987dc8b63630822031b0f4ab7659bbc2903e0919dd3e117fbecb98798a3351bd9f456f85ab76fa849e0701b66ac74ad23d410f63f8da70b3ed886ba406d46f2c5a4eb1af05394bd50e7fa10cff185f4fb961dcd6917e28d866492a449dd44cac99f4f7435805e2a3b084428a210076df1aa09758c1d339db85de7734e25d8f279760ff64a61fc62551f74d9f9f17622033dde4e4104db6eaa69e3eb58222c7e8e1f5186edf723b4419766de8cc3fcdba325d47b60cc98213ac268c51d4572c8504160446f9aec77d84dd1c1e83bd48d04a1002b9dd3a8cffdf471e854e919d9bebbde3c765f8841f062d6af4fef1eff0bf8182f4889ac2814253abb869ad716546503bd90b14e3cab0c5abb89be35462d42e26e36b7dc01a99036066cabfcb2fce9322723c43f8665a36afa2e7fca69485575362b58886e176373bb559fa4b649cd4faec06eb8dcd119ea428202854d68aa2b1be0fc08e24723a49ea90e0324f2c90438592d60d2618bb8b5ed25faf6fcbd63d54039f90da88648f300596895600217d6d2af0d761f658dd44f88109deb7fdd17fcd03724a39261623c153db8f3c5635e4ab5d3d77781c7f792d23addec57e48544c6b9edb05994ee3595c3951fd2532fe1f07350985d5fa23b9e31cf6bee74a67923070e653bbf, hmac=c9cdaf3d6993b15ef40ac295cee256f0c4d096d857bd220e1a17814ceb00198d))]
2021-02-09 13:34:16.658083-0500 Phoenix[51564:3822617] [ChannelState] localNextHtlcId=0->0
2021-02-09 13:34:16.658719-0500 Phoenix[51564:3822617] [ChannelState] remoteNextHtlcId=14->13
2021-02-09 13:34:16.658980-0500 Phoenix[51564:3822617] [ChannelState] re-processing signed IN: []
2021-02-09 13:34:16.659315-0500 Phoenix[51564:3822617] [ChannelState] c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba switching to class fr.acinq.eclair.channel.Normal
2021-02-09 13:34:16.661134-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba new state: class fr.acinq.eclair.channel.Normal
2021-02-09 13:34:16.661738-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 sending ChannelReestablish(channelId=0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba, nextLocalCommitmentNumber=27, nextRemoteRevocationNumber=26, yourLastCommitmentSecret=PrivateKey(value=1f0122a268f25aefab6337d4e90492d835ac302c1124ae8d4623eb50b244827d), myCurrentPerCommitmentPoint=02c47e0715c7e4befab3241d3959bfd6fde1cd3db0ed0d0f855a22e459c81febe4, channelData=)
2021-02-09 13:34:16.664201-0500 Phoenix[51564:3822617] [Peer] {3} respond
2021-02-09 13:34:16.708443-0500 Phoenix[51564:3822617] [AppHomeController] model=Model(balanceSat=1649, payments=[IncomingPayment(preimage=539fa2d9295d44fdb27cb6db1cb7a16cda9d14ffc9 (truncated)
2021-02-09 13:34:16.728802-0500 Phoenix[51564:3822617] [ElectrumWatcher] added watch-confirmed on txid=bbf0bfa67fe56f878bfc31c946f02689e03a77aeb4ace0ae8aacc1f9eba5900e scriptHash=606a8d646823ddb98fa375203601b74a9981f3470a503d5991c37f008d243e9b
2021-02-09 13:34:16.884357-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:34:16.884909-0500 Phoenix[51564:3822617] [LightningSession] read: (length = 138) + 16
2021-02-09 13:34:16.885940-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:34:16.886853-0500 Phoenix[51564:3822617] [LightningSession] decrypted: size = 138
2021-02-09 13:34:16.887118-0500 Phoenix[51564:3822617] [LightningSession] read: cipherlen
2021-02-09 13:34:16.888258-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received ChannelUpdate(signature=2b4b63cc260725f53f7a7e64ae05e18c0994fb02852de38256d7c9d154d8f35e0acad1aa1c4b867c328928beddbf8a41a383543b53a31f272e6ce8ae3df36f14, chainHash=43497fd7f826957108f4a30fd9cec3aeba79972084e90ead01ea330900000000, shortChannelId=1934953x154x1, timestampSeconds=1612895654, messageFlags=1, channelFlags=3, cltvExpiryDelta=CltvExpiryDelta(underlying=144), htlcMinimumMsat=1000 msat, feeBaseMsat=1000 msat, feeProportionalMillionths=100, htlcMaximumMsat=101301000 msat, unknownFields=)
2021-02-09 13:34:16.889437-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received class fr.acinq.eclair.wire.ChannelUpdate for channel 1934953x154x1
2021-02-09 13:34:16.896367-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:34:16.896764-0500 Phoenix[51564:3822617] [LightningSession] read: (length = 138) + 16
2021-02-09 13:34:16.897570-0500 Phoenix[51564:3822617] [LightningSession] decrypt: cipherlen
2021-02-09 13:34:16.898120-0500 Phoenix[51564:3822617] [LightningSession] decrypted: size = 138
2021-02-09 13:34:16.898287-0500 Phoenix[51564:3822617] [LightningSession] read: cipherlen
2021-02-09 13:34:16.899562-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received ChannelUpdate(signature=389ff28742b81a3b953ca27cb9da03c9c292525df95f2e0a472b02755cf2ec055ef8100f2776678c561a8cc74a092d2ee1d5bf286cee3ba2ddb7fa0a3a053f57, chainHash=43497fd7f826957108f4a30fd9cec3aeba79972084e90ead01ea330900000000, shortChannelId=1934953x154x1, timestampSeconds=1612895656, messageFlags=1, channelFlags=1, cltvExpiryDelta=CltvExpiryDelta(underlying=144), htlcMinimumMsat=1000 msat, feeBaseMsat=1000 msat, feeProportionalMillionths=100, htlcMaximumMsat=101301000 msat, unknownFields=)
2021-02-09 13:34:16.900189-0500 Phoenix[51564:3822617] [Peer] n:03933884aaf1d6b108397e5efe5c86bcf2d8ca8d2f700eda99db9214fc2712b134 received class fr.acinq.eclair.wire.ChannelUpdate for channel 1934953x154x1
2021-02-09 13:34:16.901868-0500 Phoenix[51564:3822617] [ElectrumWatcher] already have status=a61e44be2e43b7bd108425adbf9efa57ee0ecae5412e8fb816d8b0bffe3fbd8b for scriptHash=606a8d646823ddb98fa375203601b74a9981f3470a503d5991c37f008d243e9b
2021-02-09 13:34:21.826146-0500 Phoenix[51564:3822617] [PhoenixBusiness] incrementDisconnectCount()
2021-02-09 13:34:21.826499-0500 Phoenix[51564:3822617] [AppConnectionsDaemon] incrementDisconnectCount()
2021-02-09 13:34:21.832941-0500 Phoenix[51564:3822617] [AppConnectionsDaemon] peerControlFlow = TrafficControl(networkIsAvailable=true, disconnectCount=1)
2021-02-09 13:34:21.834150-0500 Phoenix[51564:3822617] [AppConnectionsDaemon] electrumControlFlow = TrafficControl(networkIsAvailable=true, disconnectCount=1)
2021-02-09 13:34:21.835266-0500 Phoenix[51564:3822617] [AppConnectionsDaemon] httpApiControlFlow = TrafficControl(networkIsAvailable=true, disconnectCount=1)

@t-bast
Copy link
Member

t-bast commented Feb 10, 2021 •
edited
Loading

I don't see any issue there:

  • Phoenix receives UpdateAddHtlc
  • But it does NOT receive the corresponding CommitSig
  • A disconnection happens, so the unsigned HTLC is dropped
  • The Acinq node is responsible to re-send the HTLC and its CommitSig once the reconnection flow is over (or decide to fail it back to the sender)

I'll have a look at the logs of our testnet node to see what happened for this payment.

@t-bast
Copy link
Member

t-bast commented Feb 10, 2021

Ok I found the issue, it's actually because of another, previous HTLC.
There is likely a bug in eclair-kmp, where we send some messages before the init phase is complete.
I found this in the endurance logs:

2021-02-09 18:28:04,051 INFO  f.a.e.i.Peer n:02cb6cb17a5efe0a48585ab1b68611ed53be2fe26944199814f4a31b4af55a2bdf c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba - IN msg=RevokeAndAck(0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba,PrivateKey(b4773d71f0418ad18e555c55158c52c15f844b825fadb5884a1a2ddef04173c3),0250dd1ac5b8e85b82961472edaedcc60b82b5e8d800909ca7ea82a4983d8b571b,Some(ByteVector(12295 bytes, #823830607)))
2021-02-09 18:28:04,051 WARN  f.a.e.channel.Channel n:02cb6cb17a5efe0a48585ab1b68611ed53be2fe26944199814f4a31b4af55a2bdf c:0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba - unhandled event RevokeAndAck(0e90a5ebf9c1ac8aaee0acb4ae773ae08926f046c931fc8b876fe57fa6bff0ba,PrivateKey(b4773d71f0418ad18e555c55158c52c15f844b825fadb5884a1a2ddef04173c3),0250dd1ac5b8e85b82961472edaedcc60b82b5e8d800909ca7ea82a4983d8b571b,Some(ByteVector(12295 bytes, #823830607))) in state SYNCING

We need to figure out why eclair-kmp sent a RevokeAndAck while the channel was still syncing, before its ChannelReestablish, and fix this. Thanks for the bug report, good catch!

@sstone
Copy link
Member

sstone commented Feb 10, 2021

The "syncing" code in eclair-kmp looks good and it seems that messages are not sent out of order, but there may be a problem with the coroutine channel that we use to buffer outgoing messages and that is never flushed. It is possible that an outgoing message was enqueued just before the connection was lost, not sent, and picked up when we reconnected (after the initial transport handshake), I'll check with @romainbsl and update this issue

@t-bast
Copy link
Member

t-bast commented Feb 10, 2021

Yes that's a perfectly reasonable exception. That looks similar to #175 but with sending socket instead of the receiving socket.

@robbiehanson
Copy link
Contributor Author

there may be a problem with the coroutine channel that we use to buffer outgoing messages and that is never flushed. It is possible that an outgoing message was enqueued just before the connection was lost, not sent, and picked up when we reconnected (after the initial transport handshake)

I believe he fixed this in issue #185. The code now resets the output buffer during the connection establishment process.

I believe we can close this issue. I haven't encountered it again in the last month. And if I do encounter it in the near future, it may be unrelated at this point since the code has moved so far forward.

@t-bast t-bast closed this as completed Mar 10, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@robbiehanson @sstone @t-bast