Westend sync stalls at block #2318338

[haikoschol]

Describe the bug

When syncing Westend from genesis, the node does not progress past block #2322947 #2318338. The issues seems to be related to verification of GRANDPA justifications.

Log output

2024-10-28 03:00:09.839 | 2024-10-27T20:00:09Z CRITICAL current sync strategy failed with: while handling ready block: verifying justification: decoding and verifying justification: bad justification for header: invalid commit in grandpa justification	pkg=sync  
2024-10-28 03:00:09.839 | 2024-10-27T20:00:09Z ERROR    processing block #2318339 (0xa6836b1530280181eabce3ded01e62283c7d6a64c6edbc9c789a28b10dc14be4) failed: verifying justification: decoding and verifying justification: bad justification for header: invalid commit in grandpa justification	pkg=sync

[haikoschol]

The log snippet above mentions block #2318339, which has justifications:

{
  block: {
    header: {
      parentHash: 0x16b498d8da125a4bddf9b0063111409935c033023c0d2807e228450c614836bd
      number: 2,318,339
      stateRoot: 0x724dca6938ab1c4f3ec833c60ad309cb51c8316375db2f3b4431700cc2ff248a
      extrinsicsRoot: 0x1302ac30d97f510b563025b5c314893c397004d43fd8cb258a73c82f3547961d
      digest: {
        logs: [
          {
            PreRuntime: [
              BABE
              0x020300000088cae60f00000000
            ]
          }
          {
            Seal: [
              BABE
              0x1897c97fc3d3dfe73bebbfb8ccf942104f469572c1a0eb7200e029be6310923fce7dbfa226938f1ad188a427b0c975a99a6d0f1560dd273b2f54d23fa3700886
            ]
          }
        ]
      }
    }
    extrinsics: [
      {
        isSigned: false
        method: {
          args: {
            now: 1,600,700,208,000
          }
          method: set
          section: timestamp
        }
      }
    ]
  }
  justifications: [
    [
      FRNK
      0x0600000000000000a6836b1530280181eabce3ded01e62283c7d6a64c6edbc9c789a28b10dc14be4036023002ca6836b1530280181eabce3ded01e62283c7d6a64c6edbc9c789a28b10dc14be403602300951efca205be6bf72de00ce74ad6778453f470ef6d3404a61ca2bfbfe5bcc93a7620522d08803e5081f9e93bf0dc2e8143fe764201aedc13b3455a14cf77c50307d952daf2d0e2616e5344a6cff989a3fcc5a79a5799198c15ff1c06c51a1280a6836b1530280181eabce3ded01e62283c7d6a64c6edbc9c789a28b10dc14be403602300c6291ffc574f4802d2a8c1da0581d64a3da41ae080495b0b5f746fc7fb8918a6444cad51033799a87a8a8270041392d3e4c0aaacceab1c18308b0481dd03b10e169da96fe889fe19f2e9463c4cb730b33473a561f0a15d5581ca7c52362a252da6836b1530280181eabce3ded01e62283c7d6a64c6edbc9c789a28b10dc14be4036023002cb07761a88973058336b9a6cb72535334d7ab6df78ec7f9238aa9573a25afc85fc3ec4483dd885f90b0f2cc9885c7001ce794a92df5804f458caaa11c6e830826a50082ec634a6c1bfac4d49d100555edf613df703d8a0ace3e4c95745ea699a6836b1530280181eabce3ded01e62283c7d6a64c6edbc9c789a28b10dc14be4036023004eab479a55b3bd51982351f7eb37134d8374bb163055c708cce288da2d4971ff8dda5226a2c77e88bd9fb1b83c814242538f656fb082176c16e1efcb6484510431dae797bbac0e27b901355cc90446369dcd15d8f965933b57723ee389670d55a6836b1530280181eabce3ded01e62283c7d6a64c6edbc9c789a28b10dc14be403602300c0b0dbe81a2e565ad55590c417db624031313d0fcf2dc3d9f5b09b755d0e899afa4739a2ce2aa7b6ca924cb3c54e886dba41bb0fe86e8f4222dd2b8106e2c20a404b31a6663344c68c7e7c2a1cf4a767f53a525fe022f80da283d2c8bb13686da6836b1530280181eabce3ded01e62283c7d6a64c6edbc9c789a28b10dc14be403602300a3c39a878944703d205b21957a2d6b06af1e18160beaf29b1d38f2f698eff5b727a2808df428e58548278b312937b0679609cb561090e2827ad268ce6a4f51055af0167bdf2c135191f8ffb155c75f097b8573456879d1d89c51945090e645e7a6836b1530280181eabce3ded01e62283c7d6a64c6edbc9c789a28b10dc14be4036023000f5928de38552f67ff5e62daf6c8af411450e2964ad67e32e061813ec47ec0e66f95b181644046aac8de316859a2e4adf3b900c05b171e20edd177169a1e01095d05c538467ed259f2520b56f49ff58832ccc4408a69b28a12bb273f3b419f2ca6836b1530280181eabce3ded01e62283c7d6a64c6edbc9c789a28b10dc14be403602300ce3b5aee44c76557c01d131f3f3b23e5cc0cc3314ff371e358adedfc9cd7f49a0e47dac3605f7b4390005f5f35cfa5003059e41c9339ea378b3e3497fc6a3f0fc6dc4264862e119c84ab2ea3bf4eaa9d7be104d88d7f3ee08e098be001b5abf8a6836b1530280181eabce3ded01e62283c7d6a64c6edbc9c789a28b10dc14be4036023005722ee77a43f276ac49f356d3b8f3a82a68bc7e05049a538c9e14229da133a7458493825954a9f271dbb9e8c784eaa2bf318f9c2f935add547cb963e10f4820dca6fda68419e374351c2fc8314b2b1b636932390a23224d23c30197a20ec4cb2a6836b1530280181eabce3ded01e62283c7d6a64c6edbc9c789a28b10dc14be4036023002369be2840ac2f4a60813d021a48a81a644aaa114a9251acc65cc39f08345c4a93c20cf5f1f5e1e1461ef762a7ea0ffcf05ef5a54b6333a9b029b7ab938c6a0dcbb96907efbc3ff8ed91d171ca26658a2c3905890275375eda937eb45681627ea6836b1530280181eabce3ded01e62283c7d6a64c6edbc9c789a28b10dc14be403602300245960fffbb6413a53b1716f450602d7a80850cf70bcec1257a0d4a090412f317fd875488fd65a0c0b38fee40f05b466f43ddfd65ec2a353f481d9e4eb052e0ccf2cdbf7aa9c86c4ac3ac45d110231d5ce22fe54ad15f6f78b8666c391de3e7800
    ]
  ]
}

