PostRestartHtlcCleaner spaming my logs

[DerEwige]

it looks like an htlc status update got missed during a restart.

the PostRestartHtlcCleaner tries to handle it but crashes.
It tries the same htlc every few minutes and gives me the same error.

Can I somehow clear this by updatind the DB by hand?

2022-12-12 11:06:02,081 INFO  f.a.e.p.r.PostRestartHtlcCleaner c:b081dbc88106fc8f13a0a9606d4b9d6637a401538401402cae2e08d32f19ecae - htlc failed downstream: (b081dbc88106fc8f13a0a9606d4b9d6637a401538401402cae2e08d32f19ecae,293343,RemoteFail)
2022-12-12 11:06:02,085 ERROR a.a.OneForOneStrategy - Tried to mark an outgoing payment as failed but already in final status (id=edd6c0fe-7e2a-4815-96fc-14590f7e4b23)java.lang.IllegalArgumentException: Tried to mark an outgoing payment as failed but already in final status (id=edd6c0fe-7e2a-4815-96fc-14590f7e4b23)
	at fr.acinq.eclair.db.pg.PgPaymentsDb.$anonfun$updateOutgoingPayment$9(PgPaymentsDb.scala:144)
	at fr.acinq.eclair.db.pg.PgPaymentsDb.$anonfun$updateOutgoingPayment$9$adapted(PgPaymentsDb.scala:140)
	at fr.acinq.eclair.db.jdbc.JdbcUtils.using(JdbcUtils.scala:52)
	at fr.acinq.eclair.db.jdbc.JdbcUtils.using$(JdbcUtils.scala:48)
	at fr.acinq.eclair.db.pg.PgUtils$.using(PgUtils.scala:33)
	at fr.acinq.eclair.db.pg.PgPaymentsDb.$anonfun$updateOutgoingPayment$8(PgPaymentsDb.scala:140)
	at fr.acinq.eclair.db.pg.PgPaymentsDb.$anonfun$updateOutgoingPayment$8$adapted(PgPaymentsDb.scala:139)
	at fr.acinq.eclair.db.pg.PgUtils$PgLock$LeaseLock.$anonfun$withLock$1(PgUtils.scala:133)
	at fr.acinq.eclair.db.pg.PgUtils$.inTransactionInternal(PgUtils.scala:265)
	at fr.acinq.eclair.db.pg.PgUtils$.$anonfun$inTransaction$1(PgUtils.scala:280)
	at fr.acinq.eclair.db.jdbc.JdbcUtils.withConnection(JdbcUtils.scala:37)
	at fr.acinq.eclair.db.jdbc.JdbcUtils.withConnection$(JdbcUtils.scala:34)
	at fr.acinq.eclair.db.pg.PgUtils$.withConnection(PgUtils.scala:33)
	at fr.acinq.eclair.db.pg.PgUtils$.inTransaction(PgUtils.scala:279)
	at fr.acinq.eclair.db.pg.PgUtils$PgLock$LeaseLock.withLock(PgUtils.scala:132)
	at fr.acinq.eclair.db.pg.PgPaymentsDb.$anonfun$updateOutgoingPayment$7(PgPaymentsDb.scala:139)
	at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.scala:18)
	at fr.acinq.eclair.db.Monitoring$Metrics$.$anonfun$withMetrics$1(Monitoring.scala:34)
	at fr.acinq.eclair.KamonExt$.time(PimpKamon.scala:28)
	at fr.acinq.eclair.db.Monitoring$Metrics$.withMetrics(Monitoring.scala:32)
	at fr.acinq.eclair.db.pg.PgPaymentsDb.updateOutgoingPayment(PgPaymentsDb.scala:139)
	at fr.acinq.eclair.payment.relay.PostRestartHtlcCleaner.fr$acinq$eclair$payment$relay$PostRestartHtlcCleaner$$handleDownstreamFailure(PostRestartHtlcCleaner.scala:219)
	at fr.acinq.eclair.payment.relay.PostRestartHtlcCleaner$$anonfun$main$1.applyOrElse(PostRestartHtlcCleaner.scala:141)
	at akka.actor.Actor.aroundReceive(Actor.scala:537)

