Failing HTLC with payment_hash: expired payment

[AnthonyRonning]

I'm trying to figure out why I occasionally get this error on invoices that should not be expired, typically happens to me on brand new instances.

2023-06-08 18:53:55.097 DEBUG [mutiny_core::event:427] EVENT: PendingHTLCsForwardable: 100ms, processing...
2023-06-08 18:53:55.317 TRACE [lightning::ln::inbound_payment:380] Failing HTLC with payment_hash bd2a6e0f7cf3767cda376f9e79f01dea8ead4ad2e4b33453ca8227675c664b7d: expired payment
2023-06-08 18:53:55.317 TRACE [lightning::ln::channelmanager:3604] Failing new HTLC with payment_hash bd2a6e0f7cf3767cda376f9e79f01dea8ead4ad2e4b33453ca8227675c664b7d as payment verification failed
2023-06-08 18:53:55.319 TRACE [lightning::ln::channelmanager:4103] Failing HTLC with payment_hash bd2a6e0f7cf3767cda376f9e79f01dea8ead4ad2e4b33453ca8227675c664b7d backwards from us with HTLC error code 16399
2023-06-08 18:53:55.320 DEBUG [mutiny_core::event:424] EVENT: HTLCHandlingFailed, ignored

rust-lightning/lightning/src/ln/inbound_payment.rs

Lines 379 to 382 in b6787a4

	if expiry < highest_seen_timestamp {
	log_trace!(logger, "Failing HTLC with payment_hash {}: expired payment", log_bytes!(payment_hash.0));
	return Err(())
	}

If I'm following the code correctly, this gets updated via best_block_updated:

rust-lightning/lightning/src/ln/channelmanager.rs

Line 6444 in b6787a4

max_time!(self.highest_seen_timestamp);

So I added a log before we called that to make sure that we're providing it a good timestamp, and from the same failed invoice above, this is the timestamp from the last time it was called before the failure:

2023-06-08 18:53:36.799 INFO  [mutiny_core::esplora:220] Starting transaction sync.
2023-06-08 18:53:36.920 DEBUG [mutiny_core::esplora:332] Updating best block header time: 1686250398
2023-06-08 18:53:36.921 TRACE [lightning::ln::channelmanager:6076] New best block: 0000012e841f0c6c4b8ec5ec3c3b2566e1e14ffa7413c4d182e1c78d79ae5de5 at height 139572
2023-06-08 18:53:36.923 DEBUG [mutiny_core::esplora:332] Updating best block header time: 1686250398
2023-06-08 18:53:36.924 DEBUG [lightning::chain::chainmonitor:612] New best block 0000012e841f0c6c4b8ec5ec3c3b2566e1e14ffa7413c4d182e1c78d79ae5de5 at height 139572 provided via best_block_updated
2023-06-08 18:53:36.926 TRACE [mutiny_core::background:656] Persisting ChannelManager...
2023-06-08 18:53:36.927 TRACE [mutiny_core::background:656] Done persisting ChannelManager.
2023-06-08 18:53:36.954 INFO  [mutiny_core::esplora:316] Finished transaction sync.

The invoice was:

lntbs75u1pjgyge6dqqnp4q2rzvkj5h0rz56kwx5z572pk42vnshg48a9qhq0dycgy207j5mnrzpp5h54xurmu7dm8ek3hd708nuqaa2826jkjujeng572sgnkwhrxfd7ssp5mn9e7x55gq75vvrx08vyhwkx9ulh2rykax57q8shaeveuqjjmm0s9qyysgqcqzptxqrpwusumuzwvetqwmzsqh4kwum5vz7txhtm9e2c7f7q3yz4j40t2xuqzx8mrrwk0x5dtazdrzud73v3jzcg8fuzz029drxrhhk8vazn2v9aspzvjshm

Which has a timestamp of 1686250298 with an expiry of 1500, so it should it should not be below highest seen of 1686250398.

