Merge pull request #3178 from chimp1984/Improve-logging

Improve logging
bisq-network · Sep 2, 2019 · 800b677 · 800b677
2 parents 0a12676 + 3412725
commit 800b677
Show file tree

Hide file tree

Showing 24 changed files with 117 additions and 86 deletions.
diff --git a/common/src/main/java/bisq/common/storage/FileManager.java b/common/src/main/java/bisq/common/storage/FileManager.java
@@ -190,7 +190,7 @@ public synchronized void backupFile(String fileName, int numMaxBackupFiles) {
     private void saveNowInternal(T persistable) {
         long now = System.currentTimeMillis();
         saveToFile(persistable, dir, storageFile);
-        log.trace("Save {} completed in {} msec", storageFile, System.currentTimeMillis() - now);
+        log.debug("Save {} completed in {} msec", storageFile, System.currentTimeMillis() - now);
     }
 
     private synchronized void saveToFile(T persistable, File dir, File storageFile) {

diff --git a/core/src/main/java/bisq/core/app/BisqExecutable.java b/core/src/main/java/bisq/core/app/BisqExecutable.java
@@ -281,12 +281,14 @@ public void gracefulShutDown(ResultHandler resultHandler) {
                 injector.getInstance(TradeManager.class).shutDown();
                 injector.getInstance(DaoSetup.class).shutDown();
                 injector.getInstance(OpenOfferManager.class).shutDown(() -> {
+                    log.info("OpenOfferManager shutdown completed");
                     injector.getInstance(P2PService.class).shutDown(() -> {
+                        log.info("P2PService shutdown completed");
                         injector.getInstance(WalletsSetup.class).shutDownComplete.addListener((ov, o, n) -> {
+                            log.info("WalletsSetup shutdown completed");
                             module.close(injector);
-                            log.debug("Graceful shutdown completed");
                             resultHandler.handleResult();
-
+                            log.info("Graceful shutdown completed. Exiting now.");
                             System.exit(0);
                         });
                         injector.getInstance(WalletsSetup.class).shutDown();

diff --git a/core/src/main/java/bisq/core/app/BisqSetup.java b/core/src/main/java/bisq/core/app/BisqSetup.java
@@ -289,6 +289,11 @@ public void addBisqSetupCompleteListener(BisqSetupCompleteListener listener) {
     }
 
     public void start() {
+        if (log.isDebugEnabled()) {
+            UserThread.runPeriodically(() -> {
+                log.debug("1 second heartbeat");
+            }, 1);
+        }
         maybeReSyncSPVChain();
         maybeShowTac();
     }

diff --git a/core/src/main/java/bisq/core/arbitration/DisputeList.java b/core/src/main/java/bisq/core/arbitration/DisputeList.java
@@ -79,8 +79,6 @@ public Message toProtoMessage() {
     public static DisputeList fromProto(protobuf.DisputeList proto,
                                         CoreProtoResolver coreProtoResolver,
                                         Storage<DisputeList> storage) {
-        log.debug("DisputeList fromProto of {} ", proto);
-
         List<Dispute> list = proto.getDisputeList().stream()
                 .map(disputeProto -> Dispute.fromProto(disputeProto, coreProtoResolver))
                 .collect(Collectors.toList());

diff --git a/core/src/main/java/bisq/core/dao/governance/proposal/ProposalValidator.java b/core/src/main/java/bisq/core/dao/governance/proposal/ProposalValidator.java
@@ -114,7 +114,7 @@ private boolean isValid(Proposal proposal, boolean allowUnconfirmed) {
         if (isTxConfirmed) {
             int txHeight = optionalTx.get().getBlockHeight();
             if (!periodService.isTxInCorrectCycle(txHeight, chainHeight)) {
-                log.debug("Tx is not in current cycle. proposal.getTxId()={}", proposal.getTxId());
+                log.trace("Tx is not in current cycle. proposal.getTxId()={}", proposal.getTxId());
                 return false;
             }
             if (!periodService.isInPhase(txHeight, DaoPhase.Phase.PROPOSAL)) {

diff --git a/core/src/main/java/bisq/core/dao/monitoring/BlindVoteStateMonitoringService.java b/core/src/main/java/bisq/core/dao/monitoring/BlindVoteStateMonitoringService.java
@@ -157,7 +157,14 @@ public void onDaoStateChanged(Block block) {
                         System.currentTimeMillis() - ts);
             }
         }
-        maybeUpdateHashChain(blockHeight);
+
+        long ts = System.currentTimeMillis();
+        boolean updated = maybeUpdateHashChain(blockHeight);
+        if (updated) {
+            log.info("updateHashChain for block {} took {} ms",
+                    blockHeight,
+                    System.currentTimeMillis() - ts);
+        }
     }
 
     @SuppressWarnings("Duplicates")
@@ -241,11 +248,11 @@ public void removeListener(Listener listener) {
     // Private
     ///////////////////////////////////////////////////////////////////////////////////////////
 
-    private void maybeUpdateHashChain(int blockHeight) {
+    private boolean maybeUpdateHashChain(int blockHeight) {
         // We use first block in blind vote phase to create the hash of our blindVotes. We prefer to wait as long as
         // possible to increase the chance that we have received all blindVotes.
         if (!isFirstBlockOfBlindVotePhase(blockHeight)) {
-            return;
+            return false;
         }
 
         periodService.getCycle(blockHeight).ifPresent(cycle -> {
@@ -281,9 +288,12 @@ private void maybeUpdateHashChain(int blockHeight) {
                 UserThread.runAfter(() -> blindVoteStateNetworkService.broadcastMyStateHash(myBlindVoteStateHash), delayInSec);
             }
         });
+        return true;
     }
 
-    private boolean processPeersBlindVoteStateHash(BlindVoteStateHash blindVoteStateHash, Optional<NodeAddress> peersNodeAddress, boolean notifyListeners) {
+    private boolean processPeersBlindVoteStateHash(BlindVoteStateHash blindVoteStateHash,
+                                                   Optional<NodeAddress> peersNodeAddress,
+                                                   boolean notifyListeners) {
         AtomicBoolean changed = new AtomicBoolean(false);
         AtomicBoolean inConflictWithNonSeedNode = new AtomicBoolean(this.isInConflictWithNonSeedNode);
         AtomicBoolean inConflictWithSeedNode = new AtomicBoolean(this.isInConflictWithSeedNode);

diff --git a/core/src/main/java/bisq/core/dao/monitoring/DaoStateMonitoringService.java b/core/src/main/java/bisq/core/dao/monitoring/DaoStateMonitoringService.java
@@ -117,6 +117,8 @@ public interface Listener {
     );
     private boolean checkpointFailed;
     private boolean ignoreDevMsg;
+    private int numCalls;
+    private long accumulatedDuration;
 
     private final File storageDir;
 
@@ -176,6 +178,12 @@ public void onParseBlockChainComplete() {
         if (!ignoreDevMsg) {
             verifyCheckpoints();
         }
+
+        log.info("ParseBlockChainComplete: Accumulated updateHashChain() calls for {} block took {} ms " +
+                        "({} ms in average / block)",
+                numCalls,
+                accumulatedDuration,
+                (int) ((double) accumulatedDuration / (double) numCalls));
     }
 
     @Override
@@ -277,6 +285,7 @@ public void removeListener(Listener listener) {
     ///////////////////////////////////////////////////////////////////////////////////////////
 
     private void updateHashChain(Block block) {
+        long ts = System.currentTimeMillis();
         byte[] prevHash;
         int height = block.getHeight();
         if (daoStateBlockChain.isEmpty()) {
@@ -316,6 +325,13 @@ private void updateHashChain(Block block) {
             int delayInSec = 5 + new Random().nextInt(10);
             UserThread.runAfter(() -> daoStateNetworkService.broadcastMyStateHash(myDaoStateHash), delayInSec);
         }
+        long duration = System.currentTimeMillis() - ts;
+        // We don't want to spam the output. We log accumulated time after parsing is completed.
+        log.trace("updateHashChain for block {} took {} ms",
+                block.getHeight(),
+                duration);
+        accumulatedDuration += duration;
+        numCalls++;
     }
 
     private boolean processPeersDaoStateHash(DaoStateHash daoStateHash, Optional<NodeAddress> peersNodeAddress,

diff --git a/core/src/main/java/bisq/core/dao/monitoring/ProposalStateMonitoringService.java b/core/src/main/java/bisq/core/dao/monitoring/ProposalStateMonitoringService.java
@@ -160,7 +160,13 @@ public void onDaoStateChanged(Block block) {
                         System.currentTimeMillis() - ts);
             }
         }
-        maybeUpdateHashChain(blockHeight);
+        long ts = System.currentTimeMillis();
+        boolean updated = maybeUpdateHashChain(blockHeight);
+        if (updated) {
+            log.info("updateHashChain for block {} took {} ms",
+                    blockHeight,
+                    System.currentTimeMillis() - ts);
+        }
     }
 
     @SuppressWarnings("Duplicates")

diff --git a/core/src/main/java/bisq/core/dao/node/BsqNodeProvider.java b/core/src/main/java/bisq/core/dao/node/BsqNodeProvider.java
@@ -45,9 +45,10 @@ public BsqNodeProvider(LiteNode bsqLiteNode,
                 !preferences.getRpcPw().isEmpty() &&
                 preferences.getBlockNotifyPort() > 0;
         boolean daoFullNode = preferences.isDaoFullNode();
-        if (daoFullNode && !rpcDataSet)
-            log.warn("daoFullNode is set but RPC user and pw are missing");
-
+        if (daoFullNode && !rpcDataSet) {
+            log.warn("daoFullNode is set in preferences but RPC user and pw are missing. We reset daoFullNode in preferences to false.");
+            preferences.setDaoFullNode(false);
+        }
         bsqNode = daoFullNode && rpcDataSet ? bsqFullNode : bsqLiteNode;
     }
 }
diff --git a/core/src/main/java/bisq/core/dao/node/lite/LiteNode.java b/core/src/main/java/bisq/core/dao/node/lite/LiteNode.java
@@ -88,9 +88,6 @@ public void start() {
         liteNodeNetworkService.start();
 
         bsqWalletService.addNewBestBlockListener(block -> {
-            int height = block.getHeight();
-            log.info("New block at height {} from bsqWalletService", height);
-
             // Check if we are done with parsing
             if (!daoStateService.isParseBlockChainComplete())
                 return;
@@ -100,6 +97,9 @@ public void start() {
                 checkForBlockReceivedTimer.stop();
             }
 
+            int height = block.getHeight();
+            log.info("New block at height {} from bsqWalletService", height);
+
             // We expect to receive the new BSQ block from the network shortly after BitcoinJ has been aware of it.
             // If we don't receive it we request it manually from seed nodes
             checkForBlockReceivedTimer = UserThread.runAfter(() -> {

diff --git a/core/src/main/java/bisq/core/dao/node/lite/network/LiteNodeNetworkService.java b/core/src/main/java/bisq/core/dao/node/lite/network/LiteNodeNetworkService.java
@@ -143,6 +143,10 @@ public void addListener(Listener listener) {
         listeners.add(listener);
     }
 
+    /**
+     *
+     * @param startBlockHeight      Block height from where we expect new blocks (current block height in bsqState + 1)
+     */
     public void requestBlocks(int startBlockHeight) {
         lastRequestedBlockHeight = startBlockHeight;
         Optional<Connection> connectionToSeedNodeOptional = networkNode.getConfirmedConnections().stream()

diff --git a/core/src/main/java/bisq/core/dao/node/parser/BlockParser.java b/core/src/main/java/bisq/core/dao/node/parser/BlockParser.java
@@ -80,7 +80,7 @@ public BlockParser(TxParser txParser,
      */
     public Block parseBlock(RawBlock rawBlock) throws BlockHashNotConnectingException, BlockHeightNotConnectingException {
         int blockHeight = rawBlock.getHeight();
-        log.debug("Parse block at height={} ", blockHeight);
+        log.trace("Parse block at height={} ", blockHeight);
 
         validateIfBlockIsConnecting(rawBlock);
 

diff --git a/core/src/main/java/bisq/core/dao/node/parser/TxParser.java b/core/src/main/java/bisq/core/dao/node/parser/TxParser.java
@@ -385,7 +385,7 @@ static TxType evaluateTxType(TempTx tempTx, Optional<OpReturnType> optionalOpRet
         }
 
         // TRANSFER_BSQ has no fee, no opReturn and no UNLOCK_OUTPUT at first output
-        log.debug("No burned fee and no OP_RETURN, so this is a TRANSFER_BSQ tx.");
+        log.trace("No burned fee and no OP_RETURN, so this is a TRANSFER_BSQ tx.");
         return TxType.TRANSFER_BSQ;
     }
 

diff --git a/core/src/main/java/bisq/core/offer/Offer.java b/core/src/main/java/bisq/core/offer/Offer.java
@@ -187,7 +187,7 @@ public Price getPrice() {
                     return null;
                 }
             } else {
-                log.debug("We don't have a market price.\n" +
+                log.trace("We don't have a market price. " +
                         "That case could only happen if you don't have a price feed.");
                 return null;
             }

diff --git a/core/src/main/java/bisq/core/offer/OpenOfferManager.java b/core/src/main/java/bisq/core/offer/OpenOfferManager.java
@@ -196,15 +196,14 @@ public void shutDown(@Nullable Runnable completeHandler) {
         stopPeriodicRepublishOffersTimer();
         stopRetryRepublishOffersTimer();
 
-        log.debug("remove all open offers at shutDown");
+        log.info("Remove open offers at shutDown. Number of open offers: {}", openOffers.size());
         // we remove own offers from offerbook when we go offline
         // Normally we use a delay for broadcasting to the peers, but at shut down we want to get it fast out
-
-        final int size = openOffers != null ? openOffers.size() : 0;
+        int size = openOffers != null ? openOffers.size() : 0;
         if (offerBookService.isBootstrapped() && size > 0) {
             openOffers.forEach(openOffer -> offerBookService.removeOfferAtShutDown(openOffer.getOffer().getOfferPayload()));
             if (completeHandler != null)
-                UserThread.runAfter(completeHandler::run, size * 200 + 500, TimeUnit.MILLISECONDS);
+                UserThread.runAfter(completeHandler, size * 200 + 500, TimeUnit.MILLISECONDS);
         } else {
             if (completeHandler != null)
                 completeHandler.run();
@@ -223,7 +222,7 @@ public void removeOpenOffers(List<OpenOffer> openOffers, @Nullable Runnable comp
         }, errorMessage -> {
         }));
         if (completeHandler != null)
-            UserThread.runAfter(completeHandler::run, size * 200 + 500, TimeUnit.MILLISECONDS);
+            UserThread.runAfter(completeHandler, size * 200 + 500, TimeUnit.MILLISECONDS);
     }
 
 

diff --git a/core/src/main/java/bisq/core/provider/price/PriceRequest.java b/core/src/main/java/bisq/core/provider/price/PriceRequest.java
@@ -49,7 +49,7 @@ public SettableFuture<Tuple2<Map<String, Long>, Map<String, MarketPrice>>> reque
 
         Futures.addCallback(future, new FutureCallback<Tuple2<Map<String, Long>, Map<String, MarketPrice>>>() {
             public void onSuccess(Tuple2<Map<String, Long>, Map<String, MarketPrice>> marketPriceTuple) {
-                log.debug("Received marketPriceTuple of {}\nfrom provider {}", marketPriceTuple, provider);
+                log.trace("Received marketPriceTuple of {}\nfrom provider {}", marketPriceTuple, provider);
                 resultFuture.set(marketPriceTuple);
             }
 

diff --git a/core/src/main/java/bisq/core/trade/TradableList.java b/core/src/main/java/bisq/core/trade/TradableList.java
@@ -40,8 +40,6 @@
 import lombok.Getter;
 import lombok.extern.slf4j.Slf4j;
 
-import javax.annotation.Nullable;
-
 @Slf4j
 public final class TradableList<T extends Tradable> implements PersistableEnvelope {
     transient final private Storage<TradableList<T>> storage;
@@ -80,13 +78,10 @@ public Message toProtoMessage() {
                 .build();
     }
 
-    @Nullable
     public static TradableList fromProto(protobuf.TradableList proto,
                                          CoreProtoResolver coreProtoResolver,
                                          Storage<TradableList<Tradable>> storage,
                                          BtcWalletService btcWalletService) {
-        log.debug("TradableList fromProto of {} ", proto);
-
         List<Tradable> list = proto.getTradableList().stream()
                 .map(tradable -> {
                     switch (tradable.getMessageCase()) {

diff --git a/core/src/main/java/bisq/core/trade/statistics/AssetTradeActivityCheck.java b/core/src/main/java/bisq/core/trade/statistics/AssetTradeActivityCheck.java
@@ -141,7 +141,7 @@ public void onAllServicesInitialized() {
                 "\n\n" + newAssets.toString() +
                 "\n\n" + sufficientlyTraded.toString();
         // Utilities.copyToClipboard(result);
-        log.debug(result);
+        log.trace(result);
     }
 
     private boolean isWarmingUp(String code) {

diff --git a/core/src/main/java/bisq/core/trade/statistics/TradeStatisticsManager.java b/core/src/main/java/bisq/core/trade/statistics/TradeStatisticsManager.java
@@ -170,7 +170,7 @@ private void addToMap(TradeStatistics2 tradeStatistics, boolean storeLocally) {
     private void addToMap(TradeStatistics2 tradeStatistics, Map<String, TradeStatistics2> map) {
         TradeStatistics2 prevValue = map.putIfAbsent(tradeStatistics.getOfferId(), tradeStatistics);
         if (prevValue != null)
-            log.debug("We have already an item with the same offer ID. That might happen if both the maker and the taker published the tradeStatistics");
+            log.trace("We have already an item with the same offer ID. That might happen if both the maker and the taker published the tradeStatistics");
     }
 
     private void dump() {

diff --git a/p2p/src/main/java/bisq/network/p2p/P2PService.java b/p2p/src/main/java/bisq/network/p2p/P2PService.java
@@ -537,7 +537,7 @@ private void processMailboxEntry(ProtectedMailboxStorageEntry protectedMailboxSt
                     log.error("Protobuffer data could not be processed: {}", e.toString());
                 }
             } else {
-                log.debug("Wrong blurredAddressHash. The message is not intended for us.");
+                log.trace("Wrong blurredAddressHash. The message is not intended for us.");
             }
         }
     }

diff --git a/p2p/src/main/java/bisq/network/p2p/network/Connection.java b/p2p/src/main/java/bisq/network/p2p/network/Connection.java
@@ -247,7 +247,7 @@ public void sendMessage(NetworkEnvelope networkEnvelope) {
                     String peersNodeAddress = peersNodeAddressOptional.map(NodeAddress::toString).orElse("null");
 
                     protobuf.NetworkEnvelope proto = networkEnvelope.toProtoNetworkEnvelope();
-                    log.debug("Sending message: {}", Utilities.toTruncatedString(proto.toString(), 10000));
+                    log.trace("Sending message: {}", Utilities.toTruncatedString(proto.toString(), 10000));
 
                     if (networkEnvelope instanceof Ping | networkEnvelope instanceof RefreshOfferMessage) {
                         // pings and offer refresh msg we don't want to log in production

diff --git a/p2p/src/main/java/bisq/network/p2p/peers/PeerManager.java b/p2p/src/main/java/bisq/network/p2p/peers/PeerManager.java
@@ -483,7 +483,7 @@ private void printReportedPeers() {
                 List<Peer> reportedPeersClone = new ArrayList<>(reportedPeers);
                 reportedPeersClone.stream().forEach(e -> result.append("\n").append(e));
                 result.append("\n------------------------------------------------------------\n");
-                log.debug(result.toString());
+                log.trace(result.toString());
             }
             log.debug("Number of reported peers: {}", reportedPeers.size());
         }
@@ -495,7 +495,7 @@ private void printNewReportedPeers(Set<Peer> reportedPeers) {
             StringBuilder result = new StringBuilder("We received new reportedPeers:");
             List<Peer> reportedPeersClone = new ArrayList<>(reportedPeers);
             reportedPeersClone.stream().forEach(e -> result.append("\n\t").append(e));
-            log.debug(result.toString());
+            log.trace(result.toString());
         }
         log.debug("Number of new arrived reported peers: {}", reportedPeers.size());
     }