diff --git a/node/Bond.cpp b/node/Bond.cpp index a5b3d1b03..dde6e22b6 100644 --- a/node/Bond.cpp +++ b/node/Bond.cpp @@ -16,6 +16,7 @@ #include #include +#include namespace ZeroTier { @@ -102,7 +103,7 @@ SharedPtr Bond::createTransportTriggeredBond(const RuntimeEnvironment* ren } if (! _defaultPolicy && _defaultPolicyStr.length()) { bond = new Bond(renv, _bondPolicyTemplates[_defaultPolicyStr].ptr(), peer); - bond->log("new default custom bond"); + bond->log("new default custom bond (based on %s)", bond->getPolicyStrByCode(bond->policy()).c_str()); } } else { @@ -147,14 +148,12 @@ SharedPtr Bond::createTransportTriggeredBond(const RuntimeEnvironment* ren SharedPtr Bond::getLinkBySocket(const std::string& policyAlias, uint64_t localSocket) { Mutex::Lock _l(_links_m); - char ifname[32] = { 0 }; // 256 because interfaces on Windows can potentially be that long + char ifname[64] = { 0 }; _phy->getIfName((PhySocket*)((uintptr_t)localSocket), ifname, sizeof(ifname) - 1); - // fprintf(stderr, "ifname %s\n",ifname); std::string ifnameStr(ifname); auto search = _interfaceToLinkMap[policyAlias].find(ifnameStr); if (search == _interfaceToLinkMap[policyAlias].end()) { // If the link wasn't already known, add a new entry - // fprintf(stderr, "adding new link?? %s\n", ifnameStr.c_str()); SharedPtr s = new Link(ifnameStr, 0, 0, true, ZT_BOND_SLAVE_MODE_SPARE, "", 0.0); _interfaceToLinkMap[policyAlias].insert(std::pair >(ifnameStr, s)); return s; @@ -182,7 +181,6 @@ void Bond::processBackgroundTasks(void* tPtr, const int64_t now) while (bondItr != _bonds.end()) { // Update Bond Controller's background processing timer _currMinReqMonitorInterval = std::min(_currMinReqMonitorInterval, (unsigned long)(bondItr->second->monitorInterval())); - // Process bond tasks bondItr->second->processBackgroundBondTasks(tPtr, now); ++bondItr; } @@ -215,8 +213,6 @@ Bond::Bond(const RuntimeEnvironment* renv, SharedPtr originalBond, const S void Bond::nominatePathToBond(const SharedPtr& path, int64_t now) { - char pathStr[64] = { 0 }; - path->address().toString(pathStr); Mutex::Lock _l(_paths_m); /** * Ensure the link is allowed and the path is not already present @@ -260,7 +256,7 @@ void Bond::nominatePathToBond(const SharedPtr& path, int64_t now) _paths[i].enabled = sl->enabled(); _paths[i].onlyPathOnLink = ! bFoundCommonLink; } - log("nominate link %s/%s (now in trial period)", getLink(path)->ifname().c_str(), pathStr); + log("nominate link %s", pathToStr(path).c_str()); break; } } @@ -364,9 +360,6 @@ SharedPtr Bond::getAppropriatePath(int64_t now, int32_t flowId) void Bond::recordIncomingInvalidPacket(const SharedPtr& path) { - // char pathStr[64] = { 0 }; path->address().toString(pathStr); - // log("%s (qos) Invalid packet on link %s/%s from peer %llx", - // getLink(path)->ifname().c_str(), pathStr); Mutex::Lock _l(_paths_m); for (int i = 0; i < ZT_MAX_PEER_NETWORK_PATHS; ++i) { if (_paths[i].p == path) { @@ -379,13 +372,6 @@ void Bond::recordOutgoingPacket(const SharedPtr& path, uint64_t packetId, { _freeRandomByte += (unsigned char)(packetId >> 8); // Grab entropy to use in path selection logic bool isFrame = (verb == Packet::Packet::VERB_ECHO || verb == Packet::VERB_FRAME || verb == Packet::VERB_EXT_FRAME); - if (isFrame) { - // char pathStr[64] = { 0 }; - // path->address().toString(pathStr); - // int pathIdx = getNominatedPathIdx(path); - // log("outgoing packet via [%d]", pathIdx); - // log("outgoing packet via %s/%s", getLink(path)->ifname().c_str(), pathStr); - } bool shouldRecord = (packetId & (ZT_QOS_ACK_DIVISOR - 1) && (verb != Packet::VERB_ACK) && (verb != Packet::VERB_QOS_MEASUREMENT)); if (isFrame || shouldRecord) { Mutex::Lock _l(_paths_m); @@ -416,12 +402,6 @@ void Bond::recordOutgoingPacket(const SharedPtr& path, uint64_t packetId, void Bond::recordIncomingPacket(const SharedPtr& path, uint64_t packetId, uint16_t payloadLength, Packet::Verb verb, int32_t flowId, int64_t now) { bool isFrame = (verb == Packet::Packet::VERB_ECHO || verb == Packet::VERB_FRAME || verb == Packet::VERB_EXT_FRAME); - if (isFrame) { - // char pathStr[64] = { 0 }; path->address().toString(pathStr); - // int pathIdx = getNominatedPathIdx(path); - // log("incoming packet via [%d] [id=%llx, len=%d, verb=%d, flowId=%x]", pathIdx, packetId, payloadLength, verb, flowId); - // log("incoming packet via %s/%s (ls=%llx) [id=%llx, len=%d, verb=%d, flowId=%x]", getLink(path)->ifname().c_str(), pathStr, path->localSocket(), packetId, payloadLength, verb, flowId); - } bool shouldRecord = (packetId & (ZT_QOS_ACK_DIVISOR - 1) && (verb != Packet::VERB_ACK) && (verb != Packet::VERB_QOS_MEASUREMENT)); Mutex::Lock _l(_paths_m); int pathIdx = getNominatedPathIdx(path); @@ -473,8 +453,7 @@ void Bond::receivedQoS(const SharedPtr& path, int64_t now, int count, uint if (pathIdx == ZT_MAX_PEER_NETWORK_PATHS) { return; } - // char pathStr[64] = { 0 }; path->address().toString(pathStr); - // log("received QoS packet (sampling %d frames) via %s/%s", count, getLink(path)->ifname().c_str(), pathStr); + // log("received QoS packet (sampling %d frames) via %s", count, pathToStr(path).c_str()); // Look up egress times and compute latency values for each record std::map::iterator it; for (int j = 0; j < count; j++) { @@ -509,12 +488,9 @@ int32_t Bond::generateQoSPacket(int pathIdx, int64_t now, char* qosBuffer) bool Bond::assignFlowToBondedPath(SharedPtr& flow, int64_t now) { - char curPathStr[64] = { 0 }; unsigned int idx = ZT_MAX_PEER_NETWORK_PATHS; if (_policy == ZT_BOND_POLICY_BALANCE_XOR) { idx = abs((int)(flow->id % (_numBondedPaths))); - SharedPtr link = RR->bc->getLinkBySocket(_policyAlias, _paths[_bondIdxMap[idx]].p->localSocket()); - _paths[_bondIdxMap[idx]].p->address().toString(curPathStr); flow->assignPath(_bondIdxMap[idx], now); ++(_paths[_bondIdxMap[idx]].assignedFlowCount); } @@ -541,8 +517,6 @@ bool Bond::assignFlowToBondedPath(SharedPtr& flow, int64_t now) entropy %= totalIncompleteAllocation; for (unsigned int i = 0; i < ZT_MAX_PEER_NETWORK_PATHS; ++i) { if (_paths[i].p && _paths[i].bonded) { - SharedPtr link = RR->bc->getLinkBySocket(_policyAlias, _paths[i].p->localSocket()); - _paths[i].p->address().toString(curPathStr); uint8_t probabilitySegment = (_totalBondUnderload > 0) ? _paths[i].affinity : _paths[i].allocation; if (entropy <= probabilitySegment) { idx = i; @@ -566,15 +540,13 @@ bool Bond::assignFlowToBondedPath(SharedPtr& flow, int64_t now) } flow->assignPath(_abPathIdx, now); } - _paths[flow->assignedPath].p->address().toString(curPathStr); SharedPtr link = RR->bc->getLinkBySocket(_policyAlias, _paths[flow->assignedPath].p->localSocket()); - log("assign out-flow %x to link %s/%s (%lu / %lu flows)", flow->id, link->ifname().c_str(), curPathStr, _paths[flow->assignedPath].assignedFlowCount, (unsigned long)_flows.size()); + log("assign out-flow %04x to link %s (%lu / %lu flows)", flow->id, pathToStr(_paths[flow->assignedPath].p).c_str(), _paths[flow->assignedPath].assignedFlowCount, (unsigned long)_flows.size()); return true; } SharedPtr Bond::createFlow(int pathIdx, int32_t flowId, unsigned char entropy, int64_t now) { - char curPathStr[64] = { 0 }; if (! _numBondedPaths) { log("unable to assign flow %x (bond has no links)\n", flowId); return SharedPtr(); @@ -592,10 +564,8 @@ SharedPtr Bond::createFlow(int pathIdx, int32_t flowId, unsigned cha */ if (pathIdx != ZT_MAX_PEER_NETWORK_PATHS) { flow->assignPath(pathIdx, now); - _paths[pathIdx].p->address().toString(curPathStr); _paths[pathIdx].assignedFlowCount++; - SharedPtr link = RR->bc->getLinkBySocket(_policyAlias, _paths[flow->assignedPath].p->localSocket()); - log("assign in-flow %x to link %s/%s (%lu / %lu)", flow->id, link->ifname().c_str(), curPathStr, _paths[pathIdx].assignedFlowCount, (unsigned long)_flows.size()); + log("assign in-flow %x to link %s (%lu / %lu)", flow->id, pathToStr(_paths[pathIdx].p).c_str(), _paths[pathIdx].assignedFlowCount, (unsigned long)_flows.size()); } /** * Add a flow when no path was provided. This means that it is an outgoing packet @@ -679,7 +649,6 @@ void Bond::processIncomingPathNegotiationRequest(uint64_t now, SharedPtr& void Bond::pathNegotiationCheck(void* tPtr, int64_t now) { - char pathStr[64] = { 0 }; int maxInPathIdx = ZT_MAX_PEER_NETWORK_PATHS; int maxOutPathIdx = ZT_MAX_PEER_NETWORK_PATHS; uint64_t maxInCount = 0; @@ -717,8 +686,6 @@ void Bond::pathNegotiationCheck(void* tPtr, int64_t now) sendPATH_NEGOTIATION_REQUEST(tPtr, _paths[maxOutPathIdx].p); ++_numSentPathNegotiationRequests; _lastSentPathNegotiationRequest = now; - _paths[maxOutPathIdx].p->address().toString(pathStr); - SharedPtr link = RR->bc->getLinkBySocket(_policyAlias, _paths[maxOutPathIdx].p->localSocket()); // fprintf(stderr, "sending request to use %s on %s, ls=%llx, utility=%d\n", pathStr, link->ifname().c_str(), _paths[maxOutPathIdx].p->localSocket(), _localUtility); } } @@ -737,9 +704,7 @@ void Bond::pathNegotiationCheck(void* tPtr, int64_t now) void Bond::sendPATH_NEGOTIATION_REQUEST(void* tPtr, int pathIdx) { - char pathStr[64] = { 0 }; - _paths[pathIdx].p->address().toString(pathStr); - log("send link negotiation request to peer via link %s/%s, local utility is %d", getLink(_paths[pathIdx].p)->ifname().c_str(), pathStr, _localUtility); + log("send link negotiation request to peer via link %s, local utility is %d", pathToStr(_paths[pathIdx].p).c_str(), _localUtility); if (_abLinkSelectMethod != ZT_BOND_RESELECTION_POLICY_OPTIMIZE) { return; } @@ -753,8 +718,6 @@ void Bond::sendPATH_NEGOTIATION_REQUEST(void* tPtr, int pathIdx) void Bond::sendQOS_MEASUREMENT(void* tPtr, int pathIdx, int64_t localSocket, const InetAddress& atAddress, int64_t now) { - char pathStr[64] = { 0 }; - _paths[pathIdx].p->address().toString(pathStr); int64_t _now = RR->node->now(); Packet outp(_peer->_id.address(), RR->identity.address(), Packet::VERB_QOS_MEASUREMENT); char qosData[ZT_QOS_MAX_PACKET_SIZE]; @@ -772,7 +735,7 @@ void Bond::sendQOS_MEASUREMENT(void* tPtr, int pathIdx, int64_t localSocket, con _paths[pathIdx].packetsReceivedSinceLastQoS = 0; _paths[pathIdx].lastQoSMeasurement = now; } - // log("send QOS via link %s/%s (len=%d)", getLink(_paths[pathIdx].p)->ifname().c_str(), pathStr, len); + // log("send QOS via link %s (len=%d)", pathToStr(_paths[pathIdx].p).c_str(), len); } void Bond::processBackgroundBondTasks(void* tPtr, int64_t now) @@ -793,17 +756,14 @@ void Bond::processBackgroundBondTasks(void* tPtr, int64_t now) // Send ambient monitoring traffic for (unsigned int i = 0; i < ZT_MAX_PEER_NETWORK_PATHS; ++i) { if (_paths[i].p && _paths[i].allowed()) { - // ECHO (this is our bond's heartbeat) if ((_monitorInterval > 0) && ((now - _paths[i].p->_lastOut) >= _monitorInterval)) { if ((_peer->remoteVersionProtocol() >= 5) && (! ((_peer->remoteVersionMajor() == 1) && (_peer->remoteVersionMinor() == 1) && (_peer->remoteVersionRevision() == 0)))) { - Packet outp(_peer->address(), RR->identity.address(), Packet::VERB_ECHO); + Packet outp(_peer->address(), RR->identity.address(), Packet::VERB_ECHO); // ECHO (this is our bond's heartbeat) outp.armor(_peer->key(), true, _peer->aesKeysIfSupported()); RR->node->expectReplyTo(outp.packetId()); RR->node->putPacket(tPtr, _paths[i].p->localSocket(), _paths[i].p->address(), outp.data(), outp.size()); _overheadBytes += outp.size(); - char pathStr[64] = { 0 }; - _paths[i].p->address().toString(pathStr); - // log("send HELLO via link %s/%s (len=%d)", getLink(_paths[i].p)->ifname().c_str(), pathStr, outp.size()); + log("sent ECHO via link %s", pathToStr(_paths[i].p).c_str()); } } // QOS @@ -836,7 +796,6 @@ void Bond::processBackgroundBondTasks(void* tPtr, int64_t now) void Bond::curateBond(int64_t now, bool rebuildBond) { - char pathStr[64] = { 0 }; uint8_t tmpNumAliveLinks = 0; uint8_t tmpNumTotalLinks = 0; /** @@ -854,7 +813,7 @@ void Bond::curateBond(int64_t now, bool rebuildBond) } /** - * Determine alive-ness + * Determine aliveness */ _paths[i].alive = (now - _paths[i].p->_lastIn) < _failoverInterval; @@ -879,12 +838,11 @@ void Bond::curateBond(int64_t now, bool rebuildBond) * Note eligibility state change (if any) and take appropriate action */ if (currEligibility != _paths[i].eligible) { - _paths[i].p->address().toString(pathStr); if (currEligibility == 0) { - log("link %s/%s is no longer eligible", getLink(_paths[i].p)->ifname().c_str(), pathStr); + log("link %s is no longer eligible", pathToStr(_paths[i].p).c_str()); } if (currEligibility == 1) { - log("link %s/%s is eligible", getLink(_paths[i].p)->ifname().c_str(), pathStr); + log("link %s is eligible", pathToStr(_paths[i].p).c_str()); } dumpPathStatus(now, i); if (currEligibility) { @@ -894,8 +852,7 @@ void Bond::curateBond(int64_t now, bool rebuildBond) _paths[i].adjustRefractoryPeriod(now, _defaultPathRefractoryPeriod, ! currEligibility); if (_paths[i].bonded) { if (_allowFlowHashing) { - _paths[i].p->address().toString(pathStr); - log("link %s/%s was bonded, flow reallocation will occur soon", getLink(_paths[i].p)->ifname().c_str(), pathStr); + log("link %s was bonded, flow reallocation will occur soon", pathToStr(_paths[i].p).c_str()); rebuildBond = true; _paths[i].shouldReallocateFlows = _paths[i].bonded; } @@ -916,19 +873,13 @@ void Bond::curateBond(int64_t now, bool rebuildBond) _numTotalLinks = tmpNumTotalLinks; bool tmpHealthStatus = true; - if (_policy == ZT_BOND_POLICY_ACTIVE_BACKUP) { - if (_numAliveLinks < 2) { - // Considered healthy if there is at least one backup link - tmpHealthStatus = false; - } - } if (_policy == ZT_BOND_POLICY_BROADCAST) { if (_numAliveLinks < 1) { // Considered healthy if we're able to send frames at all tmpHealthStatus = false; } } - if ((_policy == ZT_BOND_POLICY_BALANCE_RR) || (_policy == ZT_BOND_POLICY_BALANCE_XOR) || (_policy == ZT_BOND_POLICY_BALANCE_AWARE)) { + if ((_policy == ZT_BOND_POLICY_BALANCE_RR) || (_policy == ZT_BOND_POLICY_BALANCE_XOR) || (_policy == ZT_BOND_POLICY_BALANCE_AWARE || (_policy == ZT_BOND_POLICY_ACTIVE_BACKUP))) { if (_numAliveLinks < _numTotalLinks) { tmpHealthStatus = false; } @@ -941,7 +892,7 @@ void Bond::curateBond(int64_t now, bool rebuildBond) else { healthStatusStr = "DEGRADED"; } - log("bond is in a %s state (links: %d/%d)", healthStatusStr.c_str(), _numAliveLinks, _numTotalLinks); + log("bond is %s (%d/%d links)", healthStatusStr.c_str(), _numAliveLinks, _numTotalLinks); dumpInfo(now, true); } @@ -958,7 +909,6 @@ void Bond::curateBond(int64_t now, bool rebuildBond) } if (rebuildBond) { log("rebuilding bond"); - // TODO: Obey blacklisting int updatedBondedPathCount = 0; // Build map associating paths with local physical links. Will be selected from in next step std::map, std::vector > linkMap; @@ -983,8 +933,7 @@ void Bond::curateBond(int64_t now, bool rebuildBond) } addPathToBond(idx, updatedBondedPathCount); ++updatedBondedPathCount; - _paths[idx].p->address().toString(pathStr); - log("add %s/%s (no user addr preference)", link->ifname().c_str(), pathStr); + log("add %s (no user addr preference)", pathToStr(_paths[idx].p).c_str()); } } // If the user prefers to only use one address type (IPv4 or IPv6) @@ -995,14 +944,12 @@ void Bond::curateBond(int64_t now, bool rebuildBond) continue; } if (! _paths[idx].allowed()) { - _paths[idx].p->address().toString(pathStr); - log("did not add %s/%s (user addr preference %d)", link->ifname().c_str(), pathStr, ipvPref); + log("did not add %s (user addr preference %d)", pathToStr(_paths[idx].p).c_str(), ipvPref); continue; } addPathToBond(idx, updatedBondedPathCount); ++updatedBondedPathCount; - _paths[idx].p->address().toString(pathStr); - log("add path %s/%s (user addr preference %d)", link->ifname().c_str(), pathStr, ipvPref); + log("add path %s (user addr preference %d)", pathToStr(_paths[idx].p).c_str(), ipvPref); } } // If the users prefers one address type to another, try to find at least @@ -1018,8 +965,7 @@ void Bond::curateBond(int64_t now, bool rebuildBond) if (_paths[idx].preferred()) { addPathToBond(idx, updatedBondedPathCount); ++updatedBondedPathCount; - _paths[idx].p->address().toString(pathStr); - log("add %s/%s (user addr preference %d)", link->ifname().c_str(), pathStr, ipvPref); + log("add %s (user addr preference %d)", pathToStr(_paths[idx].p).c_str(), ipvPref); foundPreferredPath = true; } } @@ -1033,8 +979,7 @@ void Bond::curateBond(int64_t now, bool rebuildBond) } addPathToBond(idx, updatedBondedPathCount); ++updatedBondedPathCount; - _paths[idx].p->address().toString(pathStr); - log("add %s/%s (user addr preference %d)", link->ifname().c_str(), pathStr, ipvPref); + log("add %s (user addr preference %d)", pathToStr(_paths[idx].p).c_str(), ipvPref); foundPreferredPath = true; } } @@ -1150,8 +1095,6 @@ void Bond::estimatePathQuality(int64_t now) void Bond::processBalanceTasks(int64_t now) { - char pathStr[64] = { 0 }; - if (_allowFlowHashing) { /** * Clean up and reset flows if necessary @@ -1176,8 +1119,7 @@ void Bond::processBalanceTasks(int64_t now) continue; } if (! _paths[i].eligible && _paths[i].shouldReallocateFlows) { - _paths[i].p->address().toString(pathStr); - log("reallocate flows from dead link %s/%s", getLink(_paths[i].p)->ifname().c_str(), pathStr); + log("reallocate flows from dead link %s", pathToStr(_paths[i].p).c_str()); std::map >::iterator flow_it = _flows.begin(); while (flow_it != _flows.end()) { if (_paths[flow_it->second->assignedPath].p == _paths[i].p) { @@ -1213,8 +1155,7 @@ void Bond::processBalanceTasks(int64_t now) continue; } if (_paths[i].p && _paths[i].bonded && _paths[i].eligible && (_paths[i].allocation < minimumAllocationValue) && _paths[i].assignedFlowCount) { - _paths[i].p->address().toString(pathStr); - log("reallocate flows from under-performing link %s/%s\n", getLink(_paths[i].p)->ifname().c_str(), pathStr); + log("reallocate flows from under-performing link %s\n", pathToStr(_paths[i].p).c_str()); std::map >::iterator flow_it = _flows.begin(); while (flow_it != _flows.end()) { if (flow_it->second->assignedPath == _paths[i].p) { @@ -1248,14 +1189,10 @@ void Bond::dequeueNextActiveBackupPath(uint64_t now) bool Bond::abForciblyRotateLink() { - char prevPathStr[64]; - char curPathStr[64]; if (_policy == ZT_BOND_POLICY_ACTIVE_BACKUP) { int prevPathIdx = _abPathIdx; - _paths[_abPathIdx].p->address().toString(prevPathStr); dequeueNextActiveBackupPath(RR->node->now()); - _paths[_abPathIdx].p->address().toString(curPathStr); - log("forcibly rotate link from %s/%s to %s/%s", getLink(_paths[prevPathIdx].p)->ifname().c_str(), prevPathStr, getLink(_paths[_abPathIdx].p)->ifname().c_str(), curPathStr); + log("active link rotated from %s to %s", pathToStr(_paths[prevPathIdx].p).c_str(), pathToStr(_paths[_abPathIdx].p).c_str()); return true; } return false; @@ -1263,9 +1200,6 @@ bool Bond::abForciblyRotateLink() void Bond::processActiveBackupTasks(void* tPtr, int64_t now) { - char pathStr[64] = { 0 }; - char prevPathStr[64]; - char curPathStr[64]; int prevActiveBackupPathIdx = _abPathIdx; int nonPreferredPathIdx; bool bFoundPrimaryLink = false; @@ -1279,11 +1213,10 @@ void Bond::processActiveBackupTasks(void* tPtr, int64_t now) log("no active link"); } else if (_paths[_abPathIdx].p) { - _paths[_abPathIdx].p->address().toString(curPathStr); - log("active link is %s/%s, failover queue size is %zu", getLink(_paths[_abPathIdx].p)->ifname().c_str(), curPathStr, _abFailoverQueue.size()); + log("active link is %s, failover queue size is %zu", pathToStr(_paths[_abPathIdx].p).c_str(), _abFailoverQueue.size()); } if (_abFailoverQueue.empty()) { - log("failover queue is empty, no longer fault-tolerant"); + log("failover queue is empty, bond is no longer fault-tolerant"); } } @@ -1303,10 +1236,9 @@ void Bond::processActiveBackupTasks(void* tPtr, int64_t now) log("no user-specified links"); for (int i = 0; i < ZT_MAX_PEER_NETWORK_PATHS; ++i) { if (_paths[i].p && _paths[i].eligible) { - _paths[i].p->address().toString(curPathStr); SharedPtr link = RR->bc->getLinkBySocket(_policyAlias, _paths[i].p->localSocket()); if (link) { - log("found eligible link %s/%s", getLink(_paths[i].p)->ifname().c_str(), curPathStr); + log("found eligible link %s", pathToStr(_paths[i].p).c_str()); _abPathIdx = i; break; } @@ -1326,18 +1258,16 @@ void Bond::processActiveBackupTasks(void* tPtr, int64_t now) SharedPtr link = RR->bc->getLinkBySocket(_policyAlias, _paths[i].p->localSocket()); if (_paths[i].eligible && link->primary()) { if (! _paths[i].preferred()) { - _paths[i].p->address().toString(curPathStr); // Found path on primary link, take note in case we don't find a preferred path nonPreferredPathIdx = i; bFoundPrimaryLink = true; } if (_paths[i].preferred()) { _abPathIdx = i; - _paths[_abPathIdx].p->address().toString(curPathStr); bFoundPrimaryLink = true; SharedPtr link = RR->bc->getLinkBySocket(_policyAlias, _paths[_abPathIdx].p->localSocket()); if (link) { - log("found preferred primary link %s/%s", getLink(_paths[_abPathIdx].p)->ifname().c_str(), curPathStr); + log("found preferred primary link %s", pathToStr(_paths[_abPathIdx].p).c_str()); } break; // Found preferred path on primary link } @@ -1363,8 +1293,7 @@ void Bond::processActiveBackupTasks(void* tPtr, int64_t now) if (_abPathIdx != ZT_MAX_PEER_NETWORK_PATHS) { SharedPtr link = RR->bc->getLinkBySocket(_policyAlias, _paths[_abPathIdx].p->localSocket()); if (link) { - _paths[_abPathIdx].p->address().toString(curPathStr); - log("select non-primary link %s/%s", getLink(_paths[_abPathIdx].p)->ifname().c_str(), curPathStr); + log("select non-primary link %s", pathToStr(_paths[_abPathIdx].p).c_str()); } } } @@ -1379,11 +1308,10 @@ void Bond::processActiveBackupTasks(void* tPtr, int64_t now) // Remove ineligible paths from the failover link queue for (std::deque::iterator it(_abFailoverQueue.begin()); it != _abFailoverQueue.end();) { if (_paths[(*it)].p && ! _paths[(*it)].eligible) { - _paths[(*it)].p->address().toString(curPathStr); SharedPtr link = RR->bc->getLinkBySocket(_policyAlias, _paths[(*it)].p->localSocket()); it = _abFailoverQueue.erase(it); if (link) { - log("link %s/%s is now ineligible, removing from failover queue (%zu links in queue)", getLink(_paths[_abPathIdx].p)->ifname().c_str(), curPathStr, _abFailoverQueue.size()); + log("link %s is ineligible, removing from failover queue (%zu links in queue)", pathToStr(_paths[_abPathIdx].p).c_str(), _abFailoverQueue.size()); } } else { @@ -1409,7 +1337,6 @@ void Bond::processActiveBackupTasks(void* tPtr, int64_t now) continue; } SharedPtr link = RR->bc->getLinkBySocket(_policyAlias, _paths[i].p->localSocket()); - _paths[i].p->address().toString(pathStr); int failoverScoreHandicap = _paths[i].failoverScore; if (_paths[i].preferred()) { @@ -1431,7 +1358,6 @@ void Bond::processActiveBackupTasks(void* tPtr, int64_t now) if (failoverLink) { for (int j = 0; j < ZT_MAX_PEER_NETWORK_PATHS; j++) { if (_paths[j].p && getLink(_paths[j].p) == failoverLink.ptr()) { - _paths[j].p->address().toString(pathStr); int inheritedHandicap = failoverScoreHandicap - 10; int newHandicap = _paths[j].failoverScore > inheritedHandicap ? _paths[j].failoverScore : inheritedHandicap; if (! _paths[j].preferred()) { @@ -1450,8 +1376,7 @@ void Bond::processActiveBackupTasks(void* tPtr, int64_t now) } if (! bFoundPathInQueue) { _abFailoverQueue.push_front(i); - _paths[i].p->address().toString(curPathStr); - log("add link %s/%s to failover queue (%zu links in queue)", getLink(_paths[_abPathIdx].p)->ifname().c_str(), curPathStr, _abFailoverQueue.size()); + log("add link %s to failover queue (%zu links in queue)", pathToStr(_paths[i].p).c_str(), _abFailoverQueue.size()); addPathToBond(0, i); } } @@ -1496,8 +1421,7 @@ void Bond::processActiveBackupTasks(void* tPtr, int64_t now) } if (! bFoundPathInQueue) { _abFailoverQueue.push_front(i); - _paths[i].p->address().toString(curPathStr); - log("add link %s/%s to failover queue (%zu links in queue)", getLink(_paths[i].p)->ifname().c_str(), curPathStr, _abFailoverQueue.size()); + log("add link %s to failover queue (%zu links in queue)", pathToStr(_paths[i].p).c_str(), _abFailoverQueue.size()); addPathToBond(0, i); } } @@ -1527,12 +1451,10 @@ void Bond::processActiveBackupTasks(void* tPtr, int64_t now) * Fulfill primary re-select obligations */ if (_paths[_abPathIdx].p && ! _paths[_abPathIdx].eligible) { // Implicit ZT_BOND_RESELECTION_POLICY_FAILURE - _paths[_abPathIdx].p->address().toString(curPathStr); - log("link %s/%s has failed, select link from failover queue (%zu links in queue)", getLink(_paths[_abPathIdx].p)->ifname().c_str(), curPathStr, _abFailoverQueue.size()); + log("link %s has failed, select link from failover queue (%zu links in queue)", pathToStr(_paths[_abPathIdx].p).c_str(), _abFailoverQueue.size()); if (! _abFailoverQueue.empty()) { dequeueNextActiveBackupPath(now); - _paths[_abPathIdx].p->address().toString(curPathStr); - log("active link switched to %s/%s", getLink(_paths[_abPathIdx].p)->ifname().c_str(), curPathStr); + log("active link switched to %s", pathToStr(_paths[_abPathIdx].p).c_str()); } else { log("failover queue is empty, no links to choose from"); @@ -1547,8 +1469,7 @@ void Bond::processActiveBackupTasks(void* tPtr, int64_t now) if (_abLinkSelectMethod == ZT_BOND_RESELECTION_POLICY_ALWAYS) { if (_paths[_abPathIdx].p && ! getLink(_paths[_abPathIdx].p)->primary() && getLink(_paths[_abFailoverQueue.front()].p)->primary()) { dequeueNextActiveBackupPath(now); - _paths[_abPathIdx].p->address().toString(curPathStr); - log("switch back to available primary link %s/%s (select: always)", getLink(_paths[_abPathIdx].p)->ifname().c_str(), curPathStr); + log("switch back to available primary link %s (select mode: always)", pathToStr(_paths[_abPathIdx].p).c_str()); } } if (_abLinkSelectMethod == ZT_BOND_RESELECTION_POLICY_BETTER) { @@ -1556,8 +1477,7 @@ void Bond::processActiveBackupTasks(void* tPtr, int64_t now) // Active backup has switched to "better" primary link according to re-select policy. if (getLink(_paths[_abFailoverQueue.front()].p)->primary() && (_paths[_abFailoverQueue.front()].failoverScore > _paths[_abPathIdx].failoverScore)) { dequeueNextActiveBackupPath(now); - _paths[_abPathIdx].p->address().toString(curPathStr); - log("switch back to user-defined primary link %s/%s (select: better)", getLink(_paths[_abPathIdx].p)->ifname().c_str(), curPathStr); + log("switch back to user-defined primary link %s (select mode: better)", pathToStr(_paths[_abPathIdx].p).c_str()); } } } @@ -1567,10 +1487,8 @@ void Bond::processActiveBackupTasks(void* tPtr, int64_t now) */ if (_paths[_abFailoverQueue.front()].negotiated) { dequeueNextActiveBackupPath(now); - _paths[_abPathIdx].p->address().toString(prevPathStr); _lastPathNegotiationCheck = now; - _paths[_abPathIdx].p->address().toString(curPathStr); - log("switch negotiated link %s/%s (select: optimize)", getLink(_paths[_abPathIdx].p)->ifname().c_str(), curPathStr); + log("switch negotiated link %s (select mode: optimize)", pathToStr(_paths[_abPathIdx].p).c_str()); } else { // Try to find a better path and automatically switch to it -- not too often, though. @@ -1583,18 +1501,12 @@ void Bond::processActiveBackupTasks(void* tPtr, int64_t now) int thresholdQuantity = (int)(ZT_BOND_ACTIVE_BACKUP_OPTIMIZE_MIN_THRESHOLD * (float)_paths[_abPathIdx].allocation); if ((failoverScoreDifference > 0) && (failoverScoreDifference > thresholdQuantity)) { SharedPtr oldPath = _paths[_abPathIdx].p; - _paths[_abPathIdx].p->address().toString(prevPathStr); dequeueNextActiveBackupPath(now); - _paths[_abPathIdx].p->address().toString(curPathStr); - log("ab", - "switch from %s/%s (score: %d) to better link %s/%s (score: %d) for peer %llx (select: optimize)", - getLink(oldPath)->ifname().c_str(), - prevPathStr, + log("switch from %s (score: %d) to better link %s (score: %d) (select mode: optimize)", + pathToStr(oldPath).c_str(), prevFScore, - getLink(_paths[_abPathIdx].p)->ifname().c_str(), - curPathStr, - newFScore, - _peerId); + pathToStr(_paths[_abPathIdx].p).c_str(), + newFScore); } } } @@ -1751,28 +1663,44 @@ SharedPtr Bond::getLink(const SharedPtr& path) return RR->bc->getLinkBySocket(_policyAlias, path->localSocket()); } +std::string Bond::pathToStr(const SharedPtr& path) +{ +#ifdef ZT_TRACE + char pathStr[64] = { 0 }; + char fullPathStr[256] = { 0 }; + path->address().toString(pathStr); + snprintf(fullPathStr, 256, "%.16llx-%s/%s", (unsigned long long)(path->localSocket()), getLink(path)->ifname().c_str(), pathStr); + return std::string(fullPathStr); +#else + return ""; +#endif +} + void Bond::dumpPathStatus(int64_t now, int pathIdx) { - char pathStr[64] = { 0 }; - _paths[pathIdx].p->address().toString(pathStr); - log("path status: [%2d] alive:%d, eli:%d, bonded:%d, flows:%6d, lat:%10.3f, jitter:%10.3f, error:%6.4f, loss:%6.4f, age:%6d alloc:%d--- (%s/%s)", +#ifdef ZT_TRACE + std::string aliveOrDead = _paths[pathIdx].alive ? std::string("alive") : std::string("dead"); + std::string eligibleOrNot = _paths[pathIdx].eligible ? std::string("eligible") : std::string("ineligible"); + std::string bondedOrNot = _paths[pathIdx].bonded ? std::string("bonded") : std::string("unbonded"); + log("path[%2d] --- %5s (%7d), %10s, %8s, flows=%-6d lat=%-8.3f pdv=%-7.3f err=%-6.4f loss=%-6.4f alloc=%-3d --- (%s)", pathIdx, - _paths[pathIdx].alive, - _paths[pathIdx].eligible, - _paths[pathIdx].bonded, + aliveOrDead.c_str(), + _paths[pathIdx].p->age(now), + eligibleOrNot.c_str(), + bondedOrNot.c_str(), _paths[pathIdx].assignedFlowCount, _paths[pathIdx].latencyMean, _paths[pathIdx].latencyVariance, _paths[pathIdx].packetErrorRatio, _paths[pathIdx].packetLossRatio, - _paths[pathIdx].p->age(now), _paths[pathIdx].allocation, - getLink(_paths[pathIdx].p)->ifname().c_str(), - pathStr); + pathToStr(_paths[pathIdx].p).c_str()); +#endif } void Bond::dumpInfo(int64_t now, bool force) { +#ifdef ZT_TRACE uint64_t timeSinceLastDump = now - _lastSummaryDump; if (! force && timeSinceLastDump < ZT_BOND_STATUS_INTERVAL) { return; @@ -1780,12 +1708,14 @@ void Bond::dumpInfo(int64_t now, bool force) _lastSummaryDump = now; float overhead = (_overheadBytes / (timeSinceLastDump / 1000.0f) / 1000.0f); _overheadBytes = 0; - log("bond status: bp: %d, fi: %d, mi: %d, ud: %d, dd: %d, flows: %lu, ambient: %f KB/s", _policy, _failoverInterval, _monitorInterval, _upDelay, _downDelay, (unsigned long)_flows.size(), overhead); + log("bond: bp=%d, fi=%d, mi=%d, ud=%d, dd=%d, flows=%lu, overhead=%f KB/s", _policy, _failoverInterval, _monitorInterval, _upDelay, _downDelay, (unsigned long)_flows.size(), overhead); for (int i = 0; i < ZT_MAX_PEER_NETWORK_PATHS; ++i) { if (_paths[i].p) { dumpPathStatus(now, i); } } + log(""); +#endif } } // namespace ZeroTier diff --git a/node/Bond.hpp b/node/Bond.hpp index 11e5980da..ec44da06b 100644 --- a/node/Bond.hpp +++ b/node/Bond.hpp @@ -518,6 +518,7 @@ class Bond { public: void dumpInfo(int64_t now, bool force); + std::string pathToStr(const SharedPtr& path); void dumpPathStatus(int64_t now, int pathIdx); SharedPtr getLink(const SharedPtr& path); @@ -1138,6 +1139,7 @@ class Bond { */ void log(const char* fmt, ...) { +#ifdef ZT_TRACE time_t rawtime; struct tm* timeinfo; char timestamp[80]; @@ -1157,6 +1159,7 @@ class Bond { va_end(args); RR->t->bondStateMessage(NULL, traceMsg); #undef MAX_MSG_LEN +#endif } private: