Merge pull request #3428 from codablock/pr_better_conn_logging

Improve network connections related logging
This commit is contained in:
Alexander Block 2020-04-17 21:46:17 +02:00 committed by GitHub
commit 0cb385c567
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
6 changed files with 37 additions and 20 deletions

View File

@ -41,7 +41,7 @@ void CMNAuth::PushMNAUTH(CNode* pnode, CConnman& connman)
mnauth.proRegTxHash = activeMasternodeInfo.proTxHash; mnauth.proRegTxHash = activeMasternodeInfo.proTxHash;
mnauth.sig = activeMasternodeInfo.blsKeyOperator->Sign(signHash); mnauth.sig = activeMasternodeInfo.blsKeyOperator->Sign(signHash);
LogPrint(BCLog::NET, "CMNAuth::%s -- Sending MNAUTH, peer=%d\n", __func__, pnode->GetId()); LogPrint(BCLog::NET_NETCONN, "CMNAuth::%s -- Sending MNAUTH, peer=%d\n", __func__, pnode->GetId());
connman.PushMessage(pnode, CNetMsgMaker(pnode->GetSendVersion()).Make(NetMsgType::MNAUTH, mnauth)); connman.PushMessage(pnode, CNetMsgMaker(pnode->GetSendVersion()).Make(NetMsgType::MNAUTH, mnauth));
} }
@ -117,7 +117,7 @@ void CMNAuth::ProcessMessage(CNode* pnode, const std::string& strCommand, CDataS
if (!pnode->fInbound) { if (!pnode->fInbound) {
mmetaman.GetMetaInfo(mnauth.proRegTxHash)->SetLastOutboundSuccess(GetAdjustedTime()); mmetaman.GetMetaInfo(mnauth.proRegTxHash)->SetLastOutboundSuccess(GetAdjustedTime());
if (pnode->fMasternodeProbe) { if (pnode->fMasternodeProbe) {
LogPrint(BCLog::NET, "CMNAuth::ProcessMessage -- masternode probe successful for %s, disconnecting. peer=%d\n", LogPrint(BCLog::NET_NETCONN, "CMNAuth::ProcessMessage -- masternode probe successful for %s, disconnecting. peer=%d\n",
mnauth.proRegTxHash.ToString(), pnode->GetId()); mnauth.proRegTxHash.ToString(), pnode->GetId());
pnode->fDisconnect = true; pnode->fDisconnect = true;
return; return;
@ -133,27 +133,27 @@ void CMNAuth::ProcessMessage(CNode* pnode, const std::string& strCommand, CDataS
if (pnode2->verifiedProRegTxHash == mnauth.proRegTxHash) { if (pnode2->verifiedProRegTxHash == mnauth.proRegTxHash) {
if (fMasternodeMode) { if (fMasternodeMode) {
auto deterministicOutbound = llmq::CLLMQUtils::DeterministicOutboundConnection(activeMasternodeInfo.proTxHash, mnauth.proRegTxHash); auto deterministicOutbound = llmq::CLLMQUtils::DeterministicOutboundConnection(activeMasternodeInfo.proTxHash, mnauth.proRegTxHash);
LogPrint(BCLog::NET, "CMNAuth::ProcessMessage -- Masternode %s has already verified as peer %d, deterministicOutbound=%s. peer=%d\n", LogPrint(BCLog::NET_NETCONN, "CMNAuth::ProcessMessage -- Masternode %s has already verified as peer %d, deterministicOutbound=%s. peer=%d\n",
mnauth.proRegTxHash.ToString(), pnode2->GetId(), deterministicOutbound.ToString(), pnode->GetId()); mnauth.proRegTxHash.ToString(), pnode2->GetId(), deterministicOutbound.ToString(), pnode->GetId());
if (deterministicOutbound == activeMasternodeInfo.proTxHash) { if (deterministicOutbound == activeMasternodeInfo.proTxHash) {
if (pnode2->fInbound) { if (pnode2->fInbound) {
LogPrint(BCLog::NET, "CMNAuth::ProcessMessage -- dropping old inbound, peer=%d\n", pnode2->GetId()); LogPrint(BCLog::NET_NETCONN, "CMNAuth::ProcessMessage -- dropping old inbound, peer=%d\n", pnode2->GetId());
pnode2->fDisconnect = true; pnode2->fDisconnect = true;
} else if (pnode->fInbound) { } else if (pnode->fInbound) {
LogPrint(BCLog::NET, "CMNAuth::ProcessMessage -- dropping new inbound, peer=%d\n", pnode->GetId()); LogPrint(BCLog::NET_NETCONN, "CMNAuth::ProcessMessage -- dropping new inbound, peer=%d\n", pnode->GetId());
pnode->fDisconnect = true; pnode->fDisconnect = true;
} }
} else { } else {
if (!pnode2->fInbound) { if (!pnode2->fInbound) {
LogPrint(BCLog::NET, "CMNAuth::ProcessMessage -- dropping old outbound, peer=%d\n", pnode2->GetId()); LogPrint(BCLog::NET_NETCONN, "CMNAuth::ProcessMessage -- dropping old outbound, peer=%d\n", pnode2->GetId());
pnode2->fDisconnect = true; pnode2->fDisconnect = true;
} else if (!pnode->fInbound) { } else if (!pnode->fInbound) {
LogPrint(BCLog::NET, "CMNAuth::ProcessMessage -- dropping new outbound, peer=%d\n", pnode->GetId()); LogPrint(BCLog::NET_NETCONN, "CMNAuth::ProcessMessage -- dropping new outbound, peer=%d\n", pnode->GetId());
pnode->fDisconnect = true; pnode->fDisconnect = true;
} }
} }
} else { } else {
LogPrint(BCLog::NET, "CMNAuth::ProcessMessage -- Masternode %s has already verified as peer %d, dropping new connection. peer=%d\n", LogPrint(BCLog::NET_NETCONN, "CMNAuth::ProcessMessage -- Masternode %s has already verified as peer %d, dropping new connection. peer=%d\n",
mnauth.proRegTxHash.ToString(), pnode2->GetId(), pnode->GetId()); mnauth.proRegTxHash.ToString(), pnode2->GetId(), pnode->GetId());
pnode->fDisconnect = true; pnode->fDisconnect = true;
} }
@ -170,7 +170,7 @@ void CMNAuth::ProcessMessage(CNode* pnode, const std::string& strCommand, CDataS
pnode->verifiedPubKeyHash = dmn->pdmnState->pubKeyOperator.GetHash(); pnode->verifiedPubKeyHash = dmn->pdmnState->pubKeyOperator.GetHash();
} }
LogPrint(BCLog::NET, "CMNAuth::%s -- Valid MNAUTH for %s, peer=%d\n", __func__, mnauth.proRegTxHash.ToString(), pnode->GetId()); LogPrint(BCLog::NET_NETCONN, "CMNAuth::%s -- Valid MNAUTH for %s, peer=%d\n", __func__, mnauth.proRegTxHash.ToString(), pnode->GetId());
} }
} }
@ -203,7 +203,7 @@ void CMNAuth::NotifyMasternodeListChanged(bool undo, const CDeterministicMNList&
} }
if (doRemove) { if (doRemove) {
LogPrint(BCLog::NET, "CMNAuth::NotifyMasternodeListChanged -- Disconnecting MN %s due to key changed/removed, peer=%d\n", LogPrint(BCLog::NET_NETCONN, "CMNAuth::NotifyMasternodeListChanged -- Disconnecting MN %s due to key changed/removed, peer=%d\n",
pnode->verifiedProRegTxHash.ToString(), pnode->GetId()); pnode->verifiedProRegTxHash.ToString(), pnode->GetId());
pnode->fDisconnect = true; pnode->fDisconnect = true;
} }

View File

@ -177,7 +177,7 @@ void CLLMQUtils::EnsureQuorumConnections(Consensus::LLMQType llmqType, const CBl
debugMsg += strprintf(" %s (%s)\n", c.ToString(), dmn->pdmnState->addr.ToString(false)); debugMsg += strprintf(" %s (%s)\n", c.ToString(), dmn->pdmnState->addr.ToString(false));
} }
} }
LogPrint(BCLog::LLMQ, debugMsg.c_str()); LogPrint(BCLog::NET_NETCONN, debugMsg.c_str());
} }
g_connman->SetMasternodeQuorumNodes(llmqType, pindexQuorum->GetBlockHash(), connections); g_connman->SetMasternodeQuorumNodes(llmqType, pindexQuorum->GetBlockHash(), connections);
} }
@ -213,7 +213,7 @@ void CLLMQUtils::AddQuorumProbeConnections(Consensus::LLMQType llmqType, const C
debugMsg += strprintf(" %s (%s)\n", c.ToString(), dmn->pdmnState->addr.ToString(false)); debugMsg += strprintf(" %s (%s)\n", c.ToString(), dmn->pdmnState->addr.ToString(false));
} }
} }
LogPrint(BCLog::LLMQ, debugMsg.c_str()); LogPrint(BCLog::NET_NETCONN, debugMsg.c_str());
} }
g_connman->AddPendingProbeConnections(probeConnections); g_connman->AddPendingProbeConnections(probeConnections);
} }

