iotaledger / iri

IOTA Reference Implementation
Other
1.15k stars 370 forks source link

Investigate when the `repairing corrupted milestone` mechanism triggers nowadays #1435

Closed jakubcech closed 5 years ago

jakubcech commented 5 years ago

Description

Investigate when the repairing corrupted milestone mechanism triggers nowadays. We know (sorta) it keeps triggering still, but we're not sure if it works when it does. And we especially aren't sure what the exact scenario of when this happens is exactly. One reason might be that a newer milestone solidifies faster than an older one.

This could be related to #1434.

DyrellC commented 5 years ago

@jakubcech @GalRogozinski
I have found a way to trigger the resetting corrupted milestone service consistently. While spamming milestones at my node using my spammer (not compass) I was able to trigger the mechanism by interrupting one of the attachToTangle() instances for a milestone. I spammed 60 milestones in total using my spammer tools and interrupted the 21st one from attaching correctly. By only interrupting the one milestone the tangle was no longer able to become solid beyond milestone 20, but the other 40 milestones were able to be introduced to the db with a bunch of zero value transactions as well. Once I attached a 21st milestone, the resetting mechanism kicked in and managed to reset the remaining milestones and solidify.

This was in a zero value transaction environment, my next test will be to see what happens when there are transactions with value present in both the first 20 milestones prior to the failed milestone, and the remaining transactions attached after the failed milestone to see what happens in this instance. I expect that what will happen is that if there are no conflicting spends then all the milestones will solidify again, but if I introduce conflicts, it should invalidate the milestones that tried to confirm the inconsistent transactions following the missed milestone, and will instead solidify to milestone 21 and no further.

