Fix: Milestone progress bar v2

src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java

@@ -37,7 +37,7 @@ public class MilestoneSolidifierImpl implements MilestoneSolidifier {
 
     private static final IntervalLogger latestSolidMilestoneLogger = new IntervalLogger(MilestoneSolidifierImpl.class);
 
-    private static final IntervalLogger solidifyLogger = new IntervalLogger(MilestoneSolidifierImpl.class);
+    private static final IntervalLogger solidifyLogger = new IntervalLogger(MilestoneSolidifierImpl.class, 10000);
 
     private static final IntervalLogger progressBarLogger = new IntervalLogger(MilestoneSolidifierImpl.class);
 
@@ -111,9 +111,8 @@ public void start() {
 
             Snapshot latestSnapshot = snapshotProvider.getLatestSnapshot();
             setLatestMilestone(latestSnapshot.getHash(), latestSnapshot.getIndex());
-            logChange(snapshotProvider.getInitialSnapshot().getIndex());
+            //logChange(snapshotProvider.getInitialSnapshot().getIndex());
 
-            syncProgressInfo.setSyncMilestoneStartIndex(snapshotProvider.getInitialSnapshot().getIndex());
             milestoneSolidifier.start();
 
         } catch (Exception e) {
@@ -219,7 +218,13 @@ private void processSolidifyQueue() throws Exception {
             }
         }
 
+        int lowest = oldestMilestoneInQueue == null ? -1 : oldestMilestoneInQueue.getValue();
         scanMilestonesInQueue();
+        if (oldestMilestoneInQueue != null && lowest > oldestMilestoneInQueue.getValue()) {
+            // Going down or going up doesnt matter to the calculation
+            syncProgressInfo.addMilestoneApplicationTime();
+            logChange(-1);
+        }
     }
 
     /**
@@ -243,7 +248,7 @@ private void checkLatestSolidMilestone() {
                 }
             }
         } catch (Exception e) {
-            log.info(e.getMessage());
+            log.error(e.getMessage(), e);
         }
     }
 
@@ -288,7 +293,7 @@ private void bootStrapSolidMilestones() throws Exception {
                         addMilestoneCandidate(hash, index);
                     }
                 }
-                if (processed % 1000 == 0 || processed % milestoneTransactions.size() == 0){
+                if (processed % (milestoneTransactions.size()/10) == 0 || processed % milestoneTransactions.size() == 0){
                     log.info("Bootstrapping milestones: [ " + processed  + " / " + milestoneTransactions.size() + " ]");
                 }
             } catch(Exception e) {
@@ -446,43 +451,55 @@ private boolean applySolidMilestoneToLedger(MilestoneViewModel milestone) throws
             return false;
         }
     }
-
-
-
-
+
+    /**
+     * Logs changes to the console based on a change in syncing state
+     * 
+     * @param prevSolidMilestoneIndex THe previous solid milestone, -1 if we went down 1 ms in oldestMilestoneInQueue
+     */
     private void logChange(int prevSolidMilestoneIndex) {
         Snapshot latestSnapshot = snapshotProvider.getLatestSnapshot();
         int nextLatestSolidMilestone = latestSnapshot.getIndex();
-        setLatestSolidMilestone(nextLatestSolidMilestone);
+
+        if (prevSolidMilestoneIndex != -1) {
+            if (prevSolidMilestoneIndex == nextLatestSolidMilestone) {
+                return;
+            }
 
+            setLatestSolidMilestone(nextLatestSolidMilestone);
+            latestSolidMilestoneLogger.info("Latest SOLID milestone index changed from #" + prevSolidMilestoneIndex + " to #" + nextLatestSolidMilestone);
 
-        if (prevSolidMilestoneIndex == nextLatestSolidMilestone) {
-            return;
+            tangle.publish("lmsi %d %d", prevSolidMilestoneIndex, nextLatestSolidMilestone);
+            tangle.publish("lmhs %s", latestMilestoneHash);
         }
 
-        latestSolidMilestoneLogger.info("Latest SOLID milestone index changed from #" + prevSolidMilestoneIndex + " to #" + nextLatestSolidMilestone);
-
-        tangle.publish("lmsi %d %d", prevSolidMilestoneIndex, nextLatestSolidMilestone);
-        tangle.publish("lmhs %s", latestMilestoneHash);
-
         if (!config.isPrintSyncProgressEnabled()) {
             return;
         }
 
         // only print more sophisticated progress if we are coming from a more unsynced state
-        if (getLatestMilestoneIndex() - nextLatestSolidMilestone < 1) {
+        if (prevSolidMilestoneIndex != -1 && getLatestMilestoneIndex() - nextLatestSolidMilestone < 1) {
             syncProgressInfo.setSyncMilestoneStartIndex(nextLatestSolidMilestone);
             syncProgressInfo.resetMilestoneApplicationTimes();
             return;
         }
 
+        // oldestMilestoneInQueue can be null if they are processed faster than coming in. 
+        // Unlikely to happen on mainnet though.
+        double percentageSynced = syncProgressInfo.calculatePercentageSynced(getLatestMilestoneIndex(), 
+                getLatestSolidMilestoneIndex(),  
+                oldestMilestoneInQueue == null ? 0 : oldestMilestoneInQueue.getValue());
+        if (percentageSynced  == -1) {
+            // Were still starting up things... 
+            return;
+        }
+
         int estSecondsToBeSynced = syncProgressInfo.computeEstimatedTimeToSyncUpSeconds(getLatestMilestoneIndex(),
                 nextLatestSolidMilestone);
+
         StringBuilder progressSB = new StringBuilder();
-
         // add progress bar
-        progressSB.append(ASCIIProgressBar.getProgressBarString(syncProgressInfo.getSyncMilestoneStartIndex(),
-                getLatestMilestoneIndex(), nextLatestSolidMilestone));
+        progressSB.append(ASCIIProgressBar.getProgressBarString(0, 100, (int)Math.round(percentageSynced)));
         // add lsm to lm
         progressSB.append(String.format(" [LSM %d / LM %d - remaining: %d]", nextLatestSolidMilestone,
                 getLatestMilestoneIndex(), getLatestMilestoneIndex() - nextLatestSolidMilestone));
@@ -498,10 +515,19 @@ private void logChange(int prevSolidMilestoneIndex) {
      * Holds variables containing information needed for sync progress calculation.
      */
     private static class SyncProgressInfo {
+
+        static final double PERCENT_WEIGHT_DOWN = 95;
+
         /**
          * The actual start milestone index from which the node started from when syncing up.
          */
         private int syncMilestoneStartIndex;
+
+        /**
+         * The oldest milestone index we have seen. 
+         * Cached so that once we synced down, it doesnt revert to the new latest milestone index
+         */
+        private int oldestSeenMilestoneIndex;
 
         /**
          * Used to calculate the average time needed to apply a milestone.
@@ -541,6 +567,7 @@ void addMilestoneApplicationTime() {
          */
         void resetMilestoneApplicationTimes() {
             lastMilestoneApplyTimes.clear();
+            oldestSeenMilestoneIndex = 0;
         }
 
         /**
@@ -568,6 +595,32 @@ int computeEstimatedTimeToSyncUpSeconds(int latestMilestoneIndex, int latestSoli
 
             return (int) ((avgMilestoneApplyMillisec / 1000) * (latestMilestoneIndex - latestSolidMilestoneIndex));
         }
+
+        /**
+         * Calculates the percentage we are synced
+         * 
+         * @param latest latest milestone index
+         * @param latestSolid latest solid milestone index
+         * @param oldestInQueue oldest milestone index we process, can be <code>null</code>
+         * @return A percentage value of syncedness
+         */
+        double calculatePercentageSynced(int latest, int latestSolid, int oldestInQueue) {
+            if (oldestInQueue != 0 && oldestInQueue > latestSolid &&
+                    (oldestSeenMilestoneIndex > oldestInQueue || oldestSeenMilestoneIndex == 0)) {
+                oldestSeenMilestoneIndex = oldestInQueue;
+            }
+
+            double currentD = (oldestInQueue == 0 ? latestSolid : oldestSeenMilestoneIndex) - latestSolid;
+            double targetD  = latest - latestSolid;
+
+            double processPercentage = (100 - currentD / targetD / 0.01d) / 100d * PERCENT_WEIGHT_DOWN;
+            if (processPercentage >= 95 && latestSolid != latest) {
+                return -1;
+            }
+
+            double percentageSynced = processPercentage + ((latestSolid / latest / 0.01d) / 100d * (100d - PERCENT_WEIGHT_DOWN));
+            return percentageSynced;
+        }
     }
 
 }