Invalid signature on reconnection eclair/c-lightning

[pm47]

Issue and Steps to Reproduce

Following an unrelated memory issue with eclair causing it to grind to a halt, I had to forcekill the node, and on restart I saw a few Bad commit_sig from several c-lightning nodes. After investigating I think this may have revealed a corner case problem on c-lightning's side related to update_fee.

Here is what happened (taken from the logs below):

 eclair           c-lightning
   |                   |
   |  (idle, no htlc)  |
   |                   |
   |<------ fee1 ------|
   |<------ sig -------|
   |------ rev ------->|
   |------- sig ------>|
   |<------ fee2 ------|
   |<------ sig -------|
   |<----- rev --------|
   |-rev-> ?           |
   |                   |
   |   (reconnection)  |
   |                   |
   |------- rev ------>|
   |------- sig ------>|
   |<------ err -------| <- Bad commit_sig feerate=fee1
   |        ...        |

I think eclair is right to have been using feerate=fee2 after reconnection.

2019-05-21 18:55:39,565 INFO IN msg=UpdateFee(edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277,41186)
2019-05-21 18:55:39,565 INFO IN msg=CommitSig(edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277,3bdbd03cccbf8bf1f14909ec9bc2de9e4e7d36ccc1a14d643ff0e84e5111c9fe314c2b270241044708077b3c02029ea7589f2f24734b286811afbc140667bd46,List())
2019-05-21 18:56:15,680 INFO built local commit number=1868 htlc_in= htlc_out= feeratePerKw=41186 txid=b1155d1d24358f1351cf32dabf04dcb2ff583ff8515d819991916d183167a251 tx=0200000001edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa2770000000000bafd188001466de400000000001600140fbea428c4ff928c2a0090ba0842499b8471b5f515231220
2019-05-21 18:56:36,965 INFO built remote commit number=1868 htlc_in= htlc_out= feeratePerKw=41186 txid=1e7de91fc13f3156d4ce6936a6c9cf770e3a0aefe31f61e7850e724743af1dc6 tx=0200000001edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa2770000000000bafd188001466de40000000000220020763457b672c1e62fee350241cac82ddd90fefc30cb233920edf045af4762fbaf15231220
2019-05-21 18:56:36,967 INFO OUT msg=RevokeAndAck(edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277,696eb92f5b9833d87cddde7b168c08005b039da998bf3a42aa83d815c7acad0e,039314eb7e617941a275040c0dae4f013c77084d8f2c54d9bfd002b51a0a73e685)
2019-05-21 18:56:44,069 INFO  f.a.e.db.BackupHandler  - database backup triggered by channelId=edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277 took 7117ms
2019-05-21 18:56:44,069 INFO OUT msg=CommitSig(edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277,88d579eb0e0d586cb5686850d55eaf9d525cdcded2a6a7d7629f6883e4f18309707f3cabd7e70ad870ef074d8073e901f4f48cdb033cbd324366da54254d2652,List())
2019-05-21 18:56:49,200 INFO IN msg=UpdateFee(edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277,41167)
2019-05-21 18:56:49,200 INFO IN msg=CommitSig(edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277,f374c037e8fe81346589331e359fbdda28f2a2ee06f05b5c52d490b2fa0f187257b0d7cab653d6a76ee48da2aeb4ddbaf563e9f3138d3c31fda1af9c45c5c10e,List())
2019-05-21 18:56:49,204 INFO built local commit number=1869 htlc_in= htlc_out= feeratePerKw=41167 txid=4bfd6397433b995dfd807a1854ec2dafe44a4faf154de0c99d238f91cc75c96f tx=0200000001edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa2770000000000bafd188001546de4000000000016001415939184bb32d1d27f1972543904365e9d3da4f414231220
2019-05-21 18:56:55,396 INFO IN msg=RevokeAndAck(edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277,79bd4885c75c521334f22558fbabfc8e0194f794728eea42844e0928f0fa9a57,03b700847056de2dddbf7a4c409448ec05583fc07385f86de581f23b3fe90c334e)
2019-05-21 18:56:55,396 WARN waited for too long for a revocation to remoteCommitNumber=1867, disconnecting


