Nodes go out of sync every three hours

[dzhelezov]

On test- and mainnet, the node sync check peaks to ~100 every three hours or so, then gets back to normal. (In particular, around 11/24 16:28 server time, logs attached) testnet_sync_fail.zip

[fsbbn]

Log Analysis #222250 - #222300

Round Solidification stops at Round #222251

Nominee 1, Process Milestone #222250
nominee1 | 11/24 16:27:52.118 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Process Milestone hash, round =004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7 222250
nominee1 | 11/24 16:27:52.120 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:186 - New milestone 004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7 (1/1) added to round #222250

Relayer 3, Round #222250 is SOLID
relayer3 | 11/24 16:27:52.707 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Process Milestone hash, round =004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7 222250
relayer3 | 11/24 16:27:52.708 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:186 - New milestone 004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7 (1/1) added to round #222250
relayer3 | 11/24 16:27:52.993 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:173 - solid round: round #222250 (004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7)
relayer3 | 11/24 16:27:52.994 [Latest Solid Milestone Tracker] DEBUG SnapshotServiceImpl:170 - Applying round #222250, snapshot hash: 004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7 to ledger
relayer3 | 11/24 16:27:52.994 [Latest Solid Milestone Tracker] DEBUG LatestSolidMilestoneTrackerImpl:391 - Round #222250 is SOLID

Nominee 1, Round #222250 is SOLID
nominee1 | 11/24 16:27:52.246 [Latest Solid Milestone Tracker] DEBUG SnapshotServiceImpl:170 - Applying round #222250, snapshot hash: 004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7 to ledger
nominee1 | 11/24 16:27:52.245 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:173 - solid round: round #222250 (004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7)
nominee1 | 11/24 16:27:52.246 [Latest Solid Milestone Tracker] DEBUG LatestSolidMilestoneTrackerImpl:391 - Round #222250 is SOLID

Relayer 1, Round #222250 is SOLID
relayer1 | 11/24 16:27:52.771 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Process Milestone hash, round =004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7 222250
relayer1 | 11/24 16:27:52.772 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:186 - New milestone 004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7 (1/1) added to round #222250
relayer1 | 11/24 16:27:53.099 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:173 - solid round: round #222250 (004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7)
relayer1 | 11/24 16:27:53.099 [Latest Solid Milestone Tracker] DEBUG SnapshotServiceImpl:170 - Applying round #222250, snapshot hash: 004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7 to ledger
relayer1 | 11/24 16:27:53.099 [Latest Solid Milestone Tracker] DEBUG LatestSolidMilestoneTrackerImpl:391 - Round #222250 is SOLID

Milestone #222250 is VALID
nominee1 | 11/24 16:27:55.118 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Milestone 004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7 is VALID
relayer3 | 11/24 16:27:55.707 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Milestone 004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7 is VALID
relayer1 | 11/24 16:27:55.771 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Milestone 004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7 is VALID

Process Milestone #222251
relayer3 | 11/24 16:28:07.028 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Process Milestone hash, round =000f3b5f9c5757edad7979589e50bad86704aa934236d5e12fd0d3b023fc8f08 222251
relayer1 | 11/24 16:28:07.132 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Process Milestone hash, round =000f3b5f9c5757edad7979589e50bad86704aa934236d5e12fd0d3b023fc8f08 222251
nominee1 | 11/24 16:28:07.463 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Process Milestone hash, round =000f3b5f9c5757edad7979589e50bad86704aa934236d5e12fd0d3b023fc8f08 222251

Round #222250 has not finished
nominee1 | 11/24 16:28:07.253 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:167 - round has not finished: round #222250 (004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7)
relayer1 | 11/24 16:28:08.105 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:167 - round has not finished: round #222250 (004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7)
relayer3 | 11/24 16:28:09.001 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:167 - round has not finished: round #222250 (004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7)

nominee1 | 11/24 16:28:08.253 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:167 - round has not finished: round #222250 (004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7)
relayer1 | 11/24 16:28:09.106 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:167 - round has not finished: round #222250 (004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7)
relayer3 | 11/24 16:28:10.002 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:167 - round has not finished: round #222250 (004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7)

Milestone #222251 is VALID
relayer3 | 11/24 16:28:10.028 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Milestone 000f3b5f9c5757edad7979589e50bad86704aa934236d5e12fd0d3b023fc8f08 is VALID
relayer1 | 11/24 16:28:10.132 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Milestone 000f3b5f9c5757edad7979589e50bad86704aa934236d5e12fd0d3b023fc8f08 is VALID
nominee1 | 11/24 16:28:10.463 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Milestone 000f3b5f9c5757edad7979589e50bad86704aa934236d5e12fd0d3b023fc8f08 is VALID

Round #222250 has not finished
nominee1 | 11/24 16:28:10.255 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:167 - round has not finished: round #222250 (004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7)
relayer1 | 11/24 16:28:11.107 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:167 - round has not finished: round #222250 (004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7)
relayer3 | 11/24 16:28:12.003 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:167 - round has not finished: round #222250 (004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7)

