diff --git a/CHANGELOG.md b/CHANGELOG.md
index 5bff8162e40..dccf8f80978 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -14,6 +14,7 @@
- Changed: [#5576](https://github.com/ethereum/aleth/pull/5576) Moved sstore_combinations and static_Call50000_sha256 tests to stTimeConsuming test suite. (testeth runs them only with `--all` flag)
- Changed: [#5589](https://github.com/ethereum/aleth/pull/5589) Make aleth output always line-buffered even when redirected to file or pipe.
- Changed: [#5602](https://github.com/ethereum/aleth/pull/5602) Better predicting external IP address and UDP port.
+- Changed: [#5605](https://github.com/ethereum/aleth/pull/5605) Network logging bugfixes and improvements and add warpcap log channel.
- Fixed: [#5562](https://github.com/ethereum/aleth/pull/5562) Don't send header request messages to peers that haven't sent us Status yet.
- Fixed: [#5581](https://github.com/ethereum/aleth/pull/5581) Fixed finding neighbour nodes in Discovery.
- Fixed: [#5599](https://github.com/ethereum/aleth/pull/5600) Prevent aleth from attempting concurrent connection to node which results in disconnect of original connection.
diff --git a/aleth/main.cpp b/aleth/main.cpp
index 321d0019bc0..7664baedff7 100644
--- a/aleth/main.cpp
+++ b/aleth/main.cpp
@@ -323,7 +323,7 @@ int main(int argc, char** argv)
std::string const logChannels =
"block blockhdr bq chain client debug discov error ethcap exec host impolite info net "
- "overlaydb p2pcap peer rlpx rpc snap statedb sync timer tq trace vmtrace warn watch";
+ "overlaydb p2pcap peer rlpx rpc snap statedb sync timer tq trace vmtrace warn warpcap watch";
LoggingOptions loggingOptions;
po::options_description loggingProgramOptions(
createLoggingProgramOptions(c_lineWidth, loggingOptions, logChannels));
diff --git a/libdevcore/Log.cpp b/libdevcore/Log.cpp
index 0517bb36465..a1eb6755fbc 100644
--- a/libdevcore/Log.cpp
+++ b/libdevcore/Log.cpp
@@ -1,23 +1,6 @@
-/*
- This file is part of cpp-ethereum.
-
- cpp-ethereum is free software: you can redistribute it and/or modify
- it under the terms of the GNU General Public License as published by
- the Free Software Foundation, either version 3 of the License, or
- (at your option) any later version.
-
- cpp-ethereum is distributed in the hope that it will be useful,
- but WITHOUT ANY WARRANTY; without even the implied warranty of
- MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
- GNU General Public License for more details.
-
- You should have received a copy of the GNU General Public License
- along with cpp-ethereum. If not, see .
-*/
-/** @file Log.cpp
- * @author Gav Wood
- * @date 2014
- */
+/// Aleth: Ethereum C++ client, tools and libraries.
+// Copyright 2019 Aleth Authors.
+// Licensed under the GNU General Public License, Version 3.
#include "Log.h"
@@ -48,7 +31,8 @@ using log_sink = boost::log::sinks::synchronous_sink;
namespace dev
{
BOOST_LOG_ATTRIBUTE_KEYWORD(channel, "Channel", std::string)
-BOOST_LOG_ATTRIBUTE_KEYWORD(context, "Context", std::string)
+BOOST_LOG_ATTRIBUTE_KEYWORD(prefix, "Prefix", std::string)
+BOOST_LOG_ATTRIBUTE_KEYWORD(suffix, "Suffix", std::string)
BOOST_LOG_ATTRIBUTE_KEYWORD(severity, "Severity", int)
BOOST_LOG_ATTRIBUTE_KEYWORD(threadName, "ThreadName", std::string)
BOOST_LOG_ATTRIBUTE_KEYWORD(timestamp, "TimeStamp", boost::posix_time::ptime)
@@ -96,10 +80,13 @@ void formatter(boost::log::record_view const& _rec, boost::log::formatting_ostre
_strm << EthNavy << std::setw(4) << std::left << _rec[threadName] << EthReset " ";
_strm << std::setw(6) << std::left << _rec[channel] << " ";
- if (boost::log::expressions::has_attr(context)(_rec))
- _strm << EthNavy << _rec[context] << EthReset " ";
+ if (boost::log::expressions::has_attr(prefix)(_rec))
+ _strm << EthNavy << _rec[prefix] << EthReset " ";
_strm << _rec[boost::log::expressions::smessage];
+
+ if (boost::log::expressions::has_attr(suffix)(_rec))
+ _strm << " " EthNavy << _rec[suffix] << EthReset;
}
} // namespace
diff --git a/libdevcore/Log.h b/libdevcore/Log.h
index bc172dbef0b..02ff6bbba99 100644
--- a/libdevcore/Log.h
+++ b/libdevcore/Log.h
@@ -1,19 +1,6 @@
-/*
- This file is part of cpp-ethereum.
-
- cpp-ethereum is free software: you can redistribute it and/or modify
- it under the terms of the GNU General Public License as published by
- the Free Software Foundation, either version 3 of the License, or
- (at your option) any later version.
-
- cpp-ethereum is distributed in the hope that it will be useful,
- but WITHOUT ANY WARRANTY; without even the implied warranty of
- MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
- GNU General Public License for more details.
-
- You should have received a copy of the GNU General Public License
- along with cpp-ethereum. If not, see .
-*/
+/// Aleth: Ethereum C++ client, tools and libraries.
+// Copyright 2019 Aleth Authors.
+// Licensed under the GNU General Public License, Version 3.
#pragma once
@@ -128,11 +115,6 @@ inline Logger createLogger(int _severity, std::string const& _channel)
boost::log::keywords::severity = _severity, boost::log::keywords::channel = _channel);
}
-// Adds the context string to all log messages in the scope
-#define LOG_SCOPED_CONTEXT(context) \
- BOOST_LOG_SCOPED_THREAD_ATTR("Context", boost::log::attributes::constant(context));
-
-
// Below overloads for both const and non-const references are needed, because without overload for
// non-const reference generic operator<<(formatting_ostream& _strm, T& _value) will be preferred by
// overload resolution.
diff --git a/libethereum/BlockChainSync.cpp b/libethereum/BlockChainSync.cpp
index 3cdce18cadb..e55eb77167b 100644
--- a/libethereum/BlockChainSync.cpp
+++ b/libethereum/BlockChainSync.cpp
@@ -196,7 +196,7 @@ void BlockChainSync::onPeerStatus(EthereumPeer const& _peer)
if (!disconnectReason.empty())
{
- LOG(m_logger) << "Peer not suitable for sync: " << disconnectReason;
+ LOG(m_logger) << "Peer " << _peer.id() << " not suitable for sync: " << disconnectReason;
m_host.capabilityHost().disconnect(_peer.id(), p2p::UserReason);
return;
}
@@ -255,13 +255,15 @@ void BlockChainSync::syncPeer(NodeID const& _peerID, bool _force)
if (_force || peerTotalDifficulty > syncingDifficulty)
{
if (peerTotalDifficulty > syncingDifficulty)
- LOG(m_logger) << "Discovered new highest difficulty";
+ LOG(m_logger) << "Discovered new highest difficulty (" << peerTotalDifficulty
+ << ") from peer " << peer.id();
// start sync
m_syncingTotalDifficulty = peerTotalDifficulty;
if (m_state == SyncState::Idle || m_state == SyncState::NotSynced)
{
LOG(m_loggerInfo) << "Starting full sync";
+ LOG(m_logger) << "Syncing with peer " << peer.id();
m_state = SyncState::Blocks;
}
peer.requestBlockHeaders(peer.latestHash(), 1, 0, false);
@@ -289,9 +291,8 @@ void BlockChainSync::requestBlocks(NodeID const& _peerID)
clearPeerDownload(_peerID);
if (host().bq().knownFull())
{
- LOG(m_loggerDetail)
- << "Waiting for block queue before downloading blocks. Block queue status: "
- << host().bq().status();
+ LOG(m_loggerDetail) << "Waiting for block queue before downloading blocks from " << _peerID
+ << ". Block queue status: " << host().bq().status();
pauseSync();
return;
}
@@ -379,7 +380,7 @@ void BlockChainSync::requestBlocks(NodeID const& _peerID)
}
}
else
- m_host.peer(_peerID).requestBlockHeaders(start, 1, 0, false);
+ m_host.peer(_peerID).requestBlockHeaders(start, 1 /* count */, 0 /* skip */, false);
}
}
@@ -446,7 +447,7 @@ void BlockChainSync::onPeerBlockHeaders(NodeID const& _peerID, RLP const& _r)
DEV_INVARIANT_CHECK;
size_t itemCount = _r.itemCount();
LOG(m_logger) << "BlocksHeaders (" << dec << itemCount << " entries) "
- << (itemCount ? "" : ": NoMoreHeaders");
+ << (itemCount ? "" : ": NoMoreHeaders") << " from " << _peerID;
if (m_daoChallengedPeers.find(_peerID) != m_daoChallengedPeers.end())
{
@@ -462,17 +463,17 @@ void BlockChainSync::onPeerBlockHeaders(NodeID const& _peerID, RLP const& _r)
clearPeerDownload(_peerID);
if (m_state != SyncState::Blocks && m_state != SyncState::Waiting)
{
- LOG(m_logger) << "Ignoring unexpected blocks";
+ LOG(m_logger) << "Ignoring unexpected blocks from " << _peerID;
return;
}
if (m_state == SyncState::Waiting)
{
- LOG(m_loggerDetail) << "Ignored blocks while waiting";
+ LOG(m_loggerDetail) << "Ignored blocks from " << _peerID << " while waiting";
return;
}
if (itemCount == 0)
{
- LOG(m_loggerDetail) << "Peer does not have the blocks requested";
+ LOG(m_loggerDetail) << "Peer " << _peerID << " does not have the blocks requested";
m_host.capabilityHost().updateRating(_peerID, -1);
}
for (unsigned i = 0; i < itemCount; i++)
@@ -481,17 +482,19 @@ void BlockChainSync::onPeerBlockHeaders(NodeID const& _peerID, RLP const& _r)
unsigned blockNumber = static_cast(info.number());
if (blockNumber < m_chainStartBlock)
{
- LOG(m_logger) << "Skipping too old header " << blockNumber;
+ LOG(m_logger) << "Skipping too old header " << blockNumber << " from " << _peerID;
continue;
}
if (haveItem(m_headers, blockNumber))
{
- LOG(m_logger) << "Skipping header " << blockNumber << " (already downloaded)";
+ LOG(m_logger) << "Skipping header " << blockNumber << " (already downloaded) from "
+ << _peerID;
continue;
}
if (blockNumber <= m_lastImportedBlock && m_haveCommonHeader)
{
- LOG(m_logger) << "Skipping header " << blockNumber << " (already imported)";
+ LOG(m_logger) << "Skipping header " << blockNumber << " (already imported) from "
+ << _peerID;
continue;
}
if (blockNumber > m_highestBlock)
@@ -509,8 +512,8 @@ void BlockChainSync::onPeerBlockHeaders(NodeID const& _peerID, RLP const& _r)
{
// Start of the header chain in m_headers doesn't match our known chain,
// probably we've downloaded other fork
- clog(VerbosityWarning, "sync")
- << "Unknown parent of the downloaded headers, restarting sync";
+ LOG(m_loggerWarning)
+ << "Unknown parent of the downloaded headers, restarting sync with " << _peerID;
restartSync();
return;
}
@@ -527,8 +530,9 @@ void BlockChainSync::onPeerBlockHeaders(NodeID const& _peerID, RLP const& _r)
if ((prevBlock && prevBlock->hash != info.parentHash()) || (blockNumber == m_lastImportedBlock + 1 && info.parentHash() != m_lastImportedBlockHash))
{
// mismatching parent id, delete the previous block and don't add this one
- clog(VerbosityWarning, "sync") << "Unknown block header " << blockNumber << " "
- << info.hash() << " (Restart syncing)";
+ LOG(m_loggerWarning)
+ << "Unknown block header " << blockNumber << " " << info.hash()
+ << " (Restart syncing with " << _peerID << ")";
m_host.capabilityHost().updateRating(_peerID, -1);
restartSync();
return ;
@@ -537,8 +541,8 @@ void BlockChainSync::onPeerBlockHeaders(NodeID const& _peerID, RLP const& _r)
Header const* nextBlock = findItem(m_headers, blockNumber + 1);
if (nextBlock && nextBlock->parent != info.hash())
{
- LOG(m_loggerDetail)
- << "Unknown block header " << blockNumber + 1 << " " << nextBlock->hash;
+ LOG(m_loggerDetail) << "Unknown block header " << blockNumber + 1 << " "
+ << nextBlock->hash << " from " << _peerID;
// clear following headers
unsigned n = blockNumber + 1;
auto headers = m_headers.at(n);
@@ -590,20 +594,20 @@ void BlockChainSync::onPeerBlockBodies(NodeID const& _peerID, RLP const& _r)
DEV_INVARIANT_CHECK;
size_t itemCount = _r.itemCount();
LOG(m_logger) << "BlocksBodies (" << dec << itemCount << " entries) "
- << (itemCount ? "" : ": NoMoreBodies");
+ << (itemCount ? "" : ": NoMoreBodies") << " from " << _peerID;
clearPeerDownload(_peerID);
if (m_state != SyncState::Blocks && m_state != SyncState::Waiting) {
- LOG(m_logger) << "Ignoring unexpected blocks";
+ LOG(m_logger) << "Ignoring unexpected blocks from " << _peerID;
return;
}
if (m_state == SyncState::Waiting)
{
- LOG(m_loggerDetail) << "Ignored blocks while waiting";
+ LOG(m_loggerDetail) << "Ignored blocks from " << _peerID << " while waiting";
return;
}
if (itemCount == 0)
{
- LOG(m_loggerDetail) << "Peer does not have the blocks requested";
+ LOG(m_loggerDetail) << "Peer " << _peerID << " does not have the blocks requested";
m_host.capabilityHost().updateRating(_peerID, -1);
}
for (unsigned i = 0; i < itemCount; i++)
@@ -617,13 +621,14 @@ void BlockChainSync::onPeerBlockBodies(NodeID const& _peerID, RLP const& _r)
auto iter = m_headerIdToNumber.find(id);
if (iter == m_headerIdToNumber.end() || !haveItem(m_headers, iter->second))
{
- LOG(m_loggerDetail) << "Ignored unknown block body";
+ LOG(m_loggerDetail) << "Ignored unknown block body from " << _peerID;
continue;
}
unsigned blockNumber = iter->second;
if (haveItem(m_bodies, blockNumber))
{
- LOG(m_logger) << "Skipping already downloaded block body " << blockNumber;
+ LOG(m_logger) << "Skipping already downloaded block body " << blockNumber << " from "
+ << _peerID;
continue;
}
m_headerIdToNumber.erase(id);
@@ -705,7 +710,7 @@ void BlockChainSync::collectBlocks()
if (host().bq().unknownFull())
{
- clog(VerbosityWarning, "sync") << "Too many unknown blocks, restarting sync";
+ LOG(m_loggerWarning) << "Too many unknown blocks, restarting sync";
restartSync();
return;
}
@@ -755,7 +760,8 @@ void BlockChainSync::onPeerNewBlock(NodeID const& _peerID, RLP const& _r)
unsigned blockNumber = static_cast(info.number());
if (blockNumber > (m_lastImportedBlock + 1))
{
- LOG(m_loggerDetail) << "Received unknown new block";
+ LOG(m_loggerDetail) << "Received unknown new block (" << blockNumber << ") from "
+ << _peerID;
// Update the hash of highest known block of the peer.
// syncPeer will then request the highest block header to properly restart syncing
peer.setLatestHash(h);
@@ -781,8 +787,9 @@ void BlockChainSync::onPeerNewBlock(NodeID const& _peerID, RLP const& _r)
{
if (!m_bodies.empty())
{
- LOG(m_loggerDetail)
- << "Block headers map is empty, but block bodies map is not. Force-clearing.";
+ LOG(m_loggerDetail) << "Block headers map is empty, but block bodies map is not. "
+ "Force-clearing (peer: "
+ << _peerID << ")";
m_bodies.clear();
}
completeSync();
@@ -815,7 +822,9 @@ void BlockChainSync::onPeerNewBlock(NodeID const& _peerID, RLP const& _r)
u256 totalDifficulty = _r[1].toInt();
if (totalDifficulty > peer.totalDifficulty())
{
- LOG(m_loggerDetail) << "Received block with no known parent. Peer needs syncing...";
+ LOG(m_loggerDetail) << "Received block (" << blockNumber
+ << ") with no known parent. Peer " << _peerID
+ << " needs syncing...";
syncPeer(_peerID, true);
}
break;
@@ -882,10 +891,12 @@ void BlockChainSync::onPeerNewHashes(
auto& peer = m_host.peer(_peerID);
if (peer.isConversing())
{
- LOG(m_loggerDetail) << "Ignoring new hashes since we're already downloading.";
+ LOG(m_loggerDetail) << "Ignoring new hashes since we're already downloading from peer "
+ << _peerID;
return;
}
- LOG(m_loggerDetail) << "Not syncing and new block hash discovered: syncing.";
+ LOG(m_loggerDetail) << "Not syncing and new block hash discovered: syncing with peer "
+ << _peerID;
unsigned knowns = 0;
unsigned unknowns = 0;
unsigned maxHeight = 0;
@@ -899,7 +910,8 @@ void BlockChainSync::onPeerNewHashes(
knowns++;
else if (status == QueueStatus::Bad)
{
- cwarn << "block hash bad!" << h << ". Bailing...";
+ LOG(m_loggerWarning) << "block hash bad!" << h << ". Bailing... (peer: " << _peerID
+ << ")";
return;
}
else if (status == QueueStatus::Unknown)
@@ -914,10 +926,11 @@ void BlockChainSync::onPeerNewHashes(
else
knowns++;
}
- LOG(m_logger) << knowns << " knowns, " << unknowns << " unknowns";
+ LOG(m_logger) << knowns << " knowns, " << unknowns << " unknowns (peer: " << _peerID << ")";
if (unknowns > 0)
{
- LOG(m_loggerDetail) << "Not syncing and new block hash discovered: syncing.";
+ LOG(m_loggerDetail) << "Not syncing and new block hash discovered: start syncing with "
+ << _peerID;
syncPeer(_peerID, true);
}
}
diff --git a/libethereum/BlockChainSync.h b/libethereum/BlockChainSync.h
index 11575a78e8e..adcfd4c18a8 100644
--- a/libethereum/BlockChainSync.h
+++ b/libethereum/BlockChainSync.h
@@ -150,6 +150,7 @@ class BlockChainSync final: public HasInvariants
Logger m_logger{createLogger(VerbosityDebug, "sync")};
Logger m_loggerInfo{createLogger(VerbosityInfo, "sync")};
Logger m_loggerDetail{createLogger(VerbosityTrace, "sync")};
+ Logger m_loggerWarning{createLogger(VerbosityWarning, "sync")};
private:
static char const* const s_stateNames[static_cast(SyncState::Size)];
diff --git a/libethereum/EthereumCapability.cpp b/libethereum/EthereumCapability.cpp
index 3658f1ce771..8d8e6587528 100644
--- a/libethereum/EthereumCapability.cpp
+++ b/libethereum/EthereumCapability.cpp
@@ -241,9 +241,8 @@ class EthereumHostData: public EthereumHostDataFace
blockHash = {};
}
- auto nextHash = [this](h256 _h, unsigned _step)
- {
- static const unsigned c_blockNumberUsageLimit = 1000;
+ auto nextHash = [this](h256 _h, unsigned _step) {
+ constexpr unsigned c_blockNumberUsageLimit = 1000;
const auto lastBlock = m_chain.number();
const auto limitBlock = lastBlock > c_blockNumberUsageLimit ? lastBlock - c_blockNumberUsageLimit : 0; // find the number of the block below which we don't expect BC changes.
@@ -657,8 +656,9 @@ bool EthereumCapability::interpretCapabilityPacket(
auto const latestHash = _r[3].toHash();
auto const genesisHash = _r[4].toHash();
- LOG(m_logger) << "Status: " << peerProtocolVersion << " / " << networkId << " / "
- << genesisHash << ", TD: " << totalDifficulty << " = " << latestHash;
+ LOG(m_logger) << "Status (from " << _peerID << "): " << peerProtocolVersion << " / "
+ << networkId << " / " << genesisHash << ", TD: " << totalDifficulty
+ << " = " << latestHash;
peer.setStatus(
peerProtocolVersion, networkId, totalDifficulty, latestHash, genesisHash);
@@ -686,7 +686,8 @@ bool EthereumCapability::interpretCapabilityPacket(
if (skip > std::numeric_limits::max() - 1)
{
- cnetdetails << "Requested block skip is too big: " << skip;
+ LOG(m_loggerDetail)
+ << "Requested block skip is too big: " << skip << " (peer: " << _peerID << ")";
break;
}
@@ -703,8 +704,8 @@ bool EthereumCapability::interpretCapabilityPacket(
case BlockHeadersPacket:
{
if (peer.asking() != Asking::BlockHeaders)
- LOG(m_loggerImpolite)
- << "Peer giving us block headers when we didn't ask for them.";
+ LOG(m_loggerImpolite) << "Peer " << _peerID
+ << " giving us block headers when we didn't ask for them.";
else
{
setIdle(_peerID);
@@ -715,11 +716,11 @@ bool EthereumCapability::interpretCapabilityPacket(
case GetBlockBodiesPacket:
{
unsigned count = static_cast(_r.itemCount());
- cnetlog << "GetBlockBodies (" << dec << count << " entries)";
+ LOG(m_logger) << "GetBlockBodies (" << dec << count << " entries) from " << _peerID;
if (!count)
{
- LOG(m_loggerImpolite) << "Zero-entry GetBlockBodies: Not replying.";
+ LOG(m_loggerImpolite) << "Zero-entry GetBlockBodies: Not replying to " << _peerID;
m_host->updateRating(_peerID, -10);
break;
}
@@ -736,7 +737,8 @@ bool EthereumCapability::interpretCapabilityPacket(
case BlockBodiesPacket:
{
if (peer.asking() != Asking::BlockBodies)
- LOG(m_loggerImpolite) << "Peer giving us block bodies when we didn't ask for them.";
+ LOG(m_loggerImpolite)
+ << "Peer " << _peerID << " giving us block bodies when we didn't ask for them.";
else
{
setIdle(_peerID);
@@ -753,8 +755,8 @@ bool EthereumCapability::interpretCapabilityPacket(
{
unsigned itemCount = _r.itemCount();
- cnetlog << "BlockHashes (" << dec << itemCount << " entries) "
- << (itemCount ? "" : " : NoMoreHashes");
+ LOG(m_logger) << "BlockHashes (" << dec << itemCount << " entries) "
+ << (itemCount ? "" : " : NoMoreHashes") << " from " << _peerID;
if (itemCount > c_maxIncomingNewHashes)
{
@@ -774,11 +776,11 @@ bool EthereumCapability::interpretCapabilityPacket(
unsigned count = static_cast(_r.itemCount());
if (!count)
{
- LOG(m_loggerImpolite) << "Zero-entry GetNodeData: Not replying.";
+ LOG(m_loggerImpolite) << "Zero-entry GetNodeData: Not replying to " << _peerID;
m_host->updateRating(_peerID, -10);
break;
}
- cnetlog << "GetNodeData (" << dec << count << " entries)";
+ LOG(m_logger) << "GetNodeData (" << dec << count << " entries) from " << _peerID;
strings const data = m_hostData->nodeData(_r);
@@ -795,11 +797,11 @@ bool EthereumCapability::interpretCapabilityPacket(
unsigned count = static_cast(_r.itemCount());
if (!count)
{
- LOG(m_loggerImpolite) << "Zero-entry GetReceipts: Not replying.";
+ LOG(m_loggerImpolite) << "Zero-entry GetReceipts: Not replying to " << _peerID;
m_host->updateRating(_peerID, -10);
break;
}
- cnetlog << "GetReceipts (" << dec << count << " entries)";
+ LOG(m_logger) << "GetReceipts (" << dec << count << " entries) from " << _peerID;
pair const rlpAndItemCount = m_hostData->receipts(_r);
@@ -813,7 +815,8 @@ bool EthereumCapability::interpretCapabilityPacket(
case NodeDataPacket:
{
if (peer.asking() != Asking::NodeData)
- LOG(m_loggerImpolite) << "Peer giving us node data when we didn't ask for them.";
+ LOG(m_loggerImpolite)
+ << "Peer " << _peerID << " giving us node data when we didn't ask for them.";
else
{
setIdle(_peerID);
@@ -824,7 +827,8 @@ bool EthereumCapability::interpretCapabilityPacket(
case ReceiptsPacket:
{
if (peer.asking() != Asking::Receipts)
- LOG(m_loggerImpolite) << "Peer giving us receipts when we didn't ask for them.";
+ LOG(m_loggerImpolite)
+ << "Peer " << _peerID << " giving us receipts when we didn't ask for them.";
else
{
setIdle(_peerID);
@@ -838,12 +842,13 @@ bool EthereumCapability::interpretCapabilityPacket(
}
catch (Exception const&)
{
- cnetlog << "Peer causing an Exception: "
- << boost::current_exception_diagnostic_information() << " " << _r;
+ LOG(m_loggerWarn) << "Peer " << _peerID << " causing an exception: "
+ << boost::current_exception_diagnostic_information() << " " << _r;
}
catch (std::exception const& _e)
{
- cnetlog << "Peer causing an exception: " << _e.what() << " " << _r;
+ LOG(m_loggerWarn) << "Peer " << _peerID << " causing an exception: " << _e.what() << " "
+ << _r;
}
return true;
diff --git a/libethereum/EthereumCapability.h b/libethereum/EthereumCapability.h
index d3c74637f36..a5f8c277d75 100644
--- a/libethereum/EthereumCapability.h
+++ b/libethereum/EthereumCapability.h
@@ -189,6 +189,8 @@ class EthereumCapability : public p2p::CapabilityFace
mutable std::mt19937_64 m_urng; // Mersenne Twister psuedo-random number generator
Logger m_logger{createLogger(VerbosityDebug, "ethcap")};
+ Logger m_loggerDetail{createLogger(VerbosityTrace, "ethcap")};
+ Logger m_loggerWarn{createLogger(VerbosityWarning, "ethcap")};
/// Logger for messages about impolite behaivour of peers.
Logger m_loggerImpolite{createLogger(VerbosityDebug, "impolite")};
};
diff --git a/libethereum/EthereumPeer.h b/libethereum/EthereumPeer.h
index d0079d9b7f4..01b1e534807 100644
--- a/libethereum/EthereumPeer.h
+++ b/libethereum/EthereumPeer.h
@@ -1,20 +1,6 @@
-/*
- This file is part of cpp-ethereum.
-
- cpp-ethereum is free software: you can redistribute it and/or modify
- it under the terms of the GNU General Public License as published by
- the Free Software Foundation, either version 3 of the License, or
- (at your option) any later version.
-
- cpp-ethereum is distributed in the hope that it will be useful,
- but WITHOUT ANY WARRANTY; without even the implied warranty of
- MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
- GNU General Public License for more details.
-
- You should have received a copy of the GNU General Public License
- along with cpp-ethereum. If not, see .
-*/
-
+// Aleth: Ethereum C++ client, tools and libraries.
+// Copyright 2018 Aleth Authors.
+// Licensed under the GNU General Public License, Version 3.
#pragma once
#include "CommonNet.h"
@@ -35,7 +21,10 @@ class EthereumPeer
EthereumPeer(std::shared_ptr _host, NodeID const& _peerID,
u256 const& /*_capabilityVersion*/)
: m_host(std::move(_host)), m_id(_peerID)
- {}
+ {
+ m_logger.add_attribute(
+ "Suffix", boost::log::attributes::constant{m_id.abridged()});
+ }
bool statusReceived() const { return m_protocolVersion != 0; }
diff --git a/libethereum/WarpCapability.cpp b/libethereum/WarpCapability.cpp
index ff0964e19be..cbe84d1434f 100644
--- a/libethereum/WarpCapability.cpp
+++ b/libethereum/WarpCapability.cpp
@@ -123,9 +123,9 @@ class WarpPeerObserver : public WarpPeerObserverFace
data.toBytesConstRef());
LOG(m_logger) << "Saved chunk " << hash << " Chunks left: " << m_neededChunks.size()
- << " Requested chunks: " << m_requestedChunks.size();
+ << " (peer: " << _peerID << ")";
if (m_neededChunks.empty() && m_requestedChunks.empty())
- LOG(m_logger) << "Snapshot download complete!";
+ LOG(m_logger) << "Snapshot download complete";
}
else
m_neededChunks.push_back(askedHash);
@@ -288,7 +288,7 @@ class WarpPeerObserver : public WarpPeerObserverFace
peerID = m_freePeers.value_pop();
} while (!m_host.requestData(peerID, chunkHash));
- LOG(m_logger) << "Requested chunk " << chunkHash;
+ LOG(m_logger) << "Requested chunk " << chunkHash << " from " << peerID;
m_requestedChunks[peerID] = chunkHash;
m_neededChunks.pop_front();
@@ -389,12 +389,13 @@ bool WarpCapability::interpretCapabilityPacket(NodeID const& _peerID, unsigned _
peerStatus.m_snapshotHash = _r[5].toHash();
peerStatus.m_snapshotNumber = _r[6].toInt();
- cnetlog << "Status: "
- << " protocol version " << peerStatus.m_protocolVersion << " networkId "
- << peerStatus.m_networkId << " genesis hash " << peerStatus.m_genesisHash
- << " total difficulty " << peerStatus.m_totalDifficulty << " latest hash "
- << peerStatus.m_latestHash << " snapshot hash " << peerStatus.m_snapshotHash
- << " snapshot number " << peerStatus.m_snapshotNumber;
+ LOG(m_logger) << "Status (from " << _peerID << "): "
+ << " protocol version " << peerStatus.m_protocolVersion << " networkId "
+ << peerStatus.m_networkId << " genesis hash " << peerStatus.m_genesisHash
+ << " total difficulty " << peerStatus.m_totalDifficulty << " latest hash "
+ << peerStatus.m_latestHash << " snapshot hash "
+ << peerStatus.m_snapshotHash << " snapshot number "
+ << peerStatus.m_snapshotNumber;
setIdle(_peerID);
m_peerObserver->onPeerStatus(_peerID);
break;
@@ -455,12 +456,13 @@ bool WarpCapability::interpretCapabilityPacket(NodeID const& _peerID, unsigned _
}
catch (Exception const&)
{
- cnetlog << "Warp Peer causing an Exception: "
- << boost::current_exception_diagnostic_information() << " " << _r;
+ LOG(m_loggerWarn) << "Warp Peer " << _peerID << " causing an exception: "
+ << boost::current_exception_diagnostic_information() << " " << _r;
}
catch (std::exception const& _e)
{
- cnetlog << "Warp Peer causing an exception: " << _e.what() << " " << _r;
+ LOG(m_loggerWarn) << "Warp Peer " << _peerID << " causing an exception: " << _e.what()
+ << " " << _r;
}
return true;
diff --git a/libethereum/WarpCapability.h b/libethereum/WarpCapability.h
index 570648afd6d..c2c41df5378 100644
--- a/libethereum/WarpCapability.h
+++ b/libethereum/WarpCapability.h
@@ -129,6 +129,9 @@ class WarpCapability : public p2p::CapabilityFace
std::shared_ptr m_peerObserver;
std::unordered_map m_peers;
+
+ Logger m_logger{createLogger(VerbosityDebug, "warpcap")};
+ Logger m_loggerWarn{createLogger(VerbosityWarning, "warpcap")};
};
} // namespace eth
diff --git a/libp2p/Host.cpp b/libp2p/Host.cpp
index e8f6b4adf41..d58e502e707 100644
--- a/libp2p/Host.cpp
+++ b/libp2p/Host.cpp
@@ -311,8 +311,9 @@ void Host::startPeerSession(Public const& _id, RLP const& _hello,
for (auto cap: caps)
capslog << "(" << cap.first << "," << dec << cap.second << ")";
- cnetlog << "Starting peer session with " << clientVersion << " V[" << protocolVersion << "]"
- << " " << _id << " " << showbase << capslog.str() << " " << dec << listenPort;
+ cnetlog << "Starting peer session with " << clientVersion << " (protocol: V" << protocolVersion
+ << ") " << _id << " " << showbase << "capabilities: " << capslog.str() << " " << dec
+ << "port: " << listenPort;
// create session so disconnects are managed
shared_ptr session = make_shared(this, move(_io), _s, peer,
@@ -659,8 +660,8 @@ void Host::connect(shared_ptr const& _p)
if (isHandshaking(_p->id))
{
- cwarn << "Aborted connection. RLPX handshake to peer already in progress: " << _p->id << "@"
- << _p->endpoint;
+ cwarn << "Aborted connection. RLPX handshake with peer already in progress: " << _p->id
+ << "@" << _p->endpoint;
return;
}
@@ -891,7 +892,7 @@ void Host::logActivePeers()
if (m_netConfig.discovery)
LOG(m_infoLogger) << "Looking for peers...";
- LOG(m_detailsLogger) << "Peers: " << peerSessionInfos();
+ LOG(m_logger) << "Peers: " << peerSessionInfos();
m_lastPeerLogMessage = chrono::steady_clock::now();
}
diff --git a/libp2p/RLPxHandshake.cpp b/libp2p/RLPxHandshake.cpp
index 23e7e14f664..4de9e319ae8 100644
--- a/libp2p/RLPxHandshake.cpp
+++ b/libp2p/RLPxHandshake.cpp
@@ -32,17 +32,27 @@ RLPXHandshake::RLPXHandshake(
m_socket(_socket),
m_idleTimer(m_socket->ref().get_io_service())
{
- m_logger.add_attribute(
- "Context", boost::log::attributes::constant(connectionDirectionString()));
- m_errorLogger.add_attribute(
- "Context", boost::log::attributes::constant(connectionDirectionString()));
+ auto const prefixAttr =
+ boost::log::attributes::constant{connectionDirectionString()};
+ m_logger.add_attribute("Prefix", prefixAttr);
+ m_errorLogger.add_attribute("Prefix", prefixAttr);
+
+ stringstream remoteInfoStream;
+ remoteInfoStream << "(" << _remote;
+ if (remoteSocketConnected())
+ remoteInfoStream << "@" << m_socket->remoteEndpoint();
+ remoteInfoStream << ")";
+ auto const suffixAttr = boost::log::attributes::constant{remoteInfoStream.str()};
+ m_logger.add_attribute("Suffix", suffixAttr);
+ m_errorLogger.add_attribute("Suffix", suffixAttr);
+
crypto::Nonce::get().ref().copyTo(m_nonce.ref());
}
void RLPXHandshake::writeAuth()
{
- LOG(m_logger) << "auth to " << m_remote << "@" << m_socket->remoteEndpoint();
+ LOG(m_logger) << "auth to";
m_auth.resize(Signature::size + h256::size + Public::size + h256::size + 1);
bytesRef sig(&m_auth[0], Signature::size);
bytesRef hepubk(&m_auth[Signature::size], h256::size);
@@ -68,7 +78,7 @@ void RLPXHandshake::writeAuth()
void RLPXHandshake::writeAck()
{
- LOG(m_logger) << "ack to " << m_remote << "@" << m_socket->remoteEndpoint();
+ LOG(m_logger) << "ack to";
m_ack.resize(Public::size + h256::size + 1);
bytesRef epubk(&m_ack[0], Public::size);
bytesRef nonce(&m_ack[Public::size], h256::size);
@@ -86,7 +96,7 @@ void RLPXHandshake::writeAck()
void RLPXHandshake::writeAckEIP8()
{
- LOG(m_logger) << "EIP-8 ack to " << m_remote << "@" << m_socket->remoteEndpoint();
+ LOG(m_logger) << "EIP-8 ack to";
RLPStream rlp;
rlp.appendList(3)
<< m_ecdheLocal.pub()
@@ -120,7 +130,6 @@ void RLPXHandshake::setAuthValues(Signature const& _sig, Public const& _remotePu
void RLPXHandshake::readAuth()
{
- LOG(m_logger) << "auth from " << m_remote << "@" << m_socket->remoteEndpoint();
m_authCipher.resize(c_authCipherSizeBytes);
auto self(shared_from_this());
ba::async_read(m_socket->ref(), ba::buffer(m_authCipher, c_authCipherSizeBytes),
@@ -129,6 +138,7 @@ void RLPXHandshake::readAuth()
transition(ec);
else if (decryptECIES(m_host->m_alias.secret(), bytesConstRef(&m_authCipher), m_auth))
{
+ LOG(m_logger) << "auth from";
bytesConstRef data(&m_auth);
Signature sig(data.cropped(0, Signature::size));
Public pubk(data.cropped(Signature::size + h256::size, Public::size));
@@ -144,9 +154,8 @@ void RLPXHandshake::readAuth()
void RLPXHandshake::readAuthEIP8()
{
assert(m_authCipher.size() == c_authCipherSizeBytes);
- uint16_t size(m_authCipher[0]<<8 | m_authCipher[1]);
- LOG(m_logger) << size << " bytes EIP-8 auth from " << m_remote << "@"
- << m_socket->remoteEndpoint();
+ uint16_t const size(m_authCipher[0] << 8 | m_authCipher[1]);
+ LOG(m_logger) << size << " bytes EIP-8 auth from";
m_authCipher.resize((size_t)size + 2);
auto rest = ba::buffer(ba::buffer(m_authCipher) + c_authCipherSizeBytes);
auto self(shared_from_this());
@@ -169,8 +178,7 @@ void RLPXHandshake::readAuthEIP8()
}
else
{
- LOG(m_logger) << "auth decrypt failed for " << m_remote << "@"
- << m_socket->remoteEndpoint();
+ LOG(m_logger) << "EIP-8 auth decrypt failed";
m_nextState = Error;
transition();
}
@@ -179,7 +187,6 @@ void RLPXHandshake::readAuthEIP8()
void RLPXHandshake::readAck()
{
- LOG(m_logger) << "ack from " << m_remote << "@" << m_socket->remoteEndpoint();
m_ackCipher.resize(c_ackCipherSizeBytes);
auto self(shared_from_this());
ba::async_read(m_socket->ref(), ba::buffer(m_ackCipher, c_ackCipherSizeBytes),
@@ -188,6 +195,7 @@ void RLPXHandshake::readAck()
transition(ec);
else if (decryptECIES(m_host->m_alias.secret(), bytesConstRef(&m_ackCipher), m_ack))
{
+ LOG(m_logger) << "ack from";
bytesConstRef(&m_ack).cropped(0, Public::size).copyTo(m_ecdheRemote.ref());
bytesConstRef(&m_ack).cropped(Public::size, h256::size).copyTo(m_remoteNonce.ref());
m_remoteVersion = c_rlpxVersion;
@@ -201,9 +209,8 @@ void RLPXHandshake::readAck()
void RLPXHandshake::readAckEIP8()
{
assert(m_ackCipher.size() == c_ackCipherSizeBytes);
- uint16_t size(m_ackCipher[0]<<8 | m_ackCipher[1]);
- LOG(m_logger) << size << " bytes EIP-8 ack from " << m_remote << "@"
- << m_socket->remoteEndpoint();
+ uint16_t const size(m_ackCipher[0] << 8 | m_ackCipher[1]);
+ LOG(m_logger) << size << " bytes EIP-8 ack from";
m_ackCipher.resize((size_t)size + 2);
auto rest = ba::buffer(ba::buffer(m_ackCipher) + c_ackCipherSizeBytes);
auto self(shared_from_this());
@@ -222,8 +229,7 @@ void RLPXHandshake::readAckEIP8()
}
else
{
- LOG(m_logger) << "ack decrypt failed for " << m_remote << "@"
- << m_socket->remoteEndpoint();
+ LOG(m_logger) << "EIP-8 ack decrypt failed";
m_nextState = Error;
transition();
}
@@ -238,13 +244,18 @@ void RLPXHandshake::cancel()
m_io.reset();
}
-void RLPXHandshake::error()
+void RLPXHandshake::error(boost::system::error_code _ech)
{
+ stringstream errorStream;
+ errorStream << "Handshake failed";
+ if (_ech)
+ errorStream << " (I/O error: " << _ech.message() << ")";
if (remoteSocketConnected())
- LOG(m_logger) << "Disconnecting " << m_remote << "@" << m_socket->remoteEndpoint()
- << " (Handshake Failed)";
+ errorStream << ". Disconnecting from";
else
- LOG(m_logger) << "Handshake Failed (Connection reset by peer " << m_remote << ")";
+ errorStream << " (Connection reset by peer)";
+
+ LOG(m_logger) << errorStream.str();
cancel();
}
@@ -256,16 +267,7 @@ void RLPXHandshake::transition(boost::system::error_code _ech)
if (_ech || m_nextState == Error || m_cancel)
{
- stringstream errorStream;
- errorStream << "Handshake Failed ";
- if (_ech)
- errorStream << "(I/O Error: " << _ech.message() << ") ";
- errorStream << "(" << m_remote;
- if (remoteSocketConnected())
- errorStream << "@" << m_socket->remoteEndpoint();
- errorStream << ")";
- LOG(m_logger) << errorStream.str();
- return error();
+ return error(_ech);
}
auto self(shared_from_this());
@@ -275,12 +277,7 @@ void RLPXHandshake::transition(boost::system::error_code _ech)
{
if (!_ec)
{
- std::stringstream errorStream;
- errorStream << "Disconnecting " << m_remote;
- if (remoteSocketConnected())
- errorStream << "@" << m_socket->remoteEndpoint();
- errorStream << " (Handshake Timeout)";
- LOG(m_logger) << errorStream.str();
+ LOG(m_logger) << "Disconnecting (Handshake Timeout) from";
cancel();
}
});
@@ -312,8 +309,7 @@ void RLPXHandshake::transition(boost::system::error_code _ech)
else if (m_nextState == WriteHello)
{
// Send the p2p capability Hello frame
- LOG(m_logger) << p2pPacketTypeToString(HelloPacket) << " to " << m_remote << "@"
- << m_socket->remoteEndpoint();
+ LOG(m_logger) << p2pPacketTypeToString(HelloPacket) << " to";
m_nextState = ReadHello;
@@ -339,8 +335,6 @@ void RLPXHandshake::transition(boost::system::error_code _ech)
}
else if (m_nextState == ReadHello)
{
- LOG(m_logger) << "Frame header from " << m_remote << "@" << m_socket->remoteEndpoint();
-
// Authenticate and decrypt initial hello frame with initial RLPXFrameCoder
// and request m_host to start session.
m_nextState = StartSession;
@@ -365,6 +359,8 @@ void RLPXHandshake::transition(boost::system::error_code _ech)
return;
}
+ LOG(m_logger) << "Frame header from";
+
/// authenticate and decrypt header
if (!m_io->authAndDecryptHeader(
bytesRef(m_handshakeInBuffer.data(), m_handshakeInBuffer.size())))
@@ -374,8 +370,7 @@ void RLPXHandshake::transition(boost::system::error_code _ech)
return;
}
- LOG(m_logger) << "Successfully decrypted frame header from " << m_remote << "@"
- << m_socket->remoteEndpoint() << ". Validating contents...";
+ LOG(m_logger) << "Successfully decrypted frame header, validating contents...";
/// check frame size
bytes const& header = m_handshakeInBuffer;
@@ -387,8 +382,7 @@ void RLPXHandshake::transition(boost::system::error_code _ech)
// all future frames: 16777216
LOG(m_logger)
<< "Frame is too large! Expected size: " << expectedFrameSizeBytes
- << " bytes, actual size: " << frameSize << " bytes (" << m_remote << "@"
- << m_socket->remoteEndpoint() << ")";
+ << " bytes, actual size: " << frameSize << " bytes";
m_nextState = Error;
transition();
return;
@@ -400,13 +394,13 @@ void RLPXHandshake::transition(boost::system::error_code _ech)
bytesConstRef(&header).cropped(3).copyTo(&headerRLP);
/// read padded frame and mac
- LOG(m_logger) << "Frame body from " << m_remote << "@"
- << m_socket->remoteEndpoint();
-
constexpr size_t byteBoundary = 16;
m_handshakeInBuffer.resize(
frameSize + ((byteBoundary - (frameSize % byteBoundary)) % byteBoundary) +
h128::size);
+
+ LOG(m_logger) << "Frame header contents validated";
+
ba::async_read(m_socket->ref(),
boost::asio::buffer(m_handshakeInBuffer, m_handshakeInBuffer.size()),
[this, self, headerRLP](boost::system::error_code ec, std::size_t) {
@@ -419,18 +413,16 @@ void RLPXHandshake::transition(boost::system::error_code _ech)
if (!m_io)
{
LOG(m_errorLogger) << "Internal error in handshake: "
- "RLPXFrameCoder disappeared ("
- << m_remote << ")";
+ "RLPXFrameCoder disappeared";
m_nextState = Error;
transition();
return;
}
-
+ LOG(m_logger) << "Frame body from";
bytesRef frame(&m_handshakeInBuffer);
if (!m_io->authAndDecryptFrame(frame))
{
- LOG(m_logger) << "Frame body decrypt failed (" << m_remote
- << "@" << m_socket->remoteEndpoint() << ")";
+ LOG(m_logger) << "Frame body decrypt failed";
m_nextState = Error;
transition();
return;
@@ -443,17 +435,14 @@ void RLPXHandshake::transition(boost::system::error_code _ech)
LOG(m_logger)
<< "Invalid packet type. Expected: "
<< p2pPacketTypeToString(HelloPacket)
- << ", received: " << p2pPacketTypeToString(packetType)
- << " (" << m_remote << "@" << m_socket->remoteEndpoint()
- << ")";
+ << ", received: " << p2pPacketTypeToString(packetType);
m_nextState = Error;
transition();
return;
}
LOG(m_logger) << p2pPacketTypeToString(HelloPacket)
- << " verified. Starting session with " << m_remote
- << "@" << m_socket->remoteEndpoint();
+ << " verified. Starting session with";
try
{
RLP rlp(
@@ -462,12 +451,8 @@ void RLPXHandshake::transition(boost::system::error_code _ech)
}
catch (std::exception const& _e)
{
- stringstream errorStream;
- errorStream << "Handshake with " << m_remote;
- if (remoteSocketConnected())
- errorStream << "@" << m_socket->remoteEndpoint();
- errorStream << " causing an exception: " << _e.what();
- LOG(m_errorLogger) << errorStream.str();
+ LOG(m_errorLogger)
+ << "Handshake causing an exception: " << _e.what();
m_nextState = Error;
transition();
}
diff --git a/libp2p/RLPxHandshake.h b/libp2p/RLPxHandshake.h
index a2403b6129a..bae3e2a6b76 100644
--- a/libp2p/RLPxHandshake.h
+++ b/libp2p/RLPxHandshake.h
@@ -90,10 +90,10 @@ class RLPXHandshake: public std::enable_shared_from_this
void readAckEIP8();
/// Closes connection and ends transitions.
- void error();
-
+ void error(boost::system::error_code _ech = {});
+
/// Performs transition for m_nextState.
- virtual void transition(boost::system::error_code _ech = boost::system::error_code());
+ virtual void transition(boost::system::error_code _ech = {});
/// Get a string indicating if the connection is incoming or outgoing
inline char const* connectionDirectionString() const
diff --git a/libp2p/Session.cpp b/libp2p/Session.cpp
index a89008a8ce7..cb8f66f6760 100644
--- a/libp2p/Session.cpp
+++ b/libp2p/Session.cpp
@@ -22,18 +22,29 @@ Session::Session(Host* _h, unique_ptr&& _io, std::shared_ptrremoteEndpoint() << ")";
+
+ m_logSuffix = remoteInfoStream.str();
+
+ auto const attr = boost::log::attributes::constant{remoteInfoStream.str()};
+ m_netLogger.add_attribute("Suffix", attr);
+ m_netLoggerDetail.add_attribute("Suffix", attr);
+ m_netLoggerError.add_attribute("Suffix", attr);
+
+ m_capLogger.add_attribute("Suffix", attr);
+ m_capLoggerDetail.add_attribute("Suffix", attr);
+
m_peer->m_lastDisconnect = NoDisconnect;
m_lastReceived = m_connect = chrono::steady_clock::now();
}
Session::~Session()
{
- LOG_SCOPED_CONTEXT(m_logContext);
+ cnetlog << "Closing peer session with " << m_logSuffix;
- cnetlog << "Closing peer session :-(";
m_peer->m_lastConnected = m_peer->m_lastAttempted - chrono::seconds(1);
// Read-chain finished for one reason or another.
@@ -85,15 +96,14 @@ int Session::rating() const
bool Session::readPacket(uint16_t _capId, unsigned _packetType, RLP const& _r)
{
m_lastReceived = chrono::steady_clock::now();
- clog(VerbosityTrace, "net") << "Received " << capabilityPacketTypeToString(_packetType) << "("
- << _packetType << ") from " << m_info.id << "@"
- << m_socket->remoteEndpoint();
+ LOG(m_netLoggerDetail) << "Received " << capabilityPacketTypeToString(_packetType) << " ("
+ << _packetType << ") from";
try // Generic try-catch block designed to capture RLP format errors - TODO: give decent diagnostics, make a bit more specific over what is caught.
{
// v4 frame headers are useless, offset packet type used
// v5 protocol type is in header, packet type not offset
if (_capId == 0 && _packetType < UserPacket)
- return interpret(static_cast(_packetType), _r);
+ return interpretP2pPacket(static_cast(_packetType), _r);
for (auto const& cap : m_capabilities)
{
@@ -115,18 +125,18 @@ bool Session::readPacket(uint16_t _capId, unsigned _packetType, RLP const& _r)
}
catch (std::exception const& _e)
{
- cnetlog << "Exception caught in p2p::Session::interpret(): " << _e.what()
- << ". PacketType: " << _packetType << ". RLP: " << _r;
+ LOG(m_netLogger) << "Exception caught in p2p::Session::readPacket(): " << _e.what()
+ << ". PacketType: " << capabilityPacketTypeToString(_packetType) << " ("
+ << _packetType << "). RLP: " << _r;
disconnect(BadProtocol);
return true;
}
return true;
}
-bool Session::interpret(P2pPacketType _t, RLP const& _r)
+bool Session::interpretP2pPacket(P2pPacketType _t, RLP const& _r)
{
- clog(VerbosityTrace, "p2pcap")
- << p2pPacketTypeToString(_t) << " from " << m_info.id << "@" << m_socket->remoteEndpoint();
+ LOG(m_capLoggerDetail) << p2pPacketTypeToString(_t) << " from";
switch (_t)
{
case DisconnectPacket:
@@ -138,15 +148,14 @@ bool Session::interpret(P2pPacketType _t, RLP const& _r)
else
{
reason = reasonOf(r);
- clog(VerbosityDebug, "p2pcap") << "Disconnect (reason: " << reason << ") from " << m_info.id << "@"
- << m_socket->remoteEndpoint();
+ LOG(m_capLogger) << "Disconnect (reason: " << reason << ") from";
drop(DisconnectRequested);
}
break;
}
case PingPacket:
{
- clog(VerbosityTrace, "p2pcap") << "Pong to " << m_info.id << "@" << m_socket->remoteEndpoint();
+ LOG(m_capLoggerDetail) << "Pong to";
RLPStream s;
sealAndSend(prep(s, PongPacket));
break;
@@ -155,9 +164,9 @@ bool Session::interpret(P2pPacketType _t, RLP const& _r)
DEV_GUARDED(x_info)
{
m_info.lastPing = std::chrono::steady_clock::now() - m_ping;
- clog(VerbosityTrace, "p2pcap") << "Ping latency: "
- << chrono::duration_cast(m_info.lastPing).count()
- << " ms";
+ LOG(m_capLoggerDetail)
+ << "Ping latency: "
+ << chrono::duration_cast(m_info.lastPing).count() << " ms";
}
break;
default:
@@ -168,7 +177,7 @@ bool Session::interpret(P2pPacketType _t, RLP const& _r)
void Session::ping()
{
- clog(VerbosityTrace, "p2pcap") << "Ping to " << m_info.id << "@" << m_socket->remoteEndpoint();
+ clog(VerbosityTrace, "p2pcap") << "Ping to " << m_logSuffix;
RLPStream s;
sealAndSend(prep(s, PingPacket));
m_ping = std::chrono::steady_clock::now();
@@ -198,10 +207,10 @@ bool Session::checkPacket(bytesConstRef _msg)
void Session::send(bytes&& _msg)
{
bytesConstRef msg(&_msg);
- clog(VerbosityTrace, "net") << "Sending " << capabilityPacketTypeToString(_msg[0]) << " to "
- << m_info.id << "@" << m_socket->remoteEndpoint();
+ LOG(m_netLoggerDetail) << capabilityPacketTypeToString(_msg[0]) << " to";
if (!checkPacket(msg))
- cnetlog << "INVALID PACKET CONSTRUCTED!";
+ clog(VerbosityError, "net") << "Invalid packet constructed. Size: " << msg.size()
+ << " bytes, message: " << toHex(msg);
if (!m_socket->ref().is_open())
return;
@@ -228,12 +237,10 @@ void Session::write()
auto self(shared_from_this());
ba::async_write(m_socket->ref(), ba::buffer(*out),
[this, self](boost::system::error_code ec, std::size_t /*length*/) {
- LOG_SCOPED_CONTEXT(m_logContext);
-
// must check queue, as write callback can occur following dropped()
if (ec)
{
- cnetlog << "Error sending: " << ec.message();
+ LOG(m_netLogger) << "Error sending: " << ec.message();
drop(TCPError);
return;
}
@@ -274,8 +281,7 @@ void Session::drop(DisconnectReason _reason)
try
{
boost::system::error_code ec;
- cnetdetails << "Closing " << socket.remote_endpoint(ec) << " (" << reasonOf(_reason)
- << ")";
+ LOG(m_netLoggerDetail) << "Closing (" << reasonOf(_reason) << ") connection with";
socket.shutdown(boost::asio::ip::tcp::socket::shutdown_both, ec);
socket.close();
}
@@ -292,8 +298,7 @@ void Session::drop(DisconnectReason _reason)
void Session::disconnect(DisconnectReason _reason)
{
- cnetdetails << "Disconnecting (our reason: " << reasonOf(_reason) << ") from " << m_info.id
- << "@" << m_socket->remoteEndpoint();
+ cnetdetails << "Disconnecting (our reason: " << reasonOf(_reason) << ") from " << m_logSuffix;
if (m_socket->ref().is_open())
{
@@ -320,13 +325,11 @@ void Session::doRead()
m_data.resize(h256::size);
ba::async_read(m_socket->ref(), boost::asio::buffer(m_data, h256::size),
[this, self](boost::system::error_code ec, std::size_t length) {
- LOG_SCOPED_CONTEXT(m_logContext);
-
if (!checkRead(h256::size, ec, length))
return;
else if (!m_io->authAndDecryptHeader(bytesRef(m_data.data(), length)))
{
- cnetlog << "header decrypt failed";
+ LOG(m_netLogger) << "Header decrypt failed";
drop(BadProtocol); // todo: better error
return;
}
@@ -343,8 +346,8 @@ void Session::doRead()
}
catch (std::exception const& _e)
{
- cnetlog << "Exception decoding frame header RLP: " << _e.what() << " "
- << bytesConstRef(m_data.data(), h128::size).cropped(3);
+ LOG(m_netLogger) << "Exception decoding frame header RLP: " << _e.what() << " "
+ << bytesConstRef(m_data.data(), h128::size).cropped(3);
drop(BadProtocol);
return;
}
@@ -355,13 +358,12 @@ void Session::doRead()
ba::async_read(m_socket->ref(), boost::asio::buffer(m_data, tlen),
[this, self, hLength, hProtocolId, tlen](
boost::system::error_code ec, std::size_t length) {
- LOG_SCOPED_CONTEXT(m_logContext);
if (!checkRead(tlen, ec, length))
return;
else if (!m_io->authAndDecryptFrame(bytesRef(m_data.data(), tlen)))
{
- cnetlog << "frame decrypt failed";
+ LOG(m_netLogger) << "Frame decrypt failed";
drop(BadProtocol); // todo: better error
return;
}
@@ -369,8 +371,8 @@ void Session::doRead()
bytesConstRef frame(m_data.data(), hLength);
if (!checkPacket(frame))
{
- cerr << "Received " << frame.size() << ": " << toHex(frame) << endl;
- cnetlog << "INVALID MESSAGE RECEIVED";
+ LOG(m_netLogger) << "Received invalid message. Size: " << frame.size()
+ << " bytes, message: " << toHex(frame) << endl;
disconnect(BadProtocol);
return;
}
@@ -380,7 +382,9 @@ void Session::doRead()
RLP r(frame.cropped(1));
bool ok = readPacket(hProtocolId, packetType, r);
if (!ok)
- cnetlog << "Couldn't interpret packet. " << RLP(r);
+ LOG(m_netLogger)
+ << "Couldn't interpret " << p2pPacketTypeToString(packetType)
+ << " (" << packetType << "). RLP: " << RLP(r);
}
doRead();
});
@@ -391,13 +395,13 @@ bool Session::checkRead(std::size_t _expected, boost::system::error_code _ec, st
{
if (_ec && _ec.category() != boost::asio::error::get_misc_category() && _ec.value() != boost::asio::error::eof)
{
- cnetdetails << "Error reading: " << _ec.message();
+ LOG(m_netLogger) << "Error reading: " << _ec.message();
drop(TCPError);
return false;
}
else if (_ec && _length < _expected)
{
- cnetlog << "Error reading - Abrupt peer disconnect: " << _ec.message();
+ LOG(m_netLogger) << "Error reading - Abrupt peer disconnect: " << _ec.message();
repMan().noteRude(*this);
drop(TCPError);
return false;
@@ -406,7 +410,9 @@ bool Session::checkRead(std::size_t _expected, boost::system::error_code _ec, st
{
// with static m_data-sized buffer this shouldn't happen unless there's a regression
// sec recommends checking anyways (instead of assert)
- cnetlog << "Error reading - TCP read buffer length differs from expected frame size.";
+ LOG(m_netLoggerError)
+ << "Error reading - TCP read buffer length differs from expected frame size ("
+ << _length << " != " << _expected << ")";
disconnect(UserReason);
return false;
}
@@ -434,8 +440,7 @@ bool Session::canHandle(
void Session::disableCapability(std::string const& _capabilityName, std::string const& _problem)
{
- cnetdetails << "DISABLE: Disabling capability '" << _capabilityName
- << "'. Reason: " << _problem;
+ cnetlog << "Disabling capability '" << _capabilityName << "'. Reason: " << _problem << " " << m_logSuffix;
m_disabledCapabilities.insert(_capabilityName);
}
diff --git a/libp2p/Session.h b/libp2p/Session.h
index b3e92d075f1..ea5a5457194 100644
--- a/libp2p/Session.h
+++ b/libp2p/Session.h
@@ -135,7 +135,7 @@ class Session: public SessionFace, public std::enable_shared_from_this m_disabledCapabilities;
- std::string const m_logContext;
+ std::string m_logSuffix;
+
+ Logger m_netLogger{createLogger(VerbosityDebug, "net")};
+ Logger m_netLoggerDetail{createLogger(VerbosityTrace, "net")};
+ Logger m_netLoggerError{createLogger(VerbosityError, "net")};
+
+ Logger m_capLogger{createLogger(VerbosityDebug, "p2pcap")};
+ Logger m_capLoggerDetail{createLogger(VerbosityTrace, "p2pcap")};
};
}