View File

@ -1225,9 +1225,9 @@ void CConnman::AcceptConnection(const ListenSocket& hListenSocket) {
m_msgproc->InitializeNode(pnode); m_msgproc->InitializeNode(pnode);
if (fLogIPs) { if (fLogIPs) {
LogPrint(BCLog::NET, "connection from %s accepted\n", addr.ToString()); LogPrint(BCLog::NET_NETCONN, "connection from %s accepted, sock=%d, peer=%d\n", addr.ToString(), pnode->hSocket, pnode->GetId());
} else { } else {
LogPrint(BCLog::NET, "connection accepted\n"); LogPrint(BCLog::NET_NETCONN, "connection accepted, sock=%d, peer=%d\n", pnode->hSocket, pnode->GetId());
} }
{ {
@ -2298,7 +2298,7 @@ void CConnman::ThreadOpenMasternodeConnections()
vPendingMasternodes.erase(vPendingMasternodes.begin()); vPendingMasternodes.erase(vPendingMasternodes.begin());
if (dmn && !connectedNodes.count(dmn->pdmnState->addr) && !IsMasternodeOrDisconnectRequested(dmn->pdmnState->addr)) { if (dmn && !connectedNodes.count(dmn->pdmnState->addr) && !IsMasternodeOrDisconnectRequested(dmn->pdmnState->addr)) {
connectToDmn = dmn; connectToDmn = dmn;
LogPrint(BCLog::NET, "CConnman::%s -- opening pending masternode connection to %s, service=%s\n", __func__, dmn->proTxHash.ToString(), dmn->pdmnState->addr.ToString(false)); LogPrint(BCLog::NET_NETCONN, "CConnman::%s -- opening pending masternode connection to %s, service=%s\n", __func__, dmn->proTxHash.ToString(), dmn->pdmnState->addr.ToString(false));
} }
} }
@ -2324,7 +2324,7 @@ void CConnman::ThreadOpenMasternodeConnections()
if (!pending.empty()) { if (!pending.empty()) {
connectToDmn = pending[GetRandInt(pending.size())]; connectToDmn = pending[GetRandInt(pending.size())];
LogPrint(BCLog::NET, "CConnman::%s -- opening quorum connection to %s, service=%s\n", __func__, connectToDmn->proTxHash.ToString(), connectToDmn->pdmnState->addr.ToString(false)); LogPrint(BCLog::NET_NETCONN, "CConnman::%s -- opening quorum connection to %s, service=%s\n", __func__, connectToDmn->proTxHash.ToString(), connectToDmn->pdmnState->addr.ToString(false));
} }
} }
@ -2359,7 +2359,7 @@ void CConnman::ThreadOpenMasternodeConnections()
masternodePendingProbes.erase(connectToDmn->proTxHash); masternodePendingProbes.erase(connectToDmn->proTxHash);
isProbe = true; isProbe = true;
LogPrint(BCLog::NET, "CConnman::%s -- probing masternode %s, service=%s\n", __func__, connectToDmn->proTxHash.ToString(), connectToDmn->pdmnState->addr.ToString(false)); LogPrint(BCLog::NET_NETCONN, "CConnman::%s -- probing masternode %s, service=%s\n", __func__, connectToDmn->proTxHash.ToString(), connectToDmn->pdmnState->addr.ToString(false));
} }
} }
} }
@ -2381,6 +2381,7 @@ void CConnman::ThreadOpenMasternodeConnections()
return true; return true;
}); });
if (!connected) { if (!connected) {
LogPrint(BCLog::NET_NETCONN, "CConnman::%s -- connection failed for masternode %s, service=%s\n", __func__, connectToDmn->proTxHash.ToString(), connectToDmn->pdmnState->addr.ToString(false));
// reset last outbound success // reset last outbound success
mmetaman.GetMetaInfo(connectToDmn->proTxHash)->SetLastOutboundSuccess(0); mmetaman.GetMetaInfo(connectToDmn->proTxHash)->SetLastOutboundSuccess(0);
} }
@ -2417,10 +2418,22 @@ void CConnman::OpenNetworkConnection(const CAddress& addrConnect, bool fCountFai
} else if (FindNode(std::string(pszDest))) } else if (FindNode(std::string(pszDest)))
return; return;
auto getIpStr = [&]() {
if (fLogIPs) {
return addrConnect.ToString(false);
} else {
return std::string("new peer");
}
};
LogPrint(BCLog::NET_NETCONN, "CConnman::%s -- connecting to %s\n", __func__, getIpStr());
CNode* pnode = ConnectNode(addrConnect, pszDest, fCountFailure); CNode* pnode = ConnectNode(addrConnect, pszDest, fCountFailure);
if (!pnode) if (!pnode) {
LogPrint(BCLog::NET_NETCONN, "CConnman::%s -- ConnectNode failed for %s\n", __func__, getIpStr());
return; return;
}
LogPrint(BCLog::NET_NETCONN, "CConnman::%s -- succesfully connected to %s, sock=%d, peer=%d\n", __func__, getIpStr(), pnode->hSocket, pnode->GetId());
if (grantOutbound) if (grantOutbound)
grantOutbound->MoveTo(pnode->grantOutbound); grantOutbound->MoveTo(pnode->grantOutbound);
if (fOneShot) if (fOneShot)

