From 40a8cdc71f976c31fbe19da8f8c4e993b6c24c02 Mon Sep 17 00:00:00 2001
From: CalDescent <caldescent@protonmail.com>
Date: Mon, 31 Jan 2022 22:35:12 +0000
Subject: [PATCH] Improved logging when fetching data files

---
 .../arbitrary/ArbitraryDataFileManager.java          | 12 +++++++++---
 1 file changed, 9 insertions(+), 3 deletions(-)

diff --git a/src/main/java/org/qortal/controller/arbitrary/ArbitraryDataFileManager.java b/src/main/java/org/qortal/controller/arbitrary/ArbitraryDataFileManager.java
index 8eeda508..6c5376dd 100644
--- a/src/main/java/org/qortal/controller/arbitrary/ArbitraryDataFileManager.java
+++ b/src/main/java/org/qortal/controller/arbitrary/ArbitraryDataFileManager.java
@@ -119,13 +119,16 @@ public class ArbitraryDataFileManager {
             if (!arbitraryDataFile.chunkExists(hash)) {
                 // Only request the file if we aren't already requesting it from someone else
                 if (!arbitraryDataFileRequests.containsKey(Base58.encode(hash))) {
+                    LOGGER.debug("Requesting data file {} from peer {}", Base58.encode(hash), peer);
+                    Long startTime = NTP.getTime();
                     ArbitraryDataFileMessage receivedArbitraryDataFileMessage = fetchArbitraryDataFile(peer, null, signature, hash, null);
+                    Long endTime = NTP.getTime();
                     if (receivedArbitraryDataFileMessage != null) {
-                        LOGGER.debug("Received data file {} from peer {}", receivedArbitraryDataFileMessage.getArbitraryDataFile().getHash58(), peer);
+                        LOGGER.debug("Received data file {} from peer {}. Time taken: {} ms", receivedArbitraryDataFileMessage.getArbitraryDataFile().getHash58(), peer, (endTime-startTime));
                         receivedAtLeastOneFile = true;
                     }
                     else {
-                        LOGGER.debug("Peer {} didn't respond with data file {} for signature {}", peer, Base58.encode(hash), Base58.encode(signature));
+                        LOGGER.debug("Peer {} didn't respond with data file {} for signature {}. Time taken: {} ms", peer, Base58.encode(hash), Base58.encode(signature), (endTime-startTime));
                     }
                 }
                 else {
@@ -171,11 +174,11 @@ public class ArbitraryDataFileManager {
     private ArbitraryDataFileMessage fetchArbitraryDataFile(Peer peer, Peer requestingPeer, byte[] signature, byte[] hash, Message originalMessage) throws DataException {
         ArbitraryDataFile existingFile = ArbitraryDataFile.fromHash(hash, signature);
         boolean fileAlreadyExists = existingFile.exists();
+        String hash58 = Base58.encode(hash);
         Message message = null;
 
         // Fetch the file if it doesn't exist locally
         if (!fileAlreadyExists) {
-            String hash58 = Base58.encode(hash);
             LOGGER.debug(String.format("Fetching data file %.8s from peer %s", hash58, peer));
             arbitraryDataFileRequests.put(hash58, NTP.getTime());
             Message getArbitraryDataFileMessage = new GetArbitraryDataFileMessage(signature, hash);
@@ -195,6 +198,9 @@ public class ArbitraryDataFileManager {
                 return null;
             }
         }
+        else {
+            LOGGER.debug(String.format("File hash %s already exists, so skipping the request", hash58));
+        }
         ArbitraryDataFileMessage arbitraryDataFileMessage = (ArbitraryDataFileMessage) message;
 
         // We might want to forward the request to the peer that originally requested it