After processing Milestone #222300, Round Solidification starts again

Process Milestone #222298
relayer3 | 11/24 16:39:52.941 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Process Milestone hash, round =00000c9c05a96044870f224217484488e4fd0d7a96f2f177446f70e5fabfb621 222298
nominee1 | 11/24 16:39:53.673 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Process Milestone hash, round =00000c9c05a96044870f224217484488e4fd0d7a96f2f177446f70e5fabfb621 
relayer1 | 11/24 16:39:53.716 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Process Milestone hash, round =00000c9c05a96044870f224217484488e4fd0d7a96f2f177446f70e5fabfb621 

Milestone #222298 is VALID
relayer3 | 11/24 16:39:55.941 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Milestone 00000c9c05a96044870f224217484488e4fd0d7a96f2f177446f70e5fabfb621 is VALID
nominee1 | 11/24 16:39:56.674 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Milestone 00000c9c05a96044870f224217484488e4fd0d7a96f2f177446f70e5fabfb621 is VALID
relayer1 | 11/24 16:39:56.717 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Milestone 00000c9c05a96044870f224217484488e4fd0d7a96f2f177446f70e5fabfb621 is VALID

Process Milestone #222300
nominee1 | 11/24 16:40:07.995 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Process Milestone hash, round =00a90eae9148c680efd57d47c966be467a617d97437f23bb46955c05d0e4800a 222300
nominee1 | 11/24 16:40:07.997 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:186 - New milestone 00a90eae9148c680efd57d47c966be467a617d97437f23bb46955c05d0e4800a (1/1) added to round #222300

relayer1 | 11/24 16:40:08.079 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Process Milestone hash, round =00a90eae9148c680efd57d47c966be467a617d97437f23bb46955c05d0e4800a 222300
relayer1 | 11/24 16:40:08.080 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:186 - New milestone 00a90eae9148c680efd57d47c966be467a617d97437f23bb46955c05d0e4800a (1/1) added to round #222300

relayer3 | 11/24 16:40:08.291 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Process Milestone hash, round =00a90eae9148c680efd57d47c966be467a617d97437f23bb46955c05d0e4800a 222300
relayer3 | 11/24 16:40:08.293 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:186 - New milestone 00a90eae9148c680efd57d47c966be467a617d97437f23bb46955c05d0e4800a (1/1) added to round #222300

Rounds #222251 to #222299 becomes empty rounds
relayer3 | 11/24 16:40:08.428 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:160 - Round #222251 has finished without milestones
relayer3 | 11/24 16:40:08.428 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:171 - Round = 222251, solid = true
relayer3 | 11/24 16:40:08.428 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:163 - created and stored empty round: 222251
relayer3 | 11/24 16:40:08.428 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:173 - solid round: round #222251 ()
relayer3 | 11/24 16:40:08.428 [Latest Solid Milestone Tracker] DEBUG LatestSolidMilestoneTrackerImpl:391 - Round #222251 is SOLID
relayer3 | 11/24 16:40:08.428 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:181 - ctx= [], round=222251
relayer3 | 11/24 16:40:08.429 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:160 - Round #222252 has finished without milestones
relayer3 | 11/24 16:40:08.429 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:163 - created and stored empty round: 222252
relayer3 | 11/24 16:40:08.429 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:173 - solid round: round #222252 ()
relayer3 | 11/24 16:40:08.429 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:171 - Round = 222252, solid = true
relayer3 | 11/24 16:40:08.429 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:181 - ctx= [], round=222252
…
relayer3 | 11/24 16:40:08.446 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:171 - Round = 222297, solid = true
relayer3 | 11/24 16:40:08.446 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:181 - ctx= [], round=222297
relayer3 | 11/24 16:40:08.446 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:160 - Round #222298 has finished without milestones
relayer3 | 11/24 16:40:08.446 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:171 - Round = 222298, solid = true
relayer3 | 11/24 16:40:08.446 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:173 - solid round: round #222298 ()
relayer3 | 11/24 16:40:08.446 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:163 - created and stored empty round: 222298
relayer3 | 11/24 16:40:08.447 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:181 - ctx= [], round=222298
relayer3 | 11/24 16:40:08.447 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:160 - Round #222299 has finished without milestones
relayer3 | 11/24 16:40:08.447 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:171 - Round = 222299, solid = true
relayer3 | 11/24 16:40:08.447 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:163 - created and stored empty round: 222299
relayer3 | 11/24 16:40:08.447 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:173 - solid round: round #222299 ()
relayer3 | 11/24 16:40:08.447 [Latest Solid Milestone Tracker] DEBUG SnapshotServiceImpl:170 - Applying round #222299, snapshot hash: 00000000000000000000000000000000000000000000656d707479726f756e64 to ledger

