Two expired HTLCs followed by remote force-close with testnet Eclair node

[akumaigorodski]

Remote node is endurance, channel id is f3f72886a022c36329257fc459478201512d2744facffc3a3b343a4e25e9ce34, there were two stuck HTLCs with expiration at block 1575802 but endurance was not failing them after that deadline has passed.

Channel was eventually force-closed by endurance with this commit tx: https://testnet.smartbit.com.au/tx/5176657c307a30ae61d3217cfcca8b7d5e0aba297dfa2b2911e826d559db2abb

[pm47]

Ok so block 1575802 was mined on 08/25/2019 @ 3:14pm (UTC).

Our last commitments before that were:

2019-08-25 13:48:29,565 INFO  f.a.e.channel.Channel n:0388ad12b719892f87f2d4f3d2718970caffe3a77ee731651e67e5f42fd8879388 c:f3f72886a022c36329257fc459478201512d2744facffc3a3b343a4e25e9ce34 - built local commit number=278 htlc_in=23,33 htlc_out= feeratePerKw=1250 txid=7d0afb68c9486a3d685b00e831605e26b37d54a4d72d27f162c5abbd0f574e49 tx=0200000001f3f72886a022c36329257fc459478201512d2744facffc3a3b343a4e25e9ce34000000000018062d80048b130000000000002200201cf019ec10887b65b46289f1e52faa5767742651dd1f27bc3eacd5778b0f89a2af860100000000002200209d74b649da9999c68ad9a8a089d663d4901d9274d32b0ddeabc71124249ab22386d5150000000000160014e0f6abbfb814828284d8aa909d9adb7d9d7bfc36684f540000000000220020e8c8c53ca582a53a34cb1cefca6440b6b482c7b023c56d380b54d09d03d4d04af1057120
2019-08-25 13:48:29,575 INFO  f.a.e.channel.Channel n:0388ad12b719892f87f2d4f3d2718970caffe3a77ee731651e67e5f42fd8879388 c:f3f72886a022c36329257fc459478201512d2744facffc3a3b343a4e25e9ce34 - built remote commit number=278 htlc_in=23,33 htlc_out= feeratePerKw=1250 txid=2871b7e81a16149ec770e2432b8d4f30e3a47eb6fcecfd4f1dea5f51a110f13e tx=0200000001f3f72886a022c36329257fc459478201512d2744facffc3a3b343a4e25e9ce34000000000018062d80048b13000000000000220020c5c73a1bd9250eb594e630339bbefd2fd3772ef1a5376db6938541436c42728aaf86010000000000220020bc44cc23a6aad9e6d000a07fd3340cb72cebcac24fd55c93db2856488fcf0fba86d51500000000002200204af91b94eed4f67652cf1454ef9277debff38841fa2f20d1752ac2ab98892e53684f540000000000160014e637093f512d7af4e47c68b2871cced782a0caf6f1057120

Where htlcs are:

2019-08-22 15:35:18,180 INFO  f.a.eclair.Diagnostics n:0388ad12b719892f87f2d4f3d2718970caffe3a77ee731651e67e5f42fd8879388 c:f3f72886a022c36329257fc459478201512d2744facffc3a3b343a4e25e9ce34 - IN msg=UpdateAddHtlc(f3f72886a022c36329257fc459478201512d2744facffc3a3b343a4e25e9ce34,23,MilliSatoshi(100015080),9d367c04a3291a576be1f0e1361e74713dbd8c89e37880a564cb3009880b5106,1575802,OnionRoutingPacket(0,ByteVector(33 bytes, 0x03225b2543ab1cc9ab260a699be2e978f89be54c500a1f1d0410a6946e8f2a3a41),ByteVector(1300 bytes, #-865787359),8a38696f8fc724092f73f97968dbb2b66d02939656272109e581e542edb77d85))
2019-08-22 15:37:11,914 INFO  f.a.eclair.Diagnostics n:0388ad12b719892f87f2d4f3d2718970caffe3a77ee731651e67e5f42fd8879388 c:f3f72886a022c36329257fc459478201512d2744facffc3a3b343a4e25e9ce34 - IN msg=UpdateAddHtlc(f3f72886a022c36329257fc459478201512d2744facffc3a3b343a4e25e9ce34,33,MilliSatoshi(5003585),cceb6dca04b0d49a574737face3565366f338de7ae8a3ccb8c21b8986d8fa439,1575802,OnionRoutingPacket(0,ByteVector(33 bytes, 0x023b029abfe60d8701653710aab9fd4108e7c2304c7638df7f9c4b4c3cec2b235c),ByteVector(1300 bytes, #-1194817628),a47c4ea2861d4ab719304d339d1c5f8c850817f3b7ebd91d523c6b5279095b3a))

Indeed something is fishy, I see a parsing error in the logs. Is there anything special about those htlcs?

[akumaigorodski]

Is there anything special about those htlcs?

Not in a sense that I did something special to those HTLCs, those two payments had many retries with rather long routes and ended up stuck eventually. Sadly I don't have that channel data by now.

[pm47]

@t-bast could be related to #976?

We received this failure from a downstream node:

2019-08-22 15:35:25,850 INFO  f.a.eclair.Diagnostics n:030b9e80fa104866a6c3d9cb399fa1ab6647fe13757c0ff13bc799a96f5dfef424 c:d2915b677f260abffaab015d4981c54b3acda2cf9546d6c68267f985887fd21f - IN msg=UpdateFailHtlc(d2915b677f260abffaab015d4981c54b3acda2cf9546d6c68267f985887fd21f,14,ByteVector(260 bytes, 0x943f0a7db7ff23e21cf80516e9980feb2f4576035a22bbd0a3873882776f199602e6335226a1ffc70fd2c825059fab0ed1b76e97dc077937aa3f7f4d34eae64dd17b127ce50e368f8bf7886a1cfaf04efd93d081d0fe9495f8b800f91cdec75975a9d633b154c9cd165e4decfba4e39a57d302ebd6b83ddfd8815c343b283e61ac0f930db1967436690805893e7465e42b66e59f8c4b11a347fb3848a89f42913612c4a4f32a7a7f49a64d9e7e8bc177a079f88dc97d02060322a23829d4b3e48ec69c21ed40dc22e90cba2648e4c1821216185a98db2a6c61eb830795be635cd5445a5e33ec80a8a67fb6ac5b39bfc2a9e17c5493b8d2f6dd4ae829c6a601da556807a2))

Which has a 260-bytes failure packet, but we are expecting a 292-bytes field in the below code resulting in a requirement failed: invalid error packet length 260, must be 292.

eclair/eclair-core/src/main/scala/fr/acinq/eclair/crypto/Sphinx.scala

Lines 320 to 321 in 8da509b

	def wrap(packet: ByteVector, sharedSecret: ByteVector32): ByteVector = {
	require(packet.length == PacketLength, s"invalid error packet length ${packet.length}, must be $PacketLength")

[t-bast]

Interesting, I checked our code and I don't think we can generate such invalid onion errors (it looks like the mac is missing). However we might not be propagating the failure correctly upstream when we receive such an invalid onion, I'll fix that.

I'll have a quick look at lnd and c-lightning to see if they have a bug. It's likely that one of the implementations introduced that bug when implementing variable-length onion (or it's a malicious node somewhere).

[t-bast]

Thanks for spotting this @btcontract, good catch!