DyrellC commented 5 years ago
05/09 13:58:12.777 [Latest Solid Milestone Tracker] INFO  LatestSolidMilestoneTrackerImpl:369 - Latest SOLID milestone index changed from #12 to #13
05/09 13:58:12.799 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 48
05/09 13:58:13.243 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #15 to #16
05/09 13:58:14.390 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #16 to #17
05/09 13:58:15.777 [Latest Solid Milestone Tracker] INFO  LatestSolidMilestoneTrackerImpl:369 - Latest SOLID milestone index changed from #14 to #15
05/09 13:58:16.476 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #17 to #18
05/09 13:58:17.565 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #18 to #19
05/09 13:58:18.647 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #19 to #20
05/09 13:58:18.778 [Latest Solid Milestone Tracker] INFO  LatestSolidMilestoneTrackerImpl:369 - Latest SOLID milestone index changed from #18 to #19
05/09 13:58:20.788 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #20 to #22
05/09 13:58:21.947 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #22 to #23
05/09 13:58:22.785 [Latest Solid Milestone Tracker] INFO  LatestSolidMilestoneTrackerImpl:369 - Latest SOLID milestone index changed from #19 to #20
05/09 13:58:22.825 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 68
05/09 13:58:24.061 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #23 to #24
05/09 13:58:25.210 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #24 to #25
05/09 13:58:27.340 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #25 to #26
05/09 13:58:28.491 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #26 to #27
05/09 13:58:30.630 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #27 to #28
05/09 13:58:31.758 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #28 to #29
05/09 13:58:32.843 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 93
05/09 13:58:32.850 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #29 to #30
05/09 13:58:33.943 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #30 to #31
05/09 13:58:34.952 [XNIO-1 task-15] INFO  API:1495 - Last 100 PoW consumed 2 seconds processing time.
05/09 13:58:36.063 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #31 to #32
05/09 13:58:37.201 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #32 to #33
05/09 13:58:38.345 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #33 to #34
05/09 13:58:40.409 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #34 to #35
05/09 13:58:41.497 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #35 to #36
05/09 13:58:42.871 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 117
05/09 13:58:43.579 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #36 to #37
05/09 13:58:44.660 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #37 to #38
05/09 13:58:46.747 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #38 to #39
05/09 13:58:47.891 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #39 to #40
05/09 13:58:49.031 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #40 to #41
05/09 13:58:50.148 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #41 to #42
05/09 13:58:52.234 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #42 to #43
05/09 13:58:52.897 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 139
05/09 13:58:53.392 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #43 to #44
05/09 13:58:54.471 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #44 to #45
05/09 13:58:56.565 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #45 to #46
05/09 13:58:58.659 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #46 to #47
05/09 13:58:59.743 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #47 to #48
05/09 13:59:00.836 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #48 to #49
05/09 13:59:01.919 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #49 to #50
05/09 13:59:02.913 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 160
05/09 13:59:04.016 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #50 to #51
05/09 13:59:05.136 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #51 to #52
05/09 13:59:07.242 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #52 to #53
05/09 13:59:08.312 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #53 to #54
05/09 13:59:10.402 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #54 to #55
05/09 13:59:12.483 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #55 to #56
05/09 13:59:12.947 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 185
05/09 13:59:13.572 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #56 to #57
05/09 13:59:14.654 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #57 to #58
05/09 13:59:16.743 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #58 to #59
05/09 13:59:18.838 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #59 to #60
05/09 13:59:19.919 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #60 to #61
05/09 13:59:21.215 [XNIO-1 task-10] INFO  API:1495 - Last 100 PoW consumed 2 seconds processing time.
05/09 13:59:22.963 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 203
05/09 13:59:23.041 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #61 to #71
05/09 13:59:25.124 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #71 to #72
05/09 13:59:26.206 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #72 to #73
05/09 13:59:27.301 [Latest Milestone Tracker] INFO  LatestMilestoneTrackerImpl:158 - Latest milestone has changed from #73 to #74
05/09 13:59:32.986 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 219
05/09 13:59:43.002 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 234
05/09 13:59:53.024 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 246
05/09 14:00:03.038 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 258
05/09 14:00:13.066 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:00:23.099 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:00:33.121 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:00:43.143 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:00:53.165 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:01:03.186 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:01:13.210 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:01:23.232 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:01:33.256 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:01:43.279 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:01:53.302 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:02:03.323 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:02:13.343 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:02:23.365 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:02:33.389 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:02:43.411 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:02:53.433 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:03:03.453 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:03:13.475 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:03:23.499 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:03:33.528 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:03:43.555 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:03:53.579 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:04:03.599 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:04:13.623 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:04:23.649 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:04:33.668 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:04:43.692 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:04:53.716 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:05:03.737 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:05:13.762 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:05:23.783 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:05:33.803 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:05:43.828 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:05:53.849 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:06:03.869 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:06:13.889 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:06:23.912 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:06:33.931 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:06:43.951 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:06:53.971 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:07:03.994 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:07:14.020 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:07:24.039 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:07:34.060 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:07:44.082 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
205/09 14:07:54.104 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 266
05/09 14:07:57.823 [Latest Solid Milestone Tracker] INFO  LatestSolidMilestoneTrackerImpl:369 - Latest SOLID milestone index changed from #20 to #21
05/09 14:07:57.824 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #24
05/09 14:07:57.825 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #25
05/09 14:07:57.826 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #26
05/09 14:07:57.826 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #27
05/09 14:07:57.827 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #28
05/09 14:07:57.827 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #29
05/09 14:07:57.828 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #30
05/09 14:07:57.828 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #31
05/09 14:07:57.828 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #32
05/09 14:07:57.829 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #33
05/09 14:07:57.829 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #34
05/09 14:07:57.830 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #35
05/09 14:07:57.830 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #36
05/09 14:07:57.831 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #37
05/09 14:07:57.831 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #38
05/09 14:07:57.831 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #39
05/09 14:07:57.832 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #40
05/09 14:07:57.832 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #41
05/09 14:07:57.833 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #42
05/09 14:07:57.834 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #43
05/09 14:07:57.834 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #44
05/09 14:07:57.835 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #45
05/09 14:07:57.835 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #46
05/09 14:07:57.836 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #47
05/09 14:07:57.836 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #48
05/09 14:07:57.837 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #49
05/09 14:07:57.838 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #50
05/09 14:07:57.838 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #51
05/09 14:07:57.839 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #52
05/09 14:07:57.839 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #53
05/09 14:07:57.840 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #54
05/09 14:07:57.841 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #55
05/09 14:07:57.842 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #56
05/09 14:07:57.843 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #57
05/09 14:07:57.843 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #58
05/09 14:07:57.844 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #59
05/09 14:07:57.845 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #60
05/09 14:07:57.845 [Latest Solid Milestone Tracker] INFO  MilestoneServiceImpl:516 - resetting corrupted milestone #61
05/09 14:08:00.823 [Latest Solid Milestone Tracker] INFO  LatestSolidMilestoneTrackerImpl:369 - Latest SOLID milestone index changed from #60 to #61
05/09 14:08:04.129 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 268
05/09 14:08:14.152 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 268
05/09 14:08:24.177 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 268
05/09 14:08:34.198 [pool-11-thread-2] INFO  Node:656 - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 268