2022-12-12 11:06:02,123 INFO  f.a.e.p.r.PostRestartHtlcCleaner - htlc-timeout tx for htlc #575623 paymentHash=e4857b16bd60f6d51f5230670dab1c210ddc7a4eb71fdecd7cb58fd6fe00766b expiry=766809 has been confirmed (tx=02000000000103e54fe826c75299b86df49e0fd4c7676f51286d096afc54b0d35da9eca09073dd040000000001000000d488787819984676905715fb6c8bd1143d6434c5ef4bcbb46f9f492961a1c4bc0000000000fdffffff2e9ed612cf9cdcbf329bc1fb4645613aaa36d769f26e4b0e1a60840e92d6cf1f0000000000fdffffff02429c0000000000002200203a935f4e9e047a2af152667a426cf5b5a0ca643efaf1c7694cfeaf586857e3ac9df00900000000002251205b080da030b60b3c50419d389b96c765c07960620029029b89f0bc9062cbffa70500483045022100b7a2c83b4e755b2b800e00caadc491cd0a0c08ea42b7956f5d1e0786cad3689c0220039f8e16db8b5696b860f256e162470d36c12ce18cc1103458b8548648186fce83473044022028245f03696a18a6ed7174121c1b2ee5d14027229a44f35d6ce2a4d7cc06fc040220633220e1f930911cc10cd2d3e4e25877cdb74a230086442fb16ca0407d78466401008876a914177f65da3aa1cb88be8622956b1e6a40d5d2a8ab8763ac672102fc28fb67aa4ee8dc7df604eb62372b7c436a238e863e7b4ba7735b12cc84a8107c820120876475527c2102ff6c72a457bc11fe480e69942bcfddabf6ed5cf568b1fba050ecc2e10830086e52ae67a9142a4b6b6bddeeda552177b4e5718e55ae2ea52f7e88ac6851b275680247304402202ac7559667ec990337bd914b9f1836a0ba9b1998025742a8f3bd52cffb71c79302201f05b7b98079ebee2640b09612581c806041e8b2910d8f35a93e6e4a908aa6f10121033c10c11ad3809953c5accc8628e5c746e2f448f176e9375226fd454269c8757b02473044022031db9acfd993aa0551b5895a4d9c3c125c4345dcbc2c46fba92e2e7639673f0a02202275adb4ae145ad75a3c1f8e372764b34b2f01260b8904c5e2d2a7fb0cab2aff0121033c10c11ad3809953c5accc8628e5c746e2f448f176e9375226fd454269c8757b59b30b00)
2022-12-12 11:06:02,130 INFO  f.a.e.p.r.PostRestartHtlcCleaner - cleaning up channelId=d9e805a87db38ad958a325baddbe3de72cea61656479daf99e3a23ea6c7c1859 htlcId=18027 from relay db
2022-12-12 11:06:02,133 INFO  f.a.e.p.r.PostRestartHtlcCleaner - cleaning up channelId=d9e805a87db38ad958a325baddbe3de72cea61656479daf99e3a23ea6c7c1859 htlcId=18031 from relay db
2022-12-12 11:06:02,137 INFO  f.a.e.p.r.PostRestartHtlcCleaner - cleaning up channelId=d9e805a87db38ad958a325baddbe3de72cea61656479daf99e3a23ea6c7c1859 htlcId=18030 from relay db
2022-12-12 11:06:02,141 INFO  f.a.e.p.r.PostRestartHtlcCleaner - htlcsIn=2 notRelayed=0 relayedOut=62
2022-12-12 11:06:02,141 INFO  f.a.e.p.r.PostRestartHtlcCleaner - notRelayed=List()
2022-12-12 11:06:02,142 INFO  f.a.e.p.r.PostRestartHtlcCleaner - relayedOut=HashMap(LocalCold(5425bf8f-5b97-4c58-929c-655769ab36b1) -> Set((2983e39d070a13e5982d49c109e37d5a046eed18074841ea9f5acc7daef3a25f,110098)), LocalCold(60ed4d2b-5a47-4bda-a06a-ad487437dbb2) -> Set((e8f12269cf4207493e126240d20952b46ae57b77d64b5dfde547c3caae7478eb,970830)), LocalCold(f0497592-2539-4329-94a0-56e98b099054) -> Set((0d049079de6eb6578cd40687122a72bafcc2421ce16a77187c31d220542bff6a,895134)), LocalCold(dd9d31e4-c87e-4367-9840-4b2a2abe5db9) -> Set((1a73f8264afc8de7eb510fe638657634691d88ef7f5f59c58dced4a981a8e359,411658)), LocalCold(70eb96cb-3a89-4162-95ab-75f78be9515d) -> Set((416dceb36aa93efe3134bdf6790952eb7b99ea43176d18e8154bf9565c1860e3,68423)), LocalCold(da62b90d-89cb-48b9-a028-1358de7adef1) -> Set((77375851b088dc123d0e38cd31b46e68c0ad5d1b59542403fb0e138b370c8df7,175154)), LocalCold(aa01b0c3-b57d-46b6-966a-8278dc3ffac8) -> Set((541d056e364094d9e6a00483b4004fdf7620465126fd1d7f872942495a07beab,26615)), LocalCold(f37ac442-a10f-46e9-9a55-06ce54ba6622) -> Set((0c35193da6968f80cc81c17885a51607ad9707a84183630df5052c13d755e625,128849)), LocalCold(8f86dc4b-a132-4da0-a80b-9e358c9aa105) -> Set((6293922b5dfdc6e56d93e409772e546697b3b9bb7b24bef86e6af705e5a27f71,8440)), LocalCold(eef2ca93-0cb0-45cd-b0e3-87e5bc5ffda0) -> Set((701d72bb7d9986f6e97a21ac6443cfdbb24374a247609ed686b6edeccd0c4195,59342)), LocalCold(eadf88be-3470-4ef1-b86f-0ba557d538c7) -> Set((54b1121c4bfd4fc73669104fefaa346659ec440def663554b0e764971f7546e5,611446)), LocalCold(864b212b-11e5-48cd-8365-f5b9850dea49) -> Set((24b600a3cfbc8c185fc774672cb21abffd9d2d7557269544d1e3761b397082d5,1264854)), LocalCold(5173a67b-54c5-415b-98dc-0b455c0fdbb2) -> Set((701d72bb7d9986f6e97a21ac6443cfdbb24374a247609ed686b6edeccd0c4195,60078)), LocalCold(29ce11a6-9ffd-4121-a205-a3a1ab9b3d0c) -> Set((b081dbc88106fc8f13a0a9606d4b9d6637a401538401402cae2e08d32f19ecae,302712)), LocalCold(ff1906e8-d9b3-405c-9c28-3bfa4ddfb5ef) -> Set((0942443a8864b1f2b76a6777ffb303abc4ab7410cd3af6de8f2948c4c67a0d6d,24292)), LocalCold(8bdff8b5-6de9-40c4-8fca-cd9b78441a61) -> Set((68a5bffaa8f16fa58c031a790d1c52faa214956ed32814716d525e5d067395d0,162988)), LocalCold(b5fd2e86-b26c-46da-8b9f-aa947c37efdd) -> Set((701d72bb7d9986f6e97a21ac6443cfdbb24374a247609ed686b6edeccd0c4195,59745)), LocalCold(4e4b172c-ce85-4843-815a-a0b8ef909b64) -> Set((c5bae8fccc0b064e9a07f31eb252f6f453583d76eb8e5b6a125b226b5176f6a3,201651)), LocalCold(0fa46e40-acf3-4044-9f29-a1522aaa309a) -> Set((c5bae8fccc0b064e9a07f31eb252f6f453583d76eb8e5b6a125b226b5176f6a3,201646)), LocalCold(dc64649e-2e7f-44b0-9f2b-43786857ca05) -> Set((96183fb82827516a7319abc3a3b2218876677ba02680611aa80244036de830cc,600897)), LocalCold(a52306f8-1c36-4921-91cd-9203a34c2921) -> Set((2c39b0079261b6eaec5504c5970788d1039b8007d0302c37b6077f5f38c18204,127258)), LocalCold(72752f62-dc6d-4a90-8e24-f37db377afdc) -> Set((77375851b088dc123d0e38cd31b46e68c0ad5d1b59542403fb0e138b370c8df7,175151)), LocalCold(a50474a7-083f-42fc-911d-6569da2fa4f4) -> Set((2983e39d070a13e5982d49c109e37d5a046eed18074841ea9f5acc7daef3a25f,114682)), LocalCold(efd13ba9-57f2-40da-b644-4cd7654199dd) -> Set((cec9ced132c1ecc77173ed2fe289a17197edea2feb3663fc763379a035e2619f,100924)), LocalCold(c0c27292-afe7-4349-ac69-ba4bebfc0664) -> Set((24b600a3cfbc8c185fc774672cb21abffd9d2d7557269544d1e3761b397082d5,1261956)), LocalCold(3f915f99-604f-42a3-bac9-eaa54d00ba8b) -> Set((6293922b5dfdc6e56d93e409772e546697b3b9bb7b24bef86e6af705e5a27f71,13702)), LocalCold(a9fc9384-fdb2-48a3-8d65-a2600ba8c4ae) -> Set((77375851b088dc123d0e38cd31b46e68c0ad5d1b59542403fb0e138b370c8df7,175147)), LocalCold(d09355b2-00c0-493c-9771-36f929ead77a) -> Set((9f9dbe8dd807333b7b51e30a6b2ead85461beb5079c75ee21f9ff2cac8233d46,524956)), LocalCold(f7441766-79a2-44ea-96bc-0ff269643ab3) -> Set((77375851b088dc123d0e38cd31b46e68c0ad5d1b59542403fb0e138b370c8df7,175153)), LocalCold(cf8eb7d4-dd67-4eef-a4b2-097db08cc4a7) -> Set((0942443a8864b1f2b76a6777ffb303abc4ab7410cd3af6de8f2948c4c67a0d6d,21131)), LocalCold(23105d32-8ce8-49f9-9f1a-325cbec60a4d) -> Set((24b600a3cfbc8c185fc774672cb21abffd9d2d7557269544d1e3761b397082d5,1265416)), LocalCold(7fdeaaef-e58c-47ac-a896-c04399fd40c3) -> Set((d9e805a87db38ad958a325baddbe3de72cea61656479daf99e3a23ea6c7c1859,249310)), LocalCold(f33b2108-ae46-426a-80d4-d1609b4a2577) -> Set((cec9ced132c1ecc77173ed2fe289a17197edea2feb3663fc763379a035e2619f,100932)), LocalCold(18d44235-83ac-4c2f-a19a-76084d6b5a9f) -> Set((96183fb82827516a7319abc3a3b2218876677ba02680611aa80244036de830cc,600892)), LocalCold(eb1bc8d1-c6fe-4878-b7d0-cf335a9b00e1) -> Set((541d056e364094d9e6a00483b4004fdf7620465126fd1d7f872942495a07beab,26614)), LocalCold(de6bb9cf-fb02-44dc-9e2f-609911424d36) -> Set((fd4051c7cd42abd92576c4d78233b32b8f9a1aaf067170c5c90c0490a66bd62e,5912)), LocalCold(68c03076-c81d-472b-8c6a-69c823e4c3fd) -> Set((6293922b5dfdc6e56d93e409772e546697b3b9bb7b24bef86e6af705e5a27f71,13696)), LocalCold(4f749469-2e95-459b-a55a-6886fd4084eb) -> Set((2983e39d070a13e5982d49c109e37d5a046eed18074841ea9f5acc7daef3a25f,115376)), LocalCold(c968b102-8d8c-4d92-b32e-cd4409887f03) -> Set((701d72bb7d9986f6e97a21ac6443cfdbb24374a247609ed686b6edeccd0c4195,59372)), LocalCold(b733f991-232b-4556-9fd9-bddbf7270d5c) -> Set((24b600a3cfbc8c185fc774672cb21abffd9d2d7557269544d1e3761b397082d5,1252972)), LocalCold(3060134d-e859-466b-8fd2-05f68087a167) -> Set((fd4051c7cd42abd92576c4d78233b32b8f9a1aaf067170c5c90c0490a66bd62e,7551)), LocalCold(576ddb1c-4cbf-409e-8709-02334849a147) -> Set((68a5bffaa8f16fa58c031a790d1c52faa214956ed32814716d525e5d067395d0,162989)), LocalCold(5e59d6bb-2311-4bda-806e-295312a543ba) -> Set((c5bae8fccc0b064e9a07f31eb252f6f453583d76eb8e5b6a125b226b5176f6a3,212940)), LocalCold(56f22b87-4fc6-498c-bfd0-a392d5a19a6b) -> Set((d9e805a87db38ad958a325baddbe3de72cea61656479daf99e3a23ea6c7c1859,243584)), LocalCold(b80479db-8794-495e-823d-38e1a698fadf) -> Set((96183fb82827516a7319abc3a3b2218876677ba02680611aa80244036de830cc,590443)), ChannelRelayedCold(d9e805a87db38ad958a325baddbe3de72cea61656479daf99e3a23ea6c7c1859,18010,11250358 msat,11250190 msat) -> Set((2c39b0079261b6eaec5504c5970788d1039b8007d0302c37b6077f5f38c18204,137804)), LocalCold(6d9ae268-bcdc-4945-83fe-9c262272e696) -> Set((45bc7669d34512710980b3f268d475d57e872965f683f2aa65acbaca91e36b7b,84857)), LocalCold(998821ff-44f6-4642-9353-7b89402cab85) -> Set((9a5e9611fa6df9242b77ecee5a7db0336a6f31483a922734176db02b4e808617,107052)), LocalCold(6c2c26f0-5537-4d30-88f9-62a77fc24655) -> Set((4f2c9972ab96922ff370adf7c6b0e3f2c7e8cd9842b7060cb1d83359ee3d0cfb,34376)), LocalCold(3102c9ca-8831-4ee2-9dc8-7f60071edc6e) -> Set((701d72bb7d9986f6e97a21ac6443cfdbb24374a247609ed686b6edeccd0c4195,59753)), LocalCold(f120fc92-02d9-48a0-8157-04d08d36bed9) -> Set((0942443a8864b1f2b76a6777ffb303abc4ab7410cd3af6de8f2948c4c67a0d6d,24305)), LocalCold(9e1f67c7-9ac4-4bc4-82e2-c9b20b7a013b) -> Set((20b1c7d918b6c821c8de723e3b02f8e110f9fdfecc7616080b7dd4a0431840ef,509103)), LocalCold(d5df7f34-e2ad-4f5c-9b74-b967661cd62b) -> Set((cec9ced132c1ecc77173ed2fe289a17197edea2feb3663fc763379a035e2619f,106806)), LocalCold(edd6c0fe-7e2a-4815-96fc-14590f7e4b23) -> Set((b081dbc88106fc8f13a0a9606d4b9d6637a401538401402cae2e08d32f19ecae,293343)), ChannelRelayedCold(d9e805a87db38ad958a325baddbe3de72cea61656479daf99e3a23ea6c7c1859,18032,12480543 msat,12480531 msat) -> Set((78e820a876a9d93f5e87455adae67b0c4c92fec524b851a8d00b79c8ab7c0034,70397)), LocalCold(aef2887c-5828-42af-97d7-e908e8e41b82) -> Set((fd4051c7cd42abd92576c4d78233b32b8f9a1aaf067170c5c90c0490a66bd62e,17807)), LocalCold(60229e9b-0326-442f-93a1-90d129f99cbd) -> Set((e54125951e968d70f5147cb5eefe4c558fdfc616afd85fb914cab79fa16a69b8,11639)), LocalCold(a763a78c-cb55-4166-ad00-9e7c439497fd) -> Set((b081dbc88106fc8f13a0a9606d4b9d6637a401538401402cae2e08d32f19ecae,302721)), LocalCold(7fd010e8-95d5-4da2-9c06-8c5d33583034) -> Set((fd4051c7cd42abd92576c4d78233b32b8f9a1aaf067170c5c90c0490a66bd62e,17744)), LocalCold(46b61855-2029-40c0-8f36-a4b381266fcf) -> Set((9a5e9611fa6df9242b77ecee5a7db0336a6f31483a922734176db02b4e808617,115313)), LocalCold(58525ceb-ef6e-43b4-b6f4-fe769ec3f70a) -> Set((77375851b088dc123d0e38cd31b46e68c0ad5d1b59542403fb0e138b370c8df7,175152)), LocalCold(255f223a-2db1-4397-aab5-8089bc5e0649) -> Set((fd4051c7cd42abd92576c4d78233b32b8f9a1aaf067170c5c90c0490a66bd62e,17866)))

[t-bast]

This is strange, this really shouldn't happen and is worth investigating.
What is the status of that payment in your payments DB?

I believe that to fix this, you can remove the entry in the PendingCommandsDb for that channelId and htlcId, but it's really worth looking into as we've never run into a bug here...

[DerEwige]

I only caught the error, because it started to show up every few minutes
I've made a grep for the whole day and it already happened before, just a lot less frequent

PostRestartHtlcCleaner.log
But it might have stopped at 11:20 today. I have not seen an error after this.

I did not find a payment in my payments.sent or payments.received table with the payment hash
And I only have one entry in the local.pending_settlement_commands table and it is for htlc id 36'891

So it looks like the payment might have been prunned and this resolved the problem on my node