MID-8842 ninja - logging improvements

(cherry picked from commit 4054964)

tools/ninja/src/main/java/com/evolveum/midpoint/ninja/action/RunSqlOptions.java

@@ -1,5 +1,7 @@
 package com.evolveum.midpoint.ninja.action;
 
+import static com.evolveum.midpoint.ninja.action.upgrade.UpgradeConstants.SCRIPTS_DIRECTORY;
+
 import java.io.File;
 import java.util.ArrayList;
 import java.util.Collections;
@@ -14,8 +16,6 @@
 @Parameters(resourceBundle = "messages", commandDescriptionKey = "runSql")
 public class RunSqlOptions {
 
-    public static final File SCRIPTS_DIRECTORY = new File("./doc/config/sql/native-new");
-
     public enum Mode {
 
         /**

tools/ninja/src/main/java/com/evolveum/midpoint/ninja/action/upgrade/ConsoleProgressListener.java

@@ -7,24 +7,30 @@
 
 package com.evolveum.midpoint.ninja.action.upgrade;
 
+import static com.evolveum.midpoint.ninja.util.ConsoleFormat.*;
+
 import java.text.DecimalFormat;
 
 import org.apache.commons.io.FileUtils;
-import org.fusesource.jansi.Ansi;
+import org.apache.commons.lang3.time.DurationFormatUtils;
 
 import com.evolveum.midpoint.ninja.impl.Log;
 import com.evolveum.midpoint.ninja.impl.LogLevel;
-import com.evolveum.midpoint.ninja.util.ConsoleFormat;
+import com.evolveum.midpoint.ninja.util.NinjaUtils;
 
 public class ConsoleProgressListener implements ProgressListener {
 
-    private static final DecimalFormat FORMAT = new DecimalFormat("###");
+    private static final DecimalFormat PROGRESS_FORMAT = new DecimalFormat("###");
+
+    private static final DecimalFormat SPEED_FORMAT = new DecimalFormat("####.##");
 
     private final Log log;
 
     private boolean firstUpdate = true;
 
-    private double progress = 0;
+    private long startTime;
+
+    private long lastReportTime;
 
     public ConsoleProgressListener(Log log) {
         this.log = log;
@@ -33,36 +39,49 @@ public ConsoleProgressListener(Log log) {
     @Override
     public void update(long bytesRead, long contentLength, boolean done) {
         if (done) {
-            log.info(ConsoleFormat.formatSuccessMessage("Download complete"));
+            log.info(
+                    rewriteConsoleLine(
+                            formatLogMessage(LogLevel.INFO,
+                                    formatSuccessMessage("Download complete"))));
             return;
         }
 
         if (firstUpdate) {
             firstUpdate = false;
 
+            startTime = System.currentTimeMillis();
+
             String size = contentLength == -1 ? "unknown" : FileUtils.byteCountToDisplaySize(contentLength);
 
-            log.info(ConsoleFormat.formatMessageWithInfoParameters("Download size: {}", size));
+            log.info(formatMessageWithInfoParameters("Download size: {}", size));
 
             // this empty line will be removed with progress update
-            log.info("");
+            log.info(logProgress(bytesRead, contentLength));
+            lastReportTime = System.currentTimeMillis();
         }
 
-        double newProgress = (double) (100 * bytesRead) / contentLength;
-        if (newProgress - progress > 1) {
-            logProgress(newProgress);
-
-            progress = newProgress;
+        if (System.currentTimeMillis() - lastReportTime < NinjaUtils.COUNT_STATUS_LOG_INTERVAL) {
+            return;
         }
+
+        log.info(
+                rewriteConsoleLine(
+                        logProgress(bytesRead, contentLength)));
+        lastReportTime = System.currentTimeMillis();
     }
 
-    private void logProgress(double newProgress) {
-        log.info(Ansi.ansi()
-                .cursorToColumn(1)
-                .cursorUpLine().eraseLine(Ansi.Erase.ALL)
-                .a(
-                        ConsoleFormat.formatLogMessage(LogLevel.INFO,
-                                ConsoleFormat.formatMessageWithInfoParameters("Progress: {}%", FORMAT.format(newProgress)))
-                ).toString());
+    private String logProgress(long bytesRead, long contentLength) {
+        double speed = bytesRead / ((System.currentTimeMillis() - startTime) / 1000.0);
+        double speedMB = speed / 1024 / 1024;
+        long estimatedDuration = (long) ((contentLength - bytesRead) / speed * 1000);
+
+        double progress = (double) (100 * bytesRead) / contentLength;
+
+        return formatLogMessage(LogLevel.INFO,
+                NinjaUtils.printFormatted(
+                        "Progress: {}\t{} MB/s\tETA: {}",
+                        formatMessage(PROGRESS_FORMAT.format(progress) + "%", Color.INFO),
+                        SPEED_FORMAT.format(speedMB),
+                        DurationFormatUtils.formatDurationWords(estimatedDuration, true, true)));
     }
 }

tools/ninja/src/main/java/com/evolveum/midpoint/ninja/action/upgrade/UpgradeConstants.java

@@ -1,5 +1,7 @@
 package com.evolveum.midpoint.ninja.action.upgrade;
 
+import java.io.File;
+
 public class UpgradeConstants {
 
     /**
@@ -15,4 +17,9 @@ public class UpgradeConstants {
     public static final String SUPPORTED_VERSION_TARGET = "4.8";
 
     public static final String UPGRADE_TEMP_DIRECTORY = ".upgrade";
+
+    /**
+     * Directory within distribution where SQL scripts for native PostgreSQL repository are located.
+     */
+    public static final File SCRIPTS_DIRECTORY = new File("./doc/config/sql/native-new");
 }

tools/ninja/src/main/java/com/evolveum/midpoint/ninja/action/upgrade/action/PreUpgradeCheckAction.java

@@ -53,7 +53,7 @@ public ActionResult<Boolean> execute() throws Exception {
             log.warn("Skipping database schema version check");
         }
 
-        log.info("Pre-upgrade checks finished successfully");
+        log.info(ConsoleFormat.formatSuccessMessage("Pre-upgrade checks finished successfully"));
 
         return new ActionResult<>(true);
     }

tools/ninja/src/main/java/com/evolveum/midpoint/ninja/util/ConsoleFormat.java

@@ -74,4 +74,14 @@ public static String formatLogMessage(LogLevel level, String msg) {
                 .a(msg)
                 .toString();
     }
+
+    /**
+     * Technically removes two lines, since {@Log.info} adds new line at the end of the message
+     */
+    public static String rewriteConsoleLine(String newLine) {
+        return Ansi.ansi()
+                .eraseLine(Ansi.Erase.ALL)
+                .cursorUpLine().eraseLine(Ansi.Erase.ALL)
+                .a(newLine).toString();
+    }
 }

tools/ninja/src/main/java/com/evolveum/midpoint/ninja/util/NinjaUtils.java

@@ -58,7 +58,7 @@ public class NinjaUtils {
 
     public static final DecimalFormat DECIMAL_FORMAT = new DecimalFormat("#.##");
 
-    public static final long COUNT_STATUS_LOG_INTERVAL = 2 * 1000; // two seconds
+    public static final long COUNT_STATUS_LOG_INTERVAL = 500;
 
     public static final long WAIT_FOR_EXECUTOR_FINISH = 365;