[haikoschol]

I've added a (failing) test for decoding justifications in block #2318339 here, but I'm not sure the test is correct. The justifications are copied from the JSON output of the chain_getBlock RPC in the above comment.

[haikoschol]

I've updated the number of the problematic block in the issue title and description because the most recent deployment syncing Westend stopped at this height and because it is one block before the one that actually contains the GRANDPA justifications.

I don't know what happened on the earlier deployment where, according to the Grafana dashboard, the node had supposedly synced up to #2322947. In that case, the logs still showed that block import repeatedly failed at #2318339. There might be a secondary issue with how the Prometheus metric is surfaced.

[EclesioMeloJunior]

@haikoschol can we close this issue since the fix was already merged? #4278

[haikoschol]

@haikoschol can we close this issue since the fix was already merged? #4278

That change is unrelated to this issue. #4278 fixed a storage root mismatch (#4271).

[dimartiro]

Can we update the issue and remove the stacktrace, I think that's not related with the actual issue that is when validating the commit invalid commit in grandpa justification
The stacktrace is for a different error when decoding the scale encoded justification

[dimartiro]

I've added a (failing) test for decoding justifications in block #2318339 here, but I'm not sure the test is correct. The justifications are copied from the JSON output of the chain_getBlock RPC in the above comment.