2019-05-21 19:22:11,032 INFO restoring channel channelId=edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277
2019-05-21 19:22:11,032 INFO current channel_update was created 5 days ago, will refresh it in 4 days
2019-05-21 19:22:11,032 INFO re-emitting channel_update=ChannelUpdate(ByteVector(71 bytes, 0x304402201f9ddc04b0540f32193bc4c354ebe2755dc0d34bed4dc3e220b2a7329586d0250220187eb4a2962ff7b6fbaa37b34860ca461d61c49f842bc46cec5d477cbecb469f01),6fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d6190000000000,554656x1817x0,1558011262,1,3,144,0,0,0,Some(15000000000)) enabled=false
2019-05-21 19:22:43,935 INFO OUT msg=ChannelReestablish(edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277,1870,1868,Some(79bd4885c75c521334f22558fbabfc8e0194f794728eea42844e0928f0fa9a57),Some(039314eb7e617941a275040c0dae4f013c77084d8f2c54d9bfd002b51a0a73e685))
2019-05-21 19:22:44,054 INFO IN msg=ChannelReestablish(edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277,1869,1868,Some(696eb92f5b9833d87cddde7b168c08005b039da998bf3a42aa83d815c7acad0e),Some(02763007023899c663d1304f2bb756e41ab15bf4f1141801ea35383143759a7e23))
2019-05-21 19:22:44,054 INFO OUT msg=RevokeAndAck(edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277,07fdb4b89775ed653b91fb799e9ed283e5c246b4f3a9b0a57eefcc778ae1acef,023580ac5bac2f9e4368e34306a2c379fd0f1de78fbb1b1e824021e054ade17c92)
2019-05-21 19:22:44,057 INFO built remote commit number=1869 htlc_in= htlc_out= feeratePerKw=41167 txid=28a845f354ddccc7c3c5369d5d35fe76ba3399b19068f270da58d3fde6f49707 tx=0200000001edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa2770000000000bafd188001546de40000000000220020e23ab07197ff9f9ea88eeacee40b4b114da0a0de1f66efc38c8709d476d6c55014231220
2019-05-21 19:22:44,062 INFO OUT msg=CommitSig(edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277,ByteVector(71 bytes, 0x304402204de00a6f3cdbc267a38a1d2a4536f84387df3ff4cd72e420b4944315887fb7970220570498285dc6330c22dc4a885d2be6517ea4ac4159c68e99c05b3e3914c5d32c01),List())
2019-05-21 19:22:44,148 INFO  f.a.e.db.BackupHandler  - database backup triggered by channelId=edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277 took 86ms
2019-05-21 19:22:44,175 INFO IN msg=AnnouncementSignatures(edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277,554656x1817x0,ByteVector(71 bytes, 0x304402200bf3ac5408ce731009adf23467c57507ca8bda366d039c6c4f78c5634f33676b022078e7986d65d6237c7692cdbc8cc9cbc6d17f6f46c2288df4047081272947775001),ByteVector(72 bytes, 0x3045022100b59d01441dba4bc71b6081be2a463f4154de5d8b4a8aafa479989feec7b4052902207498abbcfb6e117fe76875ff807bc7f72891c0094244c070178df84c83ee66e101))
2019-05-21 19:22:44,175 INFO re-sending our announcement sigs
2019-05-21 19:22:44,175 INFO OUT msg=AnnouncementSignatures(edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277,554656x1817x0,ByteVector(71 bytes, 0x3044022045e1e79d73f34f589e002430c9f83aadeef48c7d726f81d54f3d6e0d5161493602207520f416a3850d0b3edf39466a52a83f00bcf5dd2df173f6ae705db2b7e0408001),ByteVector(72 bytes, 0x3045022100e76feb5664ecc83d323ff0fbcb5627eb901f9731f0be249494d94d37990d8abe0220028ed614b52a45e8a25dc7f51170a91329d3ec196b26ffa49ff50bc0ae02e12f01))
2019-05-21 19:22:44,362 INFO IN msg=UpdateFee(edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277,41175)
2019-05-21 19:22:44,521 INFO IN msg=CommitSig(edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277,ByteVector(71 bytes, 0x3044022057d9a20f6a3a323927d3485bf91928aa5e10f79f305908882e5bff5f2f063c9a02200c0a591f643f39e1e02021e7498f4e02e3218a2a05cd7292de82e653310df4a101),List())
2019-05-21 19:22:44,521 INFO IN msg=Error(edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277,ByteVector(602 bytes, #-605886696))
2019-05-21 19:22:44,523 INFO built local commit number=1870 htlc_in= htlc_out= feeratePerKw=41175 txid=7c7c0859f0222b348df5af14a5a7c910555147c633071d82055a05ce9cf22f7f tx=0200000001edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa2770000000000bafd1880014e6de400000000001600147bf1e7bc6942765a97e698219807952ec476c4c017231220
2019-05-21 19:22:44,530 INFO OUT msg=RevokeAndAck(edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa277,03e72eff3f9e0767ca5df55249d014f43a4212804785cfe3a72c1bde3915633a,02c8bf4ff762ff827027691adf66fdd984fe077fdc2cf90181e724c601c4b98cab)
2019-05-21 19:22:44,531 ERRORpeer sent error: ascii='Bad commit_sig signature 1869 304402204de00a6f3cdbc267a38a1d2a4536f84387df3ff4cd72e420b4944315887fb7970220570498285dc6330c22dc4a885d2be6517ea4ac4159c68e99c05b3e3914c5d32c for tx 0200000001edc7ef107af445a433be4b2b992ca251b64df6bcb43c8c1306104cac783fa2770000000000bafd188001466de40000000000220020e23ab07197ff9f9ea88eeacee40b4b114da0a0de1f66efc38c8709d476d6c55014231220 wscript 52210243dbfd3d449f086f0e9b1679b050048f828265de443eed03b53ffe48232a694d2102abde6ccd15e4c861bafbdb4aa8052fdb0a9f85577a1226c3c5e22f8d3f01d24952ae key 0243dbfd3d449f086f0e9b1679b050048f828265de443eed03b53ffe48232a694d feerate 41186'

[pm47]

We had new occurences of this. Happened 0 time in august and 2 times in september so far. Probably not high priority but would still be nice to get fixed.

Last reported one:

2019-09-10 13:55:36,302 IN ------->  msg=UpdateFee(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,8136)
2019-09-10 13:55:41,200 IN ------->  msg=CommitSig(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,06f8509edacc4e0b8d367fb2fcd8ff3c78f42db1c907d941f7ee8f06da28eda23722d3866a6f6f164ef64c21cda5ff2b75ba200c22f309343bf362134cff16b8,List())
2019-09-10 13:55:41,210 OUT <-------  msg=RevokeAndAck(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,PrivateKey(a70f8c6e733e61349325d4f852b255db8dc2f11a84d71e005c75aa4c8f812d19),039501d259c429847e26a109d16276cc341d85400d47700f31da965666076adac9)
2019-09-10 13:55:41,410 OUT <-------  msg=CommitSig(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,c4d97273ddc8789ae3752b72563b103487e614e1059e49f24b3db154966e74f1390f64980f38e467059093fbaa90d61c0aa4e8ea8314537573809cb297a4f1aa,List())

2019-09-10 13:56:02,051 OUT <-------  msg=ChannelReestablish(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,7351,7350,Some(PrivateKey(ffeef2b9d21e54f349f2ecad68231408e9ef130f21994649165f6b58f7e7a470)),Some(0221aaef53251f43306945b54693a94a9dd74d21e58f4c3baad2cbd6d31ef517f0))
2019-09-10 13:56:32,497 IN ------->  msg=ChannelReestablish(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,7351,7350,Some(PrivateKey(a70f8c6e733e61349325d4f852b255db8dc2f11a84d71e005c75aa4c8f812d19)),Some(03568b6b0e369474d52fef04828b59a58217201c35fa7eaeef5e0c6b8e56dad20d))
2019-09-10 13:56:32,497 OUT <-------  msg=CommitSig(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,c4d97273ddc8789ae3752b72563b103487e614e1059e49f24b3db154966e74f1390f64980f38e467059093fbaa90d61c0aa4e8ea8314537573809cb297a4f1aa,List())
2019-09-10 13:56:32,527 IN ------->  msg=UpdateFee(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,9873)

2019-09-10 13:56:57,623 OUT <-------  msg=ChannelReestablish(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,7351,7350,Some(PrivateKey(ffeef2b9d21e54f349f2ecad68231408e9ef130f21994649165f6b58f7e7a470)),Some(0221aaef53251f43306945b54693a94a9dd74d21e58f4c3baad2cbd6d31ef517f0))
2019-09-10 13:57:25,084 IN ------->  msg=ChannelReestablish(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,7351,7350,Some(PrivateKey(a70f8c6e733e61349325d4f852b255db8dc2f11a84d71e005c75aa4c8f812d19)),Some(03568b6b0e369474d52fef04828b59a58217201c35fa7eaeef5e0c6b8e56dad20d))
2019-09-10 13:57:25,084 OUT <-------  msg=CommitSig(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,c4d97273ddc8789ae3752b72563b103487e614e1059e49f24b3db154966e74f1390f64980f38e467059093fbaa90d61c0aa4e8ea8314537573809cb297a4f1aa,List())

2019-09-10 13:57:47,937 OUT <-------  msg=ChannelReestablish(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,7351,7350,Some(PrivateKey(ffeef2b9d21e54f349f2ecad68231408e9ef130f21994649165f6b58f7e7a470)),Some(0221aaef53251f43306945b54693a94a9dd74d21e58f4c3baad2cbd6d31ef517f0))
2019-09-10 13:58:29,481 IN ------->  msg=ChannelReestablish(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,7351,7350,Some(PrivateKey(a70f8c6e733e61349325d4f852b255db8dc2f11a84d71e005c75aa4c8f812d19)),Some(03568b6b0e369474d52fef04828b59a58217201c35fa7eaeef5e0c6b8e56dad20d))
2019-09-10 13:58:29,481 IN ------->  msg=UpdateFee(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,12106)
2019-09-10 13:58:29,482 OUT <-------  msg=CommitSig(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,c4d97273ddc8789ae3752b72563b103487e614e1059e49f24b3db154966e74f1390f64980f38e467059093fbaa90d61c0aa4e8ea8314537573809cb297a4f1aa,List())

2019-09-10 13:58:45,351 OUT <-------  msg=ChannelReestablish(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,7351,7350,Some(PrivateKey(ffeef2b9d21e54f349f2ecad68231408e9ef130f21994649165f6b58f7e7a470)),Some(0221aaef53251f43306945b54693a94a9dd74d21e58f4c3baad2cbd6d31ef517f0))
2019-09-10 14:00:11,760 IN ------->  msg=ChannelReestablish(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,7351,7350,Some(PrivateKey(a70f8c6e733e61349325d4f852b255db8dc2f11a84d71e005c75aa4c8f812d19)),Some(03568b6b0e369474d52fef04828b59a58217201c35fa7eaeef5e0c6b8e56dad20d))
2019-09-10 14:00:11,761 OUT <-------  msg=CommitSig(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,c4d97273ddc8789ae3752b72563b103487e614e1059e49f24b3db154966e74f1390f64980f38e467059093fbaa90d61c0aa4e8ea8314537573809cb297a4f1aa,List())
2019-09-10 14:00:11,786 IN ------->  msg=UpdateFee(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,12106)
2019-09-10 14:00:11,786 IN ------->  msg=CommitSig(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,f4f320977e96380f51e06b325c90e94288e95082beac7700232e6214ad97f63500b48abbfed916109b19d2a9aa3dbf218bc83afa7ad5470879a27415c9ae5a2c,List())
2019-09-10 14:00:11,796 OUT <-------  msg=RevokeAndAck(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,PrivateKey(8c1e9b4c34c36488cc1a5aa3a05a07b170646e777738b36cc3e7faf76a0c4c7b),027f33c09b9a2533fd92f5dba0583fe9680c0503f8559e7b89eb3829ddf5eec3e6)

2019-09-10 14:00:35,753 OUT <-------  msg=ChannelReestablish(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,7352,7350,Some(PrivateKey(ffeef2b9d21e54f349f2ecad68231408e9ef130f21994649165f6b58f7e7a470)),Some(039501d259c429847e26a109d16276cc341d85400d47700f31da965666076adac9))
2019-09-10 14:01:12,395 IN ------->  msg=ChannelReestablish(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,7351,7350,Some(PrivateKey(a70f8c6e733e61349325d4f852b255db8dc2f11a84d71e005c75aa4c8f812d19)),Some(03568b6b0e369474d52fef04828b59a58217201c35fa7eaeef5e0c6b8e56dad20d))
2019-09-10 14:01:12,395 OUT <-------  msg=CommitSig(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,c4d97273ddc8789ae3752b72563b103487e614e1059e49f24b3db154966e74f1390f64980f38e467059093fbaa90d61c0aa4e8ea8314537573809cb297a4f1aa,List())
2019-09-10 14:01:12,395 OUT <-------  msg=RevokeAndAck(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,PrivateKey(8c1e9b4c34c36488cc1a5aa3a05a07b170646e777738b36cc3e7faf76a0c4c7b),027f33c09b9a2533fd92f5dba0583fe9680c0503f8559e7b89eb3829ddf5eec3e6)

2019-09-10 14:01:36,321 OUT <-------  msg=ChannelReestablish(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,7352,7350,Some(PrivateKey(ffeef2b9d21e54f349f2ecad68231408e9ef130f21994649165f6b58f7e7a470)),Some(039501d259c429847e26a109d16276cc341d85400d47700f31da965666076adac9))
2019-09-10 14:02:37,606 IN ------->  msg=ChannelReestablish(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,7351,7350,Some(PrivateKey(a70f8c6e733e61349325d4f852b255db8dc2f11a84d71e005c75aa4c8f812d19)),Some(03568b6b0e369474d52fef04828b59a58217201c35fa7eaeef5e0c6b8e56dad20d))
2019-09-10 14:02:37,606 OUT <-------  msg=CommitSig(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,c4d97273ddc8789ae3752b72563b103487e614e1059e49f24b3db154966e74f1390f64980f38e467059093fbaa90d61c0aa4e8ea8314537573809cb297a4f1aa,List())
2019-09-10 14:02:37,607 OUT <-------  msg=RevokeAndAck(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,PrivateKey(8c1e9b4c34c36488cc1a5aa3a05a07b170646e777738b36cc3e7faf76a0c4c7b),027f33c09b9a2533fd92f5dba0583fe9680c0503f8559e7b89eb3829ddf5eec3e6)

2019-09-10 14:02:58,964 OUT <-------  msg=ChannelReestablish(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,7352,7350,Some(PrivateKey(ffeef2b9d21e54f349f2ecad68231408e9ef130f21994649165f6b58f7e7a470)),Some(039501d259c429847e26a109d16276cc341d85400d47700f31da965666076adac9))
2019-09-10 14:03:13,646 IN ------->  msg=ChannelReestablish(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,7352,7350,Some(PrivateKey(a70f8c6e733e61349325d4f852b255db8dc2f11a84d71e005c75aa4c8f812d19)),Some(0218994b97c867c4728ed4b6e873522726568e7f036ffd63d08a4a168fa8965943))
2019-09-10 14:03:13,646 OUT <-------  msg=RevokeAndAck(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,PrivateKey(8c1e9b4c34c36488cc1a5aa3a05a07b170646e777738b36cc3e7faf76a0c4c7b),027f33c09b9a2533fd92f5dba0583fe9680c0503f8559e7b89eb3829ddf5eec3e6)
2019-09-10 14:03:13,686 IN ------->  msg=RevokeAndAck(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,PrivateKey(4d264f847ff9b5058eea0183e512b6e1ae29411bdba263e71051ef73c6f9d8db),030f3b79739f16f4d9a94e51794a5e9b83de20de251b5dd7dd0356a96512c03c1a)
2019-09-10 14:03:13,961 OUT <-------  msg=CommitSig(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,e9174f203b0287ba7586523c274f7ba94382de75ccd96b9c02e22c1886a1343b17997027446616878350008426bf0412352476e7004668c9cda82aef3d92e1da,List())
2019-09-10 14:03:14,195 IN ------->  msg=UpdateFee(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,12114)
2019-09-10 14:03:14,310 IN ------->  msg=CommitSig(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,b64271618aadfc0c7542f5215f18b7015a4a2e6ef34c9719fb19128878e02f895755a8e1716b63efacd90f58284cb1ad1fc97844bc09ba28d3e2c0ad62be98be,List())
2019-09-10 14:03:14,318 OUT <-------  msg=RevokeAndAck(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,PrivateKey(00b0efeee948d92778c0b12160f049a7809b5799b7719ba9c1581cdb6911edd5),0279f6e372ddc516696c37a7238149dac34d651c944720b9b73d0d14d35f5a85cd)
2019-09-10 14:03:14,334 IN ------->  msg=Error(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,ByteVector(667 bytes, #1929705247))
2019-09-10 14:03:16,679 IN ------->  msg=Error(662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c1,ByteVector(667 bytes, #1929705247))

2019-09-10 14:03:14,334 ERROR - peer sent error: ascii='Bad commit_sig signature 7352 3045022100e9174f203b0287ba7586523c274f7ba94382de75ccd96b9c02e22c1886a1343b022017997027446616878350008426bf0412352476e7004668c9cda82aef3d92e1da01 for tx 0200000001662914fd7218a8068c56f5597cc4e0f99a9a4e02442c4221b874e942cb2576c100000000003a0121800257ca7d0000000000160014254ec6de42b4cc05b560df7d1518291161e49ee8a51e8200000000002200201e354487d841ad08fd26f30aba844ad927c12f8d2b714339d6940ba17c08154f0a763620 wscript 52210321a70116a810441b4f54866bec09f77b9592b37d662ba4cf306958685f24b58b2103641baea7668eb9f6278396ec292e8e878d97e9fe460e2bab03f1bcdfeed349af52ae key 03641baea7668eb9f6278396ec292e8e878d97e9fe460e2bab03f1bcdfeed349af feerate 8136' bin=42616420636f6d6d69745f736967207369676e617475726520373335322033303435303232313030653931373466323033623032383762613735383635323363323734663762613934333832646537356363643936623963303265323263313838366131333433623032323031373939373032373434363631363837383335303030383432366266303431323335323437366537303034363638633963646138326165663364393265316461303120666f72207478203032303030303030303136363239313466643732313861383036386335366635353937636334653066393961396134653032343432633432323162383734653934326362323537366331303030303030303030303361303132313830303235376361376430303030303030303030313630303134323534656336646534326234636330356235363064663764313531383239313136316534396565386135316538323030303030303030303032323030323031653335343438376438343161643038666432366633306162613834346164393237633132663864326237313433333964363934306261313763303831353466306137363336323020777363726970742035323231303332316137303131366138313034343162346635343836366265633039663737623935393262333764363632626134636633303639353836383566323462353862323130333634316261656137363638656239663632373833393665633239326538653837386439376539666534363065326261623033663162636466656564333439616635326165206b65792030333634316261656137363638656239663632373833393665633239326538653837386439376539666534363065326261623033663162636466656564333439616620666565726174652038313336

[whitslack]

I experienced another occurrence of this failure mode.
Log attached.

My inexperienced reading of the log:

1. [168184.291307802] The peer reconnects to me.
2. [168193.207858846] The peer sends me a correct channel_reestablish.
3. [168826.516465146] The peer sends me a revoke_and_ack.
4. [168826.634901532] I recalculate the fee rate I want the peer to use and send an update_fee.
5. [168826.754513883] I send a new commitment to the peer.
6. [168826.754663635] I receive a new commitment from the peer, but it is still using the old fee rate.
7. [168826.755927629] I send an error to the peer and transition to AWAITING_UNILATERAL.

What I observe immediately is that the log records nothing that would reveal whether the peer received my update_fee (4) before or after it sent its new commitment (6). I would find it entirely plausible that the peer sent its revoke_and_ack (3), immediately followed by its new commitment (6), and only then received my update_fee (4).

Shouldn't sending an update_fee require receiving an acknowledgment from the peer before the newly requested fee becomes enforced? Otherwise we have no way of knowing at what point the peer received and processed the update_fee relative to the stream of messages the peer is sending.

[whitslack]

@darosior: This is still an issue even after the fix in #3215. I am running the 0.7.3 release, and I just got bitten again by the "Bad commit_sig signature" error.

1. [74122.478167828] I send update_fee.
2. [74122.507521065] I send commitment_signed.
3. [74122.739699679] I receive commitment_signed.
4. [74122.741327422] I send error.

[darosior]

@whitslack
Erh.. Thanks for the report, will investigate soon. Do you now the implementation that the node you were connected to runs ?

cc @rustyrussell

[darosior]

I think this is a synchro problem, from your log:

{
   "type": "DEBUG",
   "time": "74122.507213648",
   "source": "lightning_channeld-03584abd04d69168600340ad5d11723d324f2fc95ea36cbb84804580e344af235e chan #12478:",
   "log": "Sending commit_sig with 0 htlc sigs"
},
{
   "type": "DEBUG",
   "time": "74122.507521065",
   "source": "lightning_channeld-03584abd04d69168600340ad5d11723d324f2fc95ea36cbb84804580e344af235e chan #12478:",
   "log": "peer_out WIRE_COMMITMENT_SIGNED"
},
{
   "type": "DEBUG",
   "time": "74122.739699679",
   "source": "lightning_channeld-03584abd04d69168600340ad5d11723d324f2fc95ea36cbb84804580e344af235e chan #12478:",
   "log": "peer_in WIRE_COMMITMENT_SIGNED"
},
{
   "type": "DEBUG",
   "time": "74122.740028958",
   "source": "lightning_channeld-03584abd04d69168600340ad5d11723d324f2fc95ea36cbb84804580e344af235e chan #12478:",
   "log": "Received commit"
},

It looks like we send an update_fee and a commitment_signed with the new feerate while they were sending a commitment_signed with the old feerate.

[whitslack]

Do you [k]now the implementation that the node you were connected to runs ?

@darosior: No. I only know what is shown on 1ML, which isn't much for that node.

It looks like we send an update_fee and a commitment_signed with the new feerate while they were sending a commitment_signed with the old feerate.

That's how I read it as well. Repeating my question:

Shouldn't sending an update_fee require receiving an acknowledgment from the peer before the newly requested fee becomes enforced? Otherwise we have no way of knowing at what point the peer received and processed the update_fee relative to the stream of messages the peer is sending.

(Stating the obvious) It's not correct to assume that all messages received after having enqueued an update_fee message to the socket for transmission will reflect that update_fee message's having been received by the peer. We need a positive acknowledgment from the peer that it did receive and process our update_fee message before we begin enforcing the new fee.

[darosior]

(Stating the obvious) It's not correct to assume that all messages received after having enqueued an update_fee message to the socket for transmission will reflect that update_fee message's having been received by the peer. We need a positive acknowledgment from the peer that it did receive and process our update_fee message before we begin enforcing the new fee.

(Stating the obvious RFC) We should create a commit if we are the funder and consider the peer's revoke_and_ack as the acknowledgement of the fee update https://github.com/lightningnetwork/lightning-rfc/blob/master/02-peer-protocol.md#updating-fees-update_fee.

Now, we should not get upset in that specific case : we are the funder, we update the fees, we commit, we receive a commitment with old fees just after having committed. Will work on a repro test .. (edit: it's quite hard to reproduce..)