View File

@ -2128,9 +2128,9 @@ bool static ProcessMessage(CNode* pfrom, const std::string& strCommand, CDataStr
if (pfrom->fInbound) { if (pfrom->fInbound) {
pfrom->fMasternode = fOtherMasternode; pfrom->fMasternode = fOtherMasternode;
if (fOtherMasternode) { if (fOtherMasternode) {
LogPrint(BCLog::NET, "peer=%d is an inbound masternode connection, not relaying anything to it\n", pfrom->GetId()); LogPrint(BCLog::NET_NETCONN, "peer=%d is an inbound masternode connection, not relaying anything to it\n", pfrom->GetId());
if (!fMasternodeMode) { if (!fMasternodeMode) {
LogPrint(BCLog::NET, "but we're not a masternode, disconnecting\n"); LogPrint(BCLog::NET_NETCONN, "but we're not a masternode, disconnecting\n");
pfrom->fDisconnect = true; pfrom->fDisconnect = true;
return true; return true;
} }

View File

@ -288,6 +288,7 @@ const CLogCategoryDesc LogCategories[] =
{BCLog::MNSYNC, "mnsync"}, {BCLog::MNSYNC, "mnsync"},
{BCLog::PRIVATESEND, "privatesend"}, {BCLog::PRIVATESEND, "privatesend"},
{BCLog::SPORK, "spork"}, {BCLog::SPORK, "spork"},
{BCLog::NETCONN, "netconn"},
//End Dash //End Dash
}; };

View File

@ -139,8 +139,11 @@ namespace BCLog {
MNSYNC = ((uint64_t)1 << 40), MNSYNC = ((uint64_t)1 << 40),
PRIVATESEND = ((uint64_t)1 << 41), PRIVATESEND = ((uint64_t)1 << 41),
SPORK = ((uint64_t)1 << 42), SPORK = ((uint64_t)1 << 42),
NETCONN = ((uint64_t)1 << 43),
//End Dash //End Dash
NET_NETCONN = NET | NETCONN, // use this to have something logged in NET and NETCONN as well
ALL = ~(uint64_t)0, ALL = ~(uint64_t)0,
}; };
} }