** Note the gap between milestones 61 and 71 were not corrected as I interrupted these milestones from attaching correctly, so it was only able to solidify to 61.

GalRogozinski commented 5 years ago

I am unsure why the reset milestone routine was initiated... If I understand what you did correctly, none of the milestones above #21 solidified, thus nothing should have been resetted once you got #21 solid. If I am correct describing the situation can you please put a breakpoint on the resetCorruptedMilestone method and look at the call stack to understand how was this method called.

If I didn't understand correctly then don't bother of course :-P

DyrellC commented 5 years ago

image

In this case it's in the process of applying the new state to the ledger, once milestone #21 comes in, the latestSolidMilestoneTracker will see that now milestone #22 is solid (since the milestone was issued in a state where milestone #21 failed, but the attaching of milestones #22 to #61 were done so in a way that technically they are solid already without the need for milestone #21. This is a niche sort of situation to occur, and really unlikely with the way compass works, but it is nice to see where the logic is being called from when several milestones are solidifying in a row. One thing I did see in this scenario, was that if I paired a node that only solidified to #21 with one that was solidified to #61, there was no transaction request for milestone #21 so the node was never able to catch up because it didn't need to find milestones #22 through #61 since they were technically already solid.

So this behaviour was interesting to observe but as I said this was a sort of niche condition situation and doesn't really represent what's been happening in the mainnet environment. Trying to make the reset trigger through normal operations has been a real pain in the butt. In order to trigger it naturally, somehow the node needs to receive and solidify the later milestones before the prior one, but this scenario is not easily reproducible and potentially may only be able to be triggered through a race condition. How to trigger this race, I am unsure.

rajivshah3 commented 5 years ago

I saw this happen on my mainnet node, so I'll post the log here (hopefully it's helpful).

This is where it first starts to reset the milestones:

05/11 09:13:54.085 [Latest Milestone Tracker] INFO  c.i.i.s.m.i.LatestMilestoneTrackerImpl - Latest milestone has changed from #1067268 to #1067269
05/11 09:13:57.169 [pool-12-thread-2] INFO  com.iota.iri.network.Node - toProcess = 0 , toBroadcast = 0 , toRequest = 4 , toReply = 0 / totalTransactions = 12120868
05/11 09:13:57.641 [Latest Solid Milestone Tracker] INFO  c.i.i.s.m.i.LatestSolidMilestoneTrackerImpl - Latest SOLID milestone index changed from #1067268 to #1067269
05/11 09:14:00.717 [XNIO-1 task-31] INFO  com.iota.iri.service.API - API Validation failed: Invalid parameters
05/11 09:14:12.170 [pool-12-thread-2] INFO  com.iota.iri.network.Node - toProcess = 0 , toBroadcast = 0 , toRequest = 2 , toReply = 0 / totalTransactions = 12120899
05/11 09:14:12.398 [XNIO-1 task-7] INFO  com.iota.iri.service.API - API Validation failed: Invalid parameters
05/11 09:14:18.556 [pool-14-thread-22] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Opening sink redacted
05/11 09:14:18.556 [pool-14-thread-22] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Connecting sink redacted
05/11 09:14:18.650 [pool-14-thread-22] INFO  com.iota.iri.network.Neighbor - Sink redacted closed
05/11 09:14:27.171 [pool-12-thread-2] INFO  com.iota.iri.network.Node - toProcess = 0 , toBroadcast = 0 , toRequest = 3 , toReply = 0 / totalTransactions = 12120930
05/11 09:14:42.172 [pool-12-thread-2] INFO  com.iota.iri.network.Node - toProcess = 0 , toBroadcast = 0 , toRequest = 8 , toReply = 0 / totalTransactions = 12120968
05/11 09:14:48.556 [pool-14-thread-23] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Opening sink redacted
05/11 09:14:48.557 [pool-14-thread-23] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Connecting sink redacted
05/11 09:14:48.651 [pool-14-thread-23] INFO  com.iota.iri.network.Neighbor - Sink redacted closed
05/11 09:14:57.173 [pool-12-thread-2] INFO  com.iota.iri.network.Node - toProcess = 0 , toBroadcast = 0 , toRequest = 5 , toReply = 0 / totalTransactions = 12121004
05/11 09:15:00.717 [XNIO-1 task-28] INFO  com.iota.iri.service.API - API Validation failed: Invalid parameters
05/11 09:15:02.345 [XNIO-1 task-18] INFO  com.iota.iri.service.API - API Validation failed: Invalid parameters
05/11 09:15:12.174 [pool-12-thread-2] INFO  com.iota.iri.network.Node - toProcess = 0 , toBroadcast = 0 , toRequest = 2 , toReply = 0 / totalTransactions = 12121022
05/11 09:15:12.433 [pool-15-thread-29] INFO  c.i.i.n.r.ReplicatorSinkPool - Sink redacted closed
05/11 09:15:12.433 [pool-15-thread-29] INFO  com.iota.iri.network.Neighbor - Source redacted closed
05/11 09:15:14.474 [XNIO-1 task-5] INFO  com.iota.iri.service.API - API Validation failed: Invalid parameters
05/11 09:15:18.557 [pool-14-thread-18] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Opening sink redacted
05/11 09:15:18.557 [pool-14-thread-28] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Opening sink redacted
05/11 09:15:18.557 [pool-14-thread-18] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Connecting sink redacted
05/11 09:15:18.557 [pool-14-thread-28] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Connecting sink redacted
05/11 09:15:18.650 [pool-14-thread-28] INFO  com.iota.iri.network.Neighbor - Sink redacted closed
05/11 09:15:19.688 [pool-14-thread-18] INFO  com.iota.iri.network.Neighbor - Sink redacted closed
05/11 09:15:22.175 [pool-12-thread-2] INFO  com.iota.iri.network.Node - toProcess = 0 , toBroadcast = 0 , toRequest = 1 , toReply = 0 / totalTransactions = 12121040
05/11 09:15:37.214 [pool-12-thread-2] INFO  com.iota.iri.network.Node - toProcess = 0 , toBroadcast = 0 , toRequest = 2 , toReply = 0 / totalTransactions = 12121062
05/11 09:15:47.215 [pool-12-thread-2] INFO  com.iota.iri.network.Node - toProcess = 0 , toBroadcast = 0 , toRequest = 2 , toReply = 0 / totalTransactions = 12121079
05/11 09:15:48.557 [pool-14-thread-10] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Opening sink redacted
05/11 09:15:48.557 [pool-14-thread-32] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Opening sink redacted
05/11 09:15:48.557 [pool-14-thread-10] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Connecting sink redacted
05/11 09:15:48.557 [pool-14-thread-32] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Connecting sink redacted
05/11 09:15:48.651 [pool-14-thread-10] INFO  com.iota.iri.network.Neighbor - Sink redacted closed
05/11 09:15:48.660 [pool-14-thread-32] INFO  com.iota.iri.network.Neighbor - Sink redacted closed
05/11 09:15:57.216 [pool-12-thread-2] INFO  com.iota.iri.network.Node - toProcess = 0 , toBroadcast = 0 , toRequest = 5 , toReply = 0 / totalTransactions = 12121100
05/11 09:16:00.519 [XNIO-1 task-11] INFO  com.iota.iri.service.API - API Validation failed: Invalid parameters
05/11 09:16:12.217 [pool-12-thread-2] INFO  com.iota.iri.network.Node - toProcess = 0 , toBroadcast = 0 , toRequest = 3 , toReply = 0 / totalTransactions = 12121128
05/11 09:16:12.258 [pool-15-thread-30] INFO  c.i.i.n.r.ReplicatorSourceProcessor - Creating sink for redacted
05/11 09:16:12.258 [pool-15-thread-30] INFO  c.i.i.n.r.ReplicatorSourceProcessor - ----- NETWORK INFO ----- Source redacted is connected
05/11 09:16:13.258 [pool-14-thread-4] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Opening sink redacted
05/11 09:16:13.258 [pool-14-thread-4] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Connecting sink redacted
05/11 09:16:13.362 [pool-14-thread-4] INFO  c.i.i.n.r.ReplicatorSinkProcessor - ----- NETWORK INFO ----- Sink redacted is connected
05/11 09:16:16.381 [XNIO-1 task-26] INFO  com.iota.iri.service.API - API Validation failed: Invalid parameters
05/11 09:16:18.557 [pool-14-thread-8] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Opening sink redacted
05/11 09:16:18.557 [pool-14-thread-8] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Connecting sink redacted
05/11 09:16:18.651 [pool-14-thread-8] INFO  com.iota.iri.network.Neighbor - Sink redacted closed
05/11 09:16:27.218 [pool-12-thread-2] INFO  com.iota.iri.network.Node - toProcess = 0 , toBroadcast = 0 , toRequest = 1 , toReply = 0 / totalTransactions = 12121164
05/11 09:16:42.219 [pool-12-thread-2] INFO  com.iota.iri.network.Node - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 12121195
05/11 09:16:48.557 [pool-14-thread-9] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Opening sink redacted
05/11 09:16:48.557 [pool-14-thread-9] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Connecting sink redacted
05/11 09:16:48.652 [pool-14-thread-9] INFO  com.iota.iri.network.Neighbor - Sink redacted closed
05/11 09:16:57.220 [pool-12-thread-2] INFO  com.iota.iri.network.Node - toProcess = 0 , toBroadcast = 0 , toRequest = 0 , toReply = 0 / totalTransactions = 12121221
05/11 09:17:00.471 [XNIO-1 task-27] INFO  com.iota.iri.service.API - API Validation failed: Invalid parameters
05/11 09:17:12.221 [pool-12-thread-2] INFO  com.iota.iri.network.Node - toProcess = 0 , toBroadcast = 0 , toRequest = 3 , toReply = 0 / totalTransactions = 12121248
05/11 09:17:18.289 [XNIO-1 task-14] INFO  com.iota.iri.service.API - API Validation failed: Invalid parameters
05/11 09:17:18.557 [pool-14-thread-7] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Opening sink redacted
05/11 09:17:18.558 [pool-14-thread-7] INFO  c.i.i.n.r.ReplicatorSinkProcessor - Connecting sink redacted
05/11 09:17:18.651 [pool-14-thread-7] INFO  com.iota.iri.network.Neighbor - Sink redacted closed
05/11 09:17:19.302 [Latest Milestone Tracker] INFO  c.i.i.s.m.i.LatestMilestoneTrackerImpl - Latest milestone has changed from #1067269 to #1067270
05/11 09:17:23.885 [Latest Solid Milestone Tracker] INFO  c.i.i.s.s.impl.SnapshotStateImpl - negative value for address HXIUXYXOO9ZDZ9DUGILIYJQRSBDAKXVIGEHUZXFKB9UUYXQXJAUFXYZ9MJCYCNUVTABUNXR9KTHNUQCOY: -43
05/11 09:17:23.885 [Latest Solid Milestone Tracker] INFO  c.i.i.s.m.impl.MilestoneServiceImpl - resetting corrupted milestone #1067270
05/11 09:17:23.908 [Latest Solid Milestone Tracker] INFO  c.i.i.s.s.impl.SnapshotStateImpl - negative value for address HXIUXYXOO9ZDZ9DUGILIYJQRSBDAKXVIGEHUZXFKB9UUYXQXJAUFXYZ9MJCYCNUVTABUNXR9KTHNUQCOY: -43
05/11 09:17:23.908 [Latest Solid Milestone Tracker] INFO  c.i.i.s.m.impl.MilestoneServiceImpl - resetting corrupted milestone #1067270
05/11 09:17:23.914 [Latest Solid Milestone Tracker] INFO  c.i.i.s.m.impl.MilestoneServiceImpl - resetting corrupted milestone #1067269
05/11 09:17:24.320 [Latest Solid Milestone Tracker] INFO  c.i.i.s.m.i.LatestSolidMilestoneTrackerImpl - Latest SOLID milestone index changed from #1067269 to #1067268
05/11 09:17:24.360 [Latest Solid Milestone Tracker] INFO  c.i.i.s.s.impl.SnapshotStateImpl - negative value for address HXIUXYXOO9ZDZ9DUGILIYJQRSBDAKXVIGEHUZXFKB9UUYXQXJAUFXYZ9MJCYCNUVTABUNXR9KTHNUQCOY: -43
05/11 09:17:24.360 [Latest Solid Milestone Tracker] INFO  c.i.i.s.m.impl.MilestoneServiceImpl - resetting corrupted milestone #1067270
05/11 09:17:24.367 [Latest Solid Milestone Tracker] INFO  c.i.i.s.m.impl.MilestoneServiceImpl - resetting corrupted milestone #1067269
05/11 09:17:24.532 [Latest Solid Milestone Tracker] INFO  c.i.i.s.m.impl.MilestoneServiceImpl - resetting corrupted milestone #1067268
05/11 09:17:24.746 [XNIO-1 task-3] INFO  c.i.i.s.s.impl.SnapshotStateImpl - negative value for address HXIUXYXOO9ZDZ9DUGILIYJQRSBDAKXVIGEHUZXFKB9UUYXQXJAUFXYZ9MJCYCNUVTABUNXR9KTHNUQCOY: -43
05/11 09:17:24.762 [Latest Solid Milestone Tracker] INFO  c.i.i.s.s.impl.SnapshotStateImpl - negative value for address HXIUXYXOO9ZDZ9DUGILIYJQRSBDAKXVIGEHUZXFKB9UUYXQXJAUFXYZ9MJCYCNUVTABUNXR9KTHNUQCOY: -43
05/11 09:17:24.762 [Latest Solid Milestone Tracker] INFO  c.i.i.s.m.impl.MilestoneServiceImpl - resetting corrupted milestone #1067270
05/11 09:17:24.769 [Latest Solid Milestone Tracker] INFO  c.i.i.s.m.impl.MilestoneServiceImpl - resetting corrupted milestone #1067269
05/11 09:17:24.932 [Latest Solid Milestone Tracker] INFO  c.i.i.s.m.impl.MilestoneServiceImpl - resetting corrupted milestone #1067268
05/11 09:17:25.085 [Latest Solid Milestone Tracker] INFO  c.i.i.s.m.impl.MilestoneServiceImpl - resetting corrupted milestone #1067267
05/11 09:17:25.342 [Latest Solid Milestone Tracker] INFO  c.i.i.s.s.impl.SnapshotStateImpl - negative value for address HXIUXYXOO9ZDZ9DUGILIYJQRSBDAKXVIGEHUZXFKB9UUYXQXJAUFXYZ9MJCYCNUVTABUNXR9KTHNUQCOY: -43
05/11 09:17:25.342 [Latest Solid Milestone Tracker] INFO  c.i.i.s.m.impl.MilestoneServiceImpl - resetting corrupted milestone #1067270
05/11 09:17:25.351 [Latest Solid Milestone Tracker] INFO  c.i.i.s.m.impl.MilestoneServiceImpl - resetting corrupted milestone #1067269
05/11 09:17:25.504 [Latest Solid Milestone Tracker] INFO  c.i.i.s.m.impl.MilestoneServiceImpl - resetting corrupted milestone #1067268
05/11 09:17:25.654 [Latest Solid Milestone Tracker] INFO  c.i.i.s.m.impl.MilestoneServiceImpl - resetting corrupted milestone #1067267
05/11 09:17:26.006 [Latest Solid Milestone Tracker] INFO  c.i.i.s.m.impl.MilestoneServiceImpl - resetting corrupted milestone #1067266
05/11 09:17:26.290 [Latest Solid Milestone Tracker] INFO  c.i.i.s.s.impl.SnapshotStateImpl - negative value for address HXIUXYXOO9ZDZ9DUGILIYJQRSBDAKXVIGEHUZXFKB9UUYXQXJAUFXYZ9MJCYCNUVTABUNXR9KTHNUQCOY: -43

I've also attached the full logs: iri.log.zip

GalRogozinski commented 5 years ago

This also happened on devnet (v1.5.6). I have a copy of the DB. We can emit a new milestone and reproduce.

GalRogozinski commented 5 years ago

I have no proof but I believe this relates to #1187

GalRogozinski commented 5 years ago

@DyrellC I want to rule out the possibility of a transaction below pruning depth because it happened to Zoran on a permanode. He had local snapshots disabled completely so I don't think it something with Local Snapshots at all

jakubcech commented 5 years ago

Investigate whether it has to do with the address reuse or a race condition like outlined here (or a different one:)): https://github.com/iotaledger/iri/issues/1187

jakubcech commented 5 years ago

Closing in favor of #1493 for better tracking of the spent effort