Perhaps could the max time function not be working properly? Or we have some other time race going on? Or is expiry < highest_seen_timestamp correct? Perhaps just a naming issue but expiry is relative, so 1500 would be below timestamp and would cause the problem too, I would expect it to be invoice_timestamp + expiry < highest_seen_timestamp

[TheBlueMatt]

Mmm, so I think what's going on here is we haven't connected any blocks when we create the invoice - create_invoice_from_channelmanager_and_duration_since_epoch calls ChannelManager::create_inbound_payment which uses highest_seen_timestamp (plus the invoice expiry plus two hours) as the inbound payment expiry time, which is zero plus some offset. Thus we fail the inbound payment.

There's a few potential fixes to this -

• we could simply require that users connect one block before using the ChannelManager/call best_block_updated on the current tip. This is kinda dumb
• We could add a "current timestamp" or "latest block timestamp" argument to ChannelManager::new/via ChainParameters
• we could take a current timestamp in ChannelManager::create_inbound_payment, which the invoice utils could easily provide, but makes it less general.

[AnthonyRonning]

Just from my naive opinion, the 2nd option there does sound like a good one.

Just so I'm understanding it correctly, it sounds like there's a little bit of in memory state then for invoices? When the invoice is created, this is set in stone so it doesn't matter if syncing completes by the time the payment is received? Trying to think about how to solve this in the interim.

[TheBlueMatt]

Just so I'm understanding it correctly, it sounds like there's a little bit of in memory state then for invoices? When the invoice is created, this is set in stone so it doesn't matter if syncing completes by the time the payment is received? Trying to think about how to solve this in the interim.

Its not in memory, its hidden in the invoice's payment_secret, but, yes, we store the expiry time (cryptographically committed to) in the invoice.

[AnthonyRonning]

we could simply require that users connect one block before using the ChannelManager/call best_block_updated on the current tip

I'm trying to figure out how to work around this now. What exactly do you mean by "connect one block"? We are trying to make sure BDK syncs first before creating the first invoice but it's still not working.

Can we create invoices that don't hide expiry time into it? I don't really see a reason for that when expiry and timestamp already exists as a concept. Why does it have to be encoded again and basing it on block?

Nevermind, rebuilt and tested a dozen times, think it's working.

[AnthonyRonning]

It's more reliable now but still somehow getting expired payments. We now wait until we are synced for the first time before creating an invoice but from the logs below, I still got this on a fresh node.