Regarding the test, it's failing because you are using uint64 but the right type is uint32

[dimartiro]

I was able to code a test to reproduce this with the same voters set, we can try to debug the issue using it.

[dimartiro]

I've been executing a substrate node logging the justification verification data to see what the difference could be. So far I found we are using the wrong setId.

Based on our logs we are using setId: 2684 but substrate is using setId: 2685

From substrate:

importing 2318339: 0xa6836b1530280181eabce3ded01e62283c7d6a64c6edbc9c789a28b10dc14be4,
justification: [6, 0, 0, 0, 0, 0, 0, 0, 166, 131, 107, 21, 48, 40, 1, 129, 234, 188, 227, 222, 208, 30, 98, 40, 60, 125, 106, 100, 198, 237, 188, 156, 120, 154, 40, 177, 13, 193, 75, 228, 3, 96, 35, 0, 44, 166, 131, 107, 21, 48, 40, 1, 129, 234, 188, 227, 222, 208, 30, 98, 40, 60, 125, 106, 100, 198, 237, 188, 156, 120, 154, 40, 177, 13, 193, 75, 228, 3, 96, 35, 0, 149, 30, 252, 162, 5, 190, 107, 247, 45, 224, 12, 231, 74, 214, 119, 132, 83, 244, 112, 239, 109, 52, 4, 166, 28, 162, 191, 191, 229, 188, 201, 58, 118, 32, 82, 45, 8, 128, 62, 80, 129, 249, 233, 59, 240, 220, 46, 129, 67, 254, 118, 66, 1, 174, 220, 19, 179, 69, 90, 20, 207, 119, 197, 3, 7, 217, 82, 218, 242, 208, 226, 97, 110, 83, 68, 166, 207, 249, 137, 163, 252, 197, 167, 154, 87, 153, 25, 140, 21, 255, 28, 6, 197, 26, 18, 128, 166, 131, 107, 21, 48, 40, 1, 129, 234, 188, 227, 222, 208, 30, 98, 40, 60, 125, 106, 100, 198, 237, 188, 156, 120, 154, 40, 177, 13, 193, 75, 228, 3, 96, 35, 0, 198, 41, 31, 252, 87, 79, 72, 2, 210, 168, 193, 218, 5, 129, 214, 74, 61, 164, 26, 224, 128, 73, 91, 11, 95, 116, 111, 199, 251, 137, 24, 166, 68, 76, 173, 81, 3, 55, 153, 168, 122, 138, 130, 112, 4, 19, 146, 211, 228, 192, 170, 172, 206, 171, 28, 24, 48, 139, 4, 129, 221, 3, 177, 14, 22, 157, 169, 111, 232, 137, 254, 25, 242, 233, 70, 60, 76, 183, 48, 179, 52, 115, 165, 97, 240, 161, 93, 85, 129, 202, 124, 82, 54, 42, 37, 45, 166, 131, 107, 21, 48, 40, 1, 129, 234, 188, 227, 222, 208, 30, 98, 40, 60, 125, 106, 100, 198, 237, 188, 156, 120, 154, 40, 177, 13, 193, 75, 228, 3, 96, 35, 0, 44, 176, 119, 97, 168, 137, 115, 5, 131, 54, 185, 166, 203, 114, 83, 83, 52, 215, 171, 109, 247, 142, 199, 249, 35, 138, 169, 87, 58, 37, 175, 200, 95, 195, 236, 68, 131, 221, 136, 95, 144, 176, 242, 204, 152, 133, 199, 0, 28, 231, 148, 169, 45, 245, 128, 79, 69, 140, 170, 161, 28, 110, 131, 8, 38, 165, 0, 130, 236, 99, 74, 108, 27, 250, 196, 212, 157, 16, 5, 85, 237, 246, 19, 223, 112, 61, 138, 10, 206, 62, 76, 149, 116, 94, 166, 153, 166, 131, 107, 21, 48, 40, 1, 129, 234, 188, 227, 222, 208, 30, 98, 40, 60, 125, 106, 100, 198, 237, 188, 156, 120, 154, 40, 177, 13, 193, 75, 228, 3, 96, 35, 0, 78, 171, 71, 154, 85, 179, 189, 81, 152, 35, 81, 247, 235, 55, 19, 77, 131, 116, 187, 22, 48, 85, 199, 8, 204, 226, 136, 218, 45, 73, 113, 255, 141, 218, 82, 38, 162, 199, 126, 136, 189, 159, 177, 184, 60, 129, 66, 66, 83, 143, 101, 111, 176, 130, 23, 108, 22, 225, 239, 203, 100, 132, 81, 4, 49, 218, 231, 151, 187, 172, 14, 39, 185, 1, 53, 92, 201, 4, 70, 54, 157, 205, 21, 216, 249, 101, 147, 59, 87, 114, 62, 227, 137, 103, 13, 85, 166, 131, 107, 21, 48, 40, 1, 129, 234, 188, 227, 222, 208, 30, 98, 40, 60, 125, 106, 100, 198, 237, 188, 156, 120, 154, 40, 177, 13, 193, 75, 228, 3, 96, 35, 0, 192, 176, 219, 232, 26, 46, 86, 90, 213, 85, 144, 196, 23, 219, 98, 64, 49, 49, 61, 15, 207, 45, 195, 217, 245, 176, 155, 117, 93, 14, 137, 154, 250, 71, 57, 162, 206, 42, 167, 182, 202, 146, 76, 179, 197, 78, 136, 109, 186, 65, 187, 15, 232, 110, 143, 66, 34, 221, 43, 129, 6, 226, 194, 10, 64, 75, 49, 166, 102, 51, 68, 198, 140, 126, 124, 42, 28, 244, 167, 103, 245, 58, 82, 95, 224, 34, 248, 13, 162, 131, 210, 200, 187, 19, 104, 109, 166, 131, 107, 21, 48, 40, 1, 129, 234, 188, 227, 222, 208, 30, 98, 40, 60, 125, 106, 100, 198, 237, 188, 156, 120, 154, 40, 177, 13, 193, 75, 228, 3, 96, 35, 0, 163, 195, 154, 135, 137, 68, 112, 61, 32, 91, 33, 149, 122, 45, 107, 6, 175, 30, 24, 22, 11, 234, 242, 155, 29, 56, 242, 246, 152, 239, 245, 183, 39, 162, 128, 141, 244, 40, 229, 133, 72, 39, 139, 49, 41, 55, 176, 103, 150, 9, 203, 86, 16, 144, 226, 130, 122, 210, 104, 206, 106, 79, 81, 5, 90, 240, 22, 123, 223, 44, 19, 81, 145, 248, 255, 177, 85, 199, 95, 9, 123, 133, 115, 69, 104, 121, 209, 216, 156, 81, 148, 80, 144, 230, 69, 231, 166, 131, 107, 21, 48, 40, 1, 129, 234, 188, 227, 222, 208, 30, 98, 40, 60, 125, 106, 100, 198, 237, 188, 156, 120, 154, 40, 177, 13, 193, 75, 228, 3, 96, 35, 0, 15, 89, 40, 222, 56, 85, 47, 103, 255, 94, 98, 218, 246, 200, 175, 65, 20, 80, 226, 150, 74, 214, 126, 50, 224, 97, 129, 62, 196, 126, 192, 230, 111, 149, 177, 129, 100, 64, 70, 170, 200, 222, 49, 104, 89, 162, 228, 173, 243, 185, 0, 192, 91, 23, 30, 32, 237, 209, 119, 22, 154, 30, 1, 9, 93, 5, 197, 56, 70, 126, 210, 89, 242, 82, 11, 86, 244, 159, 245, 136, 50, 204, 196, 64, 138, 105, 178, 138, 18, 187, 39, 63, 59, 65, 159, 44, 166, 131, 107, 21, 48, 40, 1, 129, 234, 188, 227, 222, 208, 30, 98, 40, 60, 125, 106, 100, 198, 237, 188, 156, 120, 154, 40, 177, 13, 193, 75, 228, 3, 96, 35, 0, 206, 59, 90, 238, 68, 199, 101, 87, 192, 29, 19, 31, 63, 59, 35, 229, 204, 12, 195, 49, 79, 243, 113, 227, 88, 173, 237, 252, 156, 215, 244, 154, 14, 71, 218, 195, 96, 95, 123, 67, 144, 0, 95, 95, 53, 207, 165, 0, 48, 89, 228, 28, 147, 57, 234, 55, 139, 62, 52, 151, 252, 106, 63, 15, 198, 220, 66, 100, 134, 46, 17, 156, 132, 171, 46, 163, 191, 78, 170, 157, 123, 225, 4, 216, 141, 127, 62, 224, 142, 9, 139, 224, 1, 181, 171, 248, 166, 131, 107, 21, 48, 40, 1, 129, 234, 188, 227, 222, 208, 30, 98, 40, 60, 125, 106, 100, 198, 237, 188, 156, 120, 154, 40, 177, 13, 193, 75, 228, 3, 96, 35, 0, 87, 34, 238, 119, 164, 63, 39, 106, 196, 159, 53, 109, 59, 143, 58, 130, 166, 139, 199, 224, 80, 73, 165, 56, 201, 225, 66, 41, 218, 19, 58, 116, 88, 73, 56, 37, 149, 74, 159, 39, 29, 187, 158, 140, 120, 78, 170, 43, 243, 24, 249, 194, 249, 53, 173, 213, 71, 203, 150, 62, 16, 244, 130, 13, 202, 111, 218, 104, 65, 158, 55, 67, 81, 194, 252, 131, 20, 178, 177, 182, 54, 147, 35, 144, 162, 50, 36, 210, 60, 48, 25, 122, 32, 236, 76, 178, 166, 131, 107, 21, 48, 40, 1, 129, 234, 188, 227, 222, 208, 30, 98, 40, 60, 125, 106, 100, 198, 237, 188, 156, 120, 154, 40, 177, 13, 193, 75, 228, 3, 96, 35, 0, 35, 105, 190, 40, 64, 172, 47, 74, 96, 129, 61, 2, 26, 72, 168, 26, 100, 74, 170, 17, 74, 146, 81, 172, 198, 92, 195, 159, 8, 52, 92, 74, 147, 194, 12, 245, 241, 245, 225, 225, 70, 30, 247, 98, 167, 234, 15, 252, 240, 94, 245, 165, 75, 99, 51, 169, 176, 41, 183, 171, 147, 140, 106, 13, 203, 185, 105, 7, 239, 188, 63, 248, 237, 145, 209, 113, 202, 38, 101, 138, 44, 57, 5, 137, 2, 117, 55, 94, 218, 147, 126, 180, 86, 129, 98, 126, 166, 131, 107, 21, 48, 40, 1, 129, 234, 188, 227, 222, 208, 30, 98, 40, 60, 125, 106, 100, 198, 237, 188, 156, 120, 154, 40, 177, 13, 193, 75, 228, 3, 96, 35, 0, 36, 89, 96, 255, 251, 182, 65, 58, 83, 177, 113, 111, 69, 6, 2, 215, 168, 8, 80, 207, 112, 188, 236, 18, 87, 160, 212, 160, 144, 65, 47, 49, 127, 216, 117, 72, 143, 214, 90, 12, 11, 56, 254, 228, 15, 5, 180, 102, 244, 61, 223, 214, 94, 194, 163, 83, 244, 129, 217, 228, 235, 5, 46, 12, 207, 44, 219, 247, 170, 156, 134, 196, 172, 58, 196, 93, 17, 2, 49, 213, 206, 34, 254, 84, 173, 21, 246, 247, 139, 134, 102, 195, 145, 222, 62, 120, 0]
setId: 2685
voters: VoterSet {
	voters: [
		(Public(07d952daf2d0e2616e5344a6cff989a3fcc5a79a5799198c15ff1c06c51a1280 (5CEzkWVb...)), VoterInfo { position: 0, weight: VoterWeight(1) }),
		(Public(169da96fe889fe19f2e9463c4cb730b33473a561f0a15d5581ca7c52362a252d (5CaMkDjN...)), VoterInfo { position: 1, weight: VoterWeight(1) }),
		(Public(26a50082ec634a6c1bfac4d49d100555edf613df703d8a0ace3e4c95745ea699 (5CwNh8CL...)), VoterInfo { position: 2, weight: VoterWeight(1) }),
		(Public(2767783903b5e3e7329dacf52def11668f27117761558abcec75a96f2861ce97 (5CxNTiwo...)), VoterInfo { position: 3, weight: VoterWeight(1) }),
		(Public(31dae797bbac0e27b901355cc90446369dcd15d8f965933b57723ee389670d55 (5DC5EPxF...)), VoterInfo { position: 4, weight: VoterWeight(1) }),
		(Public(404b31a6663344c68c7e7c2a1cf4a767f53a525fe022f80da283d2c8bb13686d (5DX1FyhD...)), VoterInfo { position: 5, weight: VoterWeight(1) }),
		(Public(5af0167bdf2c135191f8ffb155c75f097b8573456879d1d89c51945090e645e7 (5E7wVF6e...)), VoterInfo { position: 6, weight: VoterWeight(1) }),
		(Public(5d05c538467ed259f2520b56f49ff58832ccc4408a69b28a12bb273f3b419f2c (5EAg2P1k...)), VoterInfo { position: 7, weight: VoterWeight(1) }),
		(Public(a0c551a7eeafb294752ef15fb9e9227b28c84834806b03cbe4244ad0d3e04d83 (5FhW8mMN...)), VoterInfo { position: 8, weight: VoterWeight(1) }),
		(Public(a505ab1eccf2dccb6f1aba3ff928b765ec2f9fc7192826341ee4786a72868579 (5Fo5SbC2...)), VoterInfo { position: 9, weight: VoterWeight(1) }),
		(Public(c6dc4264862e119c84ab2ea3bf4eaa9d7be104d88d7f3ee08e098be001b5abf8 (5GZSmZFc...)), VoterInfo { position: 10, weight: VoterWeight(1) }),
		(Public(ca6fda68419e374351c2fc8314b2b1b636932390a23224d23c30197a20ec4cb2 (5Ge8ksU1...)), VoterInfo { position: 11, weight: VoterWeight(1) }),
		(Public(cbb96907efbc3ff8ed91d171ca26658a2c3905890275375eda937eb45681627e (5Gfpf1R4...)), VoterInfo { position: 12, weight: VoterWeight(1) }),
		(Public(cf2cdbf7aa9c86c4ac3ac45d110231d5ce22fe54ad15f6f78b8666c391de3e78 (5GkM6Ukp...)), VoterInfo { position: 13, weight: VoterWeight(1) }),
		(Public(dec97d6e8be01e9195f7300f4335a043fd074977844bbf5ed7b437e3606fe91f (5H6pLpid...)), VoterInfo { position: 14, weight: VoterWeight(1) })
	],
	threshold: VoterWeight(11),
	total_weight: VoterWeight(15),
}

[dimartiro]

Last finding is that we are not applying the right forced authority set change.
There is a forced auth set change generated in block #2318338 with delay = 1 that we need to apply in block #2318339 but we are trying to process the block before applying that forced set change.
I'm trying to understand where this bug was introduced to find the right fix

[dimartiro]

seems that #4336 solved this since we are able to reach the block 4M now.

@haikoschol can you take a look at that PR please?

[haikoschol]

I deployed the fix to westend-genesis-host-2 on ECS and it synced past the problematic block as well.