nominee1 | 11/24 16:40:08.764 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:171 - Round = 222297, solid = true
nominee1 | 11/24 16:40:08.765 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:181 - ctx= [], round=222297
nominee1 | 11/24 16:40:08.765 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:173 - solid round: round #222297 ()
nominee1 | 11/24 16:40:08.765 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:171 - Round = 222298, solid = true
nominee1 | 11/24 16:40:08.765 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:160 - Round #222298 has finished without milestones
nominee1 | 11/24 16:40:08.765 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:173 - solid round: round #222298 ()
nominee1 | 11/24 16:40:08.765 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:163 - created and stored empty round: 222298
nominee1 | 11/24 16:40:08.765 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:163 - created and stored empty round: 222299
nominee1 | 11/24 16:40:08.765 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:181 - ctx= [], round=222298
nominee1 | 11/24 16:40:08.765 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:171 - Round = 222299, solid = true
nominee1 | 11/24 16:40:08.765 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:160 - Round #222299 has finished without milestones
nominee1 | 11/24 16:40:08.765 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:173 - solid round: round #222299 ()
nominee1 | 11/24 16:40:08.766 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:181 - ctx= [], round=222299
nominee1 | 11/24 16:40:08.765 [Latest Solid Milestone Tracker] DEBUG SnapshotServiceImpl:170 - Applying round #222299, snapshot hash: 00000000000000000000000000000000000000000000656d707479726f756e64 to ledger

relayer1 | 11/24 16:40:08.564 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:163 - created and stored empty round: 222297
relayer1 | 11/24 16:40:08.564 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:171 - Round = 222297, solid = true
relayer1 | 11/24 16:40:08.565 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:181 - ctx= [], round=222297
relayer1 | 11/24 16:40:08.565 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:173 - solid round: round #222297 ()
relayer1 | 11/24 16:40:08.565 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:160 - Round #222298 has finished without milestones
relayer1 | 11/24 16:40:08.565 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:163 - created and stored empty round: 222298
relayer1 | 11/24 16:40:08.565 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:171 - Round = 222298, solid = true
relayer1 | 11/24 16:40:08.565 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:173 - solid round: round #222298 ()
relayer1 | 11/24 16:40:08.565 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:181 - ctx= [], round=222298
relayer1 | 11/24 16:40:08.565 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:163 - created and stored empty round: 222299
relayer1 | 11/24 16:40:08.565 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:160 - Round #222299 has finished without milestones
relayer1 | 11/24 16:40:08.565 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:171 - Round = 222299, solid = true
relayer1 | 11/24 16:40:08.565 [Latest Solid Milestone Tracker] DEBUG SnapshotServiceImpl:170 - Applying round #222299, snapshot hash: 00000000000000000000000000000000000000000000656d707479726f756e64 to ledger

Milestone #222300 is VALID
nominee1 | 11/24 16:40:10.995 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Milestone 00a90eae9148c680efd57d47c966be467a617d97437f23bb46955c05d0e4800a is VALID
relayer1 | 11/24 16:40:11.079 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Milestone 00a90eae9148c680efd57d47c966be467a617d97437f23bb46955c05d0e4800a is VALID
relayer3 | 11/24 16:40:11.292 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Milestone 00a90eae9148c680efd57d47c966be467a617d97437f23bb46955c05d0e4800a is VALID

Round #222299 is SOLID
relayer3 | 11/24 16:40:11.428 [Latest Solid Milestone Tracker] DEBUG LatestSolidMilestoneTrackerImpl:391 - Round #222299 is SOLID
nominee1 | 11/24 16:40:11.745 [Latest Solid Milestone Tracker] DEBUG LatestSolidMilestoneTrackerImpl:391 - Round #222299 is SOLID
relayer1 | 11/24 16:40:11.548 [Latest Solid Milestone Tracker] DEBUG LatestSolidMilestoneTrackerImpl:391 - Round #222299 is SOLID

