Solid Milestone initialization fix #486

Desolatora · 2018-01-18T00:25:07Z

Bug

LedgerValidator initializes wrong consistent milestone after restart when node is not fully synced.

Symptoms

When node is synced to solid milestone X and latest milestone is Y, after restart solid milestone is incorrectly initialized to Z (usually very close to Y).

Cause

Method LedgerValidator.buildSnapshot() is responsible for building the most recent consistent milestone. It uses MilestoneViewModel.firstWithSnapshot() and MilestoneViewModel.nextWithSnapshot() to iterate on every milestone with snapshot then gets the state differences and patches them to the current snapshot. These methods deterministically rely on StateDiffViewModel.exists() which internally uses tangle.maybeHas(). The problem is that tangle.maybeHas() can only guarantee when entry is not present, but does not guarantee if entry is present. This leads to MilestoneViewModel.firstWithSnapshot() and MilestoneViewModel.nextWithSnapshot() sometimes returning milestone without snapshot or more precise milestone without StateDiff. This incorrect behaviour is also supported by the fact that StateDiffViewModel.load() returns an object even if StateDiff is not present. This leads to latestSnapshot being patched with no state differences and incorrect milestone index.

Problems

When node is initialized with wrong solid milestone this may lead to solid milestone tracker appearing frozen while it is trying to solidify next milestone or compute state diff with both operations involving huge number of transactions. Sometimes wrong solid milestone index may lead to "Transaction resolves to incorrect ledger balance" errors (bug: #460).

Proposed fix

Method StateDiffViewModel.isEmpty() is introduced to check if current state difference is empty. LedgerValidator.buildSnapshot() now iterates on every candidate milestone and patches latestSnapshot only with nonempty state differences. This guarantees that initialized consistent milestone is solid.

GalRogozinski

Rebase with new code and start using locks instead of synchronized

GalRogozinski · 2018-02-28T17:49:52Z

src/main/java/com/iota/iri/LedgerValidator.java

+            MilestoneViewModel candidateMilestone = MilestoneViewModel.first(tangle);
+
+            while (candidateMilestone != null) {
+                if (candidateMilestone.index() % 1000 == 0)


Please open an if block with brackets.
Please also add && log.isDebugEnabled() and change log level to debug

GalRogozinski · 2018-02-28T17:51:03Z

src/main/java/com/iota/iri/LedgerValidator.java

+
+            while (candidateMilestone != null) {
+                if (candidateMilestone.index() % 1000 == 0)
+                    log.info("Building snapshot... Consistent: #" +


Since we are still in Java 8 it is preferable to use StringBuilder to concatenate strings

GalRogozinski · 2018-02-28T18:01:55Z

src/main/java/com/iota/iri/LedgerValidator.java

@@ -221,20 +223,34 @@ public static boolean isApproved(Snapshot snapshot, Hash hash) {
     */
    private MilestoneViewModel buildSnapshot(Snapshot latestSnapshot) throws Exception {
        MilestoneViewModel consistentMilestone = null;
+
        synchronized (latestSnapshot.snapshotSyncObject) {


Use locks. See updated code

GalRogozinski · 2018-02-28T18:04:25Z

src/main/java/com/iota/iri/controllers/StateDiffViewModel.java

@@ -24,7 +24,7 @@ public StateDiffViewModel(final Map<Hash, Long> state, final Hash hash) {
        this.stateDiff.state = state;
    }

-    public static boolean exists(Tangle tangle, Hash hash) throws Exception {
+    public static boolean maybeExists(Tangle tangle, Hash hash) throws Exception {


Desolatora · 2018-03-15T23:06:03Z

Rebased with new code.

GalRogozinski · 2018-03-19T10:04:52Z

Hey @Desolatora,
It seems like the rebase didn't roll out as smoothly as we like.
If you click on the "commits" tab or the "file changes" tab you will immediately see what I mean.

Git can be annoying sometimes, but we need to get it fixed.
If you find it too hard to fix this PR, you can close it and issue a new PR with only a link to this one in the description.

Checkstyle will fail build

Desolatora · 2018-03-19T18:58:48Z

Rebase fixed.

PR should have one area of responsibility

You don't publish ports if `--net=host` (`--network=host`) is used

GalRogozinski

I just clicked approved but I see that github claims there are still conflicts..

Desolatora · 2018-04-02T19:51:48Z

@GalRogozinski
It should be fixed now. If it isn't i will create a new PR.

alon-e

looks great! - tested it locally in different DB scenarios.
see comment about a failure mode in buildSnapshots().

but other than that 👍

alon-e · 2018-04-03T13:25:50Z

src/main/java/com/iota/iri/LedgerValidator.java

+	                    consistentMilestone = candidateMilestone;
+	                }
+	            }
+	            candidateMilestone = candidateMilestone.next(tangle);


what if a milestone is not consistent (Snapshot.isConsistent == false), but the next ones are (for example due to DB corruption or malice). then a consistent, but not the actual state would be reached, right?
would be best to fail on an existing, but inconsistent milestone stateDiff.

alon-e · 2018-04-03T13:27:31Z

src/main/java/com/iota/iri/LedgerValidator.java

-                    snapshotMilestone = snapshotMilestone.nextWithSnapshot(tangle);
+            MilestoneViewModel candidateMilestone = MilestoneViewModel.first(tangle);
+            while (candidateMilestone != null) {
+                if (log.isDebugEnabled() && candidateMilestone.index() % 10000 == 0) {


not your fault, but FYI from my tests log.isDebugEnabled() always returns true in IRI, regardless of the debug flag.

Desolatora · 2018-04-03T17:59:07Z

buildSnapshot() will now stop searching for candidates if inconsistent milestone is encountered.
Also i removed the log.isDebugEnabled() part and actually changed the log level to INFO. I think it is essencial for iri to report milestone initialization, because this is fairly slow process and it may appear that iri is stuck while actually it is properly initializing.

paulhandy requested a review from alon-e January 18, 2018 03:04

GalRogozinski suggested changes Feb 28, 2018

View reviewed changes

GalRogozinski added T-Bug C-Consensus S2 - High High Severity L-Awaiting More Reviews Lifecycle - Every PR must have at least 2 reviewers labels Mar 15, 2018

Merge pull request iotaledger#570 from GalRogozinski/checkstyle

d34bf48

Checkstyle will fail build

Desolatora force-pushed the buildsnapshot-fix branch 2 times, most recently from 96199e3 to 6662159 Compare March 19, 2018 18:56

GalRogozinski and others added 3 commits March 24, 2018 20:48

Update pull_request_template.md

b39bcc1

PR should have one area of responsibility

Update issue_template.md

0864af5

Docker: useless -p (publish)

1bd5932

You don't publish ports if `--net=host` (`--network=host`) is used

GalRogozinski approved these changes Apr 2, 2018

View reviewed changes

GalRogozinski suggested changes Apr 2, 2018

View reviewed changes

Solid milestone initialization fix.

e078f49

Desolatora force-pushed the buildsnapshot-fix branch from 6662159 to e078f49 Compare April 2, 2018 19:45

alon-e suggested changes Apr 3, 2018

View reviewed changes

buildSnapshot() should stop if inconsistent milestone is encountered

57cb3d0

alon-e approved these changes Apr 4, 2018

View reviewed changes

alon-e added L-Ready For Test Code passed review and needs to be tested and removed L-Awaiting More Reviews Lifecycle - Every PR must have at least 2 reviewers labels Apr 4, 2018

GalRogozinski approved these changes Apr 4, 2018

View reviewed changes

GalRogozinski force-pushed the dev branch from d59de9f to 004b433 Compare April 4, 2018 14:50

alon-e merged commit 47d8c4a into iotaledger:dev Apr 4, 2018

alon-e mentioned this pull request Apr 17, 2018

Transaction resolves to incorrect ledger balance (thousands of time) #460

Closed

This was referenced Apr 25, 2018

Intermittently losing track of latest solid subtangle milestone #269

Closed

Latest solid subtangle milestone does not update properly while syncing #250

Closed

V1.4.2.4 rc #734

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Solid Milestone initialization fix #486

Solid Milestone initialization fix #486

Desolatora commented Jan 18, 2018

GalRogozinski left a comment

GalRogozinski Feb 28, 2018

GalRogozinski Feb 28, 2018

GalRogozinski Feb 28, 2018

GalRogozinski Feb 28, 2018

Desolatora commented Mar 15, 2018

GalRogozinski commented Mar 19, 2018

Desolatora commented Mar 19, 2018

GalRogozinski left a comment

Desolatora commented Apr 2, 2018 •

edited

Loading

alon-e left a comment

alon-e Apr 3, 2018

alon-e Apr 3, 2018

Desolatora commented Apr 3, 2018 •

edited

Loading

Solid Milestone initialization fix #486

Solid Milestone initialization fix #486

Conversation

Desolatora commented Jan 18, 2018

Bug

Symptoms

Cause

Problems

Proposed fix

GalRogozinski left a comment

Choose a reason for hiding this comment

GalRogozinski Feb 28, 2018

Choose a reason for hiding this comment

GalRogozinski Feb 28, 2018

Choose a reason for hiding this comment

GalRogozinski Feb 28, 2018

Choose a reason for hiding this comment

GalRogozinski Feb 28, 2018

Choose a reason for hiding this comment

Desolatora commented Mar 15, 2018

GalRogozinski commented Mar 19, 2018

Desolatora commented Mar 19, 2018

GalRogozinski left a comment

Choose a reason for hiding this comment

Desolatora commented Apr 2, 2018 • edited Loading

alon-e left a comment

Choose a reason for hiding this comment

alon-e Apr 3, 2018

Choose a reason for hiding this comment

alon-e Apr 3, 2018

Choose a reason for hiding this comment

Desolatora commented Apr 3, 2018 • edited Loading

Desolatora commented Apr 2, 2018 •

edited

Loading

Desolatora commented Apr 3, 2018 •

edited

Loading