failed verifying HTLC signatures: UpdateAddHtlc - infinity loop

[ondra-novak]

This bug happened after a channel has been opened with "bfx-lnd1" (0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60) and while the first invoice has been in payment.

Resolved by force-closed, however, please look into it and try to find better solution how Electrum should handle such situation. Cycle in infinite loop is not best solution (restart did not help)

(log file / partially anonymized / from FUNDED to crash

20230205T111616.963603Z |    DEBUG | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | Setting channel state: OPENING -> FUNDED
20230205T111616.968843Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: refresh_tabs
20230205T111616.979798Z |     INFO | storage.WalletStorage | saved <anonymized>
20230205T111616.979883Z |    DEBUG | util.profiler | WalletDB._write 0.0162 sec
20230205T111616.986573Z |    DEBUG | util.profiler | Abstract_Wallet.get_full_history 0.0064 sec
20230205T111616.991634Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0228 sec
20230205T111616.992508Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | Sending FUNDING_LOCKED
20230205T111617.002068Z |    DEBUG | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | Setting channel state: FUNDED -> OPEN
20230205T111617.041231Z |     INFO | storage.WalletStorage | saved <anonymized>
20230205T111617.041349Z |    DEBUG | util.profiler | WalletDB._write 0.0392 sec
20230205T111617.047194Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | CHANNEL OPENING COMPLETED (775134x2404x1)
20230205T111617.047451Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | updating fee to bump remote ctn
20230205T111617.047549Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | (chan: 775134x2404x1) current pending feerate 4144. new feerate 4145
20230205T111617.047688Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | Sending UPDATE_FEE
20230205T111617.048025Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | send_commitment. chan 775134x2404x1. ctn: 1.
20230205T111617.048110Z |     INFO | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | sign_next_commitment 1
20230205T111617.049719Z |     INFO | transaction | adding signature for 03e0f7c51f3b82796bdf1bd4965798463fa2d4b735663c858f77e424e1d9864364
20230205T111617.051136Z |    DEBUG | transaction | is_complete False
20230205T111617.051997Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | Sending COMMITMENT_SIGNED
20230205T111617.070502Z |     INFO | storage.WalletStorage | saved <anonymized>
20230205T111617.070805Z |    DEBUG | util.profiler | WalletDB._write 0.0185 sec
20230205T111617.074239Z |     INFO | interface.[electrum.stippy.com:50002] | skipping header 775139
20230205T111617.158960Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | Received REVOKE_AND_ACK
20230205T111617.159108Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | on_revoke_and_ack. chan 775134x2404x1. ctn: 0
20230205T111617.159178Z |     INFO | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | receive_revocation
20230205T111617.176987Z |     INFO | storage.WalletStorage | saved <anonymized>
20230205T111617.177099Z |    DEBUG | util.profiler | WalletDB._write 0.0177 sec
20230205T111617.303175Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | saved remote channel_update gossip msg for chan 775134x2404x1
20230205T111617.303357Z |    DEBUG | lnworker.LNGossip | process_gossip 0 0 1
20230205T111617.303522Z |    DEBUG | channel_db.ChannelDB | add_channel_announcement: 0/0
20230205T111617.303848Z |    DEBUG | channel_db.ChannelDB | on_node_announcement: 0/0
20230205T111617.304505Z |     INFO | lnworker.LNGossip | adding 1 unknown channel ids
20230205T111617.516152Z |     INFO | interface.[electrum-btc.leblancnet.us:50002] | skipping header 775139
20230205T111617.585264Z |     INFO | lnpeer.Peer.[LNGossip, 03ecef675b-49582c0a] | Querying 1 short_channel_ids
20230205T111617.585456Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-49582c0a] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T111617.622838Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-49582c0a] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T111621.099689Z |     INFO | interface.[188.165.206.215:50002] | skipping header 775139
20230205T111621.927583Z |     INFO | interface.[34.136.171.109:50002] | skipping header 775139
20230205T111622.317769Z |    DEBUG | lnworker.LNGossip | process_gossip 0 1 0
20230205T111622.317989Z |    DEBUG | channel_db.ChannelDB | add_channel_announcement: 0/0
20230205T111622.319174Z |    DEBUG | channel_db.ChannelDB | on_node_announcement: 0/1
20230205T111622.909570Z |     INFO | interface.[E-X.not.fyi:50002] | skipping header 775139
20230205T111623.703231Z |     INFO | interface.[fulcrum.grey.pw:51002] | skipping header 775139
20230205T111625.670000Z |     INFO | interface.[btc.ocf.sh:50002] | skipping header 775139
20230205T111631.760620Z |     INFO | interface.[electrumx.alexridevski.net:50002] | skipping header 775139
20230205T111639.441920Z |     INFO | interface.[178.62.80.20:50002] | skipping header 775139
20230205T111642.246982Z |     INFO | network | fee_histogram [[11, 102977], [9, 118105], [5, 161035], [3, 156362], [2, 210372], [1, 743126], [0, 3072664]]
20230205T111700.281410Z |     INFO | network | fee_estimates {25: 1000, 10: 2113, 5: 9100, 2: 16581}
20230205T111742.435440Z |     INFO | network | fee_histogram [[5, 103807], [1, 141602], [0, 2930554]]
20230205T111813.471845Z |     INFO | channel_db.ChannelDB | Deleting 3 old policies
20230205T111842.426667Z |     INFO | network | fee_histogram [[9, 122934], [4, 203670], [3, 5745], [1, 168784], [0, 2944302]]
20230205T111942.447496Z |     INFO | network | fee_histogram [[13, 106031], [5, 107109], [4, 170079], [1, 185864], [0, 2952051]]
20230205T112013.495376Z |     INFO | channel_db.ChannelDB | Deleting 3 old policies
20230205T112042.497010Z |     INFO | network | fee_histogram [[14, 110618], [8, 110839], [4, 245418], [3, 7392], [1, 189222], [0, 2971169]]
20230205T112142.563706Z |     INFO | network | fee_histogram [[16, 100899], [9, 138315], [7, 126780], [4, 267563], [3, 7670], [1, 199752], [0, 2974410]]
20230205T112213.518330Z |     INFO | channel_db.ChannelDB | Deleting 2 old policies
20230205T112242.619765Z |     INFO | network | fee_histogram [[17, 100539], [10, 112134], [7, 197512], [4, 272663], [3, 7884], [1, 206822], [0, 2987523]]
20230205T112342.653068Z |     INFO | network | fee_histogram [[18, 102914], [10, 131538], [8, 97887], [6, 133586], [4, 253174], [1, 220954], [0, 3024567]]
20230205T112413.542080Z |     INFO | channel_db.ChannelDB | Deleting 2 old policies
20230205T112438.760830Z |     INFO | interface.[fulcrum.grey.pw:51002] | could connect 775140
20230205T112438.765370Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: refresh_tabs
20230205T112438.772359Z |    DEBUG | util.profiler | Abstract_Wallet.get_full_history 0.0068 sec
20230205T112438.777206Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0118 sec
20230205T112441.857950Z |     INFO | interface.[electrum-btc.leblancnet.us:50002] | skipping header 775140
20230205T112441.987530Z |     INFO | interface.[electrum.stippy.com:50002] | skipping header 775140
20230205T112442.731799Z |     INFO | network | fee_histogram [[19, 100510], [10, 156616], [8, 110432], [7, 107713], [4, 292805], [3, 8833], [1, 218651], [0, 3028106]]
20230205T112443.715056Z |     INFO | interface.[2electrumx.hopto.me:56022] | skipping header 775140
20230205T112444.910077Z |     INFO | interface.[E-X.not.fyi:50002] | skipping header 775140
20230205T112446.556884Z |     INFO | interface.[34.136.171.109:50002] | skipping header 775140
20230205T112449.394157Z |     INFO | interface.[188.165.206.215:50002] | skipping header 775140
20230205T112449.716040Z |     INFO | interface.[btc.ocf.sh:50002] | skipping header 775140
20230205T112452.236575Z |     INFO | interface.[electrumx.alexridevski.net:50002] | skipping header 775140
20230205T112458.836637Z |     INFO | interface.[178.62.80.20:50002] | skipping header 775140
20230205T112542.840926Z |     INFO | network | fee_histogram [[4, 123287], [0, 1988281]]
20230205T112613.565527Z |     INFO | channel_db.ChannelDB | Deleting 2 old policies
20230205T112642.919713Z |     INFO | network | fee_histogram [[8, 108324], [1, 106165], [0, 2141161]]
20230205T112743.020629Z |     INFO | network | fee_histogram [[10, 104462], [4, 118379], [0, 2193455]]
20230205T112813.597805Z |     INFO | channel_db.ChannelDB | Deleting 2 old policies
20230205T112843.101014Z |     INFO | network | fee_histogram [[10, 122887], [5, 90138], [2, 118216], [0, 2313042]]
20230205T112927.177486Z |     INFO | interface.[fulcrum.grey.pw:51002] | could connect 775141
20230205T112927.181914Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: refresh_tabs
20230205T112927.188759Z |    DEBUG | util.profiler | Abstract_Wallet.get_full_history 0.0067 sec
20230205T112927.193724Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0118 sec
20230205T112928.987741Z |     INFO | interface.[electrum.stippy.com:50002] | skipping header 775141
20230205T112930.146156Z |     INFO | interface.[electrum-btc.leblancnet.us:50002] | skipping header 775141
20230205T112930.902739Z |     INFO | interface.[2electrumx.hopto.me:56022] | skipping header 775141
20230205T112933.478678Z |     INFO | interface.[34.136.171.109:50002] | skipping header 775141
20230205T112936.509603Z |     INFO | interface.[E-X.not.fyi:50002] | skipping header 775141
20230205T112936.897946Z |     INFO | interface.[btc.ocf.sh:50002] | skipping header 775141
20230205T112938.743422Z |     INFO | interface.[188.165.206.215:50002] | skipping header 775141
20230205T112938.868119Z |     INFO | interface.[electrumx.alexridevski.net:50002] | skipping header 775141
20230205T112941.108369Z |     INFO | interface.[178.62.80.20:50002] | skipping header 775141
20230205T112943.124589Z |     INFO | network | fee_histogram [[14, 100819], [8, 117398], [2, 167250], [0, 2320246]]
20230205T113013.620289Z |     INFO | channel_db.ChannelDB | Deleting 3 old policies
20230205T113043.217023Z |     INFO | network | fee_histogram [[0, 368491]]
20230205T113116.506413Z |    DEBUG | lnworker.LNGossip | process_gossip 1 0 0
20230205T113116.506964Z |    DEBUG | channel_db.ChannelDB | add_channel_announcement: 0/1
20230205T113116.507208Z |    DEBUG | channel_db.ChannelDB | on_node_announcement: 0/0
20230205T113116.518208Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | received orphan channel update 631473x607x1
20230205T113116.521261Z |    DEBUG | lnworker.LNGossip | process_gossip 1 0 0
20230205T113116.521765Z |    DEBUG | channel_db.ChannelDB | add_channel_announcement: 0/1
20230205T113116.522028Z |    DEBUG | channel_db.ChannelDB | on_node_announcement: 0/0
20230205T113116.606252Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | received orphan channel update 633953x873x0
20230205T113116.628787Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | received orphan channel update 656958x1894x1
20230205T113116.652503Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | received orphan channel update 657578x2626x0
20230205T113116.673691Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | received orphan channel update 659475x2765x1
20230205T113116.694951Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | received orphan channel update 702879x2580x1
20230205T113116.716877Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | received orphan channel update 704197x910x0
20230205T113116.738532Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | received orphan channel update 711410x1486x0
20230205T113116.759707Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | received orphan channel update 721399x545x1
20230205T113116.781231Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | received orphan channel update 730467x1578x3
20230205T113116.802644Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | received orphan channel update 733483x664x1
20230205T113116.824279Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | received orphan channel update 733721x530x0
20230205T113116.845443Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | received orphan channel update 733926x1692x0
20230205T113116.866259Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | received orphan channel update 734215x2583x1
20230205T113116.887831Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | received orphan channel update 737626x2567x0
20230205T113116.908594Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | received orphan channel update 747173x637x1
20230205T113116.929629Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | received orphan channel update 765571x1269x1
20230205T113121.508633Z |    DEBUG | lnworker.LNGossip | process_gossip 16 0 17
20230205T113121.513129Z |    DEBUG | channel_db.ChannelDB | add_channel_announcement: 0/16
20230205T113121.513395Z |    DEBUG | channel_db.ChannelDB | on_node_announcement: 0/0
20230205T113121.522983Z |    DEBUG | lnworker.LNGossip | process_gossip 16 0 17
20230205T113121.527246Z |    DEBUG | channel_db.ChannelDB | add_channel_announcement: 0/16
20230205T113121.527565Z |    DEBUG | channel_db.ChannelDB | on_node_announcement: 0/0
20230205T113143.280709Z |     INFO | network | fee_histogram [[9, 101247], [4, 166736], [0, 359864]]
20230205T113209.054044Z |     INFO | storage.WalletStorage | saved <anonymized>
20230205T113209.054170Z |    DEBUG | util.profiler | WalletDB._write 0.0176 sec
20230205T113209.074908Z |     INFO | storage.WalletStorage | saved <anonymized>
20230205T113209.075045Z |    DEBUG | util.profiler | WalletDB._write 0.0166 sec
20230205T113209.075139Z |     INFO | lnworker.LNWallet.[<anonymized>] | pay_invoice starting session for RHASH=db97e532bed30abb35bb1efd7d5b37d1cc9ef16dc17ca24c3dd484f0ab54b8c5
20230205T113209.075237Z |     INFO | lnworker.LNWallet.[<anonymized>] | invoice status triggered (2) for key db97e532bed30abb35bb1efd7d5b37d1cc9ef16dc17ca24c3dd484f0ab54b8c5 and status 4
20230205T113209.075532Z |     INFO | lnworker.LNWallet.[<anonymized>] | channels_with_funds: {(b'\tX\xee\x8f\xe6j\x08E\x14\x9a@A\x8b\xc7\x07\xd9\xf5\xf8}/I\xe2\xdf\xed/B\xb9\x95\x8dt\xca`', b'\x03\xcd\xe6\nc#\xf7\x12-Qx%Wf\xe3\x81\x14\xb4r.\xde\x08\xf7\xc9\xe0\xc5\xdf\x9b\x91,\xc2\x01\xd6'): 16599876340}
20230205T113209.076691Z |     INFO | lnworker.LNWallet.[<anonymized>] | suggest_split 16500000000 returned 61 configurations
20230205T113209.076770Z |     INFO | lnworker.LNWallet.[<anonymized>] | trying split configuration: dict_values([[16500000000]]) rating: 2.9416073491689008
20230205T113209.103007Z |     INFO | lnrouter.LNPathFinder | found a path
20230205T113209.103235Z |    DEBUG | util.profiler | LNPathFinder.find_path_for_payment 0.0260 sec
20230205T113209.103390Z |    DEBUG | util.profiler | LNWallet.create_route_for_payment 0.0262 sec
20230205T113209.104069Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | lnpeer.pay len(route)=3
20230205T113209.104168Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] |   0: edge=775134x2404x1 hop_data=<OnionHopsDataSingle. is_tlv_payload=True. payload={'amt_to_forward': {'amt_to_forward': 16500000000}, 'outgoing_cltv_value': {'outgoing_cltv_value': 775280}, 'short_channel_id': {'short_channel_id': <ShortChannelID: 760159x919x1>}}. hmac=None>
20230205T113209.104248Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] |   1: edge=760159x919x1 hop_data=<OnionHopsDataSingle. is_tlv_payload=True. payload={'amt_to_forward': {'amt_to_forward': 16500000000}, 'outgoing_cltv_value': {'outgoing_cltv_value': 775181}, 'short_channel_id': {'short_channel_id': <ShortChannelID: 759087x2283x1>}}. hmac=None>
20230205T113209.104313Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] |   2: edge=759087x2283x1 hop_data=<OnionHopsDataSingle. is_tlv_payload=True. payload={'amt_to_forward': {'amt_to_forward': 16500000000}, 'outgoing_cltv_value': {'outgoing_cltv_value': 775181}, 'payment_data': {'payment_secret': b'\x1dHg$\xf6\x87W\x84rLcr\x83\xf2\xc0u9\xad\xc0/.\x17\x88u\xaf\x9a\xe4jCHv\xfc', 'total_msat': 16500000000, 'amount_msat': 16500000000}}. hmac=None>
20230205T113209.106823Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | starting payment. len(route)=3.
20230205T113209.107225Z |     INFO | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | add_htlc
20230205T113209.107378Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | starting payment. htlc: UpdateAddHtlc(amount_msat=16500017500, payment_hash=db97e532bed30abb35bb1efd7d5b37d1cc9ef16dc17ca24c3dd484f0ab54b8c5, cltv_expiry=775320, timestamp=1675596729, htlc_id=0)
20230205T113209.107522Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | Sending UPDATE_ADD_HTLC
20230205T113209.107890Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | send_commitment. chan 775134x2404x1. ctn: 2.
20230205T113209.107964Z |     INFO | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | sign_next_commitment 2
20230205T113209.109820Z |     INFO | transaction | adding signature for 03e0f7c51f3b82796bdf1bd4965798463fa2d4b735663c858f77e424e1d9864364
20230205T113209.110260Z |    DEBUG | transaction | is_complete False
20230205T113209.112608Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | Sending COMMITMENT_SIGNED
20230205T113209.128409Z |     INFO | storage.WalletStorage | saved <anonymized>
20230205T113209.128501Z |    DEBUG | util.profiler | WalletDB._write 0.0158 sec
20230205T113209.132448Z |     INFO | lnrouter.LNPathFinder | Adding inflight htlcs to graph (liquidity hints).
20230205T113209.132624Z |     INFO | lnworker.LNWallet.[<anonymized>] | amount inflight 16500000000
20230205T113209.200555Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | Received REVOKE_AND_ACK
20230205T113209.200936Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | on_revoke_and_ack. chan 775134x2404x1. ctn: 1
20230205T113209.201172Z |     INFO | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | receive_revocation
20230205T113209.245945Z |     INFO | storage.WalletStorage | saved <anonymized>
20230205T113209.246050Z |    DEBUG | util.profiler | WalletDB._write 0.0440 sec
20230205T113209.288728Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | Received COMMITMENT_SIGNED
20230205T113209.289148Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | on_commitment_signed. chan 775134x2404x1. ctn: 1.
20230205T113209.289546Z |     INFO | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | receive_new_commitment. ctn=1, len(htlc_sigs)=1
20230205T113209.309550Z |    ERROR | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | Exception in main_loop: LNProtocolWarning('failed verifying HTLC signatures: UpdateAddHtlc(amount_msat=16500017500, payment_hash=db97e532bed30abb35bb1efd7d5b37d1cc9ef16dc17ca24c3dd484f0ab54b8c5, cltv_expiry=775320, timestamp=1675596729, htlc_id=0) -1, rawtx: cHNidP8BAF4CAAAAARkZDdblT4soHy0QVmhOYi/P6913NREGK2rBnBjiKNjRAQAAAAAAAAAAAXW6+wAAAAAAIgAgjwmmkTMFRdyDGW4EDLvazz452vZ+TnEdRnfoMVX2UkOY1AsAAAEFhXapFJzxs2DxG/L1mnv+CuHt7hEXA9fOh2OsZyECKeVFQY9xQuNI/L2aguwW2JIo7jsDrEq33UMRra/qgjZ8ggEgh2R1UnwhA/gHpxHcf7k8bbtXFaYA7zjZvYmG0L4SSGdMEf4DOJx4Uq5nqRTw+A84BdVQLUGsRsu8B0Tvw5p1s4isaGgBBwAAAA==')
Traceback (most recent call last):
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/util.py", line 1244, in wrapper
    return await func(*args, **kwargs)
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnpeer.py", line 415, in wrapper_func
    return await func(self, *args, **kwargs)
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnpeer.py", line 429, in main_loop
    async with self.taskgroup as group:
  File "/usr/local/lib/python3.10/dist-packages/aiorpcx/curio.py", line 297, in __aexit__
    await self.join()
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/util.py", line 1340, in join
    task.result()
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnpeer.py", line 579, in _message_loop
    self.process_message(msg)
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnpeer.py", line 229, in process_message
    execution_result = f(*args)
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnpeer.py", line 1497, in on_commitment_signed
    chan.receive_new_commitment(payload["signature"], htlc_sigs)
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnchannel.py", line 1043, in receive_new_commitment
    self._verify_htlc_sig(htlc=htlc,
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnchannel.py", line 1068, in _verify_htlc_sig
    raise LNProtocolWarning(f'failed verifying HTLC signatures: {htlc} {htlc_direction}, rawtx: {htlc_tx.serialize()}')
electrum.lnutil.LNProtocolWarning: failed verifying HTLC signatures: UpdateAddHtlc(amount_msat=16500017500, payment_hash=db97e532bed30abb35bb1efd7d5b37d1cc9ef16dc17ca24c3dd484f0ab54b8c5, cltv_expiry=775320, timestamp=1675596729, htlc_id=0) -1, rawtx: cHNidP8BAF4CAAAAARkZDdblT4soHy0QVmhOYi/P6913NREGK2rBnBjiKNjRAQAAAAAAAAAAAXW6+wAAAAAAIgAgjwmmkTMFRdyDGW4EDLvazz452vZ+TnEdRnfoMVX2UkOY1AsAAAEFhXapFJzxs2DxG/L1mnv+CuHt7hEXA9fOh2OsZyECKeVFQY9xQuNI/L2aguwW2JIo7jsDrEq33UMRra/qgjZ8ggEgh2R1UnwhA/gHpxHcf7k8bbtXFaYA7zjZvYmG0L4SSGdMEf4DOJx4Uq5nqRTw+A84BdVQLUGsRsu8B0Tvw5p1s4isaGgBBwAAAA==

(4.3.3 / 4.3.4)

[SomberNight]

Thank you for the report.
The issue is the htlc sig mismatch, the infinite-loop in itself is not that interesting (it just happens because we keep replaying the same channel updates).

Do we know what lightning node implementation (and ideally version) the counterparty (bfx-lnd1) is running?
Based on the node alias, I guess it is lnd...?

I've filtered your log lines for the interesting bits and added >/< signs:

20230205T111616.963603Z |    DEBUG | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | Setting channel state: OPENING -> FUNDED
20230205T111616.992508Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | > Sending FUNDING_LOCKED
20230205T111617.002068Z |    DEBUG | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | Setting channel state: FUNDED -> OPEN
20230205T111617.047194Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | CHANNEL OPENING COMPLETED (775134x2404x1)
20230205T111617.047451Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | updating fee to bump remote ctn
20230205T111617.047549Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | (chan: 775134x2404x1) current pending feerate 4144. new feerate 4145
20230205T111617.047688Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | > Sending UPDATE_FEE
20230205T111617.048025Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | send_commitment. chan 775134x2404x1. ctn: 1.
20230205T111617.048110Z |     INFO | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | sign_next_commitment 1
20230205T111617.051997Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | > Sending COMMITMENT_SIGNED
20230205T111617.158960Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | < Received REVOKE_AND_ACK
20230205T111617.159108Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | on_revoke_and_ack. chan 775134x2404x1. ctn: 0
20230205T111617.159178Z |     INFO | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | receive_revocation
20230205T111617.303175Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | saved remote channel_update gossip msg for chan 775134x2404x1

// was expecting "Received COMMITMENT_SIGNED" here...
// ~nothing interesting happens for ~16 mins

20230205T113209.075139Z |     INFO | lnworker.LNWallet.[<anonymized>] | pay_invoice starting session for RHASH=db97e532bed30abb35bb1efd7d5b37d1cc9ef16dc17ca24c3dd484f0ab54b8c5
20230205T113209.076770Z |     INFO | lnworker.LNWallet.[<anonymized>] | trying split configuration: dict_values([[16500000000]]) rating: 2.9416073491689008
20230205T113209.103007Z |     INFO | lnrouter.LNPathFinder | found a path
20230205T113209.107522Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | > Sending UPDATE_ADD_HTLC
20230205T113209.107890Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | send_commitment. chan 775134x2404x1. ctn: 2.
20230205T113209.107964Z |     INFO | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | sign_next_commitment 2
20230205T113209.112608Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | > Sending COMMITMENT_SIGNED
20230205T113209.200555Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | < Received REVOKE_AND_ACK
20230205T113209.200936Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | on_revoke_and_ack. chan 775134x2404x1. ctn: 1
20230205T113209.201172Z |     INFO | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | receive_revocation
20230205T113209.288728Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | < Received COMMITMENT_SIGNED
20230205T113209.289148Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | on_commitment_signed. chan 775134x2404x1. ctn: 1.
20230205T113209.289546Z |     INFO | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | receive_new_commitment. ctn=1, len(htlc_sigs)=1
20230205T113209.309550Z |    ERROR | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | Exception in main_loop: LNProtocolWarning('failed verifying HTLC signatures: UpdateAddHtlc(amount_msat=16500017500, payment_hash=db97e532bed30abb35bb1efd7d5b37d1cc9ef16dc17ca24c3dd484f0ab54b8c5, cltv_expiry=775320, timestamp=1675596729, htlc_id=0) -1, rawtx: cHNidP8BAF4CAAAAARkZDdblT4soHy0QVmhOYi/P6913NREGK2rBnBjiKNjRAQAAAAAAAAAAAXW6+wAAAAAAIgAgjwmmkTMFRdyDGW4EDLvazz452vZ+TnEdRnfoMVX2UkOY1AsAAAEFhXapFJzxs2DxG/L1mnv+CuHt7hEXA9fOh2OsZyECKeVFQY9xQuNI/L2aguwW2JIo7jsDrEq33UMRra/qgjZ8ggEgh2R1UnwhA/gHpxHcf7k8bbtXFaYA7zjZvYmG0L4SSGdMEf4DOJx4Uq5nqRTw+A84BdVQLUGsRsu8B0Tvw5p1s4isaGgBBwAAAA==')

It is interesting that the remote does not send a commit sig after we send update_fee, but 16 mins later when we send an htlc, they finally send a commit sig (immediately after we send a commit sig covering the htlc) that covers both updates. This is where the sig mismatch happens.

I have a hunch that the commit sig being delayed and covering multiple updates is related to the sig mismatch.

I've tried to reproduce this behaviour with lnd, using --channel-commit-interval=3600s. I don't know how the option is supposed to work exactly, but I can't see any difference - lnd still seems to send the commit sigs ~instantaneously.

I've also tried to reproduce with c-lightning, using --commit-time=60000. Unlike with lnd, this option seems to work, but it does not behave exactly like in your log: there is delay after both the update_fee and the update_add_htlc messages. (in the log, there is only delay after the update_fee) I could not trigger a sig mismatch however (despite managing to get CL to aggregate the two updates into a single commit sig).

I can't find a comparable option for eclair.

In any case, I wonder how it can happen that the remote does not send a commit sig for our fee update for 16 minutes... Would they have ever sent a commit sig had it not been for the update_add_htlc...

[SomberNight]

Cycle in infinite loop is not best solution (restart did not help)

Any chance you have logs for a session after you restarted electrum?

[ondra-novak]

Cycle in infinite loop is not best solution (restart did not help)

Any chance you have logs for a session after you restarted electrum?

From start until two crashes, then it repeats until force-close (at the end)

20230205T113601.524269Z |     INFO | simple_config.SimpleConfig | electrum directory /home/ondra/.electrum
20230205T113601.525922Z |     INFO | logging | Electrum version: 4.3.4 - https://electrum.org - https://github.com/spesmilo/electrum
20230205T113601.526820Z |     INFO | logging | Python version: 3.10.6 (main, Nov 14 2022, 16:10:14) [GCC 11.3.0]. On platform: Linux-5.15.0-58-generic-x86_64-with-glibc2.35
20230205T113601.526900Z |     INFO | logging | Logging to file: /home/ondra/.electrum/logs/electrum_log_20230205T113601Z_28094.log
20230205T113601.526956Z |     INFO | logging | Log filters: verbosity '', verbosity_shortcuts ''
20230205T113601.527641Z |     INFO | plugin.Plugins | registering hardware bitbox02: ('hardware', 'bitbox02', 'BitBox02')
20230205T113601.527885Z |     INFO | plugin.Plugins | registering hardware coldcard: ('hardware', 'coldcard', 'Coldcard Wallet')
20230205T113601.528245Z |     INFO | plugin.Plugins | registering hardware digitalbitbox: ('hardware', 'digitalbitbox', 'Digital Bitbox wallet')
20230205T113601.529525Z |     INFO | plugin.Plugins | registering hardware jade: ('hardware', 'jade', 'Jade wallet')
20230205T113601.529764Z |     INFO | plugin.Plugins | registering hardware keepkey: ('hardware', 'keepkey', 'KeepKey wallet')
20230205T113601.530146Z |     INFO | plugin.Plugins | registering hardware ledger: ('hardware', 'ledger', 'Ledger wallet')
20230205T113601.530677Z |     INFO | plugin.Plugins | registering hardware safe_t: ('hardware', 'safe_t', 'Safe-T mini wallet')
20230205T113601.530901Z |     INFO | plugin.Plugins | registering hardware trezor: ('hardware', 'trezor', 'Trezor wallet')
20230205T113601.531129Z |     INFO | plugin.Plugins | registering wallet type ('2fa', 'trustedcoin')
20230205T113601.531490Z |    DEBUG | util.profiler | Plugins.__init__ 0.0044 sec
20230205T113601.531952Z |     INFO | network | blockchains [0]
20230205T113601.532378Z |     INFO | exchange_rate.FxThread | using exchange CoinGecko
20230205T113601.532948Z |     INFO | network | starting network
20230205T113601.533041Z |     INFO | network | setting proxy None
20230205T113601.533190Z |     INFO | network | connecting to horsey.cryptocowboys.net:50002:s as new interface
20230205T113601.533515Z |     INFO | network | starting taskgroup (0x7f49377761d0).
20230205T113601.534715Z |     INFO | channel_db.ChannelDB | SQL thread started
20230205T113601.535180Z |     INFO | channel_db.ChannelDB | Creating database
20230205T113601.537787Z |    DEBUG | util.profiler | Daemon.__init__ 0.0062 sec
20230205T113601.537935Z |     INFO | daemon.Daemon | launching GUI: qt
20230205T113601.593832Z |     INFO | lnworker.LNGossip | starting taskgroup.
20230205T113601.594399Z |     INFO | daemon.Daemon | starting taskgroup.
20230205T113601.599566Z |     INFO | gui.qt.history_list | could not import electrum.plot. This feature needs matplotlib to be installed.
20230205T113601.619190Z |     INFO | gui.qt.ElectrumGui | Qt GUI starting up... Qt=5.15.3, PyQt=5.15.6
20230205T113601.666420Z |     INFO | daemon.CommandsServer | now running and listening. socktype=tcp, addr=('127.0.0.1', 7777)
20230205T113601.724956Z |    DEBUG | util.profiler | ElectrumGui.__init__ 0.1066 sec
20230205T113601.728064Z |     INFO | storage.WalletStorage | wallet path /home/ondra/.electrum/wallets/<anonymized>
20230205T113601.790457Z |     INFO | storage.WalletStorage | wallet path /home/ondra/.electrum/wallets/<anonymized>
20230205T113602.257262Z |     INFO | interface.[udfpzbte2hommnvag5f3qlouqkhvp3xybhlus2yvfeqdwlhjroe4bbyd.onion:60002] | disconnecting due to: ErrorGettingSSLCertFromServer(ConnectError(gaierror(-2, 'Neznámé jméno nebo služba')))
20230205T113602.261148Z |     INFO | network | couldn't launch iface udfpzbte2hommnvag5f3qlouqkhvp3xybhlus2yvfeqdwlhjroe4bbyd.onion:60002:s -- CancelledError()
20230205T113602.290923Z |     INFO | interface.[ty6cgwaf2pbc244gijtmpfvte3wwfp32wgz57eltjkgtsel2q7jufjyd.onion:50002] | disconnecting due to: ErrorGettingSSLCertFromServer(ConnectError(gaierror(-2, 'Neznámé jméno nebo služba')))
20230205T113602.291702Z |     INFO | network | couldn't launch iface ty6cgwaf2pbc244gijtmpfvte3wwfp32wgz57eltjkgtsel2q7jufjyd.onion:50002:s -- CancelledError()
20230205T113602.326895Z |     INFO | interface.[blockstream.info:700] | connection established. version: ['electrs-esplora 0.4.1', '1.4']
20230205T113602.354937Z |     INFO | interface.[blockstream.info:700] | set blockchain with height 775142
20230205T113602.355784Z |     INFO | interface.[blockstream.info:700] | skipping header 775142
20230205T113602.356082Z |     INFO | network | no height for main interface
20230205T113602.503896Z |     INFO | interface.[horsey.cryptocowboys.net:50002] | connection established. version: ['ElectrumX 1.15.0', '1.4']
20230205T113602.504379Z |     INFO | interface.[electrum.kcicom.net:50002] | connection established. version: ['ElectrumX 1.16.0', '1.4']
20230205T113602.506717Z |     INFO | network | fee_estimates {25: 1014, 10: 5081, 5: 9099, 2: 16580}
20230205T113602.544787Z |     INFO | interface.[electrum.kcicom.net:50002] | set blockchain with height 775142
20230205T113602.546068Z |     INFO | interface.[electrum.kcicom.net:50002] | skipping header 775142
20230205T113602.546376Z |     INFO | network | no height for main interface
20230205T113602.546518Z |     INFO | network | switching to blockstream.info:700:s
20230205T113602.562412Z |     INFO | interface.[electrum.bitaroo.net:50002] | connection established. version: ['ElectrumX 1.16.0', '1.4']
20230205T113602.587027Z |     INFO | network | fee_histogram [[19.051074981689453, 51563], [15.947775840759277, 50110], [3.0, 52553], [1.0001330375671387, 56779], [1.0, 23619]]
20230205T113602.587406Z |     INFO | network | fee_estimates {25: 1007, 10: 3545, 5: 9104, 2: 16581}
20230205T113602.589475Z |     INFO | interface.[electrum.bitaroo.net:50002] | set blockchain with height 775142
20230205T113602.590395Z |     INFO | interface.[electrum.bitaroo.net:50002] | skipping header 775142
20230205T113602.591780Z |     INFO | network | fee_estimates {25: 1000, 10: 2113, 5: 9100, 2: 16581}
20230205T113602.609384Z |     INFO | interface.[VPS.hsmiths.com:50002] | connection established. version: ['ElectrumX 1.10.0', '1.4']
20230205T113602.619552Z |     INFO | interface.[bitcoin.lu.ke:50002] | connection established. version: ['ElectrumX 1.16.0', '1.4']
20230205T113602.628670Z |     INFO | interface.[smmalis37.ddns.net:50002] | connection established. version: ['ElectrumX 1.16.0', '1.4']
20230205T113602.630216Z |     INFO | interface.[horsey.cryptocowboys.net:50002] | set blockchain with height 775142
20230205T113602.631758Z |     INFO | interface.[horsey.cryptocowboys.net:50002] | skipping header 775142
20230205T113602.636565Z |     INFO | interface.[34.136.139.229:50002] | connection established. version: ['ElectrumX 1.16.0', '1.4']
20230205T113602.658072Z |     INFO | interface.[bitcoin.lu.ke:50002] | set blockchain with height 775142
20230205T113602.658468Z |     INFO | interface.[bitcoin.lu.ke:50002] | skipping header 775142
20230205T113602.659430Z |     INFO | network | fee_estimates {25: 1006, 10: 2113, 5: 9100, 2: 16581}
20230205T113602.696827Z |     INFO | network | fee_estimates {25: 1000, 10: 2113, 5: 9100, 2: 16581}
20230205T113602.707844Z |     INFO | interface.[VPS.hsmiths.com:50002] | set blockchain with height 775142
20230205T113602.708672Z |     INFO | interface.[VPS.hsmiths.com:50002] | skipping header 775142
20230205T113602.759510Z |     INFO | interface.[smmalis37.ddns.net:50002] | set blockchain with height 775142
20230205T113602.760314Z |     INFO | interface.[smmalis37.ddns.net:50002] | skipping header 775142
20230205T113602.770421Z |     INFO | interface.[34.136.139.229:50002] | set blockchain with height 775142
20230205T113602.771257Z |     INFO | interface.[34.136.139.229:50002] | skipping header 775142
20230205T113602.894290Z |     INFO | interface.[electrum.hodlister.co:50002] | disconnecting due to GracefulDisconnect('too many connected servers already in bucket 45.154.0.0/16')
20230205T113602.894655Z |     INFO | network | couldn't launch iface electrum.hodlister.co:50002:s -- CancelledError()
20230205T113603.037254Z |     INFO | interface.[2AZZARITA.hopto.org:50002] | disconnecting due to: ConnectError(ConnectionRefusedError(111, "Connect call failed ('173.212.253.26', 50002)"))
20230205T113603.037520Z |     INFO | network | couldn't launch iface 2AZZARITA.hopto.org:50002:s -- CancelledError()
20230205T113603.191845Z |     INFO | interface.[eai.coincited.net:50002] | connection established. version: ['ElectrumX 1.16.0', '1.4']
20230205T113603.342494Z |     INFO | interface.[fulcrum.grey.pw:51002] | connection established. version: ['Fulcrum 1.9.0', '1.4']
20230205T113603.368017Z |     INFO | interface.[fulcrum.grey.pw:51002] | set blockchain with height 775142
20230205T113603.368682Z |     INFO | interface.[fulcrum.grey.pw:51002] | skipping header 775142
20230205T113603.450878Z |     INFO | interface.[eai.coincited.net:50002] | set blockchain with height 775142
20230205T113603.451949Z |     INFO | interface.[eai.coincited.net:50002] | skipping header 775142
20230205T113604.065785Z |     INFO | plugin.Plugins | loaded bitbox02
20230205T113604.070616Z |     INFO | plugin.Plugins | loaded coldcard
20230205T113604.073476Z |     INFO | plugin.Plugins | loaded digitalbitbox
20230205T113604.079926Z |    ERROR | plugins.jade.jade | error importing Jade plugin deps
Traceback (most recent call last):
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/plugins/jade/jade.py", line 34, in <module>
    from .jadepy.jade import JadeAPI
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/plugins/jade/jadepy/__init__.py", line 1, in <module>
    from .jade import JadeAPI
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/plugins/jade/jadepy/jade.py", line 1, in <module>
    import cbor
ModuleNotFoundError: No module named 'cbor'
20230205T113604.091454Z |     INFO | plugin.Plugins | loaded jade
20230205T113604.102891Z |     INFO | plugin.Plugins | loaded keepkey
20230205T113604.107600Z |     INFO | plugins.ledger.ledger | Library unavailable
20230205T113604.107680Z |     INFO | plugin.Plugins | loaded ledger
20230205T113604.110708Z |     INFO | plugin.Plugins | loaded safe_t
20230205T113604.182687Z |     INFO | plugin.Plugins | loaded trezor
20230205T113604.193995Z |     INFO | plugin.DeviceMgr | scanning devices...
20230205T113604.211304Z |    DEBUG | util.profiler | DeviceMgr.scan_devices 0.0173 sec
20230205T113604.224069Z |  WARNING | gui.qt.installwizard.InstallWizard | error getting device infos for bitbox02: Missing libraries for bitbox02. //     ImportError() // Make sure you install it with python3
20230205T113604.224319Z |  WARNING | gui.qt.installwizard.InstallWizard | error getting device infos for coldcard: Missing libraries for coldcard. //     ModuleNotFoundError("No module named 'ckcc'") // Make sure you install it with python3
20230205T113604.225075Z |  WARNING | gui.qt.installwizard.InstallWizard | error getting device infos for jade: Missing libraries for jade. //     ModuleNotFoundError("No module named 'cbor'") // Make sure you install it with python3
20230205T113604.226974Z |  WARNING | gui.qt.installwizard.InstallWizard | error getting device infos for keepkey: Missing libraries for keepkey. // Make sure you install it with python3
20230205T113604.227874Z |  WARNING | gui.qt.installwizard.InstallWizard | error getting device infos for ledger: Missing libraries for ledger. //     ModuleNotFoundError("No module named 'ledger_bitcoin'") // Make sure you install it with python3
20230205T113604.230122Z |  WARNING | gui.qt.installwizard.InstallWizard | error getting device infos for safe_t: Missing libraries for safe_t. //     ModuleNotFoundError("No module named 'safetlib'") // Make sure you install it with python3
20230205T113604.231324Z |     INFO | plugins.trezor.qt.Plugin | connecting to device at bridge:1
20230205T113604.248028Z |     INFO | plugins.trezor.qt.Plugin | connected to device at bridge:1
20230205T113604.517817Z |     INFO | plugin.DeviceMgr | Registering Ondruv/AA7D41CA5504EB856CB558E6
20230205T113605.821877Z |     INFO | plugin.DeviceMgr | scanning devices...
20230205T113606.109716Z |    DEBUG | util.profiler | DeviceMgr.scan_devices 0.2878 sec
20230205T113614.980719Z |     INFO | channel_db.ChannelDB | data loaded. 75166 chans. 133487 policies. 14609 nodes.
20230205T113614.980878Z |     INFO | channel_db.ChannelDB | num_channels_partitioned_by_policy_count. 0p: 356, 1p: 16133, 2p: 58677
20230205T113614.981134Z |    DEBUG | util.profiler | ChannelDB.load_data 13.4453 sec
20230205T113615.000942Z |     INFO | channel_db.ChannelDB | Deleting 356 orphaned channels
20230205T113615.001457Z |     INFO | lnworker.LNGossip | adding peer 03cde60a6323f7122d5178255766e38114b4722ede08f7c9e0c5df9b912cc201d6@34.65.85.39:9745
20230205T113615.060672Z |     INFO | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | handshake done for 03cde60a6323f7122d5178255766e38114b4722ede08f7c9e0c5df9b912cc201d6@34.65.85.39:9745
20230205T113615.060959Z |    DEBUG | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | Sending INIT
20230205T113615.087062Z |    DEBUG | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | Received INIT
20230205T113615.087744Z |     INFO | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | query channel range 497000 278142
20230205T113615.087820Z |    DEBUG | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | Sending QUERY_CHANNEL_RANGE
20230205T113615.394260Z |    DEBUG | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | Received REPLY_CHANNEL_RANGE
20230205T113615.478224Z |    DEBUG | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | Received REPLY_CHANNEL_RANGE
20230205T113615.506864Z |    DEBUG | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | Received REPLY_CHANNEL_RANGE
20230205T113615.562729Z |    DEBUG | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | Received REPLY_CHANNEL_RANGE
20230205T113615.595159Z |    DEBUG | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | Received REPLY_CHANNEL_RANGE
20230205T113615.634617Z |    DEBUG | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | Received REPLY_CHANNEL_RANGE
20230205T113615.663079Z |    DEBUG | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | Received REPLY_CHANNEL_RANGE
20230205T113615.695214Z |    DEBUG | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | Received REPLY_CHANNEL_RANGE
20230205T113615.722536Z |    DEBUG | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | Received REPLY_CHANNEL_RANGE
20230205T113615.740202Z |    DEBUG | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | Received REPLY_CHANNEL_RANGE
20230205T113615.741965Z |     INFO | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | Received 76542 channel ids. (complete: True)
20230205T113615.773799Z |     INFO | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | Querying 500 short_channel_ids
20230205T113615.774379Z |    DEBUG | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113616.004180Z |     INFO | lnworker.LNGossip | adding peer 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f@node.acinq.co:9735
20230205T113616.272226Z |     INFO | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | handshake done for 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f@node.acinq.co:9735
20230205T113616.272403Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Sending INIT
20230205T113616.393917Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received INIT
20230205T113616.395224Z |     INFO | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | query channel range 497000 278142
20230205T113616.395519Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Sending QUERY_CHANNEL_RANGE
20230205T113616.616455Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113616.727571Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113616.741067Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113616.818551Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113616.830394Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113616.841294Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113616.853495Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113616.864626Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113616.905090Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113616.915947Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113616.927245Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113616.939012Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113616.950181Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113616.961192Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113616.972925Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113616.985021Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113616.998237Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.007565Z |     INFO | lnworker.LNGossip | adding peer 03ecef675be448b615e6176424070673ef8284e0fd19d8be062a6cb5b130a0a0d1@195.201.207.61:9740
20230205T113617.031763Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.045660Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.058724Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.072182Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.086254Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.100376Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.114959Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.128273Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.134195Z |     INFO | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | handshake done for 03ecef675be448b615e6176424070673ef8284e0fd19d8be062a6cb5b130a0a0d1@195.201.207.61:9740
20230205T113617.134712Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Sending INIT
20230205T113617.142140Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.155627Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.169002Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.183094Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.185979Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received INIT
20230205T113617.187361Z |     INFO | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | query channel range 497000 278142
20230205T113617.187665Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Sending QUERY_CHANNEL_RANGE
20230205T113617.196539Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.208253Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.219525Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.231236Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.244234Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.257832Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.271920Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.285478Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.291021Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.299124Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.312668Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.316861Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.325955Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.329976Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.339270Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_CHANNEL_RANGE
20230205T113617.341280Z |     INFO | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received 61266 channel ids. (complete: True)
20230205T113617.370015Z |     INFO | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Querying 500 short_channel_ids
20230205T113617.370622Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113617.371686Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.383050Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.394268Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.406842Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.418813Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.430103Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.442199Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.455461Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.469631Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.483711Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.496318Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.507791Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.519208Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.530961Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.542738Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.554204Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.565601Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.576936Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.588294Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.600074Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.612206Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.625767Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.638360Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.641162Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T113617.642976Z |     INFO | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Querying 500 short_channel_ids
20230205T113617.644583Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113617.651698Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.665678Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.679217Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.693414Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.706564Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.718291Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.730027Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.743352Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.757331Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.770832Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.784158Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.797223Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.801577Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T113617.802989Z |     INFO | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Querying 500 short_channel_ids
20230205T113617.804528Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113617.810243Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.825066Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.837590Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_CHANNEL_RANGE
20230205T113617.839431Z |     INFO | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received 61472 channel ids. (complete: True)
20230205T113617.867968Z |     INFO | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Querying 500 short_channel_ids
20230205T113617.868560Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113618.010925Z |     INFO | lnworker.LNGossip | adding peer 03abf6f44c355dec0d5aa155bdbdd6e0c8fefe318eff402de65c6eb2e1be55dc3e@3.132.230.42:9735
20230205T113618.027230Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T113618.028426Z |     INFO | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Querying 500 short_channel_ids
20230205T113618.029972Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113618.214886Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T113618.215508Z |     INFO | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Querying 500 short_channel_ids
20230205T113618.216054Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113618.222982Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T113618.223476Z |     INFO | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Querying 500 short_channel_ids
20230205T113618.224205Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113618.268675Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T113618.269614Z |     INFO | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Querying 500 short_channel_ids
20230205T113618.271172Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113618.273849Z |     INFO | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | handshake done for 03abf6f44c355dec0d5aa155bdbdd6e0c8fefe318eff402de65c6eb2e1be55dc3e@3.132.230.42:9735
20230205T113618.274315Z |    DEBUG | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | Sending INIT
20230205T113618.376394Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T113618.377728Z |     INFO | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Querying 500 short_channel_ids
20230205T113618.379324Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113618.401730Z |    DEBUG | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | Received INIT
20230205T113618.404168Z |     INFO | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | query channel range 497000 278142
20230205T113618.404480Z |    DEBUG | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | Sending QUERY_CHANNEL_RANGE
20230205T113618.483803Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T113618.484999Z |     INFO | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Querying 500 short_channel_ids
20230205T113618.486563Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113618.597176Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T113618.597788Z |     INFO | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Querying 429 short_channel_ids
20230205T113618.599196Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113618.683104Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T113618.683864Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T113618.968796Z |    DEBUG | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | Received REPLY_CHANNEL_RANGE
20230205T113619.124813Z |    DEBUG | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | Received REPLY_CHANNEL_RANGE
20230205T113619.147285Z |    DEBUG | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | Received REPLY_CHANNEL_RANGE
20230205T113619.267497Z |    DEBUG | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | Received REPLY_CHANNEL_RANGE
20230205T113619.294110Z |    DEBUG | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | Received REPLY_CHANNEL_RANGE
20230205T113619.373248Z |    DEBUG | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | Received REPLY_CHANNEL_RANGE
20230205T113619.441504Z |    DEBUG | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | Received REPLY_CHANNEL_RANGE
20230205T113619.465398Z |    DEBUG | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | Received REPLY_CHANNEL_RANGE
20230205T113619.509789Z |    DEBUG | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | Received REPLY_CHANNEL_RANGE
20230205T113619.530758Z |    DEBUG | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | Received REPLY_CHANNEL_RANGE
20230205T113619.531513Z |     INFO | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | Received 73649 channel ids. (complete: True)
20230205T113619.554375Z |     INFO | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | Querying 500 short_channel_ids
20230205T113619.554837Z |    DEBUG | lnpeer.Peer.[LNGossip, 03abf6f44c-6fe739e3] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113619.685513Z |     INFO | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Querying 500 short_channel_ids
20230205T113619.687125Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113619.688527Z |     INFO | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Querying 500 short_channel_ids
20230205T113619.690011Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113619.874796Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T113619.875648Z |     INFO | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Querying 500 short_channel_ids
20230205T113619.877266Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113619.941972Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T113619.942656Z |     INFO | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Querying 500 short_channel_ids
20230205T113619.944175Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113620.004927Z |    DEBUG | lnworker.LNGossip | process_gossip 309 21 26
20230205T113620.101270Z |    DEBUG | channel_db.ChannelDB | add_channel_announcement: 309/309
20230205T113620.108991Z |    DEBUG | channel_db.ChannelDB | on_node_announcement: 0/21
20230205T113620.110802Z |    DEBUG | lnworker.LNGossip | process_gossip: 14/26
20230205T113620.133818Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T113620.134194Z |     INFO | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Querying 326 short_channel_ids
20230205T113620.134485Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Sending QUERY_SHORT_CHANNEL_IDS
20230205T113620.145081Z |    DEBUG | lnpeer.Peer.[LNGossip, 03ecef675b-b98727fb] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T113620.318017Z |    DEBUG | lnpeer.Peer.[LNGossip, 03864ef025-fdf64f8d] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T113621.006827Z |    DEBUG | lnworker.LNGossip | process_gossip 21 37 2
20230205T113621.023021Z |    DEBUG | channel_db.ChannelDB | add_channel_announcement: 19/21
20230205T113621.038834Z |    DEBUG | channel_db.ChannelDB | on_node_announcement: 0/37
20230205T113621.040032Z |    DEBUG | lnworker.LNGossip | process_gossip: 2/2
20230205T113622.010497Z |    DEBUG | lnworker.LNGossip | process_gossip 26 46 12
20230205T113622.023946Z |    DEBUG | channel_db.ChannelDB | add_channel_announcement: 6/26
20230205T113622.044237Z |    DEBUG | channel_db.ChannelDB | on_node_announcement: 0/46
20230205T113622.046719Z |    DEBUG | lnworker.LNGossip | process_gossip: 11/12
20230205T113623.014339Z |    DEBUG | lnworker.LNGossip | process_gossip 67 93 134
20230205T113623.040282Z |    DEBUG | channel_db.ChannelDB | add_channel_announcement: 53/67
20230205T113623.062270Z |    DEBUG | channel_db.ChannelDB | on_node_announcement: 0/93
20230205T113623.067679Z |    DEBUG | lnworker.LNGossip | process_gossip: 45/134
20230205T113625.113157Z |    DEBUG | lnworker.LNGossip | process_gossip 117 141 197
20230205T113625.163582Z |    DEBUG | channel_db.ChannelDB | add_channel_announcement: 100/117
20230205T113625.205660Z |    DEBUG | channel_db.ChannelDB | on_node_announcement: 0/141
20230205T113625.218104Z |    DEBUG | lnworker.LNGossip | process_gossip: 86/197
20230205T113628.069332Z |    DEBUG | lnworker.LNGossip | process_gossip 113 121 217
20230205T113628.114779Z |    DEBUG | channel_db.ChannelDB | add_channel_announcement: 83/113
20230205T113628.146781Z |    DEBUG | channel_db.ChannelDB | on_node_announcement: 0/121
20230205T113628.153832Z |    DEBUG | lnworker.LNGossip | process_gossip: 46/217
20230205T113628.627980Z |    DEBUG | lnpeer.Peer.[LNGossip, 03cde60a63-ee4ec145] | Received REPLY_SHORT_CHANNEL_IDS_END
20230205T113630.220498Z |    DEBUG | lnworker.LNGossip | process_gossip 74 100 139
20230205T113630.247528Z |    DEBUG | channel_db.ChannelDB | add_channel_announcement: 70/74
20230205T113630.289800Z |    DEBUG | channel_db.ChannelDB | on_node_announcement: 0/100
20230205T113630.299759Z |    DEBUG | lnworker.LNGossip | process_gossip: 70/139
20230205T113631.880048Z |    DEBUG | util.profiler | WalletDB._load_transactions 0.0357 sec
20230205T113631.881184Z |    DEBUG | util.profiler | AddressSynchronizer.load_local_history 0.0004 sec
20230205T113631.881648Z |    DEBUG | util.profiler | AddressSynchronizer.check_history 0.0004 sec
20230205T113631.884039Z |     INFO | lnworker.LNWallet.[<anonymized>] | invoice status triggered (2) for key db97e532bed30abb35bb1efd7d5b37d1cc9ef16dc17ca24c3dd484f0ab54b8c5 and status 4
20230205T113631.911882Z |     INFO | wallet.Standard_Wallet.[<anonymized>] | starting taskgroup.
20230205T113631.912094Z |     INFO | lnworker.LNWallet.[<anonymized>] | starting taskgroup.
20230205T113632.033881Z |    DEBUG | util.profiler | AddressList.update 0.0000 sec
20230205T113632.121671Z |     INFO | plugin.DeviceMgr | scanning devices...
20230205T113632.134172Z |    DEBUG | util.profiler | Deterministic_Wallet.try_detecting_internal_addresses_corruption 0.0131 sec
20230205T113632.134285Z |    DEBUG | util.profiler | ElectrumWindow.load_wallet 0.0455 sec
20230205T113632.135222Z |     INFO | gui.qt.ElectrumGui | starting Qt main loop
20230205T113632.221564Z |     INFO | address_synchronizer.AddressSynchronizer.[<anonymized>] | set_up_to_date: True
20230205T113632.244195Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230205T113632.244325Z |    DEBUG | util.profiler | WalletDB._write 0.0219 sec
20230205T113632.244468Z |     INFO | wallet.Standard_Wallet.[<anonymized>] | set_up_to_date: True
20230205T113632.296862Z |     INFO | gui.qt.update_checker.UpdateCheckThread | valid sig for version announcement '4.3.4' from address '13xjmVAB1EATPP8RshTE8S8sNwwSUM9p1P'
20230205T113632.407024Z |    DEBUG | util.profiler | DeviceMgr.scan_devices 0.2853 sec
20230205T113632.408032Z |     INFO | plugin.DeviceMgr | getting client for keystore
20230205T113632.408572Z |    DEBUG | plugin.DeviceMgr | select_device. auto-selected(1) Trezor: soft_device_id matched
20230205T113632.620499Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: update_tabs
20230205T113632.625865Z |    DEBUG | util.profiler | Abstract_Wallet.get_full_history 0.0052 sec
20230205T113632.634572Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0141 sec
20230205T113632.639616Z |    DEBUG | util.profiler | AddressList.update 0.0000 sec
20230205T113632.787838Z |     INFO | plugin.DeviceMgr | end client for keystore
20230205T113632.788476Z |     INFO | plugin.DeviceMgr | getting client for keystore
20230205T113632.788779Z |     INFO | plugin.DeviceMgr | end client for keystore
20230205T113632.914123Z |     INFO | lnworker.LNWallet.[<anonymized>] | adding peer 03cde60a6323f7122d5178255766e38114b4722ede08f7c9e0c5df9b912cc201d6@34.65.85.39:9745
20230205T113633.025860Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-899b2a67] | handshake done for 03cde60a6323f7122d5178255766e38114b4722ede08f7c9e0c5df9b912cc201d6@34.65.85.39:9745
20230205T113633.027055Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-899b2a67] | Sending INIT
20230205T113633.058514Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-899b2a67] | Received INIT
20230205T113633.073817Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-899b2a67] | saved remote channel_update gossip msg for chan 775134x2404x1
20230205T113633.085027Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-899b2a67] | Received CHANNEL_REESTABLISH
20230205T113633.085140Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-899b2a67] | channel_reestablish (775134x2404x1): received channel_reestablish with (their_next_local_ctn=3, their_oldest_unrevoked_remote_ctn=0)
20230205T113633.156231Z |    DEBUG | lnworker.LNGossip | process_gossip 106 129 208
20230205T113633.222035Z |    DEBUG | channel_db.ChannelDB | add_channel_announcement: 64/106
20230205T113633.266803Z |    DEBUG | channel_db.ChannelDB | on_node_announcement: 0/129
20230205T113633.273771Z |    DEBUG | lnworker.LNGossip | process_gossip: 47/208
20230205T113633.920987Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-899b2a67] | Sending CHANNEL_REESTABLISH
20230205T113633.921403Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-899b2a67] | channel_reestablish (775134x2404x1): sent channel_reestablish with (next_local_ctn=1, oldest_unrevoked_remote_ctn=2)
20230205T113633.921509Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-899b2a67] | channel_reestablish (775134x2404x1): replayed 0 unacked messages. []
20230205T113634.002538Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-899b2a67] | Received COMMITMENT_SIGNED
20230205T113634.002926Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-899b2a67] | on_commitment_signed. chan 775134x2404x1. ctn: 1.
20230205T113634.003365Z |     INFO | lnchannel.Channel.[775134x2404x1] | receive_new_commitment. ctn=1, len(htlc_sigs)=1
20230205T113634.025887Z |    ERROR | lnpeer.Peer.[LNWallet, 03cde60a63-899b2a67] | Exception in main_loop: LNProtocolWarning('failed verifying HTLC signatures: UpdateAddHtlc(amount_msat=16500017500, payment_hash=db97e532bed30abb35bb1efd7d5b37d1cc9ef16dc17ca24c3dd484f0ab54b8c5, cltv_expiry=775320, timestamp=1675596729, htlc_id=0) -1, rawtx: cHNidP8BAF4CAAAAARkZDdblT4soHy0QVmhOYi/P6913NREGK2rBnBjiKNjRAQAAAAAAAAAAAXW6+wAAAAAAIgAgjwmmkTMFRdyDGW4EDLvazz452vZ+TnEdRnfoMVX2UkOY1AsAAAEFhXapFJzxs2DxG/L1mnv+CuHt7hEXA9fOh2OsZyECKeVFQY9xQuNI/L2aguwW2JIo7jsDrEq33UMRra/qgjZ8ggEgh2R1UnwhA/gHpxHcf7k8bbtXFaYA7zjZvYmG0L4SSGdMEf4DOJx4Uq5nqRTw+A84BdVQLUGsRsu8B0Tvw5p1s4isaGgBBwAAAA==')
Traceback (most recent call last):
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/util.py", line 1244, in wrapper
    return await func(*args, **kwargs)
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnpeer.py", line 421, in wrapper_func
    return await func(self, *args, **kwargs)
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnpeer.py", line 435, in main_loop
    async with self.taskgroup as group:
  File "/usr/local/lib/python3.10/dist-packages/aiorpcx/curio.py", line 297, in __aexit__
    await self.join()
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/util.py", line 1340, in join
    task.result()
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnpeer.py", line 585, in _message_loop
    self.process_message(msg)
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnpeer.py", line 235, in process_message
    execution_result = f(*args)
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnpeer.py", line 1503, in on_commitment_signed
    chan.receive_new_commitment(payload["signature"], htlc_sigs)
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnchannel.py", line 1043, in receive_new_commitment
    self._verify_htlc_sig(htlc=htlc,
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnchannel.py", line 1068, in _verify_htlc_sig
    raise LNProtocolWarning(f'failed verifying HTLC signatures: {htlc} {htlc_direction}, rawtx: {htlc_tx.serialize()}')
electrum.lnutil.LNProtocolWarning: failed verifying HTLC signatures: UpdateAddHtlc(amount_msat=16500017500, payment_hash=db97e532bed30abb35bb1efd7d5b37d1cc9ef16dc17ca24c3dd484f0ab54b8c5, cltv_expiry=775320, timestamp=1675596729, htlc_id=0) -1, rawtx: cHNidP8BAF4CAAAAARkZDdblT4soHy0QVmhOYi/P6913NREGK2rBnBjiKNjRAQAAAAAAAAAAAXW6+wAAAAAAIgAgjwmmkTMFRdyDGW4EDLvazz452vZ+TnEdRnfoMVX2UkOY1AsAAAEFhXapFJzxs2DxG/L1mnv+CuHt7hEXA9fOh2OsZyECKeVFQY9xQuNI/L2aguwW2JIo7jsDrEq33UMRra/qgjZ8ggEgh2R1UnwhA/gHpxHcf7k8bbtXFaYA7zjZvYmG0L4SSGdMEf4DOJx4Uq5nqRTw+A84BdVQLUGsRsu8B0Tvw5p1s4isaGgBBwAAAA==
20230205T113637.917799Z |     INFO | lnworker.LNWallet.[<anonymized>] | adding peer 03cde60a6323f7122d5178255766e38114b4722ede08f7c9e0c5df9b912cc201d6@34.65.85.39:9745
20230205T113637.983258Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-bd3e061f] | handshake done for 03cde60a6323f7122d5178255766e38114b4722ede08f7c9e0c5df9b912cc201d6@34.65.85.39:9745
20230205T113637.983449Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-bd3e061f] | Sending INIT
20230205T113638.005694Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-bd3e061f] | Received INIT
20230205T113638.017378Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-bd3e061f] | saved remote channel_update gossip msg for chan 775134x2404x1
20230205T113638.028561Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-bd3e061f] | Received CHANNEL_REESTABLISH
20230205T113638.028653Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-bd3e061f] | channel_reestablish (775134x2404x1): received channel_reestablish with (their_next_local_ctn=3, their_oldest_unrevoked_remote_ctn=0)
20230205T113638.278271Z |    DEBUG | lnworker.LNGossip | process_gossip 111 132 219
20230205T113638.314670Z |    DEBUG | channel_db.ChannelDB | add_channel_announcement: 71/111
20230205T113638.367147Z |    DEBUG | channel_db.ChannelDB | on_node_announcement: 0/132
20230205T113638.376738Z |    DEBUG | lnworker.LNGossip | process_gossip: 59/219
20230205T113638.925921Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-bd3e061f] | Sending CHANNEL_REESTABLISH
20230205T113638.926208Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-bd3e061f] | channel_reestablish (775134x2404x1): sent channel_reestablish with (next_local_ctn=1, oldest_unrevoked_remote_ctn=2)
20230205T113638.926313Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-bd3e061f] | channel_reestablish (775134x2404x1): replayed 0 unacked messages. []
20230205T113638.998384Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-bd3e061f] | Received COMMITMENT_SIGNED
20230205T113638.998814Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-bd3e061f] | on_commitment_signed. chan 775134x2404x1. ctn: 1.
20230205T113638.999208Z |     INFO | lnchannel.Channel.[775134x2404x1] | receive_new_commitment. ctn=1, len(htlc_sigs)=1
20230205T113639.018815Z |    ERROR | lnpeer.Peer.[LNWallet, 03cde60a63-bd3e061f] | Exception in main_loop: LNProtocolWarning('failed verifying HTLC signatures: UpdateAddHtlc(amount_msat=16500017500, payment_hash=db97e532bed30abb35bb1efd7d5b37d1cc9ef16dc17ca24c3dd484f0ab54b8c5, cltv_expiry=775320, timestamp=1675596729, htlc_id=0) -1, rawtx: cHNidP8BAF4CAAAAARkZDdblT4soHy0QVmhOYi/P6913NREGK2rBnBjiKNjRAQAAAAAAAAAAAXW6+wAAAAAAIgAgjwmmkTMFRdyDGW4EDLvazz452vZ+TnEdRnfoMVX2UkOY1AsAAAEFhXapFJzxs2DxG/L1mnv+CuHt7hEXA9fOh2OsZyECKeVFQY9xQuNI/L2aguwW2JIo7jsDrEq33UMRra/qgjZ8ggEgh2R1UnwhA/gHpxHcf7k8bbtXFaYA7zjZvYmG0L4SSGdMEf4DOJx4Uq5nqRTw+A84BdVQLUGsRsu8B0Tvw5p1s4isaGgBBwAAAA==')
Traceback (most recent call last):
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/util.py", line 1244, in wrapper
    return await func(*args, **kwargs)
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnpeer.py", line 421, in wrapper_func
    return await func(self, *args, **kwargs)
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnpeer.py", line 435, in main_loop
    async with self.taskgroup as group:
  File "/usr/local/lib/python3.10/dist-packages/aiorpcx/curio.py", line 297, in __aexit__
    await self.join()
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/util.py", line 1340, in join
    task.result()
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnpeer.py", line 585, in _message_loop
    self.process_message(msg)
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnpeer.py", line 235, in process_message
    execution_result = f(*args)
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnpeer.py", line 1503, in on_commitment_signed
    chan.receive_new_commitment(payload["signature"], htlc_sigs)
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnchannel.py", line 1043, in receive_new_commitment
    self._verify_htlc_sig(htlc=htlc,
  File "/home/ondra/.local/lib/python3.10/site-packages/electrum/lnchannel.py", line 1068, in _verify_htlc_sig
    raise LNProtocolWarning(f'failed verifying HTLC signatures: {htlc} {htlc_direction}, rawtx: {htlc_tx.serialize()}')
electrum.lnutil.LNProtocolWarning: failed verifying HTLC signatures: UpdateAddHtlc(amount_msat=16500017500, payment_hash=db97e532bed30abb35bb1efd7d5b37d1cc9ef16dc17ca24c3dd484f0ab54b8c5, cltv_expiry=775320, timestamp=1675596729, htlc_id=0) -1, rawtx: cHNidP8BAF4CAAAAARkZDdblT4soHy0QVmhOYi/P6913NREGK2rBnBjiKNjRAQAAAAAAAAAAAXW6+wAAAAAAIgAgjwmmkTMFRdyDGW4EDLvazz452vZ+TnEdRnfoMVX2UkOY1AsAAAEFhXapFJzxs2DxG/L1mnv+CuHt7hEXA9fOh2OsZyECKeVFQY9xQuNI/L2aguwW2JIo7jsDrEq33UMRra/qgjZ8ggEgh2R1UnwhA/gHpxHcf7k8bbtXFaYA7zjZvYmG0L4SSGdMEf4DOJx4Uq5nqRTw+A84BdVQLUGsRsu8B0Tvw5p1s4isaGgBBwAAAA==

[ondra-novak]

I am programmer, but my knowledge about how LN works is only at level "user experience". So I can only guess what happened.

The main goal was to open a channel to the well known public node - Bitfinex bfx-lnd1 (https://ln.bitfinex.com/), then to swap out the liquidity back to the chain (through fixedfloat)

That 15 minutes inactivity happened, because I opened channel manually and during waiting for 6 confirmations I did something else, so I did not return in exact time - as there is no notification.

The very next action was to create LN invoice and let the invoice to be paid. The channel starts to switch between OPENED and DISCONNECTED repeatedly.

I might do something wrong because my laziness, so during opening channel, i reused channel ID from previously closed channel to the same node , instead of putting official ID from their page - the name of the node was resolved correctly.

It is also possible, that problem is at Bitfinex's side. Because this can happen, things often don't work correctly, I just was surprised by reaction of the Electrum. Unstoppable payment, locked assets, no available action except "force close" - which results in freeze of the assets for over 2000 blocks. Other solution would be to ask the counterparty to force close his side of channel, as there were no assets at their side, but this options was unavailable (because during DISCONNECTED, you have only one option FORCE CLOSE)

[SomberNight]

[...] so during opening channel, i reused channel ID from previously closed channel to the same node , instead of putting official ID from their page

I guess you mean you copied the node ID. That is perfectly fine.

The main goal was to open a channel to the well known public node - Bitfinex bfx-lnd1 (https://ln.bitfinex.com/), then to swap out the liquidity back to the chain (through fixedfloat)

I notice that you opened the channel for max satoshis, and tried to send a payment that is practically the full channel capacity. Have you tried this before with the bitfinex node, with another channel you had with that node? (or even another node)
I ask because I am not sure how often these larger amount channels and payments are used by electrum users (I personally only have smaller channels and do smaller payments on mainnet - but have tested large ones on regtest/testnet), and wondering if that could have anything to do with not seeing this bug so far. (but I tried to reproduce the exact msat amounts that appear in your log on regtest against lnd master (lnd is still my best guess for what bfx-lnd1 runs) and could not reproduce the bug)

[ondra-novak]

i am choosing BFX node because it allows much bigger channels then recommended maximum. (and has good capacity) This constrain should be removed in the Electrum (as i remember, but I am still mostly using recommended maximum).

However I have currently a lot of assets allocated outside of this wallet, and my current balance is low - add fact that whole capacity is currently frozen for 14 days. So I did not try to repeat the attempt. I can try with smaller amount (later today).

It is still possible that this is a rare bug which is hard to reproduce.

What about failed internet connection?, lost packet, etc?

[SomberNight]

i am choosing BFX node because it allows much bigger channels then recommended maximum. (and has good capacity) This constrain should be removed in the Electrum (as i remember, but I am still mostly using recommended maximum).

Right, there is already an issue about removing the legacy max channel capacity: #8165

add fact that whole capacity is currently frozen for 14 days. So I did not try to repeat the attempt.

I meant if you perhaps tried this already in the past (the large amounts - as in, (close to) max capacity) with this node. (especially as you said you already had a channel in this node before)

I can try with smaller amount (later today).

If you (or someone else) do(es) end up reproducing the bug, if possible, please do not force-close the channel, just write here, and then we can try modifying the code a bit, mainly to log more stuff. (but I am considering adding more logging anyway)

It is still possible that this is a rare bug which is hard to reproduce.

Yes, indeed. I suspect it is not easy to reproduce. :/

What about failed internet connection?, lost packet, etc?

There was no reconnection to the counterparty in your original log. The network connection uses TCP, so packets couldn't really have gotten lost or reordered either.

Btw thanks for the second log. Everything looks as expected there (so all the interesting bits are in the original log).

[ondra-novak]

OK, I tried to open a channel with the same node (bfx-lnd1), but I could open just for small amount (0.05 BTC). And this time, no problem happened. Do you want to see a log?

I will continue to use it as usual and if there will be similar issue, I will not force to close the channel, instead I will reopen issue here.

(I am also trade on OTC exchanges through the LN network where it is supported, because it is fast, no longer need to wait for confirmations when the rate is optimal for the trade, so I often open channel for a single exchange)

[SomberNight]

OK, I tried to open a channel with the same node (bfx-lnd1), but I could open just for small amount (0.05 BTC). And this time, no problem happened. Do you want to see a log?

Yes, please. I would like to see whether they delay signing a commitment after we send update_fee.
Could you include the log from Setting channel state: OPENING -> FUNDED to when the first payment finishes?

[ondra-novak]

The first testing payment was from one my wallet to my other wallet, so you can probably see two channels in the log. Other channel is connected to a different node. The important channel is being FUNDED (9688946346...) and leads to bfx-lnd1 (03cde60a63...) (other was already opened for a long time)

20230206T213734.368241Z |    DEBUG | lnchannel.Channel.[96889463461b28a505b071f5f1f0eba5c8efac4dfaa8eb1db542842bf8566c9e] | Setting channel state: OPENING -> FUNDED
20230206T213734.401823Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230206T213734.402222Z |    DEBUG | util.profiler | WalletDB._write 0.0339 sec
20230206T213734.402751Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Sending FUNDING_LOCKED
20230206T213734.406616Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Sending FUNDING_LOCKED
20230206T213734.410493Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Sending FUNDING_LOCKED
20230206T213734.413296Z |     INFO | address_synchronizer.AddressSynchronizer.[<anonymized>] | set_up_to_date: False
20230206T213734.416826Z |     INFO | wallet.Standard_Wallet.[<anonymized>] | set_up_to_date: False
20230206T213734.419137Z |     INFO | network | fee_estimates {25: 3002, 10: 3002, 5: 4422, 2: 15944}
20230206T213734.560114Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Received FUNDING_LOCKED
20230206T213734.560526Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | on_funding_locked. channel: 96889463461b28a505b071f5f1f0eba5c8efac4dfaa8eb1db542842bf8566c9e
20230206T213734.602481Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230206T213734.602599Z |    DEBUG | util.profiler | WalletDB._write 0.0418 sec
20230206T213734.602724Z |    DEBUG | lnchannel.Channel.[96889463461b28a505b071f5f1f0eba5c8efac4dfaa8eb1db542842bf8566c9e] | Setting channel state: FUNDED -> OPEN
20230206T213734.619035Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230206T213734.619138Z |    DEBUG | util.profiler | WalletDB._write 0.0163 sec
20230206T213734.621592Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | CHANNEL OPENING COMPLETED (775351x1751x1)
20230206T213734.966350Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | saved remote channel_update gossip msg for chan 775351x1751x1
20230206T213734.966558Z |    DEBUG | lnworker.LNGossip | process_gossip 0 0 1
20230206T213734.966766Z |    DEBUG | channel_db.ChannelDB | add_channel_announcement: 0/0
20230206T213734.967235Z |    DEBUG | channel_db.ChannelDB | on_node_announcement: 0/0
20230206T213734.967983Z |     INFO | lnworker.LNGossip | adding 1 unknown channel ids
20230206T213735.132757Z |     INFO | lnpeer.Peer.[LNGossip, 03cde60a63-b29237cb] | Querying 1 short_channel_ids
20230206T213735.133031Z |    DEBUG | lnpeer.Peer.[LNGossip, 03cde60a63-b29237cb] | Sending QUERY_SHORT_CHANNEL_IDS
20230206T213735.162738Z |    DEBUG | lnpeer.Peer.[LNGossip, 03cde60a63-b29237cb] | Received REPLY_SHORT_CHANNEL_IDS_END
20230206T213735.634645Z |     INFO | address_synchronizer.AddressSynchronizer.[<anonymized>] | set_up_to_date: True
20230206T213735.638135Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | updating fee to bump remote ctn
20230206T213735.638238Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | (chan: 775351x1751x1) current pending feerate 3985. new feerate 3986
20230206T213735.638384Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Sending UPDATE_FEE
20230206T213735.638720Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | send_commitment. chan 775351x1751x1. ctn: 1.
20230206T213735.638808Z |     INFO | lnchannel.Channel.[96889463461b28a505b071f5f1f0eba5c8efac4dfaa8eb1db542842bf8566c9e] | sign_next_commitment 1
20230206T213735.640619Z |     INFO | transaction | adding signature for 03c3ce8f791eb7721c3e9571157bfc9e985aab39c1624ad2ea0d01a36fb08d75e4
20230206T213735.641104Z |    DEBUG | transaction | is_complete False
20230206T213735.641405Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Sending COMMITMENT_SIGNED
20230206T213735.663162Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230206T213735.663278Z |    DEBUG | util.profiler | WalletDB._write 0.0217 sec
20230206T213735.666600Z |    DEBUG | util.profiler | WalletDB._write 0.0000 sec
20230206T213735.666780Z |     INFO | wallet.Standard_Wallet.[<anonymized>] | set_up_to_date: True
20230206T213735.821394Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Received REVOKE_AND_ACK
20230206T213735.821776Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | on_revoke_and_ack. chan 775351x1751x1. ctn: 0
20230206T213735.822013Z |     INFO | lnchannel.Channel.[96889463461b28a505b071f5f1f0eba5c8efac4dfaa8eb1db542842bf8566c9e] | receive_revocation
20230206T213735.868646Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230206T213735.868787Z |    DEBUG | util.profiler | WalletDB._write 0.0460 sec
20230206T213735.973583Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Received COMMITMENT_SIGNED
20230206T213735.973909Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | on_commitment_signed. chan 775351x1751x1. ctn: 1.
20230206T213735.974290Z |     INFO | lnchannel.Channel.[96889463461b28a505b071f5f1f0eba5c8efac4dfaa8eb1db542842bf8566c9e] | receive_new_commitment. ctn=1, len(htlc_sigs)=0
20230206T213735.981590Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | send_revoke_and_ack. chan 775351x1751x1. ctn: 0
20230206T213735.981874Z |     INFO | lnchannel.Channel.[96889463461b28a505b071f5f1f0eba5c8efac4dfaa8eb1db542842bf8566c9e] | revoke_current_commitment
20230206T213736.021525Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230206T213736.021625Z |    DEBUG | util.profiler | WalletDB._write 0.0322 sec
20230206T213736.021753Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Sending REVOKE_AND_ACK
20230206T213736.092015Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: update_tabs
20230206T213736.092130Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0001 sec
20230206T213736.095926Z |    DEBUG | util.profiler | AddressList.update 0.0000 sec
20230206T213736.115238Z |     INFO | network | fee_estimates {25: 3002, 10: 3002, 5: 4205, 2: 15944}
20230206T213736.750954Z |     INFO | interface.[elx.bitske.com:50002] | skipping header 775353
20230206T213737.151630Z |     INFO | interface.[ex05.axalgo.com:50002] | skipping header 775353
20230206T213738.586269Z |     INFO | interface.[2ex.digitaleveryware.com:50002] | skipping header 775353
20230206T213738.837875Z |     INFO | interface.[electrum5.hodlister.co:50002] | skipping header 775353
20230206T213739.484841Z |     INFO | interface.[caleb.vegas:50002] | skipping header 775353
20230206T213739.980929Z |    DEBUG | lnworker.LNGossip | process_gossip 0 1 0
20230206T213739.981177Z |    DEBUG | channel_db.ChannelDB | add_channel_announcement: 0/0
20230206T213739.982249Z |    DEBUG | channel_db.ChannelDB | on_node_announcement: 0/1
20230206T213741.187168Z |     INFO | interface.[assuredly.not.fyi:50002] | skipping header 775353
20230206T213741.565110Z |     INFO | interface.[btce.iiiiiii.biz:50002] | skipping header 775353
20230206T213741.881840Z |     INFO | network | fee_estimates {25: 3002, 10: 3002, 5: 3989, 2: 15944}
20230206T213743.610113Z |     INFO | interface.[exs.dyshek.org:50002] | skipping header 775353
20230206T213745.500262Z |     INFO | channel_db.ChannelDB | Deleting 13 old policies
20230206T213745.500558Z |     INFO | channel_db.ChannelDB | Deleting 2 orphaned channels
20230206T213745.665255Z |     INFO | network | fee_estimates {25: 3002, 10: 3002, 5: 3988, 2: 15944}
20230206T213748.248147Z |     INFO | network | fee_estimates {25: 3002, 10: 3002, 5: 3987, 2: 15944}
20230206T213753.640135Z |     INFO | interface.[142.93.6.38:50002] | skipping header 775353
20230206T213808.895383Z |     INFO | network | fee_histogram [[2, 180031], [1, 2449012], [0, 77699574]]
20230206T213810.408313Z |     INFO | address_synchronizer.AddressSynchronizer.[<anonymized>] | removing tx from history 987e0dcb02a92acb853dde05dd9be811b5e11869ebbf4558ce75df7599dd37e3
20230206T213810.410619Z |     INFO | lnwatcher.LNWalletWatcher.[<anonymized>-LNW] | added redeem tx: our_ctx_to_local 775134x2404x1. prevout: b18d3e1b0d996a704594883c5a24f84c3a57a2e85852896926602254ba079a93:0
20230206T213810.598243Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: update_tabs
20230206T213810.598373Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0001 sec
20230206T213810.603842Z |    DEBUG | util.profiler | AddressList.update 0.0000 sec
20230206T213834.140516Z |     INFO | network | fee_estimates {25: 3002, 10: 3002, 5: 3988, 2: 15944}
20230206T213835.659316Z |     INFO | network | fee_estimates {25: 3002, 10: 3002, 5: 3987, 2: 15944}
20230206T213908.925123Z |     INFO | network | fee_histogram [[2, 278328], [1, 2893662], [0, 77701235]]
20230206T213945.549373Z |     INFO | channel_db.ChannelDB | Deleting 19 old policies
20230206T213945.549810Z |     INFO | channel_db.ChannelDB | Deleting 10 orphaned channels
20230206T214008.931391Z |     INFO | network | fee_histogram [[9, 105870], [2, 260923], [1, 3314879], [0, 77725876]]
20230206T214010.551472Z |     INFO | address_synchronizer.AddressSynchronizer.[<anonymized>] | removing tx from history cd57f8b394a45fc9e50778117d2af87184b2301013f15e3c781ff567f33e396f
20230206T214010.552102Z |     INFO | lnwatcher.LNWalletWatcher.[<anonymized>-LNW] | added redeem tx: our_ctx_to_local 775134x2404x1. prevout: b18d3e1b0d996a704594883c5a24f84c3a57a2e85852896926602254ba079a93:0
20230206T214010.594666Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: update_tabs
20230206T214010.594789Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0001 sec
20230206T214010.598638Z |    DEBUG | util.profiler | AddressList.update 0.0000 sec
20230206T214108.958910Z |     INFO | network | fee_histogram [[11, 101455], [7, 112466], [2, 268218], [1, 3652373], [0, 78408071]]
20230206T214110.622924Z |     INFO | address_synchronizer.AddressSynchronizer.[<anonymized>] | removing tx from history 320f18a1b0d44b9e666f1f9ed0830a5f166d847879175d7f1da20c3479584ec5
20230206T214110.623684Z |     INFO | lnwatcher.LNWalletWatcher.[<anonymized>-LNW] | added redeem tx: our_ctx_to_local 775134x2404x1. prevout: b18d3e1b0d996a704594883c5a24f84c3a57a2e85852896926602254ba079a93:0
20230206T214111.108123Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: update_tabs
20230206T214111.108538Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0004 sec
20230206T214111.127159Z |    DEBUG | util.profiler | AddressList.update 0.0000 sec
20230206T214145.571500Z |     INFO | channel_db.ChannelDB | Deleting 32 old policies
20230206T214145.571866Z |     INFO | channel_db.ChannelDB | Deleting 12 orphaned channels
20230206T214209.023133Z |     INFO | network | fee_histogram [[12, 114991], [9, 115423], [3, 103501], [2, 261788], [1, 3682557], [0, 78409075]]
20230206T214210.736291Z |     INFO | address_synchronizer.AddressSynchronizer.[<anonymized>] | removing tx from history a0df7fc12ce408ee941a86a93c9336a00b427e6c85e8f9a5e08fe0105cea8a53
20230206T214210.736941Z |     INFO | lnwatcher.LNWalletWatcher.[<anonymized>-LNW] | added redeem tx: our_ctx_to_local 775134x2404x1. prevout: b18d3e1b0d996a704594883c5a24f84c3a57a2e85852896926602254ba079a93:0
20230206T214211.106899Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: update_tabs
20230206T214211.107301Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0004 sec
20230206T214211.117350Z |    DEBUG | util.profiler | AddressList.update 0.0000 sec
20230206T214226.935399Z |     INFO | interface.[fullnode.titanconnect.ca:50002] | could connect 775354
20230206T214226.941014Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: refresh_tabs
20230206T214226.953501Z |    DEBUG | util.profiler | Abstract_Wallet.get_full_history 0.0123 sec
20230206T214226.971820Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0308 sec
20230206T214226.977326Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: refresh_tabs
20230206T214226.977413Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0001 sec
20230206T214229.389191Z |     INFO | interface.[elx.bitske.com:50002] | skipping header 775354
20230206T214230.058934Z |     INFO | interface.[electrum5.hodlister.co:50002] | skipping header 775354
20230206T214230.141259Z |     INFO | interface.[btce.iiiiiii.biz:50002] | skipping header 775354
20230206T214231.612062Z |     INFO | interface.[exs.dyshek.org:50002] | skipping header 775354
20230206T214232.722635Z |     INFO | interface.[assuredly.not.fyi:50002] | skipping header 775354
20230206T214233.025001Z |     INFO | interface.[2ex.digitaleveryware.com:50002] | skipping header 775354
20230206T214233.703341Z |     INFO | interface.[ex05.axalgo.com:50002] | skipping header 775354
20230206T214236.325110Z |     INFO | interface.[caleb.vegas:50002] | skipping header 775354
20230206T214240.245435Z |     INFO | interface.[142.93.6.38:50002] | skipping header 775354
20230206T214309.061168Z |     INFO | network | fee_histogram [[2, 266886], [1, 2572490], [0, 76892631]]
20230206T214310.783010Z |     INFO | address_synchronizer.AddressSynchronizer.[<anonymized>] | removing tx from history b439314b317cbb2543b270ac6f2336165fa23bf1a09857be4d08c9c8f39cd114
20230206T214310.784158Z |     INFO | lnwatcher.LNWalletWatcher.[<anonymized>-LNW] | added redeem tx: our_ctx_to_local 775134x2404x1. prevout: b18d3e1b0d996a704594883c5a24f84c3a57a2e85852896926602254ba079a93:0
20230206T214311.112178Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: update_tabs
20230206T214311.112601Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0004 sec
20230206T214311.122734Z |    DEBUG | util.profiler | AddressList.update 0.0000 sec
20230206T214345.598521Z |     INFO | channel_db.ChannelDB | Deleting 28 old policies
20230206T214345.599042Z |     INFO | channel_db.ChannelDB | Deleting 14 orphaned channels
20230206T214351.205587Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: HistoryList.update()
20230206T214351.210996Z |    DEBUG | util.profiler | Abstract_Wallet.get_full_history 0.0052 sec
20230206T214351.253902Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0483 sec
20230206T214409.125834Z |     INFO | network | fee_histogram [[9, 110281], [2, 347815], [1, 2906780], [0, 76894725]]
20230206T214410.831561Z |     INFO | address_synchronizer.AddressSynchronizer.[<anonymized>] | removing tx from history cd57f8b394a45fc9e50778117d2af87184b2301013f15e3c781ff567f33e396f
20230206T214410.832237Z |     INFO | lnwatcher.LNWalletWatcher.[<anonymized>-LNW] | added redeem tx: our_ctx_to_local 775134x2404x1. prevout: b18d3e1b0d996a704594883c5a24f84c3a57a2e85852896926602254ba079a93:0
20230206T214411.096151Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: update_tabs
20230206T214411.096290Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0001 sec
20230206T214411.100114Z |    DEBUG | util.profiler | AddressList.update 0.0000 sec
20230206T214416.892681Z |    DEBUG | util.profiler | AddressList.update 0.0000 sec
20230206T214416.987680Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized(2)>
20230206T214416.987806Z |    DEBUG | util.profiler | WalletDB._write 0.0512 sec
20230206T214428.791963Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230206T214428.792087Z |    DEBUG | util.profiler | WalletDB._write 0.0172 sec
20230206T214428.813381Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230206T214428.813514Z |    DEBUG | util.profiler | WalletDB._write 0.0171 sec
20230206T214428.813605Z |     INFO | lnworker.LNWallet.[<anonymized>] | pay_invoice starting session for RHASH=fcf96aed7b8ccdaafae80e29e615ba6b508fd2b9de88f4e809319238e904d72b
20230206T214428.813708Z |     INFO | lnworker.LNWallet.[<anonymized>] | invoice status triggered (2) for key fcf96aed7b8ccdaafae80e29e615ba6b508fd2b9de88f4e809319238e904d72b and status 4
20230206T214428.813993Z |     INFO | lnworker.LNWallet.[<anonymized>] | channels_with_funds: {(b'\x96\x88\x94cF\x1b(\xa5\x05\xb0q\xf5\xf1\xf0\xeb\xa5\xc8\xef\xacM\xfa\xa8\xeb\x1d\xb5B\x84+\xf8Vl\x9e', b'\x03\xcd\xe6\nc#\xf7\x12-Qx%Wf\xe3\x81\x14\xb4r.\xde\x08\xf7\xc9\xe0\xc5\xdf\x9b\x91,\xc2\x01\xd6'): 4940800312}
20230206T214428.814698Z |     INFO | lnworker.LNWallet.[<anonymized>] | suggest_split 10000000 returned 1 configurations
20230206T214428.814772Z |     INFO | lnworker.LNWallet.[<anonymized>] | trying split configuration: dict_values([[10000000]]) rating: 2.0000463281697494
20230206T214429.032837Z |     INFO | lnrouter.LNPathFinder | found a path
20230206T214429.034042Z |    DEBUG | util.profiler | LNPathFinder.find_path_for_payment 0.2183 sec
20230206T214429.034214Z |    DEBUG | util.profiler | LNWallet.create_route_for_payment 0.2185 sec
20230206T214429.034836Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | lnpeer.pay len(route)=3
20230206T214429.034935Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] |   0: edge=775351x1751x1 hop_data=<OnionHopsDataSingle. is_tlv_payload=True. payload={'amt_to_forward': {'amt_to_forward': 10002000}, 'outgoing_cltv_value': {'outgoing_cltv_value': 775645}, 'short_channel_id': {'short_channel_id': <ShortChannelID: 774536x996x1>}}. hmac=None>
20230206T214429.035078Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] |   1: edge=774536x996x1 hop_data=<OnionHopsDataSingle. is_tlv_payload=True. payload={'amt_to_forward': {'amt_to_forward': 10000000}, 'outgoing_cltv_value': {'outgoing_cltv_value': 775501}, 'short_channel_id': {'short_channel_id': <ShortChannelID: 695868x864x1>}}. hmac=None>
20230206T214429.035165Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] |   2: edge=695868x864x1 hop_data=<OnionHopsDataSingle. is_tlv_payload=True. payload={'amt_to_forward': {'amt_to_forward': 10000000}, 'outgoing_cltv_value': {'outgoing_cltv_value': 775501}, 'payment_data': {'payment_secret': b">F\xe3_^H\xab\x10\xaa\x9c\xec\xfcl\xf4%#J8/\xb2\xb7\xc3\xceL='X(\xbe+Tc", 'total_msat': 10000000, 'amount_msat': 10000000}}. hmac=None>
20230206T214429.037337Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | starting payment. len(route)=3.
20230206T214429.037718Z |     INFO | lnchannel.Channel.[96889463461b28a505b071f5f1f0eba5c8efac4dfaa8eb1db542842bf8566c9e] | add_htlc
20230206T214429.037860Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | starting payment. htlc: UpdateAddHtlc(amount_msat=10003010, payment_hash=fcf96aed7b8ccdaafae80e29e615ba6b508fd2b9de88f4e809319238e904d72b, cltv_expiry=775685, timestamp=1675719869, htlc_id=0)
20230206T214429.037944Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Sending UPDATE_ADD_HTLC
20230206T214429.038239Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | send_commitment. chan 775351x1751x1. ctn: 2.
20230206T214429.038315Z |     INFO | lnchannel.Channel.[96889463461b28a505b071f5f1f0eba5c8efac4dfaa8eb1db542842bf8566c9e] | sign_next_commitment 2
20230206T214429.040132Z |     INFO | transaction | adding signature for 03c3ce8f791eb7721c3e9571157bfc9e985aab39c1624ad2ea0d01a36fb08d75e4
20230206T214429.040534Z |    DEBUG | transaction | is_complete False
20230206T214429.042818Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Sending COMMITMENT_SIGNED
20230206T214429.059267Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230206T214429.059361Z |    DEBUG | util.profiler | WalletDB._write 0.0164 sec
20230206T214429.063543Z |     INFO | lnrouter.LNPathFinder | Adding inflight htlcs to graph (liquidity hints).
20230206T214429.063710Z |     INFO | lnworker.LNWallet.[<anonymized>] | amount inflight 10000000
20230206T214429.093275Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: update_tabs
20230206T214429.093446Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0002 sec
20230206T214429.097692Z |    DEBUG | util.profiler | AddressList.update 0.0000 sec
20230206T214429.137920Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Received REVOKE_AND_ACK
20230206T214429.138058Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | on_revoke_and_ack. chan 775351x1751x1. ctn: 1
20230206T214429.138124Z |     INFO | lnchannel.Channel.[96889463461b28a505b071f5f1f0eba5c8efac4dfaa8eb1db542842bf8566c9e] | receive_revocation
20230206T214429.155452Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230206T214429.155580Z |    DEBUG | util.profiler | WalletDB._write 0.0172 sec
20230206T214429.223060Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Received COMMITMENT_SIGNED
20230206T214429.223198Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | on_commitment_signed. chan 775351x1751x1. ctn: 2.
20230206T214429.223310Z |     INFO | lnchannel.Channel.[96889463461b28a505b071f5f1f0eba5c8efac4dfaa8eb1db542842bf8566c9e] | receive_new_commitment. ctn=2, len(htlc_sigs)=1
20230206T214429.227662Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | send_revoke_and_ack. chan 775351x1751x1. ctn: 1
20230206T214429.227736Z |     INFO | lnchannel.Channel.[96889463461b28a505b071f5f1f0eba5c8efac4dfaa8eb1db542842bf8566c9e] | revoke_current_commitment
20230206T214429.246490Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230206T214429.246598Z |    DEBUG | util.profiler | WalletDB._write 0.0165 sec
20230206T214429.246721Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Sending REVOKE_AND_ACK
20230206T214430.018108Z |    DEBUG | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | Received UPDATE_ADD_HTLC
20230206T214430.018260Z |     INFO | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | on_update_add_htlc. chan 695868x864x1. htlc=UpdateAddHtlc(amount_msat=10000000, payment_hash=fcf96aed7b8ccdaafae80e29e615ba6b508fd2b9de88f4e809319238e904d72b, cltv_expiry=775501, timestamp=1675719870, htlc_id=108)
20230206T214430.018650Z |     INFO | lnchannel.Channel.[695868x864x1] | receive_htlc
20230206T214430.056854Z |    DEBUG | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | Received COMMITMENT_SIGNED
20230206T214430.056994Z |     INFO | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | on_commitment_signed. chan 695868x864x1. ctn: 424.
20230206T214430.057103Z |     INFO | lnchannel.Channel.[695868x864x1] | receive_new_commitment. ctn=424, len(htlc_sigs)=1
20230206T214430.061451Z |     INFO | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | send_revoke_and_ack. chan 695868x864x1. ctn: 423
20230206T214430.061522Z |     INFO | lnchannel.Channel.[695868x864x1] | revoke_current_commitment
20230206T214430.111610Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized(2)>
20230206T214430.111730Z |    DEBUG | util.profiler | WalletDB._write 0.0478 sec
20230206T214430.111860Z |    DEBUG | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | Sending REVOKE_AND_ACK
20230206T214430.112455Z |     INFO | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | send_commitment. chan 695868x864x1. ctn: 424.
20230206T214430.112553Z |     INFO | lnchannel.Channel.[695868x864x1] | sign_next_commitment 424
20230206T214430.119212Z |     INFO | transaction | adding signature for 021153aa5529c9e796c7ce06b83566c7f35e87da3d30a290f1662043e6a724752d
20230206T214430.120039Z |    DEBUG | transaction | is_complete False
20230206T214430.123079Z |    DEBUG | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | Sending COMMITMENT_SIGNED
20230206T214430.171388Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized(2)>
20230206T214430.171502Z |    DEBUG | util.profiler | WalletDB._write 0.0483 sec
20230206T214430.309071Z |    DEBUG | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | Received REVOKE_AND_ACK
20230206T214430.309216Z |     INFO | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | on_revoke_and_ack. chan 695868x864x1. ctn: 423
20230206T214430.309280Z |     INFO | lnchannel.Channel.[695868x864x1] | receive_revocation
20230206T214430.357315Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized(2)>
20230206T214430.357439Z |    DEBUG | util.profiler | WalletDB._write 0.0479 sec
20230206T214430.362653Z |     INFO | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | maybe_fulfill_htlc. will FULFILL HTLC: chan 695868x864x1. htlc=UpdateAddHtlc(amount_msat=10000000, payment_hash=fcf96aed7b8ccdaafae80e29e615ba6b508fd2b9de88f4e809319238e904d72b, cltv_expiry=775501, timestamp=1675719870, htlc_id=108)
20230206T214430.410703Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized(2)>
20230206T214430.410821Z |    DEBUG | util.profiler | WalletDB._write 0.0480 sec
20230206T214430.410944Z |     INFO | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | _fulfill_htlc. chan 695868x864x1. htlc_id 108
20230206T214430.411024Z |     INFO | lnchannel.Channel.[695868x864x1] | settle_htlc
20230206T214430.411128Z |    DEBUG | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | Sending UPDATE_FULFILL_HTLC
20230206T214430.413815Z |     INFO | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | send_commitment. chan 695868x864x1. ctn: 425.
20230206T214430.413909Z |     INFO | lnchannel.Channel.[695868x864x1] | sign_next_commitment 425
20230206T214430.452845Z |     INFO | transaction | adding signature for 021153aa5529c9e796c7ce06b83566c7f35e87da3d30a290f1662043e6a724752d
20230206T214430.454072Z |    DEBUG | transaction | is_complete False
20230206T214430.454980Z |    DEBUG | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | Sending COMMITMENT_SIGNED
20230206T214430.512696Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized(2)>
20230206T214430.512823Z |    DEBUG | util.profiler | WalletDB._write 0.0575 sec
20230206T214430.533000Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Received UPDATE_FULFILL_HTLC
20230206T214430.533189Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | on_update_fulfill_htlc. chan 775351x1751x1. htlc_id 0
20230206T214430.533277Z |     INFO | lnchannel.Channel.[96889463461b28a505b071f5f1f0eba5c8efac4dfaa8eb1db542842bf8566c9e] | receive_htlc_settle
20230206T214430.551457Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230206T214430.551596Z |    DEBUG | util.profiler | WalletDB._write 0.0181 sec
20230206T214430.592736Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: update_tabs
20230206T214430.592868Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0001 sec
20230206T214430.637654Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Received COMMITMENT_SIGNED
20230206T214430.637823Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | on_commitment_signed. chan 775351x1751x1. ctn: 3.
20230206T214430.637944Z |     INFO | lnchannel.Channel.[96889463461b28a505b071f5f1f0eba5c8efac4dfaa8eb1db542842bf8566c9e] | receive_new_commitment. ctn=3, len(htlc_sigs)=0
20230206T214430.646986Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | send_revoke_and_ack. chan 775351x1751x1. ctn: 2
20230206T214430.652160Z |     INFO | lnchannel.Channel.[96889463461b28a505b071f5f1f0eba5c8efac4dfaa8eb1db542842bf8566c9e] | revoke_current_commitment
20230206T214430.692130Z |    DEBUG | util.profiler | AddressList.update 0.0000 sec
20230206T214430.707278Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230206T214430.707410Z |    DEBUG | util.profiler | WalletDB._write 0.0266 sec
20230206T214430.707536Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Sending REVOKE_AND_ACK
20230206T214430.707880Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | send_commitment. chan 775351x1751x1. ctn: 3.
20230206T214430.707962Z |     INFO | lnchannel.Channel.[96889463461b28a505b071f5f1f0eba5c8efac4dfaa8eb1db542842bf8566c9e] | sign_next_commitment 3
20230206T214430.709421Z |     INFO | transaction | adding signature for 03c3ce8f791eb7721c3e9571157bfc9e985aab39c1624ad2ea0d01a36fb08d75e4
20230206T214430.709793Z |    DEBUG | transaction | is_complete False
20230206T214430.710023Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Sending COMMITMENT_SIGNED
20230206T214430.726671Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230206T214430.726788Z |    DEBUG | util.profiler | WalletDB._write 0.0166 sec
20230206T214430.731248Z |    DEBUG | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | Received REVOKE_AND_ACK
20230206T214430.731350Z |     INFO | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | on_revoke_and_ack. chan 695868x864x1. ctn: 424
20230206T214430.731474Z |     INFO | lnchannel.Channel.[695868x864x1] | receive_revocation
20230206T214430.780858Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized(2)>
20230206T214430.780980Z |    DEBUG | util.profiler | WalletDB._write 0.0491 sec
20230206T214430.792425Z |    DEBUG | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | Received COMMITMENT_SIGNED
20230206T214430.792567Z |     INFO | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | on_commitment_signed. chan 695868x864x1. ctn: 425.
20230206T214430.792683Z |     INFO | lnchannel.Channel.[695868x864x1] | receive_new_commitment. ctn=425, len(htlc_sigs)=0
20230206T214430.794642Z |     INFO | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | send_revoke_and_ack. chan 695868x864x1. ctn: 424
20230206T214430.794723Z |     INFO | lnchannel.Channel.[695868x864x1] | revoke_current_commitment
20230206T214430.844689Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized(2)>
20230206T214430.844808Z |    DEBUG | util.profiler | WalletDB._write 0.0481 sec
20230206T214430.844932Z |    DEBUG | lnpeer.Peer.[LNWallet, 03864ef025-92b91f16] | Sending REVOKE_AND_ACK
20230206T214430.994476Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | Received REVOKE_AND_ACK
20230206T214430.994866Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-20d5f5b3] | on_revoke_and_ack. chan 775351x1751x1. ctn: 2
20230206T214430.995059Z |     INFO | lnchannel.Channel.[96889463461b28a505b071f5f1f0eba5c8efac4dfaa8eb1db542842bf8566c9e] | receive_revocation
20230206T214431.035710Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230206T214431.035887Z |    DEBUG | util.profiler | WalletDB._write 0.0400 sec
20230206T214431.036332Z |     INFO | lnrouter.LNPathFinder | report 775351x1751x1 to be able to forward 10000000 msat
20230206T214431.036521Z |     INFO | lnrouter.LNPathFinder | report 774536x996x1 to be able to forward 10000000 msat
20230206T214431.036647Z |     INFO | lnrouter.LNPathFinder | report 695868x864x1 to be able to forward 10000000 msat
20230206T214431.036749Z |     INFO | lnrouter.LNPathFinder | Removing inflight htlcs to graph (liquidity hints).
20230206T214431.036866Z |     INFO | lnworker.LNWallet.[<anonymized>] | pay_invoice ending session for RHASH=fcf96aed7b8ccdaafae80e29e615ba6b508fd2b9de88f4e809319238e904d72b. success=True
20230206T214431.055788Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230206T214431.055919Z |    DEBUG | util.profiler | WalletDB._write 0.0189 sec
20230206T214431.059505Z |     INFO | lnworker.LNWallet.[<anonymized>] | invoice status triggered (2) for key fcf96aed7b8ccdaafae80e29e615ba6b508fd2b9de88f4e809319238e904d72b and status 3```

[ondra-novak]

I just compared these logs (by my eyes) and found, that the first log doesn't contain event "on_funding_locked". So I opened original version of the log and I was able to find this event before the channel is switched to FUNDED state:

The message FUNDING_LOCKED is received while the Electrum still don't see sufficient depth. Can be this an issue?

20230205T111600.226940Z |     INFO | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | funding tx is still not at sufficient depth. actual depth: 5
20230205T111600.680844Z |     INFO | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | funding tx is still not at sufficient depth. actual depth: 5
20230205T111607.652883Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | Received FUNDING_LOCKED
20230205T111607.653016Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | on_funding_locked. channel: 0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60
20230205T111607.669775Z |    DEBUG | util.profiler | WalletDB._write 0.0167 sec
20230205T111609.847584Z |     INFO | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | funding tx is still not at sufficient depth. actual depth: 5
20230205T111612.062566Z |     INFO | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | funding tx is still not at sufficient depth. actual depth: 5
20230205T111612.232967Z |     INFO | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | funding tx is still not at sufficient depth. actual depth: 5
20230205T111613.444054Z |     INFO | channel_db.ChannelDB | Deleting 2 old policies
20230205T111616.958453Z |     INFO | interface.[2electrumx.hopto.me:56022] | could connect 775139
20230205T111616.963603Z |    DEBUG | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | Setting channel state: OPENING -> FUNDED
20230205T111616.968843Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: refresh_tabs
20230205T111616.979883Z |    DEBUG | util.profiler | WalletDB._write 0.0162 sec
20230205T111616.986573Z |    DEBUG | util.profiler | Abstract_Wallet.get_full_history 0.0064 sec
20230205T111616.991634Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0228 sec
20230205T111616.992508Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-4548f074] | Sending FUNDING_LOCKED
20230205T111617.002068Z |    DEBUG | lnchannel.Channel.[0958ee8fe66a0845149a40418bc707d9f5f87d2f49e2dfed2f42b9958d74ca60] | Setting channel state: FUNDED -> OPEN
20230205T111617.041349Z |    DEBUG | util.profiler | WalletDB._write 0.0392 sec

[ondra-novak]

AUTOMATIC FORCE CLOSE!!!!

20230212T211906.567961Z |     INFO | lnchannel.Channel.[03f294e5643ed7402dfb06a0089dfec5fa3f4884ac7733357c0e07350f521252] | funding tx is still not at sufficient depth. actual depth: 5
20230212T211907.249330Z |     INFO | lnchannel.Channel.[03f294e5643ed7402dfb06a0089dfec5fa3f4884ac7733357c0e07350f521252] | funding tx is still not at sufficient depth. actual depth: 5
20230212T211911.207936Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | Received FUNDING_LOCKED
20230212T211911.208076Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | on_funding_locked. channel: 03f294e5643ed7402dfb06a0089dfec5fa3f4884ac7733357c0e07350f521252
20230212T211911.226360Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230212T211911.226558Z |    DEBUG | util.profiler | WalletDB._write 0.0184 sec
20230212T211912.501416Z |     INFO | lnchannel.Channel.[03f294e5643ed7402dfb06a0089dfec5fa3f4884ac7733357c0e07350f521252] | funding tx is still not at sufficient depth. actual depth: 5
20230212T211915.154951Z |     INFO | interface.[btc.lastingcoin.net:50002] | could connect 776243
20230212T211915.159208Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: refresh_tabs
20230212T211915.168421Z |    DEBUG | util.profiler | Abstract_Wallet.get_full_history 0.0082 sec
20230212T211915.174428Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0152 sec
20230212T211915.180099Z |    DEBUG | lnchannel.Channel.[03f294e5643ed7402dfb06a0089dfec5fa3f4884ac7733357c0e07350f521252] | Setting channel state: OPENING -> FUNDED
20230212T211915.196856Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230212T211915.196987Z |    DEBUG | util.profiler | WalletDB._write 0.0168 sec
20230212T211915.199453Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | Sending FUNDING_LOCKED
20230212T211915.200725Z |    DEBUG | lnchannel.Channel.[03f294e5643ed7402dfb06a0089dfec5fa3f4884ac7733357c0e07350f521252] | Setting channel state: FUNDED -> OPEN
20230212T211915.226389Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230212T211915.226528Z |    DEBUG | util.profiler | WalletDB._write 0.0257 sec
20230212T211915.228150Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | CHANNEL OPENING COMPLETED (776238x1553x1)
20230212T211915.242947Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | updating fee to bump remote ctn
20230212T211915.243083Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | (chan: 776238x1553x1) current pending feerate 3755. new feerate 3756
20230212T211915.246767Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | Sending UPDATE_FEE
20230212T211915.247150Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | send_commitment. chan 776238x1553x1. ctn: 1.
20230212T211915.247238Z |     INFO | lnchannel.Channel.[03f294e5643ed7402dfb06a0089dfec5fa3f4884ac7733357c0e07350f521252] | sign_next_commitment 1
20230212T211915.248748Z |     INFO | transaction | adding signature for 03b4149f5f33e7a893e8ed189ac359b655deb7052baee79e1df001a8d305e2d09c
20230212T211915.249647Z |    DEBUG | transaction | is_complete False
20230212T211915.250417Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | Sending COMMITMENT_SIGNED
20230212T211915.273995Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230212T211915.274324Z |    DEBUG | util.profiler | WalletDB._write 0.0235 sec
20230212T211915.907661Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | Received ERROR
20230212T211915.907861Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | remote peer sent error [DO NOT TRUST THIS MESSAGE]: rejected commitment: commit_height=1, invalid_commit_sig=304402205ffed5b844d11c1b8f5e4be6dfb17287265eef80ffd975195c76ee6a9ff424250220173cd11940a49db06fe524d24fbf7eb9180f93b8117536c78eb7db8904823304, commit_tx=020000000103f294e5643ed7402dfb06a0089dfec5fa3f4884ac7733357c0e07350f52125301000000007268e7800161f5ff0000000000160014aec8d8fd4e9bcb41de8f241c4eef3d2a9811e5ece6fa9d20, sig_hash=ff310d4f9219d30ff57064b885d4792314d012fd2c8e6bc5f7d3873ae412b425. chan_id=03f294e5643ed7402dfb06a0089dfec5fa3f4884ac7733357c0e07350f521252
20230212T211915.910200Z |     INFO | transaction | adding signature for 03b4149f5f33e7a893e8ed189ac359b655deb7052baee79e1df001a8d305e2d09c
20230212T211915.910624Z |    DEBUG | transaction | is_complete False
20230212T211915.910729Z |    DEBUG | lnchannel.Channel.[03f294e5643ed7402dfb06a0089dfec5fa3f4884ac7733357c0e07350f521252] | Setting channel state: OPEN -> FORCE_CLOSING
20230212T211915.927801Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230212T211915.927941Z |    DEBUG | util.profiler | WalletDB._write 0.0171 sec
20230212T211915.940433Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | Disconnecting: GracefulDisconnect()
20230212T211915.969225Z |     INFO | network | success: broadcasting force-close 20009da300a2fe7c7149badbc2ee50a0b92d4a880e3e45c9f9b7b0f234435386
20230212T211917.869314Z |     INFO | synchronizer.[<anonymized>] | receiving history bc1qyygptsqx39gp3rs750xvtmh86pcr38sqkl2et207xc7fygj2xe6smkw2y2 2
20230212T211917.918457Z |     INFO | address_synchronizer.AddressSynchronizer.[<anonymized>] | set_up_to_date: False
20230212T211917.920927Z |     INFO | wallet.Standard_Wallet.[<anonymized>] | set_up_to_date: False
20230212T211917.977340Z |     INFO | interface.[electrum.emzy.de:50002] | skipping header 776243
20230212T211917.980091Z |     INFO | synchronizer.[<anonymized>] | receiving history bc1q7axdm7su8hvqa3fwf93z9xvet52kg60dnqy9zurn3v9srcag3xmq32ex6e 1
20230212T211918.012933Z |     INFO | address_synchronizer.AddressSynchronizer.[<anonymized>] | set_up_to_date: True
20230212T211918.021518Z |    DEBUG | lnsweep | found our ctx: bc1q7axdm7su8hvqa3fwf93z9xvet52kg60dnqy9zurn3v9srcag3xmq32ex6e bc1qsulvjs339juccwz4v0krjnqxjhe2w92c30m0fx
20230212T211918.024149Z |     INFO | lnchannel.Channel.[03f294e5643ed7402dfb06a0089dfec5fa3f4884ac7733357c0e07350f521252] | we force closed
20230212T211918.027134Z |     INFO | lnwatcher.LNWalletWatcher.[<anonymized>-LNW] | added redeem tx: our_ctx_to_local 776238x1553x1. prevout: 20009da300a2fe7c7149badbc2ee50a0b92d4a880e3e45c9f9b7b0f234435386:0
20230212T211918.051542Z |     INFO | transaction | adding signature for 03b4149f5f33e7a893e8ed189ac359b655deb7052baee79e1df001a8d305e2d09c
20230212T211918.052256Z |    DEBUG | transaction | is_complete False
20230212T211918.087548Z |     INFO | storage.WalletStorage | saved /home/ondra/.electrum/wallets/<anonymized>
20230212T211918.087802Z |    DEBUG | util.profiler | WalletDB._write 0.0350 sec
20230212T211918.088035Z |     INFO | wallet.Standard_Wallet.[<anonymized>] | set_up_to_date: True
20230212T211918.284341Z |     INFO | gui.qt.history_list.HistoryModel | refreshing... reason: update_tabs
20230212T211918.307091Z |    DEBUG | util.profiler | Abstract_Wallet.get_full_history 0.0224 sec
20230212T211918.325873Z |    DEBUG | util.profiler | HistoryModel.refresh 0.0415 sec
20230212T211918.350768Z |    DEBUG | util.profiler | AddressList.update 0.0000 sec
20230212T211918.372017Z |     INFO | gui.qt.main_window.[<anonymized>] | Notifying GUI about new transactions
20230212T211919.454382Z |     INFO | interface.[e.keff.org:50002] | skipping header 776243
20230212T211919.466164Z |     INFO | transaction | adding signature for 03b4149f5f33e7a893e8ed189ac359b655deb7052baee79e1df001a8d305e2d09c
20230212T211919.466902Z |    DEBUG | transaction | is_complete False
20230212T211921.751762Z |     INFO | interface.[stavver.dyshek.org:50002] | skipping header 776243
20230212T211921.767417Z |     INFO | transaction | adding signature for 03b4149f5f33e7a893e8ed189ac359b655deb7052baee79e1df001a8d305e2d09c
20230212T211921.769167Z |    DEBUG | transaction | is_complete False
20230212T211922.712915Z |     INFO | network | fee_histogram [[4, 162960], [2, 68480], [1, 4570494], [0, 185358599]]
20230212T211923.810695Z |     INFO | address_synchronizer.AddressSynchronizer.[<anonymized>] | removing tx from history 899ef0055e5cfad5f5098965358bf2f8196fa91260402406c5cb39ae5ccb5e6e
20230212T211923.811340Z |     INFO | lnwatcher.LNWalletWatcher.[<anonymized>-LNW] | added redeem tx: our_ctx_to_local 775134x2404x1. prevout: b18d3e1b0d996a704594883c5a24f84c3a57a2e85852896926602254ba079a93:0
20230212T211923.813191Z |     INFO | address_synchronizer.AddressSynchronizer.[<anonymized>] | removing tx from history de3a1da277f6ba3086a294870bcd655f9f4058c87b09d9c152aa6c8f282ce416
20230212T211923.813772Z |     INFO | lnwatcher.LNWalletWatcher.[<anonymized>-LNW] | added redeem tx: our_ctx_to_local 776238x1553x1. prevout: 20009da300a2fe7c7149badbc2ee50a0b92d4a880e3e45c9f9b7b0f234435386:0

My suggestion - a rare bug in the signature calculation. Please focus on this, run some tests, try a lot of signatures, probably some combinations of bytes or calculation state leads to different signature. Different SSL library?

[SomberNight]

Thanks for the new log. Technically it looks somewhat different from the original issue (on the surface), but the root cause might very well be the same.

20230212T211915.199453Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | Sending FUNDING_LOCKED
20230212T211915.200725Z |    DEBUG | lnchannel.Channel.[03f294e5643ed7402dfb06a0089dfec5fa3f4884ac7733357c0e07350f521252] | Setting channel state: FUNDED -> OPEN
20230212T211915.228150Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | CHANNEL OPENING COMPLETED (776238x1553x1)
20230212T211915.242947Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | updating fee to bump remote ctn
20230212T211915.243083Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | (chan: 776238x1553x1) current pending feerate 3755. new feerate 3756
20230212T211915.246767Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | Sending UPDATE_FEE
20230212T211915.247150Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | send_commitment. chan 776238x1553x1. ctn: 1.
20230212T211915.250417Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | Sending COMMITMENT_SIGNED
20230212T211915.907661Z |    DEBUG | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | Received ERROR
20230212T211915.907861Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | remote peer sent error [DO NOT TRUST THIS MESSAGE]: rejected commitment: commit_height=1, invalid_commit_sig=304402205ffed5b844d11c1b8f5e4be6dfb17287265eef80ffd975195c76ee6a9ff424250220173cd11940a49db06fe524d24fbf7eb9180f93b8117536c78eb7db8904823304, commit_tx=020000000103f294e5643ed7402dfb06a0089dfec5fa3f4884ac7733357c0e07350f52125301000000007268e7800161f5ff0000000000160014aec8d8fd4e9bcb41de8f241c4eef3d2a9811e5ece6fa9d20, sig_hash=ff310d4f9219d30ff57064b885d4792314d012fd2c8e6bc5f7d3873ae412b425. chan_id=03f294e5643ed7402dfb06a0089dfec5fa3f4884ac7733357c0e07350f521252

Based on the error message, the remote (bfx-lnd1 - 03cde60a6323f7122d5178255766e38114b4722ede08f7c9e0c5df9b912cc201d6) is running lnd. (code here)

The funding tx outpoint is 5312520f35070e7c353377ac84483ffac5fe9d08a006fb2d40d73e64e594f203:1.

Note that we are updating the feerate:

20230212T211915.243083Z |     INFO | lnpeer.Peer.[LNWallet, 03cde60a63-b218bbf7] | (chan: 776238x1553x1) current pending feerate 3755. new feerate 3756

abs fee for the commitment tx (msat):

>>> 3755 * 724 // 1000 * 1000
2718000
>>> 3756 * 724 // 1000 * 1000
2719000

The commit_tx lnd sends it is checking our sig against:
commit_tx=020000000103f294e5643ed7402dfb06a0089dfec5fa3f4884ac7733357c0e07350f52125301000000007268e7800161f5ff0000000000160014aec8d8fd4e9bcb41de8f241c4eef3d2a9811e5ece6fa9d20
The fee lnd expects to be paid:

>>> fee=16777215-16774497
>>> fee
2718

It looks like the remote is incorrectly still calculating with the old feerate.

---

The sig that we sent is for using the new feerate, it validates if I manually modify the output value sat of the commit tx lnd expects:

>>> from electrum.crypto import sha256d
>>> from electrum import ecc
>>> from electrum.transaction import tx_from_any, PartialTransaction
>>>
>>> pubkey1 = bytes.fromhex("02d39abcc2e4a4496bc664e2c1c15e9960bc76c8bff7a5bc68bd79c9eb2f6476c6")
>>> pubkey2 = bytes.fromhex("03b4149f5f33e7a893e8ed189ac359b655deb7052baee79e1df001a8d305e2d09c")
>>>
>>> tx = tx_from_any("020000000103f294e5643ed7402dfb06a0089dfec5fa3f4884ac7733357c0e07350f52125301000000007268e7800161f5ff0000000000160014aec8d8fd4e9bcb41de8f241c4eef3d2a9811e5ece6fa9d20")
>>> tx = PartialTransaction.from_tx(tx)
>>> txin = tx._inputs[0]
>>> txin.script_type = 'p2wsh'
>>> txin.pubkeys = sorted([pubkey1, pubkey2])
>>> txin.num_sig = 2
>>> txin._trusted_value_sats = 16777215  # funding_sat
>>>
>>> tx._outputs[0].value = tx._outputs[0].value - 1  # hack to change tx to use new feerate
>>>
>>> sig = bytes.fromhex("304402205ffed5b844d11c1b8f5e4be6dfb17287265eef80ffd975195c76ee6a9ff424250220173cd11940a49db06fe524d24fbf7eb9180f93b8117536c78eb7db8904823304")
>>> sig = ecc.sig_string_from_der_sig(sig)
>>>
>>> preimage_hex = tx.serialize_preimage(0)
>>> pre_hash = sha256d(bytes.fromhex(preimage_hex))
>>>
>>> ecc.verify_signature(pubkey1, sig, pre_hash)
False
>>> ecc.verify_signature(pubkey2, sig, pre_hash)
True

The issue seems to be similar to ElementsProject/lightning#3341
which by the looks of it was worked around in c-lightning in ElementsProject/lightning#3634, instead of having the bug fixed in lnd...

I will try to open a bug report for lnd.