Relayer 3, Round #222300 is SOLID
relayer3 | 11/24 16:40:22.481 [Latest Solid Milestone Tracker] DEBUG SnapshotServiceImpl:170 - Applying round #222300, snapshot hash: 00a90eae9148c680efd57d47c966be467a617d97437f23bb46955c05d0e4800a to ledger
relayer3 | 11/24 16:40:22.482 [Latest Solid Milestone Tracker] DEBUG LatestSolidMilestoneTrackerImpl:391 - Round #222300 is SOLID
relayer3 | 11/24 16:40:22.488 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:181 - ctx= [00d6bf50ae66e6c624229488b0b46ec239d90328ee820289b80b0e9f7453b35c, 00a43f0ec8ef6bf56781630346d55e20412f23a0c38d61612fa7734eaa14ea91, 003187eb1d43c17d803a79facf7435f486c1b9d4d88a8f15e1fdec680bfc710f, 009fe1c90d3a0a3f75dcef473cbdf36de5a4743ff66925cb4a102c71e720cfa9, 00469fe71a9bfe4f90fbed9e569372d4fecc4ce53b9fe5572c1b787ffaac61c0, 001377d684f74b7ab0a43e0c2acd8282e4d7dedd3a00fedb8fa5b68876821912, 00ddd290334e049149fd2a807e4d789ea2d74ee3550f880195311221fa26f162, 00f56644de8135f8349c91da0acac2cf2b3a9f59b5b77e4ab1f802056bcd2f64, 00add451de98e7ff2e7c57a6cc9736b12d0bcf9cb9c02caf6d9324f52393ab9f, 00ed6d0eff1ab51031459d30c89aabb73f8e248b45d71d15ee763c2598adc68c, 0092590b26ab50960f24e023877f22af7938bc1a8e0bbeb6ba7d1efeec9073f3, 003bffffe6a2c3002bc57fbba7e26bc0b1d53afe8c171c07bbdc4fdc4b8cb684, 00073eef2afff423fd80c6669cc36e75f64183f397be4708b1bbe90d5a8fb032, 00d57105c66cf6c0ad82d3d2c2bdfa1f21fb6cfee2354dcfa7a1dbf46ec1b6b8, 00f58a72523a7ddd39330dcacf817a697078a0d4b8846d39340db916c29d4c4c, 0094ba9e7b7696368a7a642fb3de5766cb78f8c48ce3c672852d12dc0b366e2a, 001966e6374926b40fd25224122f0b982620fe9af287bdb086f38c92cc425fd8, 0021df9ae896890a3703e56be1e6b14d165bac03e7b4af65ef5a0357cbbb0318, 002d69c5bf9c162c3818cfc4d7ebf6a0734eec92aec66834611ff522b1ff4d35, 00ec492477272c06e76c3eb97be088ebad9d4012fddbedd44a597ad8253e6e86, 009c5ba35ee96500fce4c8cdf6b6febbd9977778dd7715a90e9cfab51d24840d, 009e2e13a689c0d022da7d7952e65d34ab7964086b1e62a7b557baac254585e0, 006d51dc18585eef5e2e6708fefb97666b659cc3912c9ee5315c5ba865083e96, 00ec8a064c9498aa353aae3cc03808d4a59a431075fb3f56315e72f7285c79ed, 00cd4f19a7b291cd7e5003c3327f9db5f79be51870b179dd2236359a7fcd92cf, 00330c3c855709d9b5fcf4770239a4bd02c926a601b815be6cee579d5ed0ed50, 00d287c06e53d262a53e6be7301c0e01d06e81d13d800af42b85ec277424a62c, 00e027408df81cde5a1e10bc499317d86683f379c7e3ebe21ea0cc43c3f5c647, 00e234c56f1d27fb441d5cf7c8473e89adaa1d2e9cc1c7667f7642886a8e7de0, 00f0ec4733c9fa4c767a9e42e47949fe2a1ab7bd75c62f2a67bac10724b9aab8, 001c863e8e22a089d55135b7f90de4032264670a68fe8edec69d3c4467e3ee45, 00af4bfc81974c9c65507d58093ff4402d889b31b0ee045ab5bd891dd795e8a5, 00e4c93c5674dc2ef1a2495927291e752c8ba8b6ba43188ee776c74140426606, 0000e5b64d460e6d452345bd97194116ff9d3247286ae9d63076eeaedf24ba9b, 00739efc8da2bbd761d65ddb0b0ab49bbb4e852a3751a601f6a6bf3a7c76bc7a, 00133cbcc8d13500b0a8229564744800304d9135184e2830ba86a753bbde99ad, 005a658999f9781507229023ec4df993e7e5301db39f6fe8f36250778349bc4a, 008f2c98ac7a55194a79e00321dc67a52be349fe760ec57cd45caf6e5b6d5866, 006aff5f1c008a001a557000c85e782e131eb0e8ebda7292500e57487a3a1220, 007926b765cb9cb79062dc777ed01caaeb760861984634ed1d07ec63ee2d245e, 008afae753d88d0e579fdb109a541380be871c46daced50963f2c4d604a761f0, 00bd08708c357282287da0be1ce126e8a4be3126e60ba4c719708976728e8983, 00e7d83ca1b462b5ff4c43274568bc7bc1e1319aae3375c77096011b663b2384, 005230fe2910eacc55c2864455f490ab97cfacd2b075e12640b534e004e21fe2, 00017b0446b736cca92a755337b9fd390332bc822eb1c0df2bd47385895d2ab2, 00a8349ef5069812d45aff40699d30516d084212f97a077ee3c45ed9c2ecc6db, 00d50ac5c5574ae0bab29a78f6d66306d9f92b97f96c37c771a35116ff5d9371, 0054c9f1fcbe43e6e504f48ea28cb89c90908592d3fa75443f7bf0ebf74141e9, 0020ee631cafaf5d31ebea4e941104682fc9f068163989ab615975c599eaf601, 00e593d0b58cbcc06555d06d8d4d8c505f0a38aab9ce3cb4662c7a0e4082c2b4, 009dcfdefe394d1648d10eb26cc3568dd7de15be65807db1272e5a66452713ef, 008e44205346ddd97230c93549e44d150148a8e6006efe66fcb9ecca811df032, 0001bffa585f16e16bd9286e36b53a9492f9e8de09ec1aa5978897e180192e30, 00b308dd069f4365a05b070eabba319785ccb3594fca45d18ce2005702119f62, 0072a545a8640496098f9e157f21904bc76f759809189fa51386e1b69c8d0cd5, 00d4a4110de3f5484025980cc596d6948feee91173ead1fda2b670a0f2f40a03, 00a90a40f55b680e41968d1d52d7ae5126b7a555467664183e501e3f1d43c380, 008cac5dabc9192e71b9ed5286c5b8704d28958df6c873f85ba8236286099943, 0016584bb535028d4d515ad9642b811f7096f714d0711d1ea6681152daae0338, 00ca16a8d89381756d396c2e692f00de46716781428d87b48788c5655492c3c4, 00fa1c314b47111e3b7301343fd77b2945bafdb35a0aa2db60c16d7a8b70dac3, 00d5df1a78b96968cb5ffd5fa14ddce5b108c66b0d119cc3d8a0b69b439f9654, 0024f4b68959d6862ba28e13f2f166220eaa0084a79755ee65043c2e7ca1dcc8, 00a9a7638fb1a4d5e26e67162f0d434cb1c6b6199505dd1641088f9c6d8cfb4b, 002c4d7f417564bc918467f8f5c64c209a0761f8ad9d181181209771f2aa4ee0, 0052a98a79538b1b7001f39967fc853e59989145f65f88d7e6bf4e390cea77c9, 003fa18024b84bb40d3570a80ba0c4dabd71131419408f58f7595f53dc8b9b59, 00e910dc584cb4ddbe187ca8541ab4007b210992d7abc40d958b694e7a4b6456, 00a1338b971d03bd79c4c9af86499d414f61a81353b2ba185f272ffc46f610da, 00d1e2be95c32d8fce60ba189b6689d2f09502af1f9bf5e7a923ff5dd5630d31, 001e64bd850167fef71664a5dd2c589d3d836da7a24cf16b05064940d54e93d4, 003fdcfb9c2cdd35235422eff3ae3155c1aebc46e9d973518749ea46644a172d, 003e0d425aabd5fa0e1a759e444d3feb1bc59d128fa9fd80574f6ff8b8b9f015, 009edcfe3e1e2bad43eabc4a52ad6a587c291cd7a1880a5959d64171c96efb4b, 00d963c898597d3df2c8ff73083c4aa8e4787eaa16122fd8381179620b445a65, 0051560be14a8c2130eee84fdd3567bbf018f139e198c2e38d35ca0c0d9a8690, 009cefffec799f5fd1a5a45821edfb8fa68400478d8251f0887e60e173be5c1e, 004a121abc2fdca2304c9104004eccefd7d6fbfd9073bafbe84ffa2f48550ce7, 00e4bcb5ad7e371e702fd239d293fef34669e003c69e3f14b62392572b35c19e, 00a29db1e60a5963881d79f3bb54e7e47e959c72a1604c4551906cb387842978, 00a4b3ca09127e47ef893eb3be96b7852e1d299f3457774ad6a3ea2a9a6ade21, 00229f87350a043c39f2858ce53e619aba40a3157325724ab71e3aa34f9e383e, 00bf432f12fc48e820c061bd343a4da7e4b7a1220c231ebd30b91f26c7c57f33, 00e03983e6e2bd99b540cc81ef7f913e3c82e9fa746939b355b6a3f8cfa8cf14, 00ee6495216f58fed84d8c15cdc769ad06e9f1b88d9421460476ce169a95b303, 008fa2d66c797ee3ed81d3224f1b9dffeda7763fe5d48c1584179b1ac5e85fbf, 00ff91abbde9959cd9190e3a88e5e0187c893b5b0ae9cfd4cd8aa212e6f26e07, 00ee4384a0095bb0701f94841342b9db3b1c6a3615bb464d2d2a39ab3f5fe17f, 0073facaad3501155a6dd4a9d1410da176fbec84a697d4047666208113eb6924, 00411284adfb60d462feebd4373d0640fa694ba12642b7a8ba9e103f4c362d99, 00f5e8f689af91b1589f3cd5fc0697150a2776b11abb914e0398b8b702d45715, 00fb8749ef21a3eb5834536cfdd7a26c447ed407d93e7fcf38b8464283cc3ea2, 007f9f148d400ce776d2be8ddb249cdaffb69d7ace584a920563d9e69508e18f, 0082df9a5df170b3ec18051e5d443e8c9b88877e0fcea18c9564c754aa25db07, 0082b104161a08a2508c60b9e6090c68f2c7708f036e031da8e0e3aa69f0edf8, 00a426d5b1197adaa0fe01aba8e2985bce3328adbcfa16dbd47eba2949fbdf85, 0090cfa6745ad1f0cb50501e2e57a6ae3261b1d795a8d722506774e2a74cd0bc, 0095d1c10798e6e5d49fb99229430ff011f98dd4cc960612831709de79265b44, 00ec2f179f67ebaafa09b23a34c2a719b9d47e1fb76eba246c0c2b97528283c5, 00978ac7abf5d5f2056d276c74a7fbb56e53ca630c125a01cf1b3aee8b9898d9, 004f53faafa876aa87b129ee8cf8274a64bbe36858cdce1e54c52d355cbba106, 00e4e9ba847d4a3e9ff303fdd87e052fd7066796798f970cf05942cc944dc202, 00bb01d29e061a692e1b1ee9e1aa7a99b88f254c00a243d295a523e35e069bbc, 008d05647203cfe8852ec8c955377dd8c6d9c83a59b57fe841f6f7744371d8ef, 00d9be4ecb0a226bb7787c675b19df8d7e35fbcf101e5fc0822ac482063785d6, 00b3a5820cc8a74d0006545bbea5ec458dfec531fcd06184f851f6a365786256, 00f64e35a8e76c379c6ad2d33c1923873ddb930fba165059891caa1cd80ec356, 000c04592cd5ebdbd795b2fd4c182197ba979dc3f164857cc7e109251468e0b4, 00e098750627d54e17ae312cbbbd9583d447182f13cfdf97b2a2791d6216de11, 00aa312ec66c33394475c3184d436e7e9c95f5515cb1455fc11fd692a0f8d4d4, 007303bb9db1c07f461409a96b324dad773fa2f76089cf96270b4fd1c2aefa69, 0032962726088448ac4cf27e3cc09e1aaa795400612675b87d7c2b7ab07ee533, 00a7dc3c9e5be2b4516e91986257a76f21be9ce85fe193154c7872c0690dd234, 00b726739002c8c9aa5833e71466578b6bceccc078e86918d41d6bdd680714a5, 003ff4790d322730dc2ff2f157e97d9a3f1b67cc178d02cc0724fba33551ea4b, 0007b3bec5df3f25f8727817f35edbec38923094d88043358397401499ebab40, 00ac11829f38410e06f3a90ac138c2773febd862ba1bb9f59f8ac60b666bee7e, 00ff0d91bdc0e244d5c863250b1b0731176b2cdebb2e5e8c9822966ae658bd1d, 00d5355d8ddff026e364946b4add1fa89255534a1b44d155cc590a0716b88ad2, 00ab198558a7255641dc30bbdf92185b3095cf94a3b971432dcf6855ffda2e61, 00fe93f426ba96338cb83e34f2844cd88703724a9c879851e4829b55fc5d6109, 00a30eb5bbe773d96f0b4c242743007bcec270b6bfe4aa27b3e7a621e67ba383, 003c54a471c23694bb52eabd8ae0aebe9f0789cd75049b79199d46c9ffe8a4a0, 00c69657ee14f9e0b512d5ef361ddb04a23b46b859a566ac4b1b91b4c2642f42, 002bae32fd705c87be91c9097963d9024e8f4bfe0e962b0603b510f2aa8b45cb, 00e76ea77fc50ff0847574ca91426f7f88873eabc3215306810bcec9a385476e, 00c1840d33bf2eb5ff891ac45b314c9655d03f6078ade2081e695b4b5f7acf62, 000478749a43b3b061fa6ed06d7a45b3e09c9847c9efc6dcf820b01eef4bff9b, 00265442323b23c69cd235a1aac0ab0b6221ee43dd82eae04f0b79aa02a70edc, 003f78c12637ba900fab7a2569ecc93f9f8be0a2494a0a53e65b73465a6daefe, 0084a20ce5f5858b2a3d8854f518aacffa32a96f722bed6ab7bc10aaaad289f3, 005e082a96d1a07fb5b654752cde2443066d418e0306a7bd5f745d5f23dd5c5d, 000f3b5f9c5757edad7979589e50bad86704aa934236d5e12fd0d3b023fc8f08, 0002b10446958e93ead573a97d6544da9a6983ed84bc22eb4374ef26df570a1d, 00000c9c05a96044870f224217484488e4fd0d7a96f2f177446f70e5fabfb621, 0054ec6b0f7a6882e7d00d9c519f6f69f579c63d56cf62e8cae84811bcab2c70, 00abbd130077b5c0082bd4e4a659cbaa2d377a807ca17cba4fea347223dab6be, 00a148ad2abe5f0bde8c4e5af8ab45acefb1ac74bbf7dd64eff9c630e63fc77c, 00fe84fddba3042ccfac859f10bda95c676e9e57c5bf99bae9800bc965dd48dc, 001941534240f704b0e9123d843ce64e84be4aadd966a2bf48cd15f2d542ef3f, 00474c92530e4c6937b434befa98c9657d45245c4f0f58326a427f98ae53894c, 0012cb8f1a53a60b37cf9707f7085576f6f932cad11ae0c53fff5ff4b345f497, 002012e6371770d6929e736bb075dda452ddfb175a0a7b30cfd134523536d97a, 0028d8d4d5e893ea6ee3442c486d8e0bc9b07e27c8c1915e1a83a1b93310c205, 00e534322d466bb592ab551ea79d1bfcced993a8e905bdcda8512c27a9a8ff2d, 00c6ed9dab05c7eca01f10922abd455d51cff1ad435e72d823cc5071f05d6eab, 00503cec5d139f10d8bed8c6d2234c74d4aacc9fd147a13979eec26a294a7d40, 0076ece778c3d0e2090f7ec72b175294f8a1fe1a2a7f103b518c36a9ffc9ed3e, 0034b1e263a923d9dbf1c6ca6d6b720486826204d71311598c6649a10e8a1a89, 00e9d431983b36d6f19ad0e044ad80f37e7b4360c69acfd72524636243691329, 001945ca8f385417770b00d830d9c64fdfd3a96b21aaa5f753f3c4de99a426e2, 003c15aab3200fb7dc7e73341f10020480cef2ed527074627e288014c82e0a60, 00c8d08a5ff2743d995e0da68cae6d81952bae5eeb236596eb0e2cd48670f4c7, 00d5f524c8934dab5cf9a91a4118a351d19c05efe7d7df6fe9c5dd3011e28f58, 003870ef47d5d325d59b2d34099f566c644de38f6684222de78f58a118b3060b, 00833b3cab089168e98cf710b84686cc1c4f06ce059dcd5524c6ba5ccc806bc5, 003ca3e8eda80e334279a867dca003ec19574917b434a4b45bd24450f8ec2eec, 00bcb94660bf65bbbe761d04bc531489bae36768d280de1b77def4a65790af3e, 00ce5f10e8fe2f5c955db8e39fe60f5fc09558ecda342b215c3412b1f5e38dbf, 003476915ae03c65aa211ad786ce5b970f77a8c86222608e7e541e5f43052443, 00a768c4be608fea168441ee7e36880550b38b090192c38d9cf4c51243f7b370, 0078aa449a933d4968235558d97e1b22fc7bb2f021a2d88a94d903a3dd4d13dc, 00609da28998bcab70a2f9bd39f00605282a49e4a6eaea017b0dcaf4b00d2fad, 002c89f73ffbdd939136c236fb89584945e8524c5ef024fa6dc49fd825dc1eb8, 005beb7067a5348db192941b93b1b3b4234f258e898be131df5ce32f5a4246e5, 00f390fd09f0c89d4c4b9e9feaf83d603dc5409a8bb2aa7bbef1fcb322792705, 003258428e119207117eb65e9c128502ee458b0c234c9f51b6f4bf6c28ffc9fd, 00de3d762b14415076efe1aee9c2f7b3d3c8cd0323c9c555561e4caa666326bb, 006a2e9859d0ad6b285577215e82869f192e281210eb9c5aec34b6fce33c33b9, 00b322d559ecf34820aef50e15c472ad4569d6ba910f002065bf52e76184bca8, 003f6a3fe087c2397867aeb75fc8c55645efa9ac7fa7c689c923cd1cdd374203, 00a7fbc6b1702f1693318da732eb53c16a5c4778a68747f7e8c590379ee61876, 00af73a562289ecf61b04030e42bbe75de0047cc5e74fe33714131debb0fbfa7, 00a8167f1c03354bd7128f1a32c6171b4e9206575048efaab9b4f66dff440727, 008b307b230ba7e436952e4d9478c1c8c3f79e7df48deea52271875a7bdff413, 007e22fcb42b629a3c61a595aa7c0cbbbeebaa7e876d55e16667c7ee82a1774b, 00800e7291ed5d92bbaa5b8035b6887ca347fa39be52e01dd13f168e9e206df6, 009281bcbaf4e0217ede79a69162575d5a1d29b8b5786ed48b94217e575b914c, 00b776b370d5de1752f08572212487aad72c0a0c703f4b0f2c282d021288e0e5, 0000000000000000000000000000000000000000000000000000000000000000, 005c01adfdd64c44bfcd3caf63e52c3bec871331215caff0b608d0996dd97df7, 0079046bbc3de2b21f048472e3126e67d00265a60c090c9c94354f09b5aed7f5, 002b275c5c3e067bbd5a3c739ab657b392787f0ce962755d7047b17f77476712, 00c40748c13c74d073b0461707769b6d084a49b3fa859418ddeb36f09d1f6d0c, 0098455860be8ed98523dbb7aa8e4c53835f81a988df962581647a284a8000a8, 004b8ae0ae43ac95fc4ed874e4ab647f3c0ccb4b2ab0b71f5c7b2b831dbe67a8, 00b2e58e65257af1756126ed00fde75b7a2c0c485e49438d2e427e78ab03ca02, 0081939f607f89f9333d2cb6d86cacc3602b00a80aa95a53b53c340ee81e9a5e, 009dbdb5a210afd710cb1b30b044dc3736d75e6b1ead5aec1844e93dc82f48a1, 00890dca209cce479273963b16eb028f4ae07569c89ca7c38125aea369a47689, 0014666563100c54bd065379e8d7b5bf077ca378a7628e291aa6711584ef2842, 002402bdd4c4c70b3655915e300aa263493cca42d44488e419e028e75e1343d7, 003c728056a48479ff67400964b242eeb6e2fbc93885363c218cb532db78d33b, 00fe6ae0dcd5d6ad9ea4cafd6b31f0f52b3f5d90517577c2515e692f3d718547, 00febe7f9511404496504488e75cf966bc782ba36eb987e33d242a866626fde6, 00d712268425b7dbc5c25f51458e34e1d147bf67323700d9508d110ae1aa2353, 002b3c31f470ce691cfffb704d1318e5addf420174b55879199fcf554a3cefb8], round=222300

