http: debug log file download duration+rate

src/main/java/me/itzg/helpers/McImageHelper.java

@@ -33,6 +33,7 @@
 import me.itzg.helpers.versions.JavaReleaseCommand;
 import org.slf4j.LoggerFactory;
 import picocli.CommandLine;
+import picocli.CommandLine.ArgGroup;
 import picocli.CommandLine.Command;
 import picocli.CommandLine.IVersionProvider;
 import picocli.CommandLine.Option;
@@ -73,15 +74,30 @@ public class McImageHelper {
   @Option(names = {"-V", "--version"}, versionHelp = true)
   boolean showVersion;
 
-  @SuppressWarnings("unused")
-  @Option(names = "--debug", description = "Enable debug output."
-      + " Can also set environment variables DEBUG_HELPER or DEBUG",
-      defaultValue = "${env:DEBUG_HELPER:-${env:DEBUG}}")
-  void setDebug(boolean value) {
-    ((Logger) LoggerFactory.getLogger("me.itzg.helpers")).setLevel(
-        value ? Level.DEBUG : Level.INFO);
+  @ArgGroup
+  LoggingOptions loggingOptions = new LoggingOptions();
+
+  static class LoggingOptions {
+    @Option(names = "--debug", description = "Enable debug output."
+        + " Can also set environment variables DEBUG_HELPER or DEBUG",
+        defaultValue = "${env:DEBUG_HELPER:-${env:DEBUG}}")
+    void setDebug(boolean enabled) {
+      setLevel(enabled, Level.DEBUG);
+    }
+
+    @Option(names = "--logging", description = "Set logging to specific level.\nValid values: ${COMPLETION-CANDIDATES}")
+    void setLoggingLevel(Level level) {
+      setLevel(true, level);
+    }
+
+    private static void setLevel(boolean enabled, Level level) {
+      ((Logger) LoggerFactory.getLogger("me.itzg.helpers")).setLevel(
+          enabled ? level : Level.INFO);
+    }
+
   }
 
+
   @Option(names = {"-s", "--silent"}, description = "Don't output logs even if there's an error")
   @Getter
   boolean silent;

src/main/java/me/itzg/helpers/curseforge/CurseForgeInstaller.java

@@ -446,8 +446,8 @@ private OverridesResult applyOverrides(Path modpackZip, String overridesDir) thr
             while ((entry = zip.getNextEntry()) != null) {
                 if (entry.getName().startsWith(overridesDirPrefix)) {
                     if (!entry.isDirectory()) {
-                        if (log.isDebugEnabled()) {
-                            log.debug("Processing override entry={}:{}", entry.isDirectory() ? "D":"F", entry.getName());
+                        if (log.isTraceEnabled()) {
+                            log.trace("Processing override entry={}:{}", entry.isDirectory() ? "D":"F", entry.getName());
                         }
                         final String subpath = entry.getName().substring(overridesPrefixLen);
                         final Path outPath = outputDir.resolve(subpath);

src/main/java/me/itzg/helpers/http/FetchBuilderBase.java

@@ -183,4 +183,25 @@ protected void applyHeaders(io.netty.handler.codec.http.HttpHeaders headers) {
 
         state.requestHeaders.forEach(headers::set);
     }
+
+    static String formatDuration(long millis) {
+        final StringBuilder sb = new StringBuilder();
+        final long minutes = millis / 60000;
+        if (minutes > 0) {
+            sb.append(minutes);
+            sb.append("m ");
+        }
+        final long seconds = (millis % 60000) / 1000;
+        if (seconds > 0) {
+            sb.append(seconds);
+            sb.append("s ");
+        }
+        sb.append(millis % 1000);
+        sb.append("ms");
+        return sb.toString();
+    }
+
+    static String transferRate(long millis, long bytes) {
+        return String.format("%d KB/s", bytes / millis);
+    }
 }

src/main/java/me/itzg/helpers/http/SpecificFileFetchBuilder.java

@@ -2,6 +2,7 @@
 
 import static io.netty.handler.codec.http.HttpHeaderNames.IF_MODIFIED_SINCE;
 import static io.netty.handler.codec.http.HttpResponseStatus.NOT_MODIFIED;
+import static java.lang.System.currentTimeMillis;
 import static java.util.Objects.requireNonNull;
 
 import io.netty.handler.codec.http.HttpResponseStatus;
@@ -115,9 +116,10 @@ public Mono<Path> assemble() {
                     return bodyMono.asInputStream()
                         .publishOn(Schedulers.boundedElastic())
                         .flatMap(inputStream -> {
+                            final long size;
                             try {
-                                @SuppressWarnings("BlockingMethodInNonBlockingContext") // see publishOn above
-                                final long size = Files.copy(inputStream, file, StandardCopyOption.REPLACE_EXISTING);
+                                //noinspection BlockingMethodInNonBlockingContext
+                                size = Files.copy(inputStream, file, StandardCopyOption.REPLACE_EXISTING);
                                 statusHandler.call(FileDownloadStatus.DOWNLOADED, uri, file);
                                 downloadedHandler.call(uri, file, size);
                             } catch (IOException e) {
@@ -130,9 +132,18 @@ public Mono<Path> assemble() {
                                     log.warn("Unable to close body input stream", e);
                                 }
                             }
-                            return Mono.just(file);
+                            return Mono
+                                .deferContextual(contextView -> {
+                                    if (log.isDebugEnabled()) {
+                                        final long durationMillis = currentTimeMillis() - contextView.<Long>get("downloadStart");
+                                        log.debug("Download of {} took {} at {}",
+                                            uri, formatDuration(durationMillis), transferRate(durationMillis, size));
+                                    }
+                                    return Mono.just(file);
+                                });
                         });
                 })
+                .contextWrite(context -> context.put("downloadStart", currentTimeMillis()))
         );
     }