Merge pull request #5071 from vespa-engine/hmusum/file-distribution-logging-changes

Reduce log level and create less garbage

6 files changed, 28 insertions, 27 deletions

diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/filedistribution/FileServer.java b/configserver/src/main/java/com/yahoo/vespa/config/server/filedistribution/FileServer.java
index dbd8fdda052..c9859cc79d3 100644
--- a/configserver/src/main/java/com/yahoo/vespa/config/server/filedistribution/FileServer.java
+++ b/configserver/src/main/java/com/yahoo/vespa/config/server/filedistribution/FileServer.java
@@ -107,7 +107,7 @@ public class FileServer {
 
     private void serveFile(FileReference reference, Receiver target) {
         File file = root.getFile(reference);
-        log.log(LogLevel.DEBUG, "Start serving reference '" + reference.value() + "' with file '" + file.getAbsolutePath() + "'");
+        log.log(LogLevel.DEBUG, () -> "Start serving reference '" + reference.value() + "' with file '" + file.getAbsolutePath() + "'");
         boolean success = false;
         String errorDescription = "OK";
         FileReferenceData fileData = FileReferenceDataBlob.empty(reference, file.getName());
@@ -141,7 +141,7 @@ public class FileServer {
     private void serveFile(String fileReference, Request request, Receiver receiver) {
         FileApiErrorCodes result;
         try {
-            log.log(LogLevel.DEBUG, "Received request for reference '" + fileReference + "'");
+            log.log(LogLevel.DEBUG, () -> "Received request for reference '" + fileReference + "'");
             result = hasFile(fileReference)
                     ? FileApiErrorCodes.OK
                     : FileApiErrorCodes.NOT_FOUND;
diff --git a/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/CompressedFileReference.java b/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/CompressedFileReference.java
index 27ada7532f5..c4cd2a073c1 100644
--- a/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/CompressedFileReference.java
+++ b/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/CompressedFileReference.java
@@ -63,7 +63,7 @@ public class CompressedFileReference {
     }
 
     static void decompress(File inputFile, File outputDir) throws IOException {
-        log.log(LogLevel.DEBUG, "Decompressing '" + inputFile + "' into '" + outputDir + "'");
+        log.log(LogLevel.DEBUG, () -> "Decompressing '" + inputFile + "' into '" + outputDir + "'");
         ArchiveInputStream ais = new TarArchiveInputStream(new GZIPInputStream(new FileInputStream(inputFile)));
         decompress(ais, outputDir);
         ais.close();
@@ -77,7 +77,7 @@ public class CompressedFileReference {
             File outFile = new File(outputFile, entry.getName());
             if (entry.isDirectory()) {
                 if (!(outFile.exists() && outFile.isDirectory())) {
-                    log.log(LogLevel.DEBUG, "Creating dir: " + outFile.getAbsolutePath());
+                    log.log(LogLevel.DEBUG, () -> "Creating dir: " + outFile.getAbsolutePath());
                     if (!outFile.mkdirs()) {
                         log.log(LogLevel.WARNING, "Could not create dir " + entry.getName());
                     }
@@ -111,7 +111,7 @@ public class CompressedFileReference {
     }
 
     private static void writeFileToTar(ArchiveOutputStream taos, File baseDir, File file) throws IOException {
-        log.log(LogLevel.DEBUG, "Adding file to tar: " + baseDir.toPath().relativize(file.toPath()).toString());
+        log.log(LogLevel.DEBUG, () -> "Adding file to tar: " + baseDir.toPath().relativize(file.toPath()).toString());
         taos.putArchiveEntry(taos.createArchiveEntry(file, baseDir.toPath().relativize(file.toPath()).toString()));
         ByteStreams.copy(new FileInputStream(file), taos);
         taos.closeArchiveEntry();
diff --git a/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileDistributionRpcServer.java b/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileDistributionRpcServer.java
index 3e81321f92e..f24d76fe8be 100644
--- a/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileDistributionRpcServer.java
+++ b/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileDistributionRpcServer.java
@@ -115,12 +115,12 @@ public class FileDistributionRpcServer {
 
     private void downloadFile(Request req) {
         FileReference fileReference = new FileReference(req.parameters().get(0).asString());
-        log.log(LogLevel.DEBUG, "getFile() called for file reference '" + fileReference.value() + "'");
+        log.log(LogLevel.DEBUG, () -> "getFile() called for file reference '" + fileReference.value() + "'");
         Optional<File> pathToFile = downloader.getFile(fileReference);
         try {
             if (pathToFile.isPresent()) {
                 req.returnValues().add(new StringValue(pathToFile.get().getAbsolutePath()));
-                log.log(LogLevel.DEBUG, "File reference '" + fileReference.value() + "' available at " + pathToFile.get());
+                log.log(LogLevel.DEBUG, () -> "File reference '" + fileReference.value() + "' available at " + pathToFile.get());
             } else {
                 log.log(LogLevel.INFO, "File reference '" + fileReference.value() + "' not found, returning error");
                 req.setError(fileReferenceDoesNotExists, "File reference '" + fileReference.value() + "' not found");
diff --git a/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileDownloader.java b/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileDownloader.java
index 5655d69593c..bed38bdcac6 100644
--- a/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileDownloader.java
+++ b/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileDownloader.java
@@ -57,7 +57,7 @@ public class FileDownloader {
     private Future<Optional<File>> getFutureFile(FileReference fileReference) {
         Objects.requireNonNull(fileReference, "file reference cannot be null");
         File directory = new File(downloadDirectory, fileReference.value());
-        log.log(LogLevel.DEBUG, "Checking if there is a file in '" + directory.getAbsolutePath() + "' ");
+        log.log(LogLevel.DEBUG, () -> "Checking if there is a file in '" + directory.getAbsolutePath() + "' ");
 
         Optional<File> file = getFileFromFileSystem(fileReference, directory);
         if (file.isPresent()) {
@@ -65,7 +65,7 @@ public class FileDownloader {
             future.set(file);
             return future;
         } else {
-            log.log(LogLevel.INFO, "File reference '" + fileReference.value() + "' not found in " +
+            log.log(LogLevel.DEBUG, () -> "File reference '" + fileReference.value() + "' not found in " +
                     directory.getAbsolutePath() + ", starting download");
             return queueForAsyncDownload(fileReference, timeout);
         }
@@ -75,7 +75,7 @@ public class FileDownloader {
     public void queueForAsyncDownload(List<FileReference> fileReferences) {
         fileReferences.forEach(fileReference -> {
             if (fileReferenceDownloader.isDownloading(fileReference)) {
-                log.log(LogLevel.DEBUG, "Already downloading '" + fileReference.value() + "'");
+                log.log(LogLevel.DEBUG, () -> "Already downloading '" + fileReference.value() + "'");
             } else {
                 queueForAsyncDownload(fileReference);
             }
@@ -117,12 +117,12 @@ public class FileDownloader {
     private synchronized Future<Optional<File>> queueForAsyncDownload(FileReference fileReference, Duration timeout) {
         Future<Optional<File>> inProgress = fileReferenceDownloader.addDownloadListener(fileReference, () -> getFile(fileReference));
         if (inProgress != null) {
-            log.log(LogLevel.DEBUG, "Already downloading '" + fileReference.value() + "'");
+            log.log(LogLevel.DEBUG, () -> "Already downloading '" + fileReference.value() + "'");
             return inProgress;
         }
 
         Future<Optional<File>> future = queueForAsyncDownload(fileReference);
-        log.log(LogLevel.INFO, "Queued '" + fileReference.value() + "' for download with timeout " + timeout);
+        log.log(LogLevel.DEBUG, () -> "Queued '" + fileReference.value() + "' for download with timeout " + timeout);
         return future;
     }
 
diff --git a/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileReceiver.java b/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileReceiver.java
index a580759b03b..83cf4e1ad80 100644
--- a/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileReceiver.java
+++ b/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileReceiver.java
@@ -113,7 +113,7 @@ public class FileReceiver {
                 // Unpack if necessary
                 if (fileType == FileReferenceData.Type.compressed) {
                     File decompressedDir = Files.createTempDirectory(tmpDir.toPath(), "archive").toFile();
-                    log.log(LogLevel.DEBUG, "Archived file, unpacking " + inprogressFile + " to " + decompressedDir);
+                    log.log(LogLevel.DEBUG, () -> "Archived file, unpacking " + inprogressFile + " to " + decompressedDir);
                     CompressedFileReference.decompress(inprogressFile, decompressedDir);
                     moveFileToDestination(decompressedDir, fileReferenceDir);
                 } else {
@@ -123,7 +123,7 @@ public class FileReceiver {
                         log.log(LogLevel.ERROR, "Failed creating directory (" + fileReferenceDir.toPath() + "): " + e.getMessage(), e);
                         throw new RuntimeException("Failed creating directory (" + fileReferenceDir.toPath() + "): ", e);
                     }
-                    log.log(LogLevel.DEBUG, "Uncompressed file, moving to " + file.getAbsolutePath());
+                    log.log(LogLevel.DEBUG, () -> "Uncompressed file, moving to " + file.getAbsolutePath());
                     moveFileToDestination(inprogressFile, file);
                 }
             } catch (IOException e) {
@@ -202,11 +202,11 @@ public class FileReceiver {
             // Unpack if necessary
             if (fileReferenceData.type() == FileReferenceData.Type.compressed) {
                 File decompressedDir = Files.createTempDirectory(tempDownloadedDir.toPath(), "decompressed").toFile();
-                log.log(LogLevel.DEBUG, "Compressed file, unpacking " + tempFile + " to " + decompressedDir);
+                log.log(LogLevel.DEBUG, () -> "Compressed file, unpacking " + tempFile + " to " + decompressedDir);
                 CompressedFileReference.decompress(tempFile, decompressedDir);
                 moveFileToDestination(decompressedDir, fileReferenceDir);
             } else {
-                log.log(LogLevel.DEBUG, "Uncompressed file, moving to " + file.getAbsolutePath());
+                log.log(LogLevel.DEBUG, () -> "Uncompressed file, moving to " + file.getAbsolutePath());
                 Files.createDirectories(fileReferenceDir.toPath());
                 moveFileToDestination(tempFile, file);
             }
@@ -220,11 +220,11 @@ public class FileReceiver {
     private static void moveFileToDestination(File tempFile, File destination) {
         try {
             Files.move(tempFile.toPath(), destination.toPath());
-            log.log(LogLevel.DEBUG, "File moved from " + tempFile.getAbsolutePath()+ " to " + destination.getAbsolutePath());
+            log.log(LogLevel.DEBUG, () -> "File moved from " + tempFile.getAbsolutePath()+ " to " + destination.getAbsolutePath());
         } catch (FileAlreadyExistsException e) {
             // Don't fail if it already exists (we might get the file from several config servers when retrying, servers are down etc.
             // so it might be written already). Delete temp file in that case, to avoid filling the disk.
-            log.log(LogLevel.DEBUG, "File '" + destination.getAbsolutePath() + "' already exists, continuing: " + e.getMessage());
+            log.log(LogLevel.DEBUG, () -> "File '" + destination.getAbsolutePath() + "' already exists, continuing: " + e.getMessage());
             try {
                 Files.delete(tempFile.toPath());
             } catch (IOException ioe) { /* ignore failure */}
@@ -237,7 +237,7 @@ public class FileReceiver {
 
     @SuppressWarnings({"UnusedDeclaration"})
     public final void receiveFileMeta(Request req) {
-        log.log(LogLevel.DEBUG, "Received method call '" + req.methodName() + "' with parameters : " + req.parameters());
+        log.log(LogLevel.DEBUG, () -> "Received method call '" + req.methodName() + "' with parameters : " + req.parameters());
         FileReference reference = new FileReference(req.parameters().get(0).asString());
         String fileName = req.parameters().get(1).asString();
         String type = req.parameters().get(2).asString();
@@ -263,7 +263,7 @@ public class FileReceiver {
 
     @SuppressWarnings({"UnusedDeclaration"})
     public final void receiveFilePart(Request req) {
-        log.log(LogLevel.DEBUG, "Received method call '" + req.methodName() + "' with parameters : " + req.parameters());
+        log.log(LogLevel.DEBUG, () -> "Received method call '" + req.methodName() + "' with parameters : " + req.parameters());
 
         FileReference reference = new FileReference(req.parameters().get(0).asString());
         int sessionId = req.parameters().get(1).asInt32();
@@ -278,14 +278,14 @@ public class FileReceiver {
             retval = 1;
         }
         double completeness = (double) session.currentFileSize / (double) session.fileSize;
-        log.log(LogLevel.DEBUG, String.format("%.1f percent of '%s' downloaded", completeness * 100, reference.value()));
+        log.log(LogLevel.DEBUG, () -> String.format("%.1f percent of '%s' downloaded", completeness * 100, reference.value()));
         downloader.setDownloadStatus(reference, completeness);
         req.returnValues().add(new Int32Value(retval));
     }
 
     @SuppressWarnings({"UnusedDeclaration"})
     public final void receiveFileEof(Request req) {
-        log.log(LogLevel.DEBUG, "Received method call '" + req.methodName() + "' with parameters : " + req.parameters());
+        log.log(LogLevel.DEBUG, () -> "Received method call '" + req.methodName() + "' with parameters : " + req.parameters());
         FileReference reference = new FileReference(req.parameters().get(0).asString());
         int sessionId = req.parameters().get(1).asInt32();
         long xxhash = req.parameters().get(2).asInt64();
diff --git a/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileReferenceDownloader.java b/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileReferenceDownloader.java
index 8e230a1a2cc..92c483fc3b1 100644
--- a/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileReferenceDownloader.java
+++ b/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileReferenceDownloader.java
@@ -11,6 +11,7 @@ import com.yahoo.jrt.StringValue;
 import com.yahoo.log.LogLevel;
 import com.yahoo.vespa.config.Connection;
 import com.yahoo.vespa.config.ConnectionPool;
+import org.apache.commons.compress.archivers.ArchiveEntry;
 
 import java.io.File;
 import java.time.Duration;
@@ -74,7 +75,7 @@ public class FileReferenceDownloader {
 
     void addToDownloadQueue(FileReferenceDownload fileReferenceDownload) {
         FileReference fileReference = fileReferenceDownload.fileReference();
-        log.log(LogLevel.DEBUG, "Will download file reference '" + fileReference.value() + "' with timeout " + downloadTimeout);
+        log.log(LogLevel.DEBUG, () -> "Will download file reference '" + fileReference.value() + "' with timeout " + downloadTimeout);
         synchronized (downloads) {
             downloads.put(fileReference, fileReferenceDownload);
             downloadStatus.put(fileReference, 0.0);
@@ -94,7 +95,7 @@ public class FileReferenceDownloader {
                 downloads.remove(fileReference);
                 download.future().set(Optional.of(file));
             } else {
-                log.log(LogLevel.INFO, "Received '" + fileReference + "', which was not requested. Can be ignored if happening during upgrades/restarts");
+                log.log(LogLevel.DEBUG, () -> "Received '" + fileReference + "', which was not requested. Can be ignored if happening during upgrades/restarts");
             }
         }
     }
@@ -106,9 +107,9 @@ public class FileReferenceDownloader {
 
         execute(request, connection);
         if (validateResponse(request)) {
-            log.log(LogLevel.DEBUG, "Request callback, OK. Req: " + request + "\nSpec: " + connection);
+            log.log(LogLevel.DEBUG, () -> "Request callback, OK. Req: " + request + "\nSpec: " + connection);
             if (request.returnValues().get(0).asInt32() == 0) {
-                log.log(LogLevel.DEBUG, "Found file reference '" + fileReference.value() + "' available at " + connection.getAddress());
+                log.log(LogLevel.DEBUG, () -> "Found file reference '" + fileReference.value() + "' available at " + connection.getAddress());
                 return true;
             } else {
                 log.log(LogLevel.INFO, "File reference '" + fileReference.value() + "' not found for " + connection.getAddress());
@@ -116,7 +117,7 @@ public class FileReferenceDownloader {
                 return false;
             }
         } else {
-            log.log(LogLevel.WARNING, "Request failed. Req: " + request + "\nSpec: " + connection.getAddress() +
+            log.log(LogLevel.INFO, "Request failed. Req: " + request + "\nSpec: " + connection.getAddress() +
                     ", error code: " + request.errorCode());
             if (request.isError() && request.errorCode() == ErrorCode.CONNECTION || request.errorCode() == ErrorCode.TIMEOUT) {
                 log.log(LogLevel.INFO, "Mark connection " + connection.getAddress() + " with error");