[dnck]

@fsbbn Is it right that there are ~ 50 rounds between starting and stopping solidification?

If so, then 50 * 15s = 12.5 minutes

The increases in sync last for around 13 minutes.

That seems like it really pinpoints the issue. Why should solidification stop/start for around 50 rounds every 3.5 hours or so?

[fsbbn]

Yeah in this example it is for around 50 rounds. But I don’t know if it's always ~ 50 rounds and why it happens periodically, maybe it has something to do with the timestamp but I’m not sure. What I’m sure about is that the milestones of the missing rounds couldn’t be stored:

Line New milestone MILESTONE_HASH (1/1) added to round #ROUND_INDEX is missing for round #222251 to #222299 (which shows that it didn’t reached this line https://github.com/HelixNetwork/pendulum/blob/476c457ab73d50994c3fba4a4bdb80f63d248e38/src/main/java/net/helix/pendulum/service/milestone/impl/MilestoneTrackerImpl.java#L332 )

and

relayer1 | 11/24 16:28:07.104 [Latest Solid Milestone Tracker] TRACE LatestSolidMilestoneTrackerImpl:149 - Current Solid Round = 222250, Current Round = 222251, Still in Round = true, Round active = false
relayer1 | 11/24 16:28:07.133 [Latest Milestone Tracker] TRACE MilestoneServiceImpl:187 - valid signature: true
relayer1 | 11/24 16:28:07.132 [Latest Milestone Tracker] DEBUG MilestoneTrackerImpl:391 - Process Milestone hash, round =000f3b5f9c5757edad7979589e50bad86704aa934236d5e12fd0d3b023fc8f08 222251
relayer1 | 11/24 16:28:07.133 [Latest Milestone Tracker] TRACE MilestoneTrackerImpl:312 - ri, calculated ri= 222251, 222251
relayer1 | 11/24 16:28:07.133 [Latest Milestone Tracker] TRACE MilestoneTrackerImpl:338 - round is not active

