Merge pull request #263 from input-output-hk/feature/loggingUpdates

Logging update

Author: LukasGasior1

src/main/resources/application.conf

@@ -260,7 +260,7 @@ grothendieck {
     peer-response-timeout = 3.minutes
 
     # Interval for logging syncing status info
-    print-status-interval = 2.seconds
+    print-status-interval = 30.seconds
 
     # How often to dump fast-sync status to disk. If the client is restarted, fast-sync will continue from this point
     persist-state-snapshot-interval = 1.minute
@@ -349,4 +349,5 @@ akka {
   loglevel = "DEBUG"
   logging-filter = "akka.event.slf4j.Slf4jLoggingFilter"
   logger-startup-timeout = 30s
+  log-dead-letters = off
 }

src/main/resources/logback.xml

@@ -1,6 +1,6 @@
 <configuration>
 
-    <property name="stdoutEncoderPattern" value="%d{HH:mm:ss.SSS} %logger{36} - %msg%n" />
+    <property name="stdoutEncoderPattern" value="%d{HH:mm:ss} %msg%n" />
     <property name="fileEncoderPattern" value="%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %X{akkaSource} - %msg%n" />
 
     <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">

src/main/scala/io/iohk/ethereum/blockchain/data/GenesisDataLoader.scala

@@ -41,15 +41,15 @@ class GenesisDataLoader(
   private val emptyEvmHash: ByteString = crypto.kec256(ByteString.empty)
 
   def loadGenesisData(): Unit = {
-    log.info("Loading genesis data")
+    log.debug("Loading genesis data")
 
     val genesisJson = blockchainConfig.customGenesisFileOpt match {
       case Some(customGenesisFile) =>
         log.debug(s"Trying to load custom genesis data from file: $customGenesisFile")
 
         Try(Source.fromFile(customGenesisFile)).recoverWith { case _: FileNotFoundException =>
-          log.info(s"Cannot load custom genesis data from file: $customGenesisFile")
-          log.info(s"Trying to load from resources: $customGenesisFile")
+          log.debug(s"Cannot load custom genesis data from file: $customGenesisFile")
+          log.debug(s"Trying to load from resources: $customGenesisFile")
           Try(Source.fromResource(customGenesisFile))
         } match {
           case Success(customGenesis) =>
@@ -64,6 +64,7 @@ class GenesisDataLoader(
             throw ex
         }
       case None =>
+        log.info(s"Using default genesis data")
         val src = Source.fromResource("blockchain/default-genesis.json")
         try {
           src.getLines().mkString
@@ -127,7 +128,7 @@ class GenesisDataLoader(
 
     blockchain.getBlockHeaderByNumber(0) match {
       case Some(existingGenesisHeader) if existingGenesisHeader.hash == header.hash =>
-        log.info("Genesis data already in the database")
+        log.debug("Genesis data already in the database")
         Success(())
       case Some(_) =>
         Failure(new RuntimeException("Genesis data present in the database does not match genesis block from file." +

src/main/scala/io/iohk/ethereum/blockchain/sync/BlacklistSupport.scala

@@ -16,7 +16,7 @@ trait BlacklistSupport {
 
   def blacklist(peerId: PeerId, duration: FiniteDuration, reason: String): Unit = {
     undoBlacklist(peerId)
-    log.info(s"Blacklisting peer ($peerId), $reason")
+    log.debug(s"Blacklisting peer ($peerId), $reason")
     val unblacklistCancellable = scheduler.scheduleOnce(duration, self, UnblacklistPeer(peerId))
     blacklistedPeers :+= (peerId, unblacklistCancellable)
   }

src/main/scala/io/iohk/ethereum/blockchain/sync/FastSync.scala

@@ -5,7 +5,7 @@ import scala.concurrent.ExecutionContext.Implicits.global
 import akka.actor._
 import akka.util.ByteString
 import io.iohk.ethereum.domain.BlockHeader
-import io.iohk.ethereum.network.{EtcPeerManagerActor, Peer}
+import io.iohk.ethereum.network.{EtcPeerManagerActor, Peer, PeerActor}
 import io.iohk.ethereum.network.PeerEventBusActor.PeerEvent.MessageFromPeer
 import io.iohk.ethereum.network.PeerEventBusActor.{PeerSelector, Subscribe, Unsubscribe}
 import io.iohk.ethereum.network.PeerEventBusActor.SubscriptionClassifier.MessageClassifier
@@ -20,7 +20,7 @@ trait FastSync {
   import SyncController._
 
   def startFastSync(): Unit = {
-    log.info("Starting fast sync")
+    log.info("Trying to start block synchronization (fast mode)")
     fastSyncStateStorage.getSyncState() match {
       case Some(syncState) => startFastSync(syncState)
       case None => startFastSyncFromScratch()
@@ -44,11 +44,12 @@ trait FastSync {
         peerEventBus ! Subscribe(MessageClassifier(Set(BlockHeaders.code), PeerSelector.WithId(peer.id)))
         etcPeerManager ! EtcPeerManagerActor.SendMessage(GetBlockHeaders(Right(status.bestHash), 1, 0, reverse = false), peer.id)
       }
-      log.info("Asking {} peers for block headers", peersUsedToChooseTarget.size)
+      log.debug("Asking {} peers for block headers", peersUsedToChooseTarget.size)
       val timeout = scheduler.scheduleOnce(peerResponseTimeout, self, BlockHeadersTimeout)
       context become waitingForBlockHeaders(peersUsedToChooseTarget.keySet, Map.empty, timeout)
     } else {
-      log.warning("Cannot start fast sync, not enough peers to download from. Scheduling retry in {}", startRetryInterval)
+      log.info("Block synchronization (fast mode) not started. Need at least {} peers, but there are only {} available at the moment. Retrying in {}",
+        minPeersToChooseTargetBlock, peersUsedToChooseTarget.size, startRetryInterval)
       scheduleStartRetry(startRetryInterval)
       context become startingFastSync
     }
@@ -87,18 +88,18 @@ trait FastSync {
   }
 
   private def tryStartFastSync(receivedHeaders: Map[Peer, BlockHeader]): Unit = {
-    log.info("Trying to start fast sync. Received {} block headers", receivedHeaders.size)
+    log.debug("Trying to start fast sync. Received {} block headers", receivedHeaders.size)
     if (receivedHeaders.size >= minPeersToChooseTargetBlock) {
       val (mostUpToDatePeer, mostUpToDateBlockHeader) = receivedHeaders.maxBy(_._2.number)
       val targetBlock = mostUpToDateBlockHeader.number - targetBlockOffset
 
       if (targetBlock < 1) {
-        log.info("Target block is less than 1, starting regular sync")
+        log.debug("Target block is less than 1, starting regular sync")
         appStateStorage.fastSyncDone()
         context become idle
         self ! FastSyncDone
       } else {
-        log.info("Starting fast sync. Asking peer {} for target block header ({})", mostUpToDatePeer.id, targetBlock)
+        log.debug("Starting fast sync. Asking peer {} for target block header ({})", mostUpToDatePeer.id, targetBlock)
 
         peerEventBus ! Subscribe(MessageClassifier(Set(BlockHeaders.code), PeerSelector.WithId(mostUpToDatePeer.id)))
         etcPeerManager ! EtcPeerManagerActor.SendMessage(GetBlockHeaders(Left(targetBlock), 1, 0, reverse = false), mostUpToDatePeer.id)
@@ -107,7 +108,8 @@ trait FastSync {
       }
 
     } else {
-      log.info("Did not receive enough status block headers to start fast sync. Retry in {}", startRetryInterval)
+      log.info("Block synchronization (fast mode) not started. Need to receive block headers from at least {} peers, but received only from {}. Retrying in {}",
+        minPeersToChooseTargetBlock, receivedHeaders.size, startRetryInterval)
       scheduleStartRetry(startRetryInterval)
       context become startingFastSync
     }
@@ -123,19 +125,21 @@ trait FastSync {
       val targetBlockHeaderOpt = blockHeaders.headers.find(header => header.number == targetBlockNumber)
       targetBlockHeaderOpt match {
         case Some(targetBlockHeader) =>
-          log.info("Received target block from peer, starting fast sync")
+          log.info("Starting block synchronization (fast mode)")
           val initialSyncState = SyncState(targetBlockHeader,
             mptNodesQueue = Seq(StateMptNodeHash(targetBlockHeader.stateRoot)))
           startFastSync(initialSyncState)
 
         case None =>
-          blacklist(peer.id, blacklistDuration,s"did not respond with target block header, blacklisting and scheduling retry in $startRetryInterval")
+          blacklist(peer.id, blacklistDuration, s"did not respond with target block header, blacklisting and scheduling retry in $startRetryInterval")
+          log.info("Block synchronization (fast mode) not started. Target block header not received. Retrying in {}", startRetryInterval)
           scheduleStartRetry(startRetryInterval)
           context become startingFastSync
       }
 
     case TargetBlockTimeout =>
       blacklist(peer.id, blacklistDuration, s"did not respond with target block header (timeout), blacklisting and scheduling retry in $startRetryInterval")
+      log.info("Block synchronization (fast mode) not started. Target block header receive timeout. Retrying in {}", startRetryInterval)
       peerEventBus ! Unsubscribe(MessageClassifier(Set(BlockHeaders.code), PeerSelector.WithId(peer.id)))
       scheduleStartRetry(startRetryInterval)
       context become startingFastSync
@@ -288,12 +292,12 @@ trait FastSync {
         finishFastSync()
       } else {
         if (anythingToDownload) processDownloads()
-        else log.info("No more items to request, waiting for {} responses", assignedHandlers.size)
+        else log.debug("No more items to request, waiting for {} responses", assignedHandlers.size)
       }
     }
 
     def finishFastSync(): Unit = {
-      log.info("Fast sync finished")
+      log.info("Block synchronization in fast mode finished, switching to regular mode")
       cleanup()
       appStateStorage.fastSyncDone()
       context become idle
@@ -310,9 +314,9 @@ trait FastSync {
     def processDownloads(): Unit = {
       if (unassignedPeers.isEmpty) {
         if (assignedHandlers.nonEmpty) {
-          log.warning("There are no available peers, waiting for responses")
+          log.debug("There are no available peers, waiting for responses")
         } else {
-          log.warning("There are no peers to download from, scheduling a retry in {}", syncRetryInterval)
+          log.debug("There are no peers to download from, scheduling a retry in {}", syncRetryInterval)
           scheduler.scheduleOnce(syncRetryInterval, self, ProcessSyncing)
         }
       } else {

src/main/scala/io/iohk/ethereum/blockchain/sync/RegularSync.scala

@@ -27,7 +27,7 @@ trait RegularSync extends BlockBroadcast {
   import Config.Sync._
 
   def startRegularSync(): Unit = {
-    log.info("Starting regular sync")
+    log.info("Starting block synchronization")
     appStateStorage.fastSyncDone()
     context become (handlePeerUpdates orElse regularSync())
     askForHeaders()
@@ -60,14 +60,14 @@ trait RegularSync extends BlockBroadcast {
             //just insert block and let resolve it with regular download
             insertMinedBlock(block, parentTd)
           case _ =>
-            log.error("fail to add mined block")
+            log.error("Failed to add mined block")
         }
       } else {
         ommersPool ! AddOmmers(block.header)
       }
 
     case PrintStatus =>
-      log.info(s"Peers: ${handshakedPeers.size} (${blacklistedPeers.size} blacklisted).")
+      log.info(s"Block: ${appStateStorage.getBestBlockNumber()}. Peers: ${handshakedPeers.size} (${blacklistedPeers.size} blacklisted)")
 
     case Done =>
       if (waitingForActor == Option(sender())) {
@@ -92,9 +92,9 @@ trait RegularSync extends BlockBroadcast {
         ommersPool ! new RemoveOmmers((block.header +: block.body.uncleNodesList).toList)
         pendingTransactionsManager ! PendingTransactionsManager.RemoveTransactions(block.body.transactionList)
 
-        log.info(s"added new block $block")
+        log.debug(s"Added new block $block")
       case Left(err) =>
-        log.info(s"fail to execute mined block because of $err")
+        log.warning(s"Failed to execute mined block because of $err")
     }
   }
 
@@ -106,7 +106,7 @@ trait RegularSync extends BlockBroadcast {
         waitingForActor = Some(context.actorOf(
           SyncBlockHeadersRequestHandler.props(peer, etcPeerManager, peerEventBus, request, resolveBranches = false)))
       case None =>
-        log.warning("no peers to download from")
+        log.debug("No peers to download from")
         scheduleResume()
     }
   }
@@ -160,7 +160,7 @@ trait RegularSync extends BlockBroadcast {
             SyncBlockHeadersRequestHandler.props(peer, etcPeerManager, peerEventBus, request, resolveBranches = true)))
         }
       case _ =>
-        log.warning("got header that does not have parent")
+        log.debug("Got block header that does not have parent")
         resumeWithDifferentPeer(peer)
     }
   }
@@ -183,7 +183,7 @@ trait RegularSync extends BlockBroadcast {
 
           if(newBlocks.nonEmpty){
             broadcastNewBlocks(newBlocks, handshakedPeers)
-            log.info(s"got new blocks up till block: ${newBlocks.last.block.header.number} " +
+            log.debug(s"got new blocks up till block: ${newBlocks.last.block.header.number} " +
               s"with hash ${Hex.toHexString(newBlocks.last.block.header.hash.toArray[Byte])}")
           }
 

src/main/scala/io/iohk/ethereum/network/EtcPeerManagerActor.scala

@@ -153,10 +153,10 @@ class EtcPeerManagerActor(peerManagerActor: ActorRef, peerEventBusActor: ActorRe
           forkBlockHeader <- blockHeaders.find(_.number == forkResolver.forkBlockNumber)
         } yield {
           val newFork = forkResolver.recognizeFork(forkBlockHeader)
-          log.info("Received fork block header with fork: {}", newFork)
+          log.debug("Received fork block header with fork: {}", newFork)
 
           if (!forkResolver.isAccepted(newFork)) {
-            log.warning("Peer is not running the accepted fork, disconnecting")
+            log.debug("Peer is not running the accepted fork, disconnecting")
             peer.ref ! DisconnectPeer(Disconnect.Reasons.UselessPeer)
             initialPeerInfo
           } else

src/main/scala/io/iohk/ethereum/network/PeerActor.scala

@@ -5,6 +5,7 @@ import java.net.{InetSocketAddress, URI}
 import io.iohk.ethereum.network.PeerManagerActor.PeerConfiguration
 import akka.actor._
 import akka.agent.Agent
+import akka.util.ByteString
 import io.iohk.ethereum.network.p2p._
 import io.iohk.ethereum.network.p2p.messages.WireProtocol._
 import io.iohk.ethereum.network.p2p.messages.Versions
@@ -78,17 +79,17 @@ class PeerActor[R <: HandshakeResult](
         processHandshakerNextMessage(initHandshaker, rlpxConnection.copy(uriOpt = Some(uri)), numRetries)
 
       case RLPxConnectionHandler.ConnectionFailed =>
-        log.warning("Failed to establish RLPx connection")
+        log.debug("Failed to establish RLPx connection")
         rlpxConnection.uriOpt match {
           case Some(uri) if numRetries < peerConfiguration.connectMaxRetries =>
             context unwatch rlpxConnection.ref
             scheduleConnectRetry(uri, numRetries)
           case Some(uri) =>
-            log.warning("No more reconnect attempts left, removing peer")
+            log.debug("No more reconnect attempts left, removing peer")
             knownNodesManager ! KnownNodesManager.RemoveKnownNode(uri)
             context stop self
           case None =>
-            log.warning("Connection was initiated by remote peer, not attempting to reconnect")
+            log.debug("Connection was initiated by remote peer, not attempting to reconnect")
             context stop self
         }
 
@@ -148,7 +149,7 @@ class PeerActor[R <: HandshakeResult](
     }
 
   private def scheduleConnectRetry(uri: URI, numRetries: Int): Unit = {
-    log.info("Scheduling connection retry in {}", peerConfiguration.connectRetryDelay)
+    log.debug("Scheduling connection retry in {}", peerConfiguration.connectRetryDelay)
     scheduler.scheduleOnce(peerConfiguration.connectRetryDelay, self, RetryConnectionTimeout)
     context become {
       case RetryConnectionTimeout => reconnect(uri, numRetries + 1)
@@ -169,7 +170,7 @@ class PeerActor[R <: HandshakeResult](
 
   def handleTerminated(rlpxConnection: RLPxConnection): Receive = {
     case Terminated(actor) if actor == rlpxConnection.ref =>
-      log.warning(s"Underlying rlpx connection with peer $peerId closed")
+      log.debug(s"Underlying rlpx connection with peer $peerId closed")
       rlpxConnection.uriOpt match {
         case Some(uri) if rlpxConnection.isInitiator => scheduleConnectRetry(uri, numRetries = 0)
         case Some(uri) =>
@@ -181,7 +182,7 @@ class PeerActor[R <: HandshakeResult](
   }
 
   def reconnect(uri: URI, numRetries: Int): Unit = {
-    log.info("Trying to reconnect")
+    log.debug("Trying to reconnect")
     val address = new InetSocketAddress(uri.getHost, uri.getPort)
     val newConnection = createRlpxConnection(address, Some(uri), true)
     newConnection.ref ! RLPxConnectionHandler.ConnectTo(uri)
@@ -200,7 +201,7 @@ class PeerActor[R <: HandshakeResult](
           rlpxConnection.uriOpt.foreach(uri => knownNodesManager ! KnownNodesManager.RemoveKnownNode(uri))
         case _ => // nothing
       }
-      log.info(s"Received {}. Closing connection with peer ${peerAddress.getHostString}:${peerAddress.getPort}", d)
+      log.debug(s"Received {}. Closing connection with peer ${peerAddress.getHostString}:${peerAddress.getPort}", d)
       context unwatch rlpxConnection.ref
       context stop self
   }

src/main/scala/io/iohk/ethereum/network/PeerManagerActor.scala

@@ -70,7 +70,7 @@ class PeerManagerActor(
       val nodesToConnect = nodes.take(peerConfiguration.maxPeers)
 
       if (nodesToConnect.nonEmpty) {
-        log.info("Trying to connect to {} known nodes", nodesToConnect.size)
+        log.debug("Trying to connect to {} known nodes", nodesToConnect.size)
         nodesToConnect.foreach(n => self ! ConnectToPeer(n))
       }
 
@@ -93,7 +93,7 @@ class PeerManagerActor(
         s"Trying to connect to ${nodesToConnect.size} more nodes.")
 
       if (nodesToConnect.nonEmpty) {
-        log.info("Trying to connect to {} nodes", nodesToConnect.size)
+        log.debug("Trying to connect to {} nodes", nodesToConnect.size)
         nodesToConnect.foreach(n => self ! ConnectToPeer(n.toUri))
       }
   }
@@ -105,10 +105,10 @@ class PeerManagerActor(
 
       if (incomingPeers.size > peerConfiguration.maxIncomingPeers) {
         peer.ref ! PeerActor.DisconnectPeer(Disconnect.Reasons.TooManyPeers)
-        log.info("Maximum number of incoming peer connections reached.")
+        log.debug("Maximum number of incoming peer connections reached.")
       }
     } else {
-      log.info("Another connection with {} is already opened. Disconnecting.", remoteAddress)
+      log.debug("Another connection with {} is already opened. Disconnecting.", remoteAddress)
       connection ! PoisonPill
     }
   }
@@ -120,10 +120,10 @@ class PeerManagerActor(
         val peer = createPeer(addr, incomingConnection = false)
         peer.ref ! PeerActor.ConnectTo(uri)
       } else {
-        log.info("Maximum number of connected peers reached.")
+        log.debug("Maximum number of connected peers reached.")
       }
     } else {
-      log.info("Maximum number of connected peers reached. Not connecting to {}", uri)
+      log.debug("Maximum number of connected peers reached. Not connecting to {}", uri)
     }
   }
 

src/main/scala/io/iohk/ethereum/network/handshaker/EtcForkBlockExchangeState.scala

@@ -30,19 +30,19 @@ case class EtcForkBlockExchangeState(handshakerConfiguration: EtcHandshakerConfi
         case Some(forkBlockHeader) =>
           val fork = forkResolver.recognizeFork(forkBlockHeader)
 
-          log.info("Peer is running the {} fork", fork)
+          log.debug("Peer is running the {} fork", fork)
 
           if (forkResolver.isAccepted(fork)) {
-            log.info("Fork is accepted")
+            log.debug("Fork is accepted")
             val peerInfo: PeerInfo = PeerInfo(remoteStatus, remoteStatus.totalDifficulty, true, forkBlockHeader.number)
             ConnectedState(peerInfo)
           } else {
-            log.warn("Fork is not accepted")
+            log.debug("Fork is not accepted")
             DisconnectedState[PeerInfo](Disconnect.Reasons.UselessPeer)
           }
 
         case None =>
-          log.info("Peer did not respond with fork block header")
+          log.debug("Peer did not respond with fork block header")
           ConnectedState(PeerInfo(remoteStatus, remoteStatus.totalDifficulty, false, 0))
       }