2023-06-22 16:27:50.737 TRACE [mutiny_core::fees:126] Retrieved fees from mempool
2023-06-22 16:27:50.738 INFO  [mutiny_core::nodemanager:762] Updated fee estimates!
2023-06-22 16:27:50.740 INFO  [mutiny_core::esplora:220] Starting transaction sync.
2023-06-22 16:27:51.113 INFO  [mutiny_core::node:278] creating lsp client
2023-06-22 16:27:51.133 TRACE [mutiny_core::background:575] Calling ChannelManager's timer_tick_occurred on startup
2023-06-22 16:27:51.137 TRACE [mutiny_core::fees:160] Got fee rate from saved cache!
2023-06-22 16:27:51.140 TRACE [mutiny_core::background:575] Rebroadcasting monitor's pending claims on startup
2023-06-22 16:27:51.916 INFO  [mutiny_core::esplora:316] Finished transaction sync.
...
2023-06-22 16:28:00.968 INFO  [mutiny_core::nodemanager:1218] We are synced!
...
2023-06-22 16:28:58.638 INFO  [mutiny_core::node:733] SUCCESS: generated invoice: lntbs75u1pjfgak2dqqnp4qtuuqa9pfudq7mde9pf9sdteswnh2uauccm4fmyjw5zu8nx90ehpvpp50y4uvpummcxkm6jhl77hw529y5nyzd4zdsd367ad06ywzhcasa0qsp53rutfxmplu9kwrshtc0fnln2ajyvgpjrg8pea6uhmgy8agm5udqq9qyysgqcqzptxqrpwusp9u2h8c3jq0jamzcp2d73z4qtl06v992mnc7rp7rrghtg8vtmh4nmlynkym2pz2nf3ahf8749eupxgqulscy4kgs3s4353q5pq06qqphr8hun
...
2023-06-22 16:29:19.252 TRACE [lightning::ln::peer_handler:1381] Received message UpdateAddHTLC(UpdateAddHTLC { channel_id: [82, 51, 38, 20, 173, 85, 212, 56, 229, 134, 158, 132, 16, 11, 82, 133, 140, 201, 57, 224, 17, 148, 175, 186, 252, 185, 210, 100, 55, 32, 158, 98], htlc_id: 0, amount_msat: 7500000, payment_hash: PaymentHash([121, 43, 198, 7, 155, 222, 13, 109, 234, 87, 255, 189, 119, 81, 69, 37, 38, 65, 54, 162, 108, 27, 29, 123, 173, 126, 136, 225, 95, 29, 135, 94]), cltv_expiry: 178102, onion_routing_packet: OnionPacket version 0 with hmac [13, 17, 23, 152, 53, 46, 89, 67, 146, 240, 98, 132, 91, 127, 223, 109, 74, 249, 51, 31, 27, 202, 60, 20, 82, 199, 131, 178, 78, 87, 35, 214] }) from 0366abc8eb4da61e31a8d2c4520d31cabdf58cc5250f855657397f3dd62493938a
2023-06-22 16:29:19.261 TRACE [mutiny_core::background:575] Persisting ChannelManager...
2023-06-22 16:29:19.263 TRACE [mutiny_core::background:575] Done persisting ChannelManager.
2023-06-22 16:29:19.555 TRACE [mutiny_core::networking::socket:77] received binary data from websocket
2023-06-22 16:29:19.557 TRACE [lightning::ln::peer_handler:1381] Received message CommitmentSigned(CommitmentSigned { channel_id: [82, 51, 38, 20, 173, 85, 212, 56, 229, 134, 158, 132, 16, 11, 82, 133, 140, 201, 57, 224, 17, 148, 175, 186, 252, 185, 210, 100, 55, 32, 158, 98], signature: 30440220447cee65fbc00b9636310761636da7c08b17cbbfaf23547acfe3c4184b20873702201b43fd9e15f22fe80c1cedb3f687c58af508f09d7158e0eb5537062a3ba07b3a, htlc_signatures: [30440220582846c47dc0738afe27fbd82bcaf275101fe4271518bb687ea822b211ef3fe2022009e48509f6cadfd7199f045e2254b936e1ca32eff13f7734e846208d7944fcfe] }) from 0366abc8eb4da61e31a8d2c4520d31cabdf58cc5250f855657397f3dd62493938a
2023-06-22 16:29:19.569 TRACE [lightning::ln::channel:1519] Building commitment transaction number 281474976710654 (really 1 xor 109198741898697) for channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62 for us, generated by remote with fee 253...
2023-06-22 16:29:19.569 TRACE [lightning::ln::channel:1580]    ...including inbound RemoteAnnounced HTLC 0 (hash 792bc6079bde0d6dea57ffbd77514525264136a26c1b1d7bad7e88e15f1d875e) with value 7500000
2023-06-22 16:29:19.569 TRACE [lightning::ln::channel:1685]    ...including to_remote output with value 100860
2023-06-22 16:29:19.571 TRACE [lightning::ln::channel:3094] Checking commitment tx signature 447cee65fbc00b9636310761636da7c08b17cbbfaf23547acfe3c4184b2087371b43fd9e15f22fe80c1cedb3f687c58af508f09d7158e0eb5537062a3ba07b3a by key 03a25f00d1f17232aaf52c6f76f3f71553a552709c713d2f4063c0e3459e92092c against tx 020000000152332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e630100000000d0506380024c1d000000000000220020df49b8595e971e8c034d97ed83d451e4b064283fc60aa0e47076cc1feaf0c4cdfc89010000000000160014c34f23512579f07b5a0b9b056652cb145cb31252c8853820 (sighash a0e6dfd01b2061c2f7e19e0efc0b23ada6672c969d56a9021c8fb4f69f8656b2) with redeemscript 47522102c0025cf6ef3c6caae2e0fbe69027365ee50faa516c7762bc6822f2b69d8d2fb42103a25f00d1f17232aaf52c6f76f3f71553a552709c713d2f4063c0e3459e92092c52ae in channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62
2023-06-22 16:29:19.581 TRACE [lightning::ln::channel:3165] Checking HTLC tx signature 582846c47dc0738afe27fbd82bcaf275101fe4271518bb687ea822b211ef3fe209e48509f6cadfd7199f045e2254b936e1ca32eff13f7734e846208d7944fcfe by key 03addb27635e80ee06e62e083ae36cefd17924f8f3a7035745879ee7e3453b0e9f against tx 0200000001212da262f9ed6121734aa29d890244c12f14390ae503d01088ea88c30e2a0c69000000000000000000019b1c000000000000220020ced99b2f8dfa06551c9115929ed8fde36b546d2176a765f969073457ca5615ce00000000 (sighash 7832fb5b9dc608de809aaa51404d3a81f7aaed1ce3b8d222d6b66dae3f7f7e6f) with redeemscript 8b76a914c4bd8a3ef144976685e8d95da9f2fde1788b18ef8763ac672103addb27635e80ee06e62e083ae36cefd17924f8f3a7035745879ee7e3453b0e9f7c8201208763a9141218635cda9edb6b58b25afb2a5d7ac7d60c02fd88527c2103d6e49e5e6959f708f311cc7258f326eb0b3968f943bf29ae9585a8e6572373d852ae677503b6b702b175ac6868 in channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62.
2023-06-22 16:29:19.586 TRACE [lightning::ln::channel:3210] Updating HTLC 792bc6079bde0d6dea57ffbd77514525264136a26c1b1d7bad7e88e15f1d875e to AwaitingRemoteRevokeToAnnounce due to commitment_signed in channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62.
2023-06-22 16:29:19.588 TRACE [lightning::ln::channel:5865] Updating HTLC state for a newly-sent commitment_signed...
2023-06-22 16:29:19.588 TRACE [lightning::ln::channel:5874]  ...promoting inbound AwaitingRemoteRevokeToAnnounce 792bc6079bde0d6dea57ffbd77514525264136a26c1b1d7bad7e88e15f1d875e to AwaitingAnnouncedRemoteRevoke
2023-06-22 16:29:19.597 TRACE [lightning::ln::channel:1519] Building commitment transaction number 281474976710654 (really 1 xor 109198741898697) for channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62 for remote, generated by us with fee 253...
2023-06-22 16:29:19.598 TRACE [lightning::ln::channel:1580]    ...including inbound AwaitingAnnouncedRemoteRevoke HTLC 0 (hash 792bc6079bde0d6dea57ffbd77514525264136a26c1b1d7bad7e88e15f1d875e) with value 7500000
2023-06-22 16:29:19.598 TRACE [lightning::ln::channel:1679]    ...including to_remote output with value 100860
2023-06-22 16:29:19.599 DEBUG [lightning::ln::channel:3287] Received valid commitment_signed from peer in channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62, updating HTLC state and responding with our own commitment_signed and a revoke_and_ack.
2023-06-22 16:29:19.608 TRACE [lightning::chain::chainmonitor:706] Updating ChannelMonitor for channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62
2023-06-22 16:29:19.608 INFO  [lightning::chain::channelmonitor:2328] Applying update to monitor 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62, bringing update_id from 0 to 1 with 2 changes.
2023-06-22 16:29:19.609 TRACE [lightning::chain::channelmonitor:2359] Updating ChannelMonitor with latest holder commitment transaction info
2023-06-22 16:29:19.610 TRACE [lightning::chain::channelmonitor:2368] Updating ChannelMonitor with latest counterparty commitment transaction info
2023-06-22 16:29:19.612 TRACE [lightning::chain::channelmonitor:2142] Tracking new counterparty commitment transaction with txid ee631c47b8d1862f59fc535f1d80a7c4eafe6b24db1b33769550cf4cf73d0aec at commitment number 281474976710654 with 1 HTLC outputs
2023-06-22 16:29:19.619 DEBUG [lightning::chain::chainmonitor:726] Persistence of ChannelMonitorUpdate for channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62 completed
2023-06-22 16:29:19.622 TRACE [lightning::ln::channel:4009] Regenerated latest commitment update in channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62 with 0 update_adds, 0 update_fulfills, 0 update_fails, and 0 update_fail_malformeds
2023-06-22 16:29:19.626 TRACE [lightning::ln::channel:1519] Building commitment transaction number 281474976710654 (really 1 xor 109198741898697) for channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62 for remote, generated by us with fee 253...
2023-06-22 16:29:19.626 TRACE [lightning::ln::channel:1580]    ...including inbound AwaitingAnnouncedRemoteRevoke HTLC 0 (hash 792bc6079bde0d6dea57ffbd77514525264136a26c1b1d7bad7e88e15f1d875e) with value 7500000
2023-06-22 16:29:19.626 TRACE [lightning::ln::channel:1679]    ...including to_remote output with value 100860
2023-06-22 16:29:19.633 TRACE [lightning::ln::channel:5968] Signed remote commitment tx 020000000152332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e630100000000d0506380024c1d000000000000220020b539b5cd42c5e4c2f4acd1a3bceafd33e1a6daea35d80e448472ab6805a44ec7fc89010000000000220020884cee41f47f0808a837f4fd00627f41b87cd32bd66669c9bd792ed5e38d4955c8853820 (txid ee631c47b8d1862f59fc535f1d80a7c4eafe6b24db1b33769550cf4cf73d0aec) with redeemscript 47522102c0025cf6ef3c6caae2e0fbe69027365ee50faa516c7762bc6822f2b69d8d2fb42103a25f00d1f17232aaf52c6f76f3f71553a552709c713d2f4063c0e3459e92092c52ae -> 3a1c15a091385fceab1b3976427414766d5b45abed21b9801a4c525627f7f0952df86f8847f1b9bc0a582c52d21a7f20e82d7b01c993234caa58ab1167a2dd71 in channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62
2023-06-22 16:29:19.634 TRACE [lightning::ln::channel:5974] Signed remote HTLC tx 0200000001ec0a3df74ccf509576331bdb246bfeeac4a7801d5f53fc592f86d1b8471c63ee00000000000000000001a51c000000000000220020884cee41f47f0808a837f4fd00627f41b87cd32bd66669c9bd792ed5e38d4955b6b70200 with redeemscript 8576a914eddde9e73ecc0a915c38f73c57eaea36ddc762ad8763ac67210203b2eec0bbdfba7dad96b7136f119a17a8b28aaaf883ff1d0732fbb5b250a0cd7c820120876475527c2103d54df7da7a204825b0aa9c7b8757d83334156b6508a6a1a0c7cc6157cf942c4752ae67a9141218635cda9edb6b58b25afb2a5d7ac7d60c02fd88ac6868 with pubkey 03d54df7da7a204825b0aa9c7b8757d83334156b6508a6a1a0c7cc6157cf942c47 -> 1e506ea10ca4e91774267a53a74447acf489e56ae5c1d00f6dbcdc2e1579746415a5dde4f9a6414550cb40111b28412a0cad4d08d02263f1bdb0926be4fb124c in channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62
2023-06-22 16:29:19.634 DEBUG [lightning::ln::channel:3899] Restored monitor updating in channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62 resulting in a commitment update and an RAA, with RAA first
2023-06-22 16:29:19.634 TRACE [lightning::ln::channelmanager:4408] Handling channel resumption for channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62 with an RAA, a commitment update, 0 pending forwards, not broadcasting funding, without channel ready, without announcement
2023-06-22 16:29:19.634 DEBUG [lightning::ln::peer_handler:1783] Handling SendRevokeAndACK event in peer_handler for node 0366abc8eb4da61e31a8d2c4520d31cabdf58cc5250f855657397f3dd62493938a for channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62
2023-06-22 16:29:19.635 TRACE [lightning::ln::peer_handler:1071] Enqueueing message RevokeAndACK { channel_id: [82, 51, 38, 20, 173, 85, 212, 56, 229, 134, 158, 132, 16, 11, 82, 133, 140, 201, 57, 224, 17, 148, 175, 186, 252, 185, 210, 100, 55, 32, 158, 98], per_commitment_secret: [4, 134, 162, 80, 157, 149, 79, 76, 221, 103, 234, 50, 1, 2, 90, 226, 64, 90, 76, 159, 68, 19, 190, 61, 151, 132, 110, 209, 30, 111, 164, 44], next_per_commitment_point: PublicKey(fabe1be3c8787d9f77e4eda23d4b12a58d0164889a99ea2cde3351c5184c1ace82f8dd666f3c57e808dcca05c3bb128af152265e3d2ba6c8ab6c6d7a83414926) } to 0366abc8eb4da61e31a8d2c4520d31cabdf58cc5250f855657397f3dd62493938a
2023-06-22 16:29:19.635 DEBUG [lightning::ln::peer_handler:1758] Handling UpdateHTLCs event in peer_handler for node 0366abc8eb4da61e31a8d2c4520d31cabdf58cc5250f855657397f3dd62493938a with 0 adds, 0 fulfills, 0 fails for channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62
2023-06-22 16:29:19.636 TRACE [lightning::ln::peer_handler:1071] Enqueueing message CommitmentSigned { channel_id: [82, 51, 38, 20, 173, 85, 212, 56, 229, 134, 158, 132, 16, 11, 82, 133, 140, 201, 57, 224, 17, 148, 175, 186, 252, 185, 210, 100, 55, 32, 158, 98], signature: 304402203a1c15a091385fceab1b3976427414766d5b45abed21b9801a4c525627f7f09502202df86f8847f1b9bc0a582c52d21a7f20e82d7b01c993234caa58ab1167a2dd71, htlc_signatures: [304402201e506ea10ca4e91774267a53a74447acf489e56ae5c1d00f6dbcdc2e15797464022015a5dde4f9a6414550cb40111b28412a0cad4d08d02263f1bdb0926be4fb124c] } to 0366abc8eb4da61e31a8d2c4520d31cabdf58cc5250f855657397f3dd62493938a
2023-06-22 16:29:19.641 TRACE [mutiny_core::background:575] Persisting ChannelManager...
2023-06-22 16:29:19.646 TRACE [mutiny_core::background:575] Done persisting ChannelManager.
2023-06-22 16:29:19.647 TRACE [mutiny_core::networking::proxy:92] sent data down websocket
2023-06-22 16:29:19.647 TRACE [mutiny_core::networking::proxy:92] sent data down websocket
2023-06-22 16:29:19.657 TRACE [mutiny_core::ldkstorage:263] Trace: checking payment key: payment_inbound/792bc6079bde0d6dea57ffbd77514525264136a26c1b1d7bad7e88e15f1d875e_16f1cbce-7b67-4082-8953-9b338dac6837
2023-06-22 16:29:20.067 TRACE [mutiny_core::networking::socket:77] received binary data from websocket
2023-06-22 16:29:20.068 TRACE [lightning::ln::peer_handler:1381] Received message RevokeAndACK(RevokeAndACK { channel_id: [82, 51, 38, 20, 173, 85, 212, 56, 229, 134, 158, 132, 16, 11, 82, 133, 140, 201, 57, 224, 17, 148, 175, 186, 252, 185, 210, 100, 55, 32, 158, 98], per_commitment_secret: [63, 22, 174, 122, 85, 184, 117, 124, 194, 50, 105, 177, 54, 24, 84, 253, 238, 193, 60, 92, 7, 156, 25, 201, 16, 202, 197, 188, 180, 216, 131, 237], next_per_commitment_point: PublicKey(231ef70277799d63bc201508152914fa7cabb1bfa177de1ad879d50b29f51065c15317ac6c5006794e783c8c0f718e41e6050a6c6bd4fb817e180a05cc15f73e) }) from 0366abc8eb4da61e31a8d2c4520d31cabdf58cc5250f855657397f3dd62493938a
2023-06-22 16:29:20.071 TRACE [lightning::ln::channel:3485] Updating HTLCs on receipt of RAA in channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62...
2023-06-22 16:29:20.071 TRACE [lightning::ln::channel:3553]  ...promoting inbound AwaitingAnnouncedRemoteRevoke 792bc6079bde0d6dea57ffbd77514525264136a26c1b1d7bad7e88e15f1d875e to Committed
2023-06-22 16:29:20.071 DEBUG [lightning::ln::channel:3646] Received a valid revoke_and_ack for channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62 with no reply necessary.
2023-06-22 16:29:20.072 TRACE [lightning::chain::chainmonitor:706] Updating ChannelMonitor for channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62
2023-06-22 16:29:20.072 INFO  [lightning::chain::channelmonitor:2328] Applying update to monitor 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62, bringing update_id from 1 to 2 with 1 changes.
2023-06-22 16:29:20.072 TRACE [lightning::chain::channelmonitor:2376] Updating ChannelMonitor with commitment secret
2023-06-22 16:29:20.076 DEBUG [lightning::chain::chainmonitor:726] Persistence of ChannelMonitorUpdate for channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62 completed
2023-06-22 16:29:20.076 DEBUG [lightning::ln::channel:3899] Restored monitor updating in channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62 resulting in no commitment update and no RAA, with RAA first
2023-06-22 16:29:20.076 TRACE [lightning::ln::channelmanager:4408] Handling channel resumption for channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62 with no RAA, no commitment update, 1 pending forwards, not broadcasting funding, without channel ready, without announcement
2023-06-22 16:29:20.080 TRACE [lightning::ln::channelmanager:2627] Generating channel update for channel 52332614ad55d438e5869e84100b52858cc939e01194afbafcb9d26437209e62
2023-06-22 16:29:20.084 TRACE [mutiny_core::background:575] Persisting ChannelManager...
2023-06-22 16:29:20.087 TRACE [mutiny_core::background:575] Done persisting ChannelManager.
2023-06-22 16:29:20.088 DEBUG [mutiny_core::event:429] EVENT: PendingHTLCsForwardable: 100ms, processing...
2023-06-22 16:29:20.638 TRACE [lightning::ln::inbound_payment:380] Failing HTLC with payment_hash 792bc6079bde0d6dea57ffbd77514525264136a26c1b1d7bad7e88e15f1d875e: expired payment
2023-06-22 16:29:20.638 TRACE [lightning::ln::channelmanager:3604] Failing new HTLC with payment_hash 792bc6079bde0d6dea57ffbd77514525264136a26c1b1d7bad7e88e15f1d875e as payment verification failed
2023-06-22 16:29:20.645 TRACE [lightning::ln::channelmanager:4103] Failing HTLC with payment_hash 792bc6079bde0d6dea57ffbd77514525264136a26c1b1d7bad7e88e15f1d875e backwards from us with HTLC error code 16399
2023-06-22 16:29:20.646 DEBUG [mutiny_core::event:426] EVENT: HTLCHandlingFailed, ignored

