Skip to content

Commit 88833e3

Browse files
LukasGasior1LukasGasior1
authored
Merge pull request #263 from input-output-hk/feature/loggingUpdates
Logging update
2 parents ee51b10 + 0c5bc5e commit 88833e3

14 files changed

+72
-72
lines changed

‎src/main/resources/application.conf

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -260,7 +260,7 @@ grothendieck {
260260
peer-response-timeout = 3.minutes
261261

262262
# Interval for logging syncing status info
263-
print-status-interval = 2.seconds
263+
print-status-interval = 30.seconds
264264

265265
# How often to dump fast-sync status to disk. If the client is restarted, fast-sync will continue from this point
266266
persist-state-snapshot-interval = 1.minute
@@ -349,4 +349,5 @@ akka {
349349
loglevel = "DEBUG"
350350
logging-filter = "akka.event.slf4j.Slf4jLoggingFilter"
351351
logger-startup-timeout = 30s
352+
log-dead-letters = off
352353
}

‎src/main/resources/logback.xml

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,6 @@
11
<configuration>
22

3-
<property name="stdoutEncoderPattern" value="%d{HH:mm:ss.SSS} %logger{36} - %msg%n" />
3+
<property name="stdoutEncoderPattern" value="%d{HH:mm:ss} %msg%n" />
44
<property name="fileEncoderPattern" value="%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %X{akkaSource} - %msg%n" />
55

66
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">

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

Lines changed: 5 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -41,15 +41,15 @@ class GenesisDataLoader(
4141
private val emptyEvmHash: ByteString = crypto.kec256(ByteString.empty)
4242

4343
def loadGenesisData(): Unit = {
44-
log.info("Loading genesis data")
44+
log.debug("Loading genesis data")
4545

4646
val genesisJson = blockchainConfig.customGenesisFileOpt match {
4747
case Some(customGenesisFile) =>
4848
log.debug(s"Trying to load custom genesis data from file: $customGenesisFile")
4949

5050
Try(Source.fromFile(customGenesisFile)).recoverWith { case _: FileNotFoundException =>
51-
log.info(s"Cannot load custom genesis data from file: $customGenesisFile")
52-
log.info(s"Trying to load from resources: $customGenesisFile")
51+
log.debug(s"Cannot load custom genesis data from file: $customGenesisFile")
52+
log.debug(s"Trying to load from resources: $customGenesisFile")
5353
Try(Source.fromResource(customGenesisFile))
5454
} match {
5555
case Success(customGenesis) =>
@@ -64,6 +64,7 @@ class GenesisDataLoader(
6464
throw ex
6565
}
6666
case None =>
67+
log.info(s"Using default genesis data")
6768
val src = Source.fromResource("blockchain/default-genesis.json")
6869
try {
6970
src.getLines().mkString
@@ -127,7 +128,7 @@ class GenesisDataLoader(
127128

128129
blockchain.getBlockHeaderByNumber(0) match {
129130
case Some(existingGenesisHeader) if existingGenesisHeader.hash == header.hash =>
130-
log.info("Genesis data already in the database")
131+
log.debug("Genesis data already in the database")
131132
Success(())
132133
case Some(_) =>
133134
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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -16,7 +16,7 @@ trait BlacklistSupport {
1616

1717
def blacklist(peerId: PeerId, duration: FiniteDuration, reason: String): Unit = {
1818
undoBlacklist(peerId)
19-
log.info(s"Blacklisting peer ($peerId), $reason")
19+
log.debug(s"Blacklisting peer ($peerId), $reason")
2020
val unblacklistCancellable = scheduler.scheduleOnce(duration, self, UnblacklistPeer(peerId))
2121
blacklistedPeers :+= (peerId, unblacklistCancellable)
2222
}

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

Lines changed: 18 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@ import scala.concurrent.ExecutionContext.Implicits.global
55
import akka.actor._
66
import akka.util.ByteString
77
import io.iohk.ethereum.domain.BlockHeader
8-
import io.iohk.ethereum.network.{EtcPeerManagerActor, Peer}
8+
import io.iohk.ethereum.network.{EtcPeerManagerActor, Peer, PeerActor}
99
import io.iohk.ethereum.network.PeerEventBusActor.PeerEvent.MessageFromPeer
1010
import io.iohk.ethereum.network.PeerEventBusActor.{PeerSelector, Subscribe, Unsubscribe}
1111
import io.iohk.ethereum.network.PeerEventBusActor.SubscriptionClassifier.MessageClassifier
@@ -20,7 +20,7 @@ trait FastSync {
2020
import SyncController._
2121

2222
def startFastSync(): Unit = {
23-
log.info("Starting fast sync")
23+
log.info("Trying to start block synchronization (fast mode)")
2424
fastSyncStateStorage.getSyncState() match {
2525
case Some(syncState) => startFastSync(syncState)
2626
case None => startFastSyncFromScratch()
@@ -44,11 +44,12 @@ trait FastSync {
4444
peerEventBus ! Subscribe(MessageClassifier(Set(BlockHeaders.code), PeerSelector.WithId(peer.id)))
4545
etcPeerManager ! EtcPeerManagerActor.SendMessage(GetBlockHeaders(Right(status.bestHash), 1, 0, reverse = false), peer.id)
4646
}
47-
log.info("Asking {} peers for block headers", peersUsedToChooseTarget.size)
47+
log.debug("Asking {} peers for block headers", peersUsedToChooseTarget.size)
4848
val timeout = scheduler.scheduleOnce(peerResponseTimeout, self, BlockHeadersTimeout)
4949
context become waitingForBlockHeaders(peersUsedToChooseTarget.keySet, Map.empty, timeout)
5050
} else {
51-
log.warning("Cannot start fast sync, not enough peers to download from. Scheduling retry in {}", startRetryInterval)
51+
log.info("Block synchronization (fast mode) not started. Need at least {} peers, but there are only {} available at the moment. Retrying in {}",
52+
minPeersToChooseTargetBlock, peersUsedToChooseTarget.size, startRetryInterval)
5253
scheduleStartRetry(startRetryInterval)
5354
context become startingFastSync
5455
}
@@ -87,18 +88,18 @@ trait FastSync {
8788
}
8889

8990
private def tryStartFastSync(receivedHeaders: Map[Peer, BlockHeader]): Unit = {
90-
log.info("Trying to start fast sync. Received {} block headers", receivedHeaders.size)
91+
log.debug("Trying to start fast sync. Received {} block headers", receivedHeaders.size)
9192
if (receivedHeaders.size >= minPeersToChooseTargetBlock) {
9293
val (mostUpToDatePeer, mostUpToDateBlockHeader) = receivedHeaders.maxBy(_._2.number)
9394
val targetBlock = mostUpToDateBlockHeader.number - targetBlockOffset
9495

9596
if (targetBlock < 1) {
96-
log.info("Target block is less than 1, starting regular sync")
97+
log.debug("Target block is less than 1, starting regular sync")
9798
appStateStorage.fastSyncDone()
9899
context become idle
99100
self ! FastSyncDone
100101
} else {
101-
log.info("Starting fast sync. Asking peer {} for target block header ({})", mostUpToDatePeer.id, targetBlock)
102+
log.debug("Starting fast sync. Asking peer {} for target block header ({})", mostUpToDatePeer.id, targetBlock)
102103

103104
peerEventBus ! Subscribe(MessageClassifier(Set(BlockHeaders.code), PeerSelector.WithId(mostUpToDatePeer.id)))
104105
etcPeerManager ! EtcPeerManagerActor.SendMessage(GetBlockHeaders(Left(targetBlock), 1, 0, reverse = false), mostUpToDatePeer.id)
@@ -107,7 +108,8 @@ trait FastSync {
107108
}
108109

109110
} else {
110-
log.info("Did not receive enough status block headers to start fast sync. Retry in {}", startRetryInterval)
111+
log.info("Block synchronization (fast mode) not started. Need to receive block headers from at least {} peers, but received only from {}. Retrying in {}",
112+
minPeersToChooseTargetBlock, receivedHeaders.size, startRetryInterval)
111113
scheduleStartRetry(startRetryInterval)
112114
context become startingFastSync
113115
}
@@ -123,19 +125,21 @@ trait FastSync {
123125
val targetBlockHeaderOpt = blockHeaders.headers.find(header => header.number == targetBlockNumber)
124126
targetBlockHeaderOpt match {
125127
case Some(targetBlockHeader) =>
126-
log.info("Received target block from peer, starting fast sync")
128+
log.info("Starting block synchronization (fast mode)")
127129
val initialSyncState = SyncState(targetBlockHeader,
128130
mptNodesQueue = Seq(StateMptNodeHash(targetBlockHeader.stateRoot)))
129131
startFastSync(initialSyncState)
130132

131133
case None =>
132-
blacklist(peer.id, blacklistDuration,s"did not respond with target block header, blacklisting and scheduling retry in $startRetryInterval")
134+
blacklist(peer.id, blacklistDuration, s"did not respond with target block header, blacklisting and scheduling retry in $startRetryInterval")
135+
log.info("Block synchronization (fast mode) not started. Target block header not received. Retrying in {}", startRetryInterval)
133136
scheduleStartRetry(startRetryInterval)
134137
context become startingFastSync
135138
}
136139

137140
case TargetBlockTimeout =>
138141
blacklist(peer.id, blacklistDuration, s"did not respond with target block header (timeout), blacklisting and scheduling retry in $startRetryInterval")
142+
log.info("Block synchronization (fast mode) not started. Target block header receive timeout. Retrying in {}", startRetryInterval)
139143
peerEventBus ! Unsubscribe(MessageClassifier(Set(BlockHeaders.code), PeerSelector.WithId(peer.id)))
140144
scheduleStartRetry(startRetryInterval)
141145
context become startingFastSync
@@ -288,12 +292,12 @@ trait FastSync {
288292
finishFastSync()
289293
} else {
290294
if (anythingToDownload) processDownloads()
291-
else log.info("No more items to request, waiting for {} responses", assignedHandlers.size)
295+
else log.debug("No more items to request, waiting for {} responses", assignedHandlers.size)
292296
}
293297
}
294298

295299
def finishFastSync(): Unit = {
296-
log.info("Fast sync finished")
300+
log.info("Block synchronization in fast mode finished, switching to regular mode")
297301
cleanup()
298302
appStateStorage.fastSyncDone()
299303
context become idle
@@ -310,9 +314,9 @@ trait FastSync {
310314
def processDownloads(): Unit = {
311315
if (unassignedPeers.isEmpty) {
312316
if (assignedHandlers.nonEmpty) {
313-
log.warning("There are no available peers, waiting for responses")
317+
log.debug("There are no available peers, waiting for responses")
314318
} else {
315-
log.warning("There are no peers to download from, scheduling a retry in {}", syncRetryInterval)
319+
log.debug("There are no peers to download from, scheduling a retry in {}", syncRetryInterval)
316320
scheduler.scheduleOnce(syncRetryInterval, self, ProcessSyncing)
317321
}
318322
} else {

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

Lines changed: 8 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -27,7 +27,7 @@ trait RegularSync extends BlockBroadcast {
2727
import Config.Sync._
2828

2929
def startRegularSync(): Unit = {
30-
log.info("Starting regular sync")
30+
log.info("Starting block synchronization")
3131
appStateStorage.fastSyncDone()
3232
context become (handlePeerUpdates orElse regularSync())
3333
askForHeaders()
@@ -60,14 +60,14 @@ trait RegularSync extends BlockBroadcast {
6060
//just insert block and let resolve it with regular download
6161
insertMinedBlock(block, parentTd)
6262
case _ =>
63-
log.error("fail to add mined block")
63+
log.error("Failed to add mined block")
6464
}
6565
} else {
6666
ommersPool ! AddOmmers(block.header)
6767
}
6868

6969
case PrintStatus =>
70-
log.info(s"Peers: ${handshakedPeers.size} (${blacklistedPeers.size} blacklisted).")
70+
log.info(s"Block: ${appStateStorage.getBestBlockNumber()}. Peers: ${handshakedPeers.size} (${blacklistedPeers.size} blacklisted)")
7171

7272
case Done =>
7373
if (waitingForActor == Option(sender())) {
@@ -92,9 +92,9 @@ trait RegularSync extends BlockBroadcast {
9292
ommersPool ! new RemoveOmmers((block.header +: block.body.uncleNodesList).toList)
9393
pendingTransactionsManager ! PendingTransactionsManager.RemoveTransactions(block.body.transactionList)
9494

95-
log.info(s"added new block $block")
95+
log.debug(s"Added new block $block")
9696
case Left(err) =>
97-
log.info(s"fail to execute mined block because of $err")
97+
log.warning(s"Failed to execute mined block because of $err")
9898
}
9999
}
100100

@@ -106,7 +106,7 @@ trait RegularSync extends BlockBroadcast {
106106
waitingForActor = Some(context.actorOf(
107107
SyncBlockHeadersRequestHandler.props(peer, etcPeerManager, peerEventBus, request, resolveBranches = false)))
108108
case None =>
109-
log.warning("no peers to download from")
109+
log.debug("No peers to download from")
110110
scheduleResume()
111111
}
112112
}
@@ -160,7 +160,7 @@ trait RegularSync extends BlockBroadcast {
160160
SyncBlockHeadersRequestHandler.props(peer, etcPeerManager, peerEventBus, request, resolveBranches = true)))
161161
}
162162
case _ =>
163-
log.warning("got header that does not have parent")
163+
log.debug("Got block header that does not have parent")
164164
resumeWithDifferentPeer(peer)
165165
}
166166
}
@@ -183,7 +183,7 @@ trait RegularSync extends BlockBroadcast {
183183

184184
if(newBlocks.nonEmpty){
185185
broadcastNewBlocks(newBlocks, handshakedPeers)
186-
log.info(s"got new blocks up till block: ${newBlocks.last.block.header.number} " +
186+
log.debug(s"got new blocks up till block: ${newBlocks.last.block.header.number} " +
187187
s"with hash ${Hex.toHexString(newBlocks.last.block.header.hash.toArray[Byte])}")
188188
}
189189

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

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -153,10 +153,10 @@ class EtcPeerManagerActor(peerManagerActor: ActorRef, peerEventBusActor: ActorRe
153153
forkBlockHeader <- blockHeaders.find(_.number == forkResolver.forkBlockNumber)
154154
} yield {
155155
val newFork = forkResolver.recognizeFork(forkBlockHeader)
156-
log.info("Received fork block header with fork: {}", newFork)
156+
log.debug("Received fork block header with fork: {}", newFork)
157157

158158
if (!forkResolver.isAccepted(newFork)) {
159-
log.warning("Peer is not running the accepted fork, disconnecting")
159+
log.debug("Peer is not running the accepted fork, disconnecting")
160160
peer.ref ! DisconnectPeer(Disconnect.Reasons.UselessPeer)
161161
initialPeerInfo
162162
} else

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

Lines changed: 8 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@ import java.net.{InetSocketAddress, URI}
55
import io.iohk.ethereum.network.PeerManagerActor.PeerConfiguration
66
import akka.actor._
77
import akka.agent.Agent
8+
import akka.util.ByteString
89
import io.iohk.ethereum.network.p2p._
910
import io.iohk.ethereum.network.p2p.messages.WireProtocol._
1011
import io.iohk.ethereum.network.p2p.messages.Versions
@@ -78,17 +79,17 @@ class PeerActor[R <: HandshakeResult](
7879
processHandshakerNextMessage(initHandshaker, rlpxConnection.copy(uriOpt = Some(uri)), numRetries)
7980

8081
case RLPxConnectionHandler.ConnectionFailed =>
81-
log.warning("Failed to establish RLPx connection")
82+
log.debug("Failed to establish RLPx connection")
8283
rlpxConnection.uriOpt match {
8384
case Some(uri) if numRetries < peerConfiguration.connectMaxRetries =>
8485
context unwatch rlpxConnection.ref
8586
scheduleConnectRetry(uri, numRetries)
8687
case Some(uri) =>
87-
log.warning("No more reconnect attempts left, removing peer")
88+
log.debug("No more reconnect attempts left, removing peer")
8889
knownNodesManager ! KnownNodesManager.RemoveKnownNode(uri)
8990
context stop self
9091
case None =>
91-
log.warning("Connection was initiated by remote peer, not attempting to reconnect")
92+
log.debug("Connection was initiated by remote peer, not attempting to reconnect")
9293
context stop self
9394
}
9495

@@ -148,7 +149,7 @@ class PeerActor[R <: HandshakeResult](
148149
}
149150

150151
private def scheduleConnectRetry(uri: URI, numRetries: Int): Unit = {
151-
log.info("Scheduling connection retry in {}", peerConfiguration.connectRetryDelay)
152+
log.debug("Scheduling connection retry in {}", peerConfiguration.connectRetryDelay)
152153
scheduler.scheduleOnce(peerConfiguration.connectRetryDelay, self, RetryConnectionTimeout)
153154
context become {
154155
case RetryConnectionTimeout => reconnect(uri, numRetries + 1)
@@ -169,7 +170,7 @@ class PeerActor[R <: HandshakeResult](
169170

170171
def handleTerminated(rlpxConnection: RLPxConnection): Receive = {
171172
case Terminated(actor) if actor == rlpxConnection.ref =>
172-
log.warning(s"Underlying rlpx connection with peer $peerId closed")
173+
log.debug(s"Underlying rlpx connection with peer $peerId closed")
173174
rlpxConnection.uriOpt match {
174175
case Some(uri) if rlpxConnection.isInitiator => scheduleConnectRetry(uri, numRetries = 0)
175176
case Some(uri) =>
@@ -181,7 +182,7 @@ class PeerActor[R <: HandshakeResult](
181182
}
182183

183184
def reconnect(uri: URI, numRetries: Int): Unit = {
184-
log.info("Trying to reconnect")
185+
log.debug("Trying to reconnect")
185186
val address = new InetSocketAddress(uri.getHost, uri.getPort)
186187
val newConnection = createRlpxConnection(address, Some(uri), true)
187188
newConnection.ref ! RLPxConnectionHandler.ConnectTo(uri)
@@ -200,7 +201,7 @@ class PeerActor[R <: HandshakeResult](
200201
rlpxConnection.uriOpt.foreach(uri => knownNodesManager ! KnownNodesManager.RemoveKnownNode(uri))
201202
case _ => // nothing
202203
}
203-
log.info(s"Received {}. Closing connection with peer ${peerAddress.getHostString}:${peerAddress.getPort}", d)
204+
log.debug(s"Received {}. Closing connection with peer ${peerAddress.getHostString}:${peerAddress.getPort}", d)
204205
context unwatch rlpxConnection.ref
205206
context stop self
206207
}

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

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -70,7 +70,7 @@ class PeerManagerActor(
7070
val nodesToConnect = nodes.take(peerConfiguration.maxPeers)
7171

7272
if (nodesToConnect.nonEmpty) {
73-
log.info("Trying to connect to {} known nodes", nodesToConnect.size)
73+
log.debug("Trying to connect to {} known nodes", nodesToConnect.size)
7474
nodesToConnect.foreach(n => self ! ConnectToPeer(n))
7575
}
7676

@@ -93,7 +93,7 @@ class PeerManagerActor(
9393
s"Trying to connect to ${nodesToConnect.size} more nodes.")
9494

9595
if (nodesToConnect.nonEmpty) {
96-
log.info("Trying to connect to {} nodes", nodesToConnect.size)
96+
log.debug("Trying to connect to {} nodes", nodesToConnect.size)
9797
nodesToConnect.foreach(n => self ! ConnectToPeer(n.toUri))
9898
}
9999
}
@@ -105,10 +105,10 @@ class PeerManagerActor(
105105

106106
if (incomingPeers.size > peerConfiguration.maxIncomingPeers) {
107107
peer.ref ! PeerActor.DisconnectPeer(Disconnect.Reasons.TooManyPeers)
108-
log.info("Maximum number of incoming peer connections reached.")
108+
log.debug("Maximum number of incoming peer connections reached.")
109109
}
110110
} else {
111-
log.info("Another connection with {} is already opened. Disconnecting.", remoteAddress)
111+
log.debug("Another connection with {} is already opened. Disconnecting.", remoteAddress)
112112
connection ! PoisonPill
113113
}
114114
}
@@ -120,10 +120,10 @@ class PeerManagerActor(
120120
val peer = createPeer(addr, incomingConnection = false)
121121
peer.ref ! PeerActor.ConnectTo(uri)
122122
} else {
123-
log.info("Maximum number of connected peers reached.")
123+
log.debug("Maximum number of connected peers reached.")
124124
}
125125
} else {
126-
log.info("Maximum number of connected peers reached. Not connecting to {}", uri)
126+
log.debug("Maximum number of connected peers reached. Not connecting to {}", uri)
127127
}
128128
}
129129

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

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -30,19 +30,19 @@ case class EtcForkBlockExchangeState(handshakerConfiguration: EtcHandshakerConfi
3030
case Some(forkBlockHeader) =>
3131
val fork = forkResolver.recognizeFork(forkBlockHeader)
3232

33-
log.info("Peer is running the {} fork", fork)
33+
log.debug("Peer is running the {} fork", fork)
3434

3535
if (forkResolver.isAccepted(fork)) {
36-
log.info("Fork is accepted")
36+
log.debug("Fork is accepted")
3737
val peerInfo: PeerInfo = PeerInfo(remoteStatus, remoteStatus.totalDifficulty, true, forkBlockHeader.number)
3838
ConnectedState(peerInfo)
3939
} else {
40-
log.warn("Fork is not accepted")
40+
log.debug("Fork is not accepted")
4141
DisconnectedState[PeerInfo](Disconnect.Reasons.UselessPeer)
4242
}
4343

4444
case None =>
45-
log.info("Peer did not respond with fork block header")
45+
log.debug("Peer did not respond with fork block header")
4646
ConnectedState(PeerInfo(remoteStatus, remoteStatus.totalDifficulty, false, 0))
4747
}
4848

0 commit comments

Comments
 (0)