In the last line it says “round is not active” which is a sign that the milestone failed the conditions in https://github.com/HelixNetwork/pendulum/blob/dev/src/main/java/net/helix/pendulum/service/milestone/impl/MilestoneTrackerImpl.java#L311 .

Here we have two conditions under which the milestone isn’t stored even it’s valid:

roundIndex == calculatedRoundIndex Should proof if the roundIndex specified in the tag matches the round index calculated from the attachment timestamp, i.e. whether the milestone was really sent in the round. We should remove this check, because the attachment timestamp has no guarantee to be correct. But beyond that, I don't think the problem is here, because we can see: ri, calculated ri= 222251, 222251.

isRoundActive(transaction.getAttachmentTimestamp()) This is probably the issue. This should proof if the milestone was sent in the active phase of the round. I thought that would be important to prevent that a milestone arrives after the round has already been applied to ledger, but if I think about it again that should not be a criterion for saving a milestone. It should be stored anyway, but if the roundIndex is smaller than the solid roundIndex, then rollback should occur, otherwise the milestone can be stored normally, even if it comes too late.

But I have no clue why it fails on this condition in these intervalls...

[dnck]

This should proof if the milestone was sent in the active phase of the round.

The attachmentTimestamp is not exactly the moment the transaction is sent, right? In fact, the time of sending comes later. and sometimes quite a bit later since the transaction goes through the broadcastQueue, which is a kind of priority queue with no guarantees that the order in which tx are added are the order in which they're sent out. So, anyway, "proof the milestone was sent" in a specific interval is obtainable, but not from the attachmentTimestamp afaiu.

It should be stored anyway, but if the roundIndex is smaller than the solid roundIndex, then rollback should occur, otherwise the milestone can be stored normally, even if it comes too late.

I don't quite follow this, since I don't understand what we're specifically trying to accomplish.

But I have no clue why it fails on this condition in these intervalls...

Yeah, so, this is the heart of the issue for me. Let's continue the investigation and squash this issue asap ;)

[dnck]

This issue is resolved in the refactoring branch!