[wpaulino]

2023-06-22 16:27:50.740 INFO [mutiny_core::esplora:220] Starting transaction sync.
2023-06-22 16:27:51.113 INFO [mutiny_core::node:278] creating lsp client
2023-06-22 16:27:51.133 TRACE [mutiny_core::background:575] Calling ChannelManager's timer_tick_occurred on startup
2023-06-22 16:27:51.137 TRACE [mutiny_core::fees:160] Got fee rate from saved cache!
2023-06-22 16:27:51.140 TRACE [mutiny_core::background:575] Rebroadcasting monitor's pending claims on startup
2023-06-22 16:27:51.916 INFO [mutiny_core::esplora:316] Finished transaction sync.

Are you sure ChannelManager::best_block_updated is being called before generating the invoice? I would've expected this sync to log New best block, unless you left it out?

[AnthonyRonning]

Okay good catch, that happened after, on the next sync:

2023-06-22 16:29:10.672 INFO  [mutiny_core::nodemanager:762] Updated fee estimates!
2023-06-22 16:29:10.675 INFO  [mutiny_core::esplora:220] Starting transaction sync.
2023-06-22 16:29:11.464 TRACE [lightning::ln::channelmanager:6076] New best block: 0000011b38960742f5b9c4808bec03fb9af620f518703cafc734cacfa88f66a2 at height 178057
2023-06-22 16:29:11.465 DEBUG [lightning::chain::chainmonitor:612] New best block 0000011b38960742f5b9c4808bec03fb9af620f518703cafc734cacfa88f66a2 at height 178057 provided via best_block_updated
2023-06-22 16:29:11.466 TRACE [mutiny_core::background:575] Persisting ChannelManager...
2023-06-22 16:29:11.467 TRACE [mutiny_core::background:575] Done persisting ChannelManager.
2023-06-22 16:29:11.472 INFO  [mutiny_core::esplora:316] Finished transaction sync.

