From 7929900e01904d683fb4097115f9a72b61c4a1d0 Mon Sep 17 00:00:00 2001 From: Geoff Bourne Date: Sat, 28 Jan 2023 12:36:33 -0600 Subject: [PATCH] http: debug log file download duration+rate --- .../java/me/itzg/helpers/McImageHelper.java | 30 ++++++++++++++----- .../curseforge/CurseForgeInstaller.java | 4 +-- .../itzg/helpers/http/FetchBuilderBase.java | 21 +++++++++++++ .../http/SpecificFileFetchBuilder.java | 17 +++++++++-- 4 files changed, 60 insertions(+), 12 deletions(-) diff --git a/src/main/java/me/itzg/helpers/McImageHelper.java b/src/main/java/me/itzg/helpers/McImageHelper.java index de7119ad..78913e60 100644 --- a/src/main/java/me/itzg/helpers/McImageHelper.java +++ b/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; diff --git a/src/main/java/me/itzg/helpers/curseforge/CurseForgeInstaller.java b/src/main/java/me/itzg/helpers/curseforge/CurseForgeInstaller.java index 6d91b070..5cdfffca 100644 --- a/src/main/java/me/itzg/helpers/curseforge/CurseForgeInstaller.java +++ b/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); diff --git a/src/main/java/me/itzg/helpers/http/FetchBuilderBase.java b/src/main/java/me/itzg/helpers/http/FetchBuilderBase.java index 787c069e..cf3dcbbc 100644 --- a/src/main/java/me/itzg/helpers/http/FetchBuilderBase.java +++ b/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); + } } diff --git a/src/main/java/me/itzg/helpers/http/SpecificFileFetchBuilder.java b/src/main/java/me/itzg/helpers/http/SpecificFileFetchBuilder.java index d636edcf..5867ba07 100644 --- a/src/main/java/me/itzg/helpers/http/SpecificFileFetchBuilder.java +++ b/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 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 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.get("downloadStart"); + log.debug("Download of {} took {} at {}", + uri, formatDuration(durationMillis), transferRate(durationMillis, size)); + } + return Mono.just(file); + }); }); }) + .contextWrite(context -> context.put("downloadStart", currentTimeMillis())) ); }