diff options
54 files changed, 739 insertions, 336 deletions
@@ -1,3 +1,60 @@ +2010-02-09 Tatsuhiro Tsujikawa <t-tujikawa@users.sourceforge.net> + + Wrapped logger->debug(...) with if(logger->debug()) { ... } + * src/AbstractCommand.cc + * src/AdaptiveURISelector.cc + * src/BtPieceMessage.cc + * src/BtPortMessage.cc + * src/CreateRequestCommand.cc + * src/DHTAbstractNodeLookupTask.cc + * src/DHTBucket.cc + * src/DHTGetPeersCommand.cc + * src/DHTMessageDispatcherImpl.cc + * src/DHTMessageFactoryImpl.cc + * src/DHTMessageTracker.cc + * src/DHTPeerAnnounceStorage.cc + * src/DHTRoutingTable.cc + * src/DHTSetup.cc + * src/DefaultBtAnnounce.cc + * src/DefaultBtInteractive.cc + * src/DefaultBtMessageDispatcher.cc + * src/DefaultBtMessageReceiver.cc + * src/DefaultBtProgressInfoFile.cc + * src/DefaultBtRequestFactory.cc + * src/DefaultPeerStorage.cc + * src/DefaultPieceStorage.cc + * src/DownloadCommand.cc + * src/DownloadEngine.cc + * src/EpollEventPoll.cc + * src/FileAllocationCommand.cc + * src/FileEntry.cc + * src/FtpNegotiationCommand.cc + * src/HandshakeExtensionMessage.cc + * src/HttpListenCommand.cc + * src/HttpServer.cc + * src/HttpSkipResponseCommand.cc + * src/IteratableChunkChecksumValidator.cc + * src/Logger.h + * src/MSEHandshake.cc + * src/MetalinkPostDownloadHandler.cc + * src/MultiDiskAdaptor.cc + * src/PeerAbstractCommand.cc + * src/PeerConnection.cc + * src/PeerListenCommand.cc + * src/PeerReceiveHandshakeCommand.cc + * src/RequestGroup.cc + * src/RequestGroupMan.cc + * src/SegmentMan.cc + * src/SelectEventPoll.cc + * src/ServerStat.cc + * src/SimpleBtMessage.cc + * src/SocketCore.cc + * src/TrackerWatcherCommand.cc + * src/UTMetadataDataExtensionMessage.cc + * src/UTMetadataRequestFactory.cc + * src/UTMetadataRequestTracker.cc + * src/XmlRpcMethod.cc + 2010-02-08 Tatsuhiro Tsujikawa <t-tujikawa@users.sourceforge.net> Changed log level from debug to info diff --git a/src/AbstractCommand.cc b/src/AbstractCommand.cc index f8055177..3294e50d 100644 --- a/src/AbstractCommand.cc +++ b/src/AbstractCommand.cc @@ -97,8 +97,10 @@ AbstractCommand::~AbstractCommand() { } bool AbstractCommand::execute() { - logger->debug("CUID#%d - socket: read:%d, write:%d, hup:%d, err:%d", - cuid, _readEvent, _writeEvent, _hupEvent, _errorEvent); + if(logger->debug()) { + logger->debug("CUID#%d - socket: read:%d, write:%d, hup:%d, err:%d", + cuid, _readEvent, _writeEvent, _hupEvent, _errorEvent); + } try { if(_requestGroup->downloadFinished() || _requestGroup->isHaltRequested()) { //logger->debug("CUID#%d - finished.", cuid); @@ -188,7 +190,9 @@ bool AbstractCommand::execute() { } } catch(DlAbortEx& err) { if(req.isNull()) { - logger->debug(EX_EXCEPTION_CAUGHT, err); + if(logger->debug()) { + logger->debug(EX_EXCEPTION_CAUGHT, err); + } } else { logger->error(MSG_DOWNLOAD_ABORTED, DL_ABORT_EX2(StringFormat @@ -240,13 +244,17 @@ void AbstractCommand::tryReserved() { // and there are no URI left. Because file length is unknown, we // can assume that there are no in-flight request object. if(entry->getLength() == 0 && entry->getRemainingUris().empty()) { - logger->debug("CUID#%d - Not trying next request." - " No reserved/pooled request is remaining and" - " total length is still unknown.", cuid); + if(logger->debug()) { + logger->debug("CUID#%d - Not trying next request." + " No reserved/pooled request is remaining and" + " total length is still unknown.", cuid); + } return; } } - logger->debug("CUID#%d - Trying reserved/pooled request.", cuid); + if(logger->debug()) { + logger->debug("CUID#%d - Trying reserved/pooled request.", cuid); + } Commands commands; _requestGroup->createNextCommand(commands, e, 1); e->setNoWait(true); @@ -259,8 +267,10 @@ bool AbstractCommand::prepareForRetry(time_t wait) { } if(!req.isNull()) { _fileEntry->poolRequest(req); - logger->debug("CUID#%d - Pooling request URI=%s", - cuid, req->getUrl().c_str()); + if(logger->debug()) { + logger->debug("CUID#%d - Pooling request URI=%s", + cuid, req->getUrl().c_str()); + } if(!_requestGroup->getSegmentMan().isNull()) { _requestGroup->getSegmentMan()->recognizeSegmentFor(_fileEntry); } @@ -286,8 +296,9 @@ void AbstractCommand::onAbort() { _fileEntry->removeIdenticalURI(req->getUrl()); _fileEntry->removeRequest(req); } - - logger->debug("CUID#%d - Aborting download", cuid); + if(logger->debug()) { + logger->debug("CUID#%d - Aborting download", cuid); + } if(!_requestGroup->getPieceStorage().isNull()) { _requestGroup->getSegmentMan()->cancelSegment(cuid); } @@ -446,9 +457,13 @@ SharedHandle<Request> AbstractCommand::createProxyRequest() const if(!proxy.empty()) { proxyRequest.reset(new Request()); if(proxyRequest->setUrl(proxy)) { - logger->debug("CUID#%d - Using proxy", cuid); + if(logger->debug()) { + logger->debug("CUID#%d - Using proxy", cuid); + } } else { - logger->debug("CUID#%d - Failed to parse proxy string", cuid); + if(logger->debug()) { + logger->debug("CUID#%d - Failed to parse proxy string", cuid); + } proxyRequest.reset(); } } diff --git a/src/AdaptiveURISelector.cc b/src/AdaptiveURISelector.cc index f631ff63..32d910b0 100644 --- a/src/AdaptiveURISelector.cc +++ b/src/AdaptiveURISelector.cc @@ -74,8 +74,10 @@ AdaptiveURISelector::~AdaptiveURISelector() {} std::string AdaptiveURISelector::select(FileEntry* fileEntry) { - _logger->debug("AdaptiveURISelector: called %d", - _requestGroup->getNumConnection()); + if(_logger->debug()) { + _logger->debug("AdaptiveURISelector: called %d", + _requestGroup->getNumConnection()); + } std::deque<std::string>& uris = fileEntry->getRemainingUris(); if (uris.empty() && _requestGroup->getNumConnection() <= 1) { // here we know the download will fail, trying to find previously @@ -103,11 +105,13 @@ void AdaptiveURISelector::mayRetryWithIncreasedTimeout(FileEntry* fileEntry) std::transform(timeouts.begin(), timeouts.end(), std::back_inserter(uris), std::mem_fun_ref(&URIResult::getURI)); - for(std::deque<std::string>::const_iterator i = uris.begin(); i != uris.end(); - ++i) { - _logger->debug("AdaptiveURISelector: will retry server with increased" - " timeout (%d s): %s", - _requestGroup->getTimeout(), (*i).c_str()); + if(_logger->debug()) { + for(std::deque<std::string>::const_iterator i = uris.begin(); + i != uris.end(); ++i) { + _logger->debug("AdaptiveURISelector: will retry server with increased" + " timeout (%d s): %s", + _requestGroup->getTimeout(), (*i).c_str()); + } } } @@ -132,8 +136,10 @@ std::string AdaptiveURISelector::selectOne(const std::deque<std::string>& uris) if(getNbTestedServers(uris) < 3) { std::string notTested = getFirstNotTestedUri(uris); if(notTested != A2STR::NIL) { - _logger->debug("AdaptiveURISelector: choosing the first non tested" - " mirror: %s", notTested.c_str()); + if(_logger->debug()) { + _logger->debug("AdaptiveURISelector: choosing the first non tested" + " mirror: %s", notTested.c_str()); + } --_nbServerToEvaluate; return notTested; } @@ -144,16 +150,21 @@ std::string AdaptiveURISelector::selectOne(const std::deque<std::string>& uris) std::string notTested = getFirstNotTestedUri(uris); if(notTested != A2STR::NIL) { /* Here we return the first untested mirror */ - _logger->debug("AdaptiveURISelector: choosing non tested mirror %s for" - " connection #%d", notTested.c_str(), _nbConnections); + if(_logger->debug()) { + _logger->debug("AdaptiveURISelector: choosing non tested mirror %s" + " for connection #%d", + notTested.c_str(), _nbConnections); + } return notTested; } else { /* Here we return a mirror which need to be tested again */ std::string toReTest = getFirstToTestUri(uris); if(toReTest != A2STR::NIL) { - _logger->debug("AdaptiveURISelector: choosing mirror %s which has not" - " been tested recently for connection #%d", - toReTest.c_str(), _nbConnections); + if(_logger->debug()) { + _logger->debug("AdaptiveURISelector: choosing mirror %s which has" + " not been tested recently for connection #%d", + toReTest.c_str(), _nbConnections); + } return toReTest; } else { return getBestMirror(uris); @@ -176,15 +187,19 @@ std::string AdaptiveURISelector::getBestMirror if (bests.size() < 2) { std::string uri = getMaxDownloadSpeedUri(uris); - _logger->debug("AdaptiveURISelector: choosing the best mirror :" - " %.2fKB/s %s (other mirrors are at least 25%% slower)", - (float) max/1024, uri.c_str()); + if(_logger->debug()) { + _logger->debug("AdaptiveURISelector: choosing the best mirror :" + " %.2fKB/s %s (other mirrors are at least 25%% slower)", + (float) max/1024, uri.c_str()); + } return uri; } else { std::string uri = selectRandomUri(bests); - _logger->debug("AdaptiveURISelector: choosing randomly one of the best" - " mirrors (range [%.2fKB/s, %.2fKB/s]): %s", - (float) min/1024, (float) max/1024, uri.c_str()); + if(_logger->debug()) { + _logger->debug("AdaptiveURISelector: choosing randomly one of the best" + " mirrors (range [%.2fKB/s, %.2fKB/s]): %s", + (float) min/1024, (float) max/1024, uri.c_str()); + } return uri; } } diff --git a/src/BtPieceMessage.cc b/src/BtPieceMessage.cc index ac08847a..93520f7e 100644 --- a/src/BtPieceMessage.cc +++ b/src/BtPieceMessage.cc @@ -88,13 +88,18 @@ void BtPieceMessage::doReceivedAction() { peer->snubbing(false); PieceHandle piece = pieceStorage->getPiece(index); off_t offset = (off_t)index*_downloadContext->getPieceLength()+begin; - logger->debug(MSG_PIECE_RECEIVED, - cuid, index, begin, blockLength, offset, slot.getBlockIndex()); + if(logger->debug()) { + logger->debug(MSG_PIECE_RECEIVED, + cuid, index, begin, blockLength, offset, + slot.getBlockIndex()); + } pieceStorage->getDiskAdaptor()->writeData(block, blockLength, offset); piece->completeBlock(slot.getBlockIndex()); - logger->debug(MSG_PIECE_BITFIELD, cuid, - util::toHex(piece->getBitfield(), - piece->getBitfieldLength()).c_str()); + if(logger->debug()) { + logger->debug(MSG_PIECE_BITFIELD, cuid, + util::toHex(piece->getBitfield(), + piece->getBitfieldLength()).c_str()); + } piece->updateHash(begin, block, blockLength); dispatcher->removeOutstandingRequest(slot); if(piece->pieceComplete()) { @@ -105,8 +110,10 @@ void BtPieceMessage::doReceivedAction() { } } } else { - logger->debug("CUID#%d - RequestSlot not found, index=%d, begin=%d", - cuid, index, begin); + if(logger->debug()) { + logger->debug("CUID#%d - RequestSlot not found, index=%d, begin=%d", + cuid, index, begin); + } } } @@ -147,9 +154,11 @@ void BtPieceMessage::send() { off_t pieceDataOffset = (off_t)index*_downloadContext->getPieceLength()+begin; size_t writtenLength = sendPieceData(pieceDataOffset, blockLength); - logger->debug("msglength = %lu bytes", - static_cast<unsigned long>(getMessageHeaderLength()+ - blockLength)); + if(logger->debug()) { + logger->debug("msglength = %lu bytes", + static_cast<unsigned long>(getMessageHeaderLength()+ + blockLength)); + } peer->updateUploadLength(writtenLength); } else { ssize_t writtenLength = peerConnection->sendPendingData(); @@ -176,8 +185,10 @@ std::string BtPieceMessage::toString() const { bool BtPieceMessage::checkPieceHash(const PieceHandle& piece) { if(piece->isHashCalculated()) { - logger->debug("Hash is available!! index=%lu", - static_cast<unsigned long>(piece->getIndex())); + if(logger->debug()) { + logger->debug("Hash is available!! index=%lu", + static_cast<unsigned long>(piece->getIndex())); + } return piece->getHashString()==_downloadContext->getPieceHash(piece->getIndex()); } else { @@ -222,12 +233,9 @@ void BtPieceMessage::onChokingEvent(const BtChokingEvent& event) if(!invalidate && !sendingInProgress && !peer->isInAmAllowedIndexSet(index)) { - logger->debug(MSG_REJECT_PIECE_CHOKED, - cuid, - index, - begin, - blockLength); - + if(logger->debug()) { + logger->debug(MSG_REJECT_PIECE_CHOKED, cuid, index, begin, blockLength); + } if(peer->isFastExtensionEnabled()) { BtMessageHandle rej = messageFactory->createRejectMessage(index, begin, @@ -246,8 +254,9 @@ void BtPieceMessage::onCancelSendingPieceEvent index == event.getIndex() && begin == event.getBegin() && blockLength == event.getLength()) { - logger->debug(MSG_REJECT_PIECE_CANCEL, - cuid, index, begin, blockLength); + if(logger->debug()) { + logger->debug(MSG_REJECT_PIECE_CANCEL, cuid, index, begin, blockLength); + } if(peer->isFastExtensionEnabled()) { BtMessageHandle rej = messageFactory->createRejectMessage(index, begin, diff --git a/src/BtPortMessage.cc b/src/BtPortMessage.cc index b21f6565..bca7b14f 100644 --- a/src/BtPortMessage.cc +++ b/src/BtPortMessage.cc @@ -72,7 +72,9 @@ void BtPortMessage::doReceivedAction() { if(!_taskFactory.isNull() && !_taskQueue.isNull()) { if(_port == 0) { - logger->debug("Ignored port 0."); + if(logger->debug()) { + logger->debug("Ignored port 0."); + } return; } // node id is random at this point. When ping reply received, new DHTNode diff --git a/src/CreateRequestCommand.cc b/src/CreateRequestCommand.cc index bfcec970..b41189d9 100644 --- a/src/CreateRequestCommand.cc +++ b/src/CreateRequestCommand.cc @@ -111,7 +111,9 @@ bool CreateRequestCommand::prepareForRetry(time_t wait) if(!_requestGroup->getPieceStorage().isNull()) { _requestGroup->getSegmentMan()->cancelSegment(cuid); } - logger->debug("CUID#%d - Reusing CreateRequestCommand", cuid); + if(logger->debug()) { + logger->debug("CUID#%d - Reusing CreateRequestCommand", cuid); + } SleepCommand* scom = new SleepCommand(cuid, e, _requestGroup, this, wait); e->commands.push_back(scom); return false; diff --git a/src/DHTAbstractNodeLookupTask.cc b/src/DHTAbstractNodeLookupTask.cc index 459074ce..f828c4dc 100644 --- a/src/DHTAbstractNodeLookupTask.cc +++ b/src/DHTAbstractNodeLookupTask.cc @@ -71,16 +71,21 @@ void DHTAbstractNodeLookupTask::onReceived(const SharedHandle<DHTMessage>& messa if(memcmp(_localNode->getID(), (*i)->_node->getID(), DHT_ID_LENGTH) != 0) { _entries.push_front(*i); ++count; - _logger->debug("Received nodes: id=%s, ip=%s", - util::toHex((*i)->_node->getID(), DHT_ID_LENGTH).c_str(), - (*i)->_node->getIPAddress().c_str()); + if(_logger->debug()) { + _logger->debug("Received nodes: id=%s, ip=%s", + util::toHex((*i)->_node->getID(), DHT_ID_LENGTH).c_str(), + (*i)->_node->getIPAddress().c_str()); + } } } - - _logger->debug("%u node lookup entries added.", count); + if(_logger->debug()) { + _logger->debug("%u node lookup entries added.", count); + } std::stable_sort(_entries.begin(), _entries.end(), DHTIDCloser(_targetID)); _entries.erase(std::unique(_entries.begin(), _entries.end()), _entries.end()); - _logger->debug("%u node lookup entries are unique.", _entries.size()); + if(_logger->debug()) { + _logger->debug("%u node lookup entries are unique.", _entries.size()); + } if(_entries.size() > DHTBucket::K) { _entries.erase(_entries.begin()+DHTBucket::K, _entries.end()); } @@ -89,8 +94,10 @@ void DHTAbstractNodeLookupTask::onReceived(const SharedHandle<DHTMessage>& messa void DHTAbstractNodeLookupTask::onTimeout(const SharedHandle<DHTNode>& node) { - _logger->debug("node lookup message timeout for node ID=%s", - util::toHex(node->getID(), DHT_ID_LENGTH).c_str()); + if(_logger->debug()) { + _logger->debug("node lookup message timeout for node ID=%s", + util::toHex(node->getID(), DHT_ID_LENGTH).c_str()); + } --_inFlightMessage; for(std::deque<SharedHandle<DHTNodeLookupEntry> >::iterator i = _entries.begin(); i != _entries.end(); ++i) { if((*i)->_node == node) { @@ -107,15 +114,19 @@ void DHTAbstractNodeLookupTask::sendMessageAndCheckFinish() sendMessage(); } if(_inFlightMessage == 0) { - _logger->debug("Finished node_lookup for node ID %s", - util::toHex(_targetID, DHT_ID_LENGTH).c_str()); + if(_logger->debug()) { + _logger->debug("Finished node_lookup for node ID %s", + util::toHex(_targetID, DHT_ID_LENGTH).c_str()); + } onFinish(); updateBucket(); _finished = true; } else { - _logger->debug("%d in flight message for node ID %s", - _inFlightMessage, - util::toHex(_targetID, DHT_ID_LENGTH).c_str()); + if(_logger->debug()) { + _logger->debug("%d in flight message for node ID %s", + _inFlightMessage, + util::toHex(_targetID, DHT_ID_LENGTH).c_str()); + } } } @@ -151,7 +162,9 @@ void DHTAbstractNodeLookupTask::startup() _inFlightMessage = 0; sendMessage(); if(_inFlightMessage == 0) { - _logger->debug("No message was sent in this lookup stage. Finished."); + if(_logger->debug()) { + _logger->debug("No message was sent in this lookup stage. Finished."); + } _finished = true; } } diff --git a/src/DHTBucket.cc b/src/DHTBucket.cc index 527c7751..724a14e7 100644 --- a/src/DHTBucket.cc +++ b/src/DHTBucket.cc @@ -201,15 +201,16 @@ SharedHandle<DHTBucket> DHTBucket::split() } _nodes = lNodes; // TODO create toString() and use it. - _logger->debug("New bucket. prefixLength=%u, Range:%s-%s", - static_cast<unsigned int>(rBucket->getPrefixLength()), - util::toHex(rBucket->getMinID(), DHT_ID_LENGTH).c_str(), - util::toHex(rBucket->getMaxID(), DHT_ID_LENGTH).c_str()); - _logger->debug("Existing bucket. prefixLength=%u, Range:%s-%s", - static_cast<unsigned int>(_prefixLength), - util::toHex(getMinID(), DHT_ID_LENGTH).c_str(), - util::toHex(getMaxID(), DHT_ID_LENGTH).c_str()); - + if(_logger->debug()) { + _logger->debug("New bucket. prefixLength=%u, Range:%s-%s", + static_cast<unsigned int>(rBucket->getPrefixLength()), + util::toHex(rBucket->getMinID(), DHT_ID_LENGTH).c_str(), + util::toHex(rBucket->getMaxID(), DHT_ID_LENGTH).c_str()); + _logger->debug("Existing bucket. prefixLength=%u, Range:%s-%s", + static_cast<unsigned int>(_prefixLength), + util::toHex(getMinID(), DHT_ID_LENGTH).c_str(), + util::toHex(getMaxID(), DHT_ID_LENGTH).c_str()); + } return rBucket; } diff --git a/src/DHTGetPeersCommand.cc b/src/DHTGetPeersCommand.cc index 01383763..34d7d631 100644 --- a/src/DHTGetPeersCommand.cc +++ b/src/DHTGetPeersCommand.cc @@ -74,8 +74,11 @@ bool DHTGetPeersCommand::execute() if(_task.isNull() && ((_numRetry > 0 && _lastGetPeerTime.elapsed(RETRY_INTERVAL)) || _lastGetPeerTime.elapsed(GET_PEER_INTERVAL))) { - logger->debug("Issuing PeerLookup for infoHash=%s", - bittorrent::getInfoHashString(_requestGroup->getDownloadContext()).c_str()); + if(logger->debug()) { + logger->debug("Issuing PeerLookup for infoHash=%s", + bittorrent::getInfoHashString + (_requestGroup->getDownloadContext()).c_str()); + } _task = _taskFactory->createPeerLookupTask (_requestGroup->getDownloadContext(), _btRuntime, _peerStorage); _taskQueue->addPeriodicTask2(_task); diff --git a/src/DHTMessageDispatcherImpl.cc b/src/DHTMessageDispatcherImpl.cc index 29662f88..92df5cd4 100644 --- a/src/DHTMessageDispatcherImpl.cc +++ b/src/DHTMessageDispatcherImpl.cc @@ -105,8 +105,10 @@ void DHTMessageDispatcherImpl::sendMessages() } } _messageQueue.erase(_messageQueue.begin(), itr); - _logger->debug("%lu dht messages remaining in the queue.", - static_cast<unsigned long>(_messageQueue.size())); + if(_logger->debug()) { + _logger->debug("%lu dht messages remaining in the queue.", + static_cast<unsigned long>(_messageQueue.size())); + } } size_t DHTMessageDispatcherImpl::countMessageInQueue() const diff --git a/src/DHTMessageFactoryImpl.cc b/src/DHTMessageFactoryImpl.cc index 27ebf211..6e3c69ae 100644 --- a/src/DHTMessageFactoryImpl.cc +++ b/src/DHTMessageFactoryImpl.cc @@ -236,7 +236,9 @@ DHTMessageFactoryImpl::createResponseMessage(const std::string& messageType, util::itos(getInteger(e, 0).i()).c_str(), util::urlencode(getString(e, 1).s()).c_str()); } else { - _logger->debug("e doesn't have 2 elements."); + if(_logger->debug()) { + _logger->debug("e doesn't have 2 elements."); + } } throw DL_ABORT_EX("Received Error DHT message."); } else if(y.s() != DHTResponseMessage::R) { diff --git a/src/DHTMessageTracker.cc b/src/DHTMessageTracker.cc index 4b112ce7..e8d7b67e 100644 --- a/src/DHTMessageTracker.cc +++ b/src/DHTMessageTracker.cc @@ -77,14 +77,18 @@ DHTMessageTracker::messageArrived(const BDE& dict, throw DL_ABORT_EX(StringFormat("Malformed DHT message. From:%s:%u", ipaddr.c_str(), port).str()); } - _logger->debug("Searching tracker entry for TransactionID=%s, Remote=%s:%u", - util::toHex(tid.s()).c_str(), ipaddr.c_str(), port); + if(_logger->debug()) { + _logger->debug("Searching tracker entry for TransactionID=%s, Remote=%s:%u", + util::toHex(tid.s()).c_str(), ipaddr.c_str(), port); + } for(std::deque<SharedHandle<DHTMessageTrackerEntry> >::iterator i = _entries.begin(); i != _entries.end(); ++i) { if((*i)->match(tid.s(), ipaddr, port)) { SharedHandle<DHTMessageTrackerEntry> entry = *i; _entries.erase(i); - _logger->debug("Tracker entry found."); + if(_logger->debug()) { + _logger->debug("Tracker entry found."); + } SharedHandle<DHTNode> targetNode = entry->getTargetNode(); SharedHandle<DHTMessage> message = @@ -93,13 +97,17 @@ DHTMessageTracker::messageArrived(const BDE& dict, targetNode->getPort()); int64_t rtt = entry->getElapsedMillis(); - _logger->debug("RTT is %s", util::itos(rtt).c_str()); + if(_logger->debug()) { + _logger->debug("RTT is %s", util::itos(rtt).c_str()); + } message->getRemoteNode()->updateRTT(rtt); SharedHandle<DHTMessageCallback> callback = entry->getCallback(); return std::pair<SharedHandle<DHTMessage>, SharedHandle<DHTMessageCallback> >(message, callback); } } - _logger->debug("Tracker entry not found."); + if(_logger->debug()) { + _logger->debug("Tracker entry not found."); + } return std::pair<SharedHandle<DHTMessage>, SharedHandle<DHTMessageCallback> >(); } @@ -112,13 +120,17 @@ void DHTMessageTracker::handleTimeout() SharedHandle<DHTMessageTrackerEntry> entry = *i; i = _entries.erase(i); SharedHandle<DHTNode> node = entry->getTargetNode(); - _logger->debug("Message timeout: To:%s:%u", - node->getIPAddress().c_str(), node->getPort()); + if(_logger->debug()) { + _logger->debug("Message timeout: To:%s:%u", + node->getIPAddress().c_str(), node->getPort()); + } node->updateRTT(entry->getElapsedMillis()); node->timeout(); if(node->isBad()) { - _logger->debug("Marked bad: %s:%u", - node->getIPAddress().c_str(), node->getPort()); + if(_logger->debug()) { + _logger->debug("Marked bad: %s:%u", + node->getIPAddress().c_str(), node->getPort()); + } _routingTable->dropNode(node); } SharedHandle<DHTMessageCallback> callback = entry->getCallback(); diff --git a/src/DHTPeerAnnounceStorage.cc b/src/DHTPeerAnnounceStorage.cc index e9f18deb..e8153869 100644 --- a/src/DHTPeerAnnounceStorage.cc +++ b/src/DHTPeerAnnounceStorage.cc @@ -86,8 +86,11 @@ void DHTPeerAnnounceStorage::addPeerAnnounce(const unsigned char* infoHash, const std::string& ipaddr, uint16_t port) { - _logger->debug("Adding %s:%u to peer announce list: infoHash=%s", - ipaddr.c_str(), port, util::toHex(infoHash, DHT_ID_LENGTH).c_str()); + if(_logger->debug()) { + _logger->debug("Adding %s:%u to peer announce list: infoHash=%s", + ipaddr.c_str(), port, + util::toHex(infoHash, DHT_ID_LENGTH).c_str()); + } getPeerAnnounceEntry(infoHash)->addPeerAddrEntry(PeerAddrEntry(ipaddr, port)); } @@ -123,27 +126,34 @@ public: void DHTPeerAnnounceStorage::handleTimeout() { - _logger->debug("Now purge peer announces(%lu entries) which are timed out.", - static_cast<unsigned long>(_entries.size())); - + if(_logger->debug()) { + _logger->debug("Now purge peer announces(%lu entries) which are timed out.", + static_cast<unsigned long>(_entries.size())); + } std::for_each(_entries.begin(), _entries.end(), RemoveStalePeerAddrEntry()); _entries.erase(std::remove_if(_entries.begin(), _entries.end(), mem_fun_sh(&DHTPeerAnnounceEntry::empty)), _entries.end()); - _logger->debug("Currently %lu peer announce entries", - static_cast<unsigned long>(_entries.size())); + if(_logger->debug()) { + _logger->debug("Currently %lu peer announce entries", + static_cast<unsigned long>(_entries.size())); + } } void DHTPeerAnnounceStorage::announcePeer() { - _logger->debug("Now announcing peer."); + if(_logger->debug()) { + _logger->debug("Now announcing peer."); + } for(std::deque<SharedHandle<DHTPeerAnnounceEntry> >::iterator i = _entries.begin(); i != _entries.end(); ++i) { if((*i)->getLastUpdated().elapsed(DHT_PEER_ANNOUNCE_INTERVAL)) { (*i)->notifyUpdate(); SharedHandle<DHTTask> task = _taskFactory->createPeerAnnounceTask((*i)->getInfoHash()); _taskQueue->addPeriodicTask2(task); - _logger->debug("Added 1 peer announce: infoHash=%s", - util::toHex((*i)->getInfoHash(), DHT_ID_LENGTH).c_str()); + if(_logger->debug()) { + _logger->debug("Added 1 peer announce: infoHash=%s", + util::toHex((*i)->getInfoHash(), DHT_ID_LENGTH).c_str()); + } } } } diff --git a/src/DHTRoutingTable.cc b/src/DHTRoutingTable.cc index 1f41a2dc..20ed75d7 100644 --- a/src/DHTRoutingTable.cc +++ b/src/DHTRoutingTable.cc @@ -74,22 +74,30 @@ bool DHTRoutingTable::addGoodNode(const SharedHandle<DHTNode>& node) bool DHTRoutingTable::addNode(const SharedHandle<DHTNode>& node, bool good) { - _logger->debug("Trying to add node:%s", node->toString().c_str()); + if(_logger->debug()) { + _logger->debug("Trying to add node:%s", node->toString().c_str()); + } if(_localNode == node) { - _logger->debug("Adding node with the same ID with localnode is not" - " allowed."); + if(_logger->debug()) { + _logger->debug("Adding node with the same ID with localnode is not" + " allowed."); + } return false; } BNode* bnode = BNode::findBNodeFor(_root, node->getID()); SharedHandle<DHTBucket> bucket = bnode->getBucket(); while(1) { if(bucket->addNode(node)) { - _logger->debug("Added DHTNode."); + if(_logger->debug()) { + _logger->debug("Added DHTNode."); + } return true; } else if(bucket->splitAllowed()) { - _logger->debug("Splitting bucket. Range:%s-%s", - util::toHex(bucket->getMinID(), DHT_ID_LENGTH).c_str(), - util::toHex(bucket->getMaxID(), DHT_ID_LENGTH).c_str()); + if(_logger->debug()) { + _logger->debug("Splitting bucket. Range:%s-%s", + util::toHex(bucket->getMinID(), DHT_ID_LENGTH).c_str(), + util::toHex(bucket->getMaxID(), DHT_ID_LENGTH).c_str()); + } SharedHandle<DHTBucket> r = bucket->split(); bnode->setBucket(SharedHandle<DHTBucket>()); @@ -108,7 +116,9 @@ bool DHTRoutingTable::addNode(const SharedHandle<DHTNode>& node, bool good) } else { if(good) { bucket->cacheNode(node); - _logger->debug("Cached node=%s", node->toString().c_str()); + if(_logger->debug()) { + _logger->debug("Cached node=%s", node->toString().c_str()); + } } return false; } diff --git a/src/DHTSetup.cc b/src/DHTSetup.cc index 7f2406e0..788b7a2f 100644 --- a/src/DHTSetup.cc +++ b/src/DHTSetup.cc @@ -118,9 +118,10 @@ void DHTSetup::setup(std::deque<Command*>& commands, } localNode->setPort(port); } - _logger->debug("Initialized local node ID=%s", - util::toHex(localNode->getID(), DHT_ID_LENGTH).c_str()); - + if(_logger->debug()) { + _logger->debug("Initialized local node ID=%s", + util::toHex(localNode->getID(), DHT_ID_LENGTH).c_str()); + } SharedHandle<DHTRoutingTable> routingTable(new DHTRoutingTable(localNode)); SharedHandle<DHTMessageFactoryImpl> factory(new DHTMessageFactoryImpl()); diff --git a/src/DefaultBtAnnounce.cc b/src/DefaultBtAnnounce.cc index f42e94c9..3f2465d5 100644 --- a/src/DefaultBtAnnounce.cc +++ b/src/DefaultBtAnnounce.cc @@ -211,7 +211,9 @@ void DefaultBtAnnounce::processAnnounceResponse(const unsigned char* trackerResponse, size_t trackerResponseLength) { - logger->debug("Now processing tracker response."); + if(logger->debug()) { + logger->debug("Now processing tracker response."); + } const BDE dict = bencode::decode(trackerResponse, trackerResponseLength); if(!dict.isDict()) { @@ -229,17 +231,23 @@ DefaultBtAnnounce::processAnnounceResponse(const unsigned char* trackerResponse, const BDE& tid = dict[BtAnnounce::TRACKER_ID]; if(tid.isString()) { trackerId = tid.s(); - logger->debug("Tracker ID:%s", trackerId.c_str()); + if(logger->debug()) { + logger->debug("Tracker ID:%s", trackerId.c_str()); + } } const BDE& ival = dict[BtAnnounce::INTERVAL]; if(ival.isInteger() && ival.i() > 0) { interval = ival.i(); - logger->debug("Interval:%d", interval); + if(logger->debug()) { + logger->debug("Interval:%d", interval); + } } const BDE& mival = dict[BtAnnounce::MIN_INTERVAL]; if(mival.isInteger() && mival.i() > 0) { minInterval = mival.i(); - logger->debug("Min interval:%d", minInterval); + if(logger->debug()) { + logger->debug("Min interval:%d", minInterval); + } if(minInterval > interval) { minInterval = interval; } @@ -250,12 +258,16 @@ DefaultBtAnnounce::processAnnounceResponse(const unsigned char* trackerResponse, const BDE& comp = dict[BtAnnounce::COMPLETE]; if(comp.isInteger()) { complete = comp.i(); - logger->debug("Complete:%d", complete); + if(logger->debug()) { + logger->debug("Complete:%d", complete); + } } const BDE& incomp = dict[BtAnnounce::INCOMPLETE]; if(incomp.isInteger()) { incomplete = incomp.i(); - logger->debug("Incomplete:%d", incomplete); + if(logger->debug()) { + logger->debug("Incomplete:%d", incomplete); + } } const BDE& peerData = dict[BtAnnounce::PEERS]; if(peerData.isNone()) { diff --git a/src/DefaultBtInteractive.cc b/src/DefaultBtInteractive.cc index bb1cf183..83ec725c 100644 --- a/src/DefaultBtInteractive.cc +++ b/src/DefaultBtInteractive.cc @@ -302,13 +302,17 @@ size_t DefaultBtInteractive::receiveMessages() { void DefaultBtInteractive::decideInterest() { if(_pieceStorage->hasMissingPiece(peer)) { if(!peer->amInterested()) { - logger->debug(MSG_PEER_INTERESTED, cuid); + if(logger->debug()) { + logger->debug(MSG_PEER_INTERESTED, cuid); + } dispatcher-> addMessageToQueue(messageFactory->createInterestedMessage()); } } else { if(peer->amInterested()) { - logger->debug(MSG_PEER_NOT_INTERESTED, cuid); + if(logger->debug()) { + logger->debug(MSG_PEER_NOT_INTERESTED, cuid); + } dispatcher-> addMessageToQueue(messageFactory->createNotInterestedMessage()); } @@ -377,8 +381,10 @@ void DefaultBtInteractive::cancelAllPiece() { _utMetadataRequestTracker->getAllTrackedIndex(); for(std::vector<size_t>::const_iterator i = metadataRequests.begin(); i != metadataRequests.end(); ++i) { - logger->debug("Cancel metadata: piece=%lu", - static_cast<unsigned long>(*i)); + if(logger->debug()) { + logger->debug("Cancel metadata: piece=%lu", + static_cast<unsigned long>(*i)); + } _pieceStorage->cancelPiece(_pieceStorage->getPiece(*i)); } } diff --git a/src/DefaultBtMessageDispatcher.cc b/src/DefaultBtMessageDispatcher.cc index 22e96d32..d3e96244 100644 --- a/src/DefaultBtMessageDispatcher.cc +++ b/src/DefaultBtMessageDispatcher.cc @@ -64,7 +64,9 @@ DefaultBtMessageDispatcher::DefaultBtMessageDispatcher(): DefaultBtMessageDispatcher::~DefaultBtMessageDispatcher() { - logger->debug("DefaultBtMessageDispatcher::deleted"); + if(logger->debug()) { + logger->debug("DefaultBtMessageDispatcher::deleted"); + } } void DefaultBtMessageDispatcher::addMessageToQueue(const BtMessageHandle& btMessage) @@ -144,11 +146,13 @@ public: void operator()(const RequestSlot& slot) const { - _logger->debug(MSG_DELETING_REQUEST_SLOT, - _cuid, - slot.getIndex(), - slot.getBlockIndex()); - _logger->debug("index=%d, begin=%d", slot.getIndex(), slot.getBegin()); + if(_logger->debug()) { + _logger->debug(MSG_DELETING_REQUEST_SLOT, + _cuid, + slot.getIndex(), + slot.getBlockIndex()); + _logger->debug("index=%d, begin=%d", slot.getIndex(), slot.getBegin()); + } _piece->cancelBlock(slot.getBlockIndex()); } }; @@ -191,11 +195,13 @@ public: void operator()(const RequestSlot& slot) const { if(!_peer->isInPeerAllowedIndexSet(slot.getIndex())) { - _logger->debug(MSG_DELETING_REQUEST_SLOT_CHOKED, - _cuid, - slot.getIndex(), - slot.getBlockIndex()); - _logger->debug("index=%d, begin=%d", slot.getIndex(), slot.getBegin()); + if(_logger->debug()) { + _logger->debug(MSG_DELETING_REQUEST_SLOT_CHOKED, + _cuid, + slot.getIndex(), + slot.getBlockIndex()); + _logger->debug("index=%d, begin=%d", slot.getIndex(), slot.getBegin()); + } SharedHandle<Piece> piece = _pieceStorage->getPiece(slot.getIndex()); piece->cancelBlock(slot.getBlockIndex()); } @@ -266,17 +272,21 @@ public: void operator()(const RequestSlot& slot) { if(slot.isTimeout(_now, _requestTimeout)) { - _logger->debug(MSG_DELETING_REQUEST_SLOT_TIMEOUT, - _cuid, - slot.getBlockIndex()); - _logger->debug("index=%d, begin=%d", slot.getIndex(), slot.getBegin()); + if(_logger->debug()) { + _logger->debug(MSG_DELETING_REQUEST_SLOT_TIMEOUT, + _cuid, + slot.getBlockIndex()); + _logger->debug("index=%d, begin=%d", slot.getIndex(), slot.getBegin()); + } slot.getPiece()->cancelBlock(slot.getBlockIndex()); _peer->snubbing(true); } else if(slot.getPiece()->hasBlock(slot.getBlockIndex())) { - _logger->debug(MSG_DELETING_REQUEST_SLOT_ACQUIRED, - _cuid, - slot.getBlockIndex()); - _logger->debug("index=%d, begin=%d", slot.getIndex(), slot.getBegin()); + if(_logger->debug()) { + _logger->debug(MSG_DELETING_REQUEST_SLOT_ACQUIRED, + _cuid, + slot.getBlockIndex()); + _logger->debug("index=%d, begin=%d", slot.getIndex(), slot.getBegin()); + } _messageDispatcher->addMessageToQueue (_messageFactory->createCancelMessage(slot.getIndex(), slot.getBegin(), diff --git a/src/DefaultBtMessageReceiver.cc b/src/DefaultBtMessageReceiver.cc index 0d4d462d..88c8a121 100644 --- a/src/DefaultBtMessageReceiver.cc +++ b/src/DefaultBtMessageReceiver.cc @@ -54,12 +54,16 @@ DefaultBtMessageReceiver::DefaultBtMessageReceiver(): handshakeSent(false), logger(LogFactory::getInstance()) { - logger->debug("DefaultBtMessageReceiver::instantiated"); + if(logger->debug()) { + logger->debug("DefaultBtMessageReceiver::instantiated"); + } } DefaultBtMessageReceiver::~DefaultBtMessageReceiver() { - logger->debug("DefaultBtMessageReceiver::deleted"); + if(logger->debug()) { + logger->debug("DefaultBtMessageReceiver::deleted"); + } } SharedHandle<BtHandshakeMessage> diff --git a/src/DefaultBtProgressInfoFile.cc b/src/DefaultBtProgressInfoFile.cc index 73ba5d4a..60558cc0 100644 --- a/src/DefaultBtProgressInfoFile.cc +++ b/src/DefaultBtProgressInfoFile.cc @@ -247,7 +247,9 @@ void DefaultBtProgressInfoFile::load() bool infoHashCheckEnabled = false; if(extension[3]&1 && isTorrentDownload()) { infoHashCheckEnabled = true; - _logger->debug("InfoHash checking enabled."); + if(_logger->debug()) { + _logger->debug("InfoHash checking enabled."); + } } uint32_t infoHashLength; diff --git a/src/DefaultBtRequestFactory.cc b/src/DefaultBtRequestFactory.cc index d97a8d33..c7ab09ed 100644 --- a/src/DefaultBtRequestFactory.cc +++ b/src/DefaultBtRequestFactory.cc @@ -54,12 +54,16 @@ DefaultBtRequestFactory::DefaultBtRequestFactory(): cuid(0), _logger(LogFactory::getInstance()) { - LogFactory::getInstance()->debug("DefaultBtRequestFactory::instantiated"); + if(_logger->debug()) { + _logger->debug("DefaultBtRequestFactory::instantiated"); + } } DefaultBtRequestFactory::~DefaultBtRequestFactory() { - LogFactory::getInstance()->debug("DefaultBtRequestFactory::deleted"); + if(_logger->debug()) { + _logger->debug("DefaultBtRequestFactory::deleted"); + } } void DefaultBtRequestFactory::addTargetPiece(const PieceHandle& piece) @@ -154,11 +158,13 @@ void DefaultBtRequestFactory::createRequestMessages size_t blockIndex; while(requests.size() < max && piece->getMissingUnusedBlockIndex(blockIndex)) { - _logger->debug("Creating RequestMessage index=%u, begin=%u, blockIndex=%u", - piece->getIndex(), - blockIndex*piece->getBlockLength(), - blockIndex); - + if(_logger->debug()) { + _logger->debug("Creating RequestMessage index=%u, begin=%u," + " blockIndex=%u", + piece->getIndex(), + blockIndex*piece->getBlockLength(), + blockIndex); + } requests.push_back(messageFactory->createRequestMessage(piece, blockIndex)); } } @@ -193,10 +199,13 @@ void DefaultBtRequestFactory::createRequestMessagesOnEndGame const size_t& blockIndex = *bitr; if(!dispatcher->isOutstandingRequest(piece->getIndex(), blockIndex)) { - _logger->debug("Creating RequestMessage index=%u, begin=%u, blockIndex=%u", - piece->getIndex(), - blockIndex*piece->getBlockLength(), - blockIndex); + if(_logger->debug()) { + _logger->debug("Creating RequestMessage index=%u, begin=%u," + " blockIndex=%u", + piece->getIndex(), + blockIndex*piece->getBlockLength(), + blockIndex); + } requests.push_back(messageFactory->createRequestMessage(piece, blockIndex)); } } diff --git a/src/DefaultPeerStorage.cc b/src/DefaultPeerStorage.cc index 13caadd6..d791ffbf 100644 --- a/src/DefaultPeerStorage.cc +++ b/src/DefaultPeerStorage.cc @@ -95,7 +95,10 @@ static size_t calculateMaxPeerListSize(const SharedHandle<BtRuntime>& btRuntime) bool DefaultPeerStorage::addPeer(const PeerHandle& peer) { if(isPeerAlreadyAdded(peer)) { - logger->debug("Adding %s:%u is rejected because it has been already added.", peer->ipaddr.c_str(), peer->port); + if(logger->debug()) { + logger->debug("Adding %s:%u is rejected because it has been already" + " added.", peer->ipaddr.c_str(), peer->port); + } return false; } size_t maxPeerListSize = calculateMaxPeerListSize(_btRuntime); @@ -111,8 +114,9 @@ void DefaultPeerStorage::addPeer(const Peers& peers) { itr != peers.end(); ++itr) { const PeerHandle& peer = *itr; if(addPeer(peer)) { - logger->debug(MSG_ADDING_PEER, - peer->ipaddr.c_str(), peer->port); + if(logger->debug()) { + logger->debug(MSG_ADDING_PEER, peer->ipaddr.c_str(), peer->port); + } } } } @@ -205,7 +209,9 @@ TransferStat DefaultPeerStorage::calculateStat() { TransferStat stat; if(_lastTransferStatMapUpdated.elapsedInMillis(250)) { - logger->debug("Updating TransferStat of PeerStorage"); + if(logger->debug()) { + logger->debug("Updating TransferStat of PeerStorage"); + } _lastTransferStatMapUpdated.reset(); _peerTransferStatMap.clear(); std::deque<SharedHandle<Peer> > activePeers; @@ -236,7 +242,9 @@ TransferStat DefaultPeerStorage::calculateStat() void DefaultPeerStorage::updateTransferStatFor(const SharedHandle<Peer>& peer) { - logger->debug("Updating TransferStat for peer %s", peer->getID().c_str()); + if(logger->debug()) { + logger->debug("Updating TransferStat for peer %s", peer->getID().c_str()); + } _cachedTransferStat -= _peerTransferStatMap[peer->getID()]; TransferStat s = calculateStatFor(peer); _cachedTransferStat += s; @@ -286,7 +294,10 @@ void DefaultPeerStorage::returnPeer(const PeerHandle& peer) { Peers::iterator itr = std::find(peers.begin(), peers.end(), peer); if(itr == peers.end()) { - logger->debug("Cannot find peer %s:%u in PeerStorage.", peer->ipaddr.c_str(), peer->port); + if(logger->debug()) { + logger->debug("Cannot find peer %s:%u in PeerStorage.", + peer->ipaddr.c_str(), peer->port); + } } else { peers.erase(itr); diff --git a/src/DefaultPieceStorage.cc b/src/DefaultPieceStorage.cc index 6fa21cbf..f25a4723 100644 --- a/src/DefaultPieceStorage.cc +++ b/src/DefaultPieceStorage.cc @@ -152,8 +152,10 @@ void DefaultPieceStorage::addUsedPiece(const PieceHandle& piece) std::deque<SharedHandle<Piece> >::iterator i = std::lower_bound(usedPieces.begin(), usedPieces.end(), piece); usedPieces.insert(i, piece); - logger->debug("usedPieces.size()=%lu", - static_cast<unsigned long>(usedPieces.size())); + if(logger->debug()) { + logger->debug("usedPieces.size()=%lu", + static_cast<unsigned long>(usedPieces.size())); + } } PieceHandle DefaultPieceStorage::findUsedPiece(size_t index) const @@ -471,7 +473,9 @@ bool DefaultPieceStorage::allDownloadFinished() void DefaultPieceStorage::initStorage() { if(downloadContext->getFileEntries().size() == 1) { - logger->debug("Instantiating DirectDiskAdaptor"); + if(logger->debug()) { + logger->debug("Instantiating DirectDiskAdaptor"); + } DirectDiskAdaptorHandle directDiskAdaptor(new DirectDiskAdaptor()); directDiskAdaptor->setTotalLength(downloadContext->getTotalLength()); directDiskAdaptor->setFileEntries(downloadContext->getFileEntries().begin(), @@ -486,7 +490,9 @@ void DefaultPieceStorage::initStorage() directDiskAdaptor->setDiskWriter(writer); this->diskAdaptor = directDiskAdaptor; } else { - logger->debug("Instantiating MultiDiskAdaptor"); + if(logger->debug()) { + logger->debug("Instantiating MultiDiskAdaptor"); + } MultiDiskAdaptorHandle multiDiskAdaptor(new MultiDiskAdaptor()); multiDiskAdaptor->setFileEntries(downloadContext->getFileEntries().begin(), downloadContext->getFileEntries().end()); @@ -574,7 +580,9 @@ void DefaultPieceStorage::removeAdvertisedPiece(time_t elapsed) Haves::iterator itr = std::find_if(haves.begin(), haves.end(), FindElapsedHave(elapsed)); if(itr != haves.end()) { - logger->debug(MSG_REMOVED_HAVE_ENTRY, haves.end()-itr); + if(logger->debug()) { + logger->debug(MSG_REMOVED_HAVE_ENTRY, haves.end()-itr); + } haves.erase(itr, haves.end()); } } diff --git a/src/DownloadCommand.cc b/src/DownloadCommand.cc index 18876dcc..68e333f1 100644 --- a/src/DownloadCommand.cc +++ b/src/DownloadCommand.cc @@ -211,8 +211,10 @@ bool DownloadCommand::executeInternal() { _requestGroup->getDownloadContext()->getPieceHash(segment->getIndex()); if(_pieceHashValidationEnabled && !expectedPieceHash.empty()) { if(segment->isHashCalculated()) { - logger->debug("Hash is available! index=%lu", - static_cast<unsigned long>(segment->getIndex())); + if(logger->debug()) { + logger->debug("Hash is available! index=%lu", + static_cast<unsigned long>(segment->getIndex())); + } validatePieceHash(segment, expectedPieceHash, segment->getHashString()); } else { _messageDigestContext->digestReset(); diff --git a/src/DownloadEngine.cc b/src/DownloadEngine.cc index 9bf881cc..6c9b5091 100644 --- a/src/DownloadEngine.cc +++ b/src/DownloadEngine.cc @@ -277,7 +277,9 @@ void DownloadEngine::poolSocket(const std::string& ipaddr, if(_lastSocketPoolScan.elapsed(60)) { std::multimap<std::string, SocketPoolEntry> newPool; - logger->debug("Scaning SocketPool and erasing timed out entry."); + if(logger->debug()) { + logger->debug("Scaning SocketPool and erasing timed out entry."); + } _lastSocketPoolScan.reset(); for(std::multimap<std::string, SocketPoolEntry>::iterator i = _socketPool.begin(); i != _socketPool.end(); ++i) { @@ -285,9 +287,11 @@ void DownloadEngine::poolSocket(const std::string& ipaddr, newPool.insert(*i); } } - logger->debug - ("%lu entries removed.", - static_cast<unsigned long>(_socketPool.size()-newPool.size())); + if(logger->debug()) { + logger->debug + ("%lu entries removed.", + static_cast<unsigned long>(_socketPool.size()-newPool.size())); + } _socketPool = newPool; } } diff --git a/src/EpollEventPoll.cc b/src/EpollEventPoll.cc index 05458c2d..e5a46e94 100644 --- a/src/EpollEventPoll.cc +++ b/src/EpollEventPoll.cc @@ -405,7 +405,10 @@ bool EpollEventPoll::addEvents(sock_t socket, &socketEntry->getEpEvent()); } if(r == -1) { - _logger->debug("Failed to add socket event %d:%s", socket, strerror(errno)); + if(_logger->debug()) { + _logger->debug("Failed to add socket event %d:%s", + socket, strerror(errno)); + } return false; } else { return true; @@ -450,18 +453,24 @@ bool EpollEventPoll::deleteEvents(sock_t socket, r = epoll_ctl(_epfd, EPOLL_CTL_MOD, (*i)->getSocket(), &(*i)->getEpEvent()); if(r == -1) { - _logger->debug("Failed to delete socket event, but may be ignored:%s", - strerror(errno)); + if(_logger->debug()) { + _logger->debug("Failed to delete socket event, but may be ignored:%s", + strerror(errno)); + } } } if(r == -1) { - _logger->debug("Failed to delete socket event:%s", strerror(errno)); + if(_logger->debug()) { + _logger->debug("Failed to delete socket event:%s", strerror(errno)); + } return false; } else { return true; } } else { - _logger->debug("Socket %d is not found in SocketEntries.", socket); + if(_logger->debug()) { + _logger->debug("Socket %d is not found in SocketEntries.", socket); + } return false; } } diff --git a/src/FileAllocationCommand.cc b/src/FileAllocationCommand.cc index c97f676d..48615624 100644 --- a/src/FileAllocationCommand.cc +++ b/src/FileAllocationCommand.cc @@ -61,9 +61,11 @@ bool FileAllocationCommand::executeInternal() } _fileAllocationEntry->allocateChunk(); if(_fileAllocationEntry->finished()) { - logger->debug(MSG_ALLOCATION_COMPLETED, - _timer.difference(), - util::itos(_requestGroup->getTotalLength(), true).c_str()); + if(logger->debug()) { + logger->debug(MSG_ALLOCATION_COMPLETED, + _timer.difference(), + util::itos(_requestGroup->getTotalLength(), true).c_str()); + } _e->_fileAllocationMan->dropPickedEntry(); std::deque<Command*> commands; diff --git a/src/FileEntry.cc b/src/FileEntry.cc index 5c3bf593..53924e64 100644 --- a/src/FileEntry.cc +++ b/src/FileEntry.cc @@ -242,8 +242,10 @@ void FileEntry::removeURIWhoseHostnameIs(const std::string& hostname) newURIs.push_back(*itr); } } - _logger->debug("Removed %d duplicate hostname URIs for path=%s", - _uris.size()-newURIs.size(), getPath().c_str()); + if(_logger->debug()) { + _logger->debug("Removed %d duplicate hostname URIs for path=%s", + _uris.size()-newURIs.size(), getPath().c_str()); + } _uris = newURIs; } @@ -297,20 +299,24 @@ void FileEntry::reuseUri(size_t num) errorUris.begin(), errorUris.end(), std::back_inserter(reusableURIs)); size_t ininum = reusableURIs.size(); - _logger->debug("Found %u reusable URIs", - static_cast<unsigned int>(ininum)); + if(_logger->debug()) { + _logger->debug("Found %u reusable URIs", static_cast<unsigned int>(ininum)); + } // Reuse at least num URIs here to avoid to // run this process repeatedly. if(ininum > 0 && ininum < num) { - _logger->debug("fewer than num=%u", - num); + if(_logger->debug()) { + _logger->debug("fewer than num=%u", num); + } for(size_t i = 0; i < num/ininum; ++i) { _uris.insert(_uris.end(), reusableURIs.begin(), reusableURIs.end()); } _uris.insert(_uris.end(), reusableURIs.begin(), reusableURIs.begin()+(num%ininum)); - _logger->debug("Duplication complete: now %u URIs for reuse", - static_cast<unsigned int>(_uris.size())); + if(_logger->debug()) { + _logger->debug("Duplication complete: now %u URIs for reuse", + static_cast<unsigned int>(_uris.size())); + } } } diff --git a/src/FtpNegotiationCommand.cc b/src/FtpNegotiationCommand.cc index ec78fa75..23e1b4ae 100644 --- a/src/FtpNegotiationCommand.cc +++ b/src/FtpNegotiationCommand.cc @@ -306,13 +306,19 @@ bool FtpNegotiationCommand::recvMdtm() time_t t = lastModifiedTime.getTime(); struct tm* tms = gmtime(&t); // returned struct is statically allocated. if(tms) { - logger->debug("MDTM result was parsed as: %s GMT", asctime(tms)); + if(logger->debug()) { + logger->debug("MDTM result was parsed as: %s GMT", asctime(tms)); + } } else { - logger->debug("gmtime() failed for MDTM result."); + if(logger->debug()) { + logger->debug("gmtime() failed for MDTM result."); + } } } else { - logger->debug("MDTM response was returned, but it seems not to be a time" - " value as in specified in RFC3659."); + if(logger->debug()) { + logger->debug("MDTM response was returned, but it seems not to be a" + " time value as in specified in RFC3659."); + } } } else { logger->info("CUID#%d - MDTM command failed.", cuid); diff --git a/src/HandshakeExtensionMessage.cc b/src/HandshakeExtensionMessage.cc index 76f662ba..1f303bc9 100644 --- a/src/HandshakeExtensionMessage.cc +++ b/src/HandshakeExtensionMessage.cc @@ -163,8 +163,11 @@ HandshakeExtensionMessage::create(const unsigned char* data, size_t length) EXTENSION_NAME.c_str(), length).str()); } HandshakeExtensionMessageHandle msg(new HandshakeExtensionMessage()); - msg->_logger->debug("Creating HandshakeExtensionMessage from %s", - util::urlencode(data, length).c_str()); + if(LogFactory::getInstance()->debug()) { + LogFactory::getInstance()->debug + ("Creating HandshakeExtensionMessage from %s", + util::urlencode(data, length).c_str()); + } const BDE dict = bencode::decode(data+1, length-1); if(!dict.isDict()) { throw DL_ABORT_EX("Unexpected payload format for extended message handshake"); diff --git a/src/HttpListenCommand.cc b/src/HttpListenCommand.cc index 5bb714be..2e85410f 100644 --- a/src/HttpListenCommand.cc +++ b/src/HttpListenCommand.cc @@ -79,7 +79,9 @@ bool HttpListenCommand::execute() _e->commands.push_back(c); } } catch(RecoverableException& e) { - logger->debug(MSG_ACCEPT_FAILURE, _e, cuid); + if(logger->debug()) { + logger->debug(MSG_ACCEPT_FAILURE, _e, cuid); + } } _e->commands.push_back(this); return false; diff --git a/src/HttpServer.cc b/src/HttpServer.cc index 16efce3c..51f88447 100644 --- a/src/HttpServer.cc +++ b/src/HttpServer.cc @@ -165,9 +165,9 @@ void HttpServer::feedResponse(const std::string& status, } header += "\r\n"; - - _logger->debug("HTTP Server sends response:\n%s", header.c_str()); - + if(_logger->debug()) { + _logger->debug("HTTP Server sends response:\n%s", header.c_str()); + } _socketBuffer.feedSendBuffer(header); _socketBuffer.feedSendBuffer(text); } diff --git a/src/HttpSkipResponseCommand.cc b/src/HttpSkipResponseCommand.cc index 521ce010..4915e64a 100644 --- a/src/HttpSkipResponseCommand.cc +++ b/src/HttpSkipResponseCommand.cc @@ -114,7 +114,9 @@ bool HttpSkipResponseCommand::executeInternal() throw DL_RETRY_EX(EX_GOT_EOF); } } catch(RecoverableException& e) { - logger->debug(EX_EXCEPTION_CAUGHT, e); + if(logger->debug()) { + logger->debug(EX_EXCEPTION_CAUGHT, e); + } return processResponse(); } diff --git a/src/IteratableChunkChecksumValidator.cc b/src/IteratableChunkChecksumValidator.cc index a700767d..c5678d29 100644 --- a/src/IteratableChunkChecksumValidator.cc +++ b/src/IteratableChunkChecksumValidator.cc @@ -94,7 +94,11 @@ void IteratableChunkChecksumValidator::validateChunk() _bitfield->unsetBit(_currentIndex); } } catch(RecoverableException& ex) { - _logger->debug("Caught exception while validating piece index=%d. Some part of file may be missing. Continue operation.", ex, _currentIndex); + if(_logger->debug()) { + _logger->debug("Caught exception while validating piece index=%d." + " Some part of file may be missing. Continue operation.", + ex, _currentIndex); + } _bitfield->unsetBit(_currentIndex); } diff --git a/src/Logger.h b/src/Logger.h index a3eb7849..330fa711 100644 --- a/src/Logger.h +++ b/src/Logger.h @@ -187,6 +187,13 @@ public: _stdoutField &= ~level; } } + + // Returns true if this logger actually writes debug log message to + // either file or stdout. + bool debug() const + { + return (DEBUG >= _logLevel && _file.is_open()) || _stdoutField&DEBUG; + } }; } // namespace aria2 diff --git a/src/MSEHandshake.cc b/src/MSEHandshake.cc index ae778d4a..4ed7a769 100644 --- a/src/MSEHandshake.cc +++ b/src/MSEHandshake.cc @@ -104,10 +104,15 @@ MSEHandshake::HANDSHAKE_TYPE MSEHandshake::identifyHandshakeType() } if(_rbuf[0] == BtHandshakeMessage::PSTR_LENGTH && memcmp(BtHandshakeMessage::BT_PSTR, _rbuf+1, 19) == 0) { - _logger->debug("CUID#%d - This is legacy BitTorrent handshake.", _cuid); + if(_logger->debug()) { + _logger->debug("CUID#%d - This is legacy BitTorrent handshake.", _cuid); + } return HANDSHAKE_LEGACY; } else { - _logger->debug("CUID#%d - This may be encrypted BitTorrent handshake.", _cuid); + if(_logger->debug()) { + _logger->debug("CUID#%d - This may be encrypted BitTorrent handshake.", + _cuid); + } return HANDSHAKE_ENCRYPTED; } } @@ -118,15 +123,18 @@ void MSEHandshake::initEncryptionFacility(bool initiator) _dh = new DHKeyExchange(); _dh->init(PRIME, PRIME_BITS, GENERATOR, 160); _dh->generatePublicKey(); - _logger->debug("CUID#%d - DH initialized.", _cuid); - + if(_logger->debug()) { + _logger->debug("CUID#%d - DH initialized.", _cuid); + } _initiator = initiator; } bool MSEHandshake::sendPublicKey() { if(_socketBuffer.sendBufferIsEmpty()) { - _logger->debug("CUID#%d - Sending public key.", _cuid); + if(_logger->debug()) { + _logger->debug("CUID#%d - Sending public key.", _cuid); + } unsigned char buffer[KEY_LENGTH+MAX_PAD_LENGTH]; _dh->getPublicKey(buffer, KEY_LENGTH); @@ -145,7 +153,9 @@ bool MSEHandshake::receivePublicKey() if(r > receiveNBytes(r)) { return false; } - _logger->debug("CUID#%d - public key received.", _cuid); + if(_logger->debug()) { + _logger->debug("CUID#%d - public key received.", _cuid); + } // TODO handle exception. in catch, resbufLength = 0; _dh->computeSecret(_secret, sizeof(_secret), _rbuf, _rbufLength); // reset _rbufLength @@ -249,7 +259,9 @@ uint16_t MSEHandshake::decodeLength16(const unsigned char* buffer) bool MSEHandshake::sendInitiatorStep2() { if(_socketBuffer.sendBufferIsEmpty()) { - _logger->debug("CUID#%d - Sending negotiation step2.", _cuid); + if(_logger->debug()) { + _logger->debug("CUID#%d - Sending negotiation step2.", _cuid); + } unsigned char md[20]; createReq1Hash(md); _socketBuffer.feedSendBuffer(std::string(&md[0], &md[sizeof(md)])); @@ -335,8 +347,9 @@ bool MSEHandshake::findInitiatorVCMarker() size_t toRead = _markerIndex+VC_LENGTH-_rbufLength; _socket->readData(_rbuf+_rbufLength, toRead); _rbufLength += toRead; - - _logger->debug("CUID#%d - VC marker found at %u", _cuid, _markerIndex); + if(_logger->debug()) { + _logger->debug("CUID#%d - VC marker found at %u", _cuid, _markerIndex); + } verifyVC(_rbuf+_markerIndex); // reset _rbufLength _rbufLength = 0; @@ -357,11 +370,15 @@ bool MSEHandshake::receiveInitiatorCryptoSelectAndPadDLength() rbufptr, sizeof(cryptoSelect)); if(cryptoSelect[3]&CRYPTO_PLAIN_TEXT && _option->get(PREF_BT_MIN_CRYPTO_LEVEL) == V_PLAIN) { - _logger->debug("CUID#%d - peer prefers plaintext.", _cuid); + if(_logger->debug()) { + _logger->debug("CUID#%d - peer prefers plaintext.", _cuid); + } _negotiatedCryptoType = CRYPTO_PLAIN_TEXT; } if(cryptoSelect[3]&CRYPTO_ARC4) { - _logger->debug("CUID#%d - peer prefers ARC4", _cuid); + if(_logger->debug()) { + _logger->debug("CUID#%d - peer prefers ARC4", _cuid); + } _negotiatedCryptoType = CRYPTO_ARC4; } if(_negotiatedCryptoType == CRYPTO_NONE) { @@ -427,8 +444,9 @@ bool MSEHandshake::findReceiverHashMarker() size_t toRead = _markerIndex+20-_rbufLength; _socket->readData(_rbuf+_rbufLength, toRead); _rbufLength += toRead; - - _logger->debug("CUID#%d - Hash marker found at %u.", _cuid, _markerIndex); + if(_logger->debug()) { + _logger->debug("CUID#%d - Hash marker found at %u.", _cuid, _markerIndex); + } verifyReq1Hash(_rbuf+_markerIndex); // reset _rbufLength _rbufLength = 0; @@ -452,8 +470,11 @@ bool MSEHandshake::receiveReceiverHashAndPadCLength const BDE& torrentAttrs = (*i)->getAttribute(bittorrent::BITTORRENT); createReq23Hash(md, torrentAttrs[bittorrent::INFO_HASH].uc()); if(memcmp(md, rbufptr, sizeof(md)) == 0) { - _logger->debug("CUID#%d - info hash found: %s", _cuid, - util::toHex(torrentAttrs[bittorrent::INFO_HASH].s()).c_str()); + if(_logger->debug()) { + _logger->debug("CUID#%d - info hash found: %s", _cuid, + util::toHex + (torrentAttrs[bittorrent::INFO_HASH].s()).c_str()); + } downloadContext = *i; break; } @@ -475,10 +496,14 @@ bool MSEHandshake::receiveReceiverHashAndPadCLength // For now, choose ARC4. if(cryptoProvide[3]&CRYPTO_PLAIN_TEXT && _option->get(PREF_BT_MIN_CRYPTO_LEVEL) == V_PLAIN) { - _logger->debug("CUID#%d - peer provides plaintext.", _cuid); + if(_logger->debug()) { + _logger->debug("CUID#%d - peer provides plaintext.", _cuid); + } _negotiatedCryptoType = CRYPTO_PLAIN_TEXT; } else if(cryptoProvide[3]&CRYPTO_ARC4) { - _logger->debug("CUID#%d - peer provides ARC4.", _cuid); + if(_logger->debug()) { + _logger->debug("CUID#%d - peer provides ARC4.", _cuid); + } _negotiatedCryptoType = CRYPTO_ARC4; } if(_negotiatedCryptoType == CRYPTO_NONE) { @@ -502,7 +527,9 @@ bool MSEHandshake::receiveReceiverIALength() return false; } _iaLength = decodeLength16(_rbuf); - _logger->debug("CUID#%d - len(IA)=%u.", _cuid, _iaLength); + if(_logger->debug()) { + _logger->debug("CUID#%d - len(IA)=%u.", _cuid, _iaLength); + } // reset _rbufLength _rbufLength = 0; return true; @@ -520,7 +547,9 @@ bool MSEHandshake::receiveReceiverIA() delete [] _ia; _ia = new unsigned char[_iaLength]; _decryptor->decrypt(_ia, _iaLength, _rbuf, _iaLength); - _logger->debug("CUID#%d - IA received.", _cuid); + if(_logger->debug()) { + _logger->debug("CUID#%d - IA received.", _cuid); + } // reset _rbufLength _rbufLength = 0; return true; @@ -559,10 +588,13 @@ bool MSEHandshake::sendReceiverStep2() uint16_t MSEHandshake::verifyPadLength(const unsigned char* padlenbuf, const char* padName) { - _logger->debug("CUID#%d - Verifying Pad length for %s", _cuid, padName); - + if(_logger->debug()) { + _logger->debug("CUID#%d - Verifying Pad length for %s", _cuid, padName); + } uint16_t padLength = decodeLength16(padlenbuf); - _logger->debug("CUID#%d - len(%s)=%u", _cuid, padName, padLength); + if(_logger->debug()) { + _logger->debug("CUID#%d - len(%s)=%u", _cuid, padName, padLength); + } if(padLength > 512) { throw DL_ABORT_EX (StringFormat("Too large %s length: %u", padName, padLength).str()); @@ -572,7 +604,9 @@ uint16_t MSEHandshake::verifyPadLength(const unsigned char* padlenbuf, const cha void MSEHandshake::verifyVC(const unsigned char* vcbuf) { - _logger->debug("CUID#%d - Verifying VC.", _cuid); + if(_logger->debug()) { + _logger->debug("CUID#%d - Verifying VC.", _cuid); + } unsigned char vc[VC_LENGTH]; _decryptor->decrypt(vc, sizeof(vc), vcbuf, sizeof(vc)); if(memcmp(VC, vc, sizeof(VC)) != 0) { @@ -583,7 +617,9 @@ void MSEHandshake::verifyVC(const unsigned char* vcbuf) void MSEHandshake::verifyReq1Hash(const unsigned char* req1buf) { - _logger->debug("CUID#%d - Verifying req hash.", _cuid); + if(_logger->debug()) { + _logger->debug("CUID#%d - Verifying req hash.", _cuid); + } unsigned char md[20]; createReq1Hash(md); if(memcmp(md, req1buf, sizeof(md)) != 0) { diff --git a/src/MetalinkPostDownloadHandler.cc b/src/MetalinkPostDownloadHandler.cc index 0fc05e73..7e4456bf 100644 --- a/src/MetalinkPostDownloadHandler.cc +++ b/src/MetalinkPostDownloadHandler.cc @@ -64,8 +64,10 @@ void MetalinkPostDownloadHandler::getNextRequestGroups (std::deque<SharedHandle<RequestGroup> >& groups, RequestGroup* requestGroup) { - _logger->debug("Generating RequestGroups for Metalink file %s", - requestGroup->getFirstFilePath().c_str()); + if(_logger->debug()) { + _logger->debug("Generating RequestGroups for Metalink file %s", + requestGroup->getFirstFilePath().c_str()); + } SharedHandle<DiskAdaptor> diskAdaptor = requestGroup->getPieceStorage()->getDiskAdaptor(); try { diff --git a/src/MultiDiskAdaptor.cc b/src/MultiDiskAdaptor.cc index 3c3d6a7d..b1967478 100644 --- a/src/MultiDiskAdaptor.cc +++ b/src/MultiDiskAdaptor.cc @@ -208,25 +208,29 @@ void MultiDiskAdaptor::resetDiskWriterEntries() if(fileEntry->getLength() > 0) { off_t lastPieceStartOffset = (fileEntry->getOffset()+fileEntry->getLength()-1)/pieceLength*pieceLength; - logger->debug("Checking adjacent backward file to %s" - " whose lastPieceStartOffset+pieceLength=%lld", - fileEntry->getPath().c_str(), - lastPieceStartOffset+pieceLength); - + if(logger->debug()) { + logger->debug("Checking adjacent backward file to %s" + " whose lastPieceStartOffset+pieceLength=%lld", + fileEntry->getPath().c_str(), + lastPieceStartOffset+pieceLength); + } ++itr; // adjacent backward files are not needed to be allocated. They // just requre DiskWriter for(; itr != diskWriterEntries.end() && (!(*itr)->getFileEntry()->isRequested() || (*itr)->getFileEntry()->getLength() == 0); ++itr) { - logger->debug("file=%s, offset=%lld", - (*itr)->getFileEntry()->getPath().c_str(), - (*itr)->getFileEntry()->getOffset()); - + if(logger->debug()) { + logger->debug("file=%s, offset=%lld", + (*itr)->getFileEntry()->getPath().c_str(), + (*itr)->getFileEntry()->getOffset()); + } if((*itr)->getFileEntry()->getOffset() < static_cast<off_t>(lastPieceStartOffset+pieceLength)) { - logger->debug("%s needs diskwriter", - (*itr)->getFileEntry()->getPath().c_str()); + if(logger->debug()) { + logger->debug("%s needs diskwriter", + (*itr)->getFileEntry()->getPath().c_str()); + } dwreq[(*itr)->getFileEntry()->getPath()] = true; } else { break; @@ -245,8 +249,10 @@ void MultiDiskAdaptor::resetDiskWriterEntries() if((*i)->needsFileAllocation() || dwreq.find((*i)->getFileEntry()->getPath()) != dwreq.end() || (*i)->fileExists()) { - logger->debug("Creating DiskWriter for filename=%s", - (*i)->getFilePath().c_str()); + if(logger->debug()) { + logger->debug("Creating DiskWriter for filename=%s", + (*i)->getFilePath().c_str()); + } (*i)->setDiskWriter(dwFactory.newDiskWriter((*i)->getFilePath())); if(_directIOAllowed) { (*i)->getDiskWriter()->allowDirectIO(); diff --git a/src/PeerAbstractCommand.cc b/src/PeerAbstractCommand.cc index 49ebd97b..67e4b26d 100644 --- a/src/PeerAbstractCommand.cc +++ b/src/PeerAbstractCommand.cc @@ -73,9 +73,12 @@ PeerAbstractCommand::~PeerAbstractCommand() bool PeerAbstractCommand::execute() { - logger->debug("CUID#%d -" - " socket: read:%d, write:%d, hup:%d, err:%d, noCheck:%d", - cuid, _readEvent, _writeEvent, _hupEvent, _errorEvent, noCheck); + if(logger->debug()) { + logger->debug("CUID#%d -" + " socket: read:%d, write:%d, hup:%d, err:%d, noCheck:%d", + cuid, _readEvent, _writeEvent, _hupEvent, _errorEvent, + noCheck); + } if(exitBeforeExecute()) { onAbort(); return true; @@ -101,9 +104,11 @@ bool PeerAbstractCommand::execute() onFailure(); return true; } catch(RecoverableException& err) { - logger->debug(MSG_TORRENT_DOWNLOAD_ABORTED, err, cuid); - logger->debug(MSG_PEER_BANNED, - cuid, peer->ipaddr.c_str(), peer->port); + if(logger->debug()) { + logger->debug(MSG_TORRENT_DOWNLOAD_ABORTED, err, cuid); + logger->debug(MSG_PEER_BANNED, + cuid, peer->ipaddr.c_str(), peer->port); + } onAbort(); return prepareForNextPeer(0); } diff --git a/src/PeerConnection.cc b/src/PeerConnection.cc index 16f0406c..ca2f9753 100644 --- a/src/PeerConnection.cc +++ b/src/PeerConnection.cc @@ -70,7 +70,9 @@ ssize_t PeerConnection::sendMessage(const unsigned char* data, size_t dataLength) { ssize_t writtenLength = sendData(data, dataLength, _encryptionEnabled); - logger->debug("sent %d byte(s).", writtenLength); + if(logger->debug()) { + logger->debug("sent %d byte(s).", writtenLength); + } return writtenLength; } @@ -88,8 +90,11 @@ bool PeerConnection::receiveMessage(unsigned char* data, size_t& dataLength) { return false; } // we got EOF - logger->debug("CUID#%d - In PeerConnection::receiveMessage(), remain=%lu", - cuid, static_cast<unsigned long>(temp)); + if(logger->debug()) { + logger->debug("CUID#%d - In PeerConnection::receiveMessage()," + " remain=%lu", + cuid, static_cast<unsigned long>(temp)); + } throw DL_ABORT_EX(EX_EOF_FROM_PEER); } lenbufLength += remaining; @@ -118,11 +123,13 @@ bool PeerConnection::receiveMessage(unsigned char* data, size_t& dataLength) { return false; } // we got EOF - logger->debug("CUID#%d - In PeerConnection::receiveMessage()," - " payloadlen=%lu, remaining=%lu", - cuid, - static_cast<unsigned long>(currentPayloadLength), - static_cast<unsigned long>(temp)); + if(logger->debug()) { + logger->debug("CUID#%d - In PeerConnection::receiveMessage()," + " payloadlen=%lu, remaining=%lu", + cuid, + static_cast<unsigned long>(currentPayloadLength), + static_cast<unsigned long>(temp)); + } throw DL_ABORT_EX(EX_EOF_FROM_PEER); } resbufLength += remaining; @@ -167,9 +174,11 @@ bool PeerConnection::receiveHandshake(unsigned char* data, size_t& dataLength, return false; } // we got EOF - logger->debug - ("CUID#%d - In PeerConnection::receiveHandshake(), remain=%lu", - cuid, static_cast<unsigned long>(temp)); + if(logger->debug()) { + logger->debug + ("CUID#%d - In PeerConnection::receiveHandshake(), remain=%lu", + cuid, static_cast<unsigned long>(temp)); + } throw DL_ABORT_EX(EX_EOF_FROM_PEER); } resbufLength += remaining; @@ -243,7 +252,9 @@ bool PeerConnection::sendBufferIsEmpty() const ssize_t PeerConnection::sendPendingData() { ssize_t writtenLength = _socketBuffer.send(); - logger->debug("sent %d byte(s).", writtenLength); + if(logger->debug()) { + logger->debug("sent %d byte(s).", writtenLength); + } return writtenLength; } diff --git a/src/PeerListenCommand.cc b/src/PeerListenCommand.cc index 61f6db40..cb213a91 100644 --- a/src/PeerListenCommand.cc +++ b/src/PeerListenCommand.cc @@ -125,10 +125,13 @@ bool PeerListenCommand::execute() { Command* command = new ReceiverMSEHandshakeCommand(cuid, peer, e, peerSocket); e->commands.push_back(command); - logger->debug("Accepted the connection from %s:%u.", - peer->ipaddr.c_str(), - peer->port); - logger->debug("Added CUID#%d to receive BitTorrent/MSE handshake.", cuid); + if(logger->debug()) { + logger->debug("Accepted the connection from %s:%u.", + peer->ipaddr.c_str(), + peer->port); + logger->debug("Added CUID#%d to receive BitTorrent/MSE handshake.", + cuid); + } } catch(RecoverableException& ex) { logger->debug(MSG_ACCEPT_FAILURE, ex, cuid); } diff --git a/src/PeerReceiveHandshakeCommand.cc b/src/PeerReceiveHandshakeCommand.cc index d4bd1942..b09e5acd 100644 --- a/src/PeerReceiveHandshakeCommand.cc +++ b/src/PeerReceiveHandshakeCommand.cc @@ -142,7 +142,9 @@ bool PeerReceiveHandshakeCommand::executeInternal() PeerInteractionCommand::RECEIVER_WAIT_HANDSHAKE, _peerConnection); e->commands.push_back(command); - logger->debug(MSG_INCOMING_PEER_CONNECTION, cuid, peer->usedBy()); + if(logger->debug()) { + logger->debug(MSG_INCOMING_PEER_CONNECTION, cuid, peer->usedBy()); + } } } return true; diff --git a/src/RequestGroup.cc b/src/RequestGroup.cc index b7a05784..44767b84 100644 --- a/src/RequestGroup.cc +++ b/src/RequestGroup.cc @@ -304,10 +304,12 @@ void RequestGroup::createInitialCommand } else { // Open file in writable mode to allow the program // truncate the file to _downloadContext->getTotalLength() - _logger->debug("File size not match. File is opened in writable mode." - " Expected:%s Actual:%s", - util::uitos(_downloadContext->getTotalLength()).c_str(), - util::uitos(actualFileSize).c_str()); + if(_logger->debug()) { + _logger->debug("File size not match. File is opened in writable" + " mode. Expected:%s Actual:%s", + util::uitos(_downloadContext->getTotalLength()).c_str(), + util::uitos(actualFileSize).c_str()); + } } } // Call Load, Save and file allocation command here @@ -450,7 +452,9 @@ void RequestGroup::initPieceStorage() // Use LongestSequencePieceSelector when HTTP/FTP/BitTorrent // integrated downloads. Currently multi-file integrated // download is not supported. - _logger->debug("Using LongestSequencePieceSelector"); + if(_logger->debug()) { + _logger->debug("Using LongestSequencePieceSelector"); + } ps->setPieceSelector (SharedHandle<PieceSelector>(new LongestSequencePieceSelector())); } @@ -807,8 +811,10 @@ void RequestGroup::releaseRuntimeResource(DownloadEngine* e) void RequestGroup::preDownloadProcessing() { - _logger->debug("Finding PreDownloadHandler for path %s.", - getFirstFilePath().c_str()); + if(_logger->debug()) { + _logger->debug("Finding PreDownloadHandler for path %s.", + getFirstFilePath().c_str()); + } try { for(PreDownloadHandlers::const_iterator itr = _preDownloadHandlers.begin(); itr != _preDownloadHandlers.end(); ++itr) { @@ -821,15 +827,19 @@ void RequestGroup::preDownloadProcessing() _logger->error(EX_EXCEPTION_CAUGHT, ex); return; } - _logger->debug("No PreDownloadHandler found."); + if(_logger->debug()) { + _logger->debug("No PreDownloadHandler found."); + } return; } void RequestGroup::postDownloadProcessing (std::deque<SharedHandle<RequestGroup> >& groups) { - _logger->debug("Finding PostDownloadHandler for path %s.", - getFirstFilePath().c_str()); + if(_logger->debug()) { + _logger->debug("Finding PostDownloadHandler for path %s.", + getFirstFilePath().c_str()); + } try { for(PostDownloadHandlers::const_iterator itr = _postDownloadHandlers.begin(); itr != _postDownloadHandlers.end(); ++itr) { @@ -841,7 +851,9 @@ void RequestGroup::postDownloadProcessing } catch(RecoverableException& ex) { _logger->error(EX_EXCEPTION_CAUGHT, ex); } - _logger->debug("No PostDownloadHandler found."); + if(_logger->debug()) { + _logger->debug("No PostDownloadHandler found."); + } } void RequestGroup::initializePreDownloadHandler() diff --git a/src/RequestGroupMan.cc b/src/RequestGroupMan.cc index 32293cf0..84d0816a 100644 --- a/src/RequestGroupMan.cc +++ b/src/RequestGroupMan.cc @@ -345,9 +345,11 @@ public: RequestGroups nextGroups; group->postDownloadProcessing(nextGroups); if(!nextGroups.empty()) { - _logger->debug - ("Adding %lu RequestGroups as a result of PostDownloadHandler.", - static_cast<unsigned long>(nextGroups.size())); + if(_logger->debug()) { + _logger->debug + ("Adding %lu RequestGroups as a result of PostDownloadHandler.", + static_cast<unsigned long>(nextGroups.size())); + } _reservedGroups.insert(_reservedGroups.begin(), nextGroups.begin(), nextGroups.end()); } @@ -440,8 +442,10 @@ void RequestGroupMan::removeStoppedGroup(DownloadEngine* e) size_t numRemoved = numPrev-_requestGroups.size(); if(numRemoved > 0) { - _logger->debug("%lu RequestGroup(s) deleted.", - static_cast<unsigned long>(numRemoved)); + if(_logger->debug()) { + _logger->debug("%lu RequestGroup(s) deleted.", + static_cast<unsigned long>(numRemoved)); + } } } @@ -496,10 +500,14 @@ void RequestGroupMan::fillRequestGroupFromReserver(DownloadEngine* e) executeStartHook(groupToAdd, e->option); } catch(RecoverableException& ex) { _logger->error(EX_EXCEPTION_CAUGHT, ex); - _logger->debug("Deleting temporal commands."); + if(_logger->debug()) { + _logger->debug("Deleting temporal commands."); + } std::for_each(commands.begin(), commands.end(), Deleter()); commands.clear(); - _logger->debug("Commands deleted"); + if(_logger->debug()) { + _logger->debug("Commands deleted"); + } groupToAdd->releaseRuntimeResource(e); _downloadResults.push_back(groupToAdd->createDownloadResult()); } @@ -509,7 +517,9 @@ void RequestGroupMan::fillRequestGroupFromReserver(DownloadEngine* e) } if(count > 0) { e->setNoWait(true); - _logger->debug("%d RequestGroup(s) added.", count); + if(_logger->debug()) { + _logger->debug("%d RequestGroup(s) added.", count); + } } } diff --git a/src/SegmentMan.cc b/src/SegmentMan.cc index c0c3116b..a7f54d36 100644 --- a/src/SegmentMan.cc +++ b/src/SegmentMan.cc @@ -116,8 +116,9 @@ SegmentHandle SegmentMan::checkoutSegment(cuid_t cuid, if(piece.isNull()) { return SharedHandle<Segment>(); } - logger->debug("Attach segment#%d to CUID#%d.", piece->getIndex(), cuid); - + if(logger->debug()) { + logger->debug("Attach segment#%d to CUID#%d.", piece->getIndex(), cuid); + } SegmentHandle segment; if(piece->getLength() == 0) { segment.reset(new GrowSegment(piece)); @@ -126,19 +127,22 @@ SegmentHandle SegmentMan::checkoutSegment(cuid_t cuid, } SegmentEntryHandle entry(new SegmentEntry(cuid, segment)); usedSegmentEntries.push_back(entry); - - logger->debug("index=%d, length=%d, segmentLength=%d, writtenLength=%d", - segment->getIndex(), - segment->getLength(), - segment->getSegmentLength(), - segment->getWrittenLength()); + if(logger->debug()) { + logger->debug("index=%d, length=%d, segmentLength=%d, writtenLength=%d", + segment->getIndex(), + segment->getLength(), + segment->getSegmentLength(), + segment->getWrittenLength()); + } if(piece->getLength() > 0) { std::map<size_t, size_t>::iterator positr = _segmentWrittenLengthMemo.find(segment->getIndex()); if(positr != _segmentWrittenLengthMemo.end()) { const size_t writtenLength = (*positr).second; - logger->debug("writtenLength(in memo)=%d, writtenLength=%d", - writtenLength, segment->getWrittenLength()); + if(logger->debug()) { + logger->debug("writtenLength(in memo)=%d, writtenLength=%d", + writtenLength, segment->getWrittenLength()); + } // If the difference between cached writtenLength and segment's // writtenLength is less than one block, we assume that these // missing bytes are already downloaded. @@ -211,8 +215,10 @@ void SegmentMan::cancelSegment(const SharedHandle<Segment>& segment) { _pieceStorage->cancelPiece(segment->getPiece()); _segmentWrittenLengthMemo[segment->getIndex()] = segment->getWrittenLength(); - logger->debug("Memorized segment index=%u, writtenLength=%u", - segment->getIndex(), segment->getWrittenLength()); + if(logger->debug()) { + logger->debug("Memorized segment index=%u, writtenLength=%u", + segment->getIndex(), segment->getWrittenLength()); + } } void SegmentMan::cancelSegment(cuid_t cuid) { diff --git a/src/SelectEventPoll.cc b/src/SelectEventPoll.cc index 67f95350..229a48a8 100644 --- a/src/SelectEventPoll.cc +++ b/src/SelectEventPoll.cc @@ -263,7 +263,10 @@ bool SelectEventPoll::addEvents(sock_t socket, Command* command, } updateFdSet(); if(r == -1) { - _logger->debug("Failed to add socket event %d:%s", socket, strerror(errno)); + if(_logger->debug()) { + _logger->debug("Failed to add socket event %d:%s", + socket, strerror(errno)); + } return false; } else { return true; @@ -284,13 +287,17 @@ bool SelectEventPoll::deleteEvents(sock_t socket, Command* command, } updateFdSet(); if(r == -1) { - _logger->debug("Failed to delete socket event:%s", strerror(errno)); + if(_logger->debug()) { + _logger->debug("Failed to delete socket event:%s", strerror(errno)); + } return false; } else { return true; } } else { - _logger->debug("Socket %d is not found in SocketEntries.", socket); + if(_logger->debug()) { + _logger->debug("Socket %d is not found in SocketEntries.", socket); + } return false; } } diff --git a/src/ServerStat.cc b/src/ServerStat.cc index 1e2a36a1..24de817a 100644 --- a/src/ServerStat.cc +++ b/src/ServerStat.cc @@ -101,16 +101,20 @@ void ServerStat::updateSingleConnectionAvgSpeed(unsigned int downloadSpeed) ((1.0/5.0)*(float)downloadSpeed); } if(avgDownloadSpeed < (int)(0.80*_singleConnectionAvgSpeed)) { - _logger->debug("ServerStat:%s: resetting counter since single connection" - " speed dropped", getHostname().c_str()); + if(_logger->debug()) { + _logger->debug("ServerStat:%s: resetting counter since single connection" + " speed dropped", getHostname().c_str()); + } _counter = 0; } - _logger->debug("ServerStat:%s: _singleConnectionAvgSpeed old:%.2fKB/s" - " new:%.2fKB/s last:%.2fKB/s", - getHostname().c_str(), - (float) _singleConnectionAvgSpeed/1024, - (float) avgDownloadSpeed/1024, - (float) downloadSpeed / 1024); + if(_logger->debug()) { + _logger->debug("ServerStat:%s: _singleConnectionAvgSpeed old:%.2fKB/s" + " new:%.2fKB/s last:%.2fKB/s", + getHostname().c_str(), + (float) _singleConnectionAvgSpeed/1024, + (float) avgDownloadSpeed/1024, + (float) downloadSpeed / 1024); + } _singleConnectionAvgSpeed = (int)avgDownloadSpeed; } @@ -134,12 +138,14 @@ void ServerStat::updateMultiConnectionAvgSpeed(unsigned int downloadSpeed) avgDownloadSpeed = ((4.0/5.0)*(float)_multiConnectionAvgSpeed) + ((1.0/5.0)*(float)downloadSpeed); } - _logger->debug("ServerStat:%s: _multiConnectionAvgSpeed old:%.2fKB/s" - " new:%.2fKB/s last:%.2fKB/s", - getHostname().c_str(), - (float) _multiConnectionAvgSpeed/1024, - (float) avgDownloadSpeed/1024, - (float) downloadSpeed / 1024); + if(_logger->debug()) { + _logger->debug("ServerStat:%s: _multiConnectionAvgSpeed old:%.2fKB/s" + " new:%.2fKB/s last:%.2fKB/s", + getHostname().c_str(), + (float) _multiConnectionAvgSpeed/1024, + (float) avgDownloadSpeed/1024, + (float) downloadSpeed / 1024); + } _multiConnectionAvgSpeed = (int)avgDownloadSpeed; } @@ -172,9 +178,11 @@ void ServerStat::setStatus(const std::string& status) void ServerStat::setStatusInternal(STATUS status) { - _logger->debug("ServerStat: set status %s for %s (%s)", - STATUS_STRING[status].c_str(), - _hostname.c_str(), _protocol.c_str()); + if(_logger->debug()) { + _logger->debug("ServerStat: set status %s for %s (%s)", + STATUS_STRING[status].c_str(), + _hostname.c_str(), _protocol.c_str()); + } _status = status; _lastUpdated.reset(); } diff --git a/src/SimpleBtMessage.cc b/src/SimpleBtMessage.cc index 22025c93..ac9558d9 100644 --- a/src/SimpleBtMessage.cc +++ b/src/SimpleBtMessage.cc @@ -57,8 +57,10 @@ void SimpleBtMessage::send() { size_t msgLength = getMessageLength(); logger->info(MSG_SEND_PEER_MESSAGE, cuid, peer->ipaddr.c_str(), peer->port, toString().c_str()); - logger->debug("msglength = %lu bytes", - static_cast<unsigned long>(msgLength)); + if(logger->debug()) { + logger->debug("msglength = %lu bytes", + static_cast<unsigned long>(msgLength)); + } peerConnection->sendMessage(msg, msgLength); } else { peerConnection->sendPendingData(); diff --git a/src/SocketCore.cc b/src/SocketCore.cc index 6d2f434c..686717cc 100644 --- a/src/SocketCore.cc +++ b/src/SocketCore.cc @@ -180,7 +180,9 @@ static sock_t bindInternal(int family, int socktype, int protocol, return -1; } if(::bind(fd, addr, addrlen) == -1) { - LogFactory::getInstance()->debug(EX_SOCKET_BIND, strerror(errno)); + if(LogFactory::getInstance()->debug()) { + LogFactory::getInstance()->debug(EX_SOCKET_BIND, strerror(errno)); + } CLOSE(fd); return -1; } @@ -328,7 +330,9 @@ void SocketCore::establishConnection(const std::string& host, uint16_t port) const_iterator i = _bindAddrs.begin(); i != _bindAddrs.end(); ++i) { if(::bind(fd,reinterpret_cast<const struct sockaddr*>(&(*i).first), (*i).second) == -1) { - LogFactory::getInstance()->debug(EX_SOCKET_BIND, strerror(errno)); + if(LogFactory::getInstance()->debug()) { + LogFactory::getInstance()->debug(EX_SOCKET_BIND, strerror(errno)); + } } else { bindSuccess = true; break; @@ -1142,7 +1146,9 @@ void SocketCore::useSelect() void SocketCore::bindAddress(const std::string& iface) { std::vector<std::pair<struct sockaddr_storage, socklen_t> > bindAddrs; - LogFactory::getInstance()->debug("Finding interface %s", iface.c_str()); + if(LogFactory::getInstance()->debug()) { + LogFactory::getInstance()->debug("Finding interface %s", iface.c_str()); + } #ifdef HAVE_GETIFADDRS // First find interface in interface addresses struct ifaddrs* ifaddr = 0; @@ -1229,7 +1235,9 @@ void SocketCore::bindAddress(const std::string& iface) host, NI_MAXHOST, 0, NI_MAXSERV, NI_NUMERICHOST); if(s == 0) { - LogFactory::getInstance()->debug("Sockets will bind to %s", host); + if(LogFactory::getInstance()->debug()) { + LogFactory::getInstance()->debug("Sockets will bind to %s", host); + } } } } diff --git a/src/TrackerWatcherCommand.cc b/src/TrackerWatcherCommand.cc index 73052b1e..39ed0fb0 100644 --- a/src/TrackerWatcherCommand.cc +++ b/src/TrackerWatcherCommand.cc @@ -91,7 +91,9 @@ bool TrackerWatcherCommand::execute() { } } if(_btAnnounce->noMoreAnnounce()) { - logger->debug("no more announce"); + if(logger->debug()) { + logger->debug("no more announce"); + } return true; } if(_trackerRequestGroup.isNull()) { @@ -106,7 +108,9 @@ bool TrackerWatcherCommand::execute() { commands.clear(); } e->addCommand(commands); - logger->debug("added tracker request command"); + if(logger->debug()) { + logger->debug("added tracker request command"); + } } } else if(_trackerRequestGroup->downloadFinished()){ try { @@ -171,7 +175,10 @@ void TrackerWatcherCommand::processTrackerResponse command->setPeerStorage(_peerStorage); command->setPieceStorage(_pieceStorage); e->commands.push_back(command); - logger->debug("CUID#%d - Adding new command CUID#%d", cuid, peer->usedBy()); + if(logger->debug()) { + logger->debug("CUID#%d - Adding new command CUID#%d", + cuid, peer->usedBy()); + } } } @@ -211,9 +218,13 @@ TrackerWatcherCommand::createRequestGroup(const std::string& uri) // If backup tracker is available, only try 2 times for each tracker // and if they all fails, then try next one. if(backupTrackerIsAvailable(_requestGroup->getDownloadContext())) { - logger->debug("This is multi-tracker announce."); + if(logger->debug()) { + logger->debug("This is multi-tracker announce."); + } } else { - logger->debug("This is single-tracker announce."); + if(logger->debug()) { + logger->debug("This is single-tracker announce."); + } } rg->getOption()->put(PREF_MAX_TRIES, "2"); // TODO When dry-run mode becomes available in BitTorrent, set diff --git a/src/UTMetadataDataExtensionMessage.cc b/src/UTMetadataDataExtensionMessage.cc index 813a2bf9..d32b23c1 100644 --- a/src/UTMetadataDataExtensionMessage.cc +++ b/src/UTMetadataDataExtensionMessage.cc @@ -70,8 +70,10 @@ std::string UTMetadataDataExtensionMessage::toString() const void UTMetadataDataExtensionMessage::doReceivedAction() { if(_tracker->tracks(_index)) { - _logger->debug("ut_metadata index=%lu found in tracking list", - static_cast<unsigned long>(_index)); + if(_logger->debug()) { + _logger->debug("ut_metadata index=%lu found in tracking list", + static_cast<unsigned long>(_index)); + } _tracker->remove(_index); _pieceStorage->getDiskAdaptor()->writeData (reinterpret_cast<const unsigned char*>(_data.c_str()), _data.size(), @@ -95,8 +97,10 @@ void UTMetadataDataExtensionMessage::doReceivedAction() } } } else { - _logger->debug("ut_metadata index=%lu is not tracked", - static_cast<unsigned long>(_index)); + if(_logger->debug()) { + _logger->debug("ut_metadata index=%lu is not tracked", + static_cast<unsigned long>(_index)); + } } } diff --git a/src/UTMetadataRequestFactory.cc b/src/UTMetadataRequestFactory.cc index 9a4a4905..4dcc27f7 100644 --- a/src/UTMetadataRequestFactory.cc +++ b/src/UTMetadataRequestFactory.cc @@ -55,12 +55,16 @@ void UTMetadataRequestFactory::create for(size_t index = 0; index < _dctx->getNumPieces() && num; ++index) { SharedHandle<Piece> p = pieceStorage->getMissingPiece(index); if(p.isNull()) { - _logger->debug("ut_metadata piece %lu is used or already acquired."); + if(_logger->debug()) { + _logger->debug("ut_metadata piece %lu is used or already acquired."); + } continue; } --num; - _logger->debug("Creating ut_metadata request index=%lu", - static_cast<unsigned long>(index)); + if(_logger->debug()) { + _logger->debug("Creating ut_metadata request index=%lu", + static_cast<unsigned long>(index)); + } SharedHandle<UTMetadataRequestExtensionMessage> m (new UTMetadataRequestExtensionMessage (_peer->getExtensionMessageID("ut_metadata"))); diff --git a/src/UTMetadataRequestTracker.cc b/src/UTMetadataRequestTracker.cc index 96f23627..fd6da586 100644 --- a/src/UTMetadataRequestTracker.cc +++ b/src/UTMetadataRequestTracker.cc @@ -71,9 +71,10 @@ std::vector<size_t> UTMetadataRequestTracker::removeTimeoutEntry() for(std::vector<RequestEntry>::iterator i = _trackedRequests.begin(); i != _trackedRequests.end();) { if((*i).elapsed(TIMEOUT)) { - LogFactory::getInstance()->debug - ("ut_metadata request timeout. index=%lu", - static_cast<unsigned long>((*i)._index)); + if(_logger->debug()) { + _logger->debug("ut_metadata request timeout. index=%lu", + static_cast<unsigned long>((*i)._index)); + } indexes.push_back((*i)._index); i = _trackedRequests.erase(i); } else { diff --git a/src/XmlRpcMethod.cc b/src/XmlRpcMethod.cc index a653cdce..d66b3ab1 100644 --- a/src/XmlRpcMethod.cc +++ b/src/XmlRpcMethod.cc @@ -70,7 +70,9 @@ XmlRpcResponse XmlRpcMethod::execute try { return XmlRpcResponse(0, process(req, e)); } catch(RecoverableException& e) { - _logger->debug(EX_EXCEPTION_CAUGHT, e); + if(_logger->debug()) { + _logger->debug(EX_EXCEPTION_CAUGHT, e); + } return XmlRpcResponse(1, createErrorResponse(e)); } } |