I'm not sure why it only worked on the 2nd sync then.. typically haven't had that problem. I can double check things on our end, but that Starting transaction sync. and Finished transaction sync. code the first time should have triggered it.

[wpaulino]

The first sync was on a fresh node, yeah? If so, a call to ChannelManager::new passes in the current tip, so when you attempt to sync, you hit the following case not triggering a best_block_updated call:

https://github.com/MutinyWallet/mutiny-node/blob/f7e5b26787fac8f59f024aee7b9d5fa33e6a4844/mutiny-core/src/esplora.rs#L232

The issue seems to be on our end because ChannelManager::new does not set highest_seen_timestamp to the current tip provided via ChainParameters::best_block.

rust-lightning/lightning/src/ln/channelmanager.rs

Line 2021 in 15b1c9b

highest_seen_timestamp: AtomicUsize::new(0),

[AnthonyRonning]

Yes, fresh node. This is odd though because it works most of the time since we added code to require the first sync before generating the invoice.

So syncing for the first time before an invoice is not enough? The user has to sync, then wait for the next block in order for invoices to work properly?

[wpaulino]

It's not enough because you're already providing the current tip when you init a fresh ChannelManager, so syncing to tip then is a no-op.

[AnthonyRonning]

Can you think of any way around this? Can I give it not the current tip so it syncs first?

If it doesn't land in 116 then it's going to be a pretty big pain point for us, so just trying to think of all the possible workarounds.

[wpaulino]

It is landing in 116 :) Feel free to try out the branch and report back.

Can I give it not the current tip so it syncs first?

You could just give it the genesis block on a fresh init, but I'm not sure if that's going to sync blocks to tip one-by-one.