github
/
aria2
mirror of https://github.com/aria2/aria2
1
0
Fork 0
Code Issues Releases Wiki Activity

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
pull/1/head
Tatsuhiro Tsujikawa 2010-02-09 12:20:20 +00:00
parent 65c094664c
commit e227e53d7b
54 changed files with 739 additions and 336 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

57
ChangeLog
View File

@ -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> 2010-02-08 Tatsuhiro Tsujikawa <t-tujikawa@users.sourceforge.net>
Changed log level from debug to info Changed log level from debug to info

41
src/AbstractCommand.cc
View File

@ -97,8 +97,10 @@ AbstractCommand::~AbstractCommand() {
} }
bool AbstractCommand::execute() { bool AbstractCommand::execute() {
logger->debug("CUID#%d - socket: read:%d, write:%d, hup:%d, err:%d", if(logger->debug()) {
cuid, _readEvent, _writeEvent, _hupEvent, _errorEvent); logger->debug("CUID#%d - socket: read:%d, write:%d, hup:%d, err:%d",
cuid, _readEvent, _writeEvent, _hupEvent, _errorEvent);
}
try { try {
if(_requestGroup->downloadFinished() || _requestGroup->isHaltRequested()) { if(_requestGroup->downloadFinished() || _requestGroup->isHaltRequested()) {
//logger->debug("CUID#%d - finished.", cuid); //logger->debug("CUID#%d - finished.", cuid);
@ -188,7 +190,9 @@ bool AbstractCommand::execute() {
} }
} catch(DlAbortEx& err) { } catch(DlAbortEx& err) {
if(req.isNull()) { if(req.isNull()) {
logger->debug(EX_EXCEPTION_CAUGHT, err); if(logger->debug()) {
logger->debug(EX_EXCEPTION_CAUGHT, err);
}
} else { } else {
logger->error(MSG_DOWNLOAD_ABORTED, logger->error(MSG_DOWNLOAD_ABORTED,
DL_ABORT_EX2(StringFormat DL_ABORT_EX2(StringFormat
@ -240,13 +244,17 @@ void AbstractCommand::tryReserved() {
// and there are no URI left. Because file length is unknown, we // and there are no URI left. Because file length is unknown, we
// can assume that there are no in-flight request object. // can assume that there are no in-flight request object.
if(entry->getLength() == 0 && entry->getRemainingUris().empty()) { if(entry->getLength() == 0 && entry->getRemainingUris().empty()) {
logger->debug("CUID#%d - Not trying next request." if(logger->debug()) {
" No reserved/pooled request is remaining and" logger->debug("CUID#%d - Not trying next request."
" total length is still unknown.", cuid); " No reserved/pooled request is remaining and"
" total length is still unknown.", cuid);
}
return; return;
} }
} }
logger->debug("CUID#%d - Trying reserved/pooled request.", cuid); if(logger->debug()) {
logger->debug("CUID#%d - Trying reserved/pooled request.", cuid);
}
Commands commands; Commands commands;
_requestGroup->createNextCommand(commands, e, 1); _requestGroup->createNextCommand(commands, e, 1);
e->setNoWait(true); e->setNoWait(true);
@ -259,8 +267,10 @@ bool AbstractCommand::prepareForRetry(time_t wait) {
} }
if(!req.isNull()) { if(!req.isNull()) {
_fileEntry->poolRequest(req); _fileEntry->poolRequest(req);
logger->debug("CUID#%d - Pooling request URI=%s", if(logger->debug()) {
cuid, req->getUrl().c_str()); logger->debug("CUID#%d - Pooling request URI=%s",
cuid, req->getUrl().c_str());
}
if(!_requestGroup->getSegmentMan().isNull()) { if(!_requestGroup->getSegmentMan().isNull()) {
_requestGroup->getSegmentMan()->recognizeSegmentFor(_fileEntry); _requestGroup->getSegmentMan()->recognizeSegmentFor(_fileEntry);
} }
@ -286,8 +296,9 @@ void AbstractCommand::onAbort() {
_fileEntry->removeIdenticalURI(req->getUrl()); _fileEntry->removeIdenticalURI(req->getUrl());
_fileEntry->removeRequest(req); _fileEntry->removeRequest(req);
} }
if(logger->debug()) {
logger->debug("CUID#%d - Aborting download", cuid); logger->debug("CUID#%d - Aborting download", cuid);
}
if(!_requestGroup->getPieceStorage().isNull()) { if(!_requestGroup->getPieceStorage().isNull()) {
_requestGroup->getSegmentMan()->cancelSegment(cuid); _requestGroup->getSegmentMan()->cancelSegment(cuid);
} }
@ -446,9 +457,13 @@ SharedHandle<Request> AbstractCommand::createProxyRequest() const
if(!proxy.empty()) { if(!proxy.empty()) {
proxyRequest.reset(new Request()); proxyRequest.reset(new Request());
if(proxyRequest->setUrl(proxy)) { if(proxyRequest->setUrl(proxy)) {
logger->debug("CUID#%d - Using proxy", cuid); if(logger->debug()) {
logger->debug("CUID#%d - Using proxy", cuid);
}
} else { } 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(); proxyRequest.reset();
} }
} }

55
src/AdaptiveURISelector.cc
View File

@ -74,8 +74,10 @@ AdaptiveURISelector::~AdaptiveURISelector() {}
std::string AdaptiveURISelector::select(FileEntry* fileEntry) std::string AdaptiveURISelector::select(FileEntry* fileEntry)
{ {
_logger->debug("AdaptiveURISelector: called %d", if(_logger->debug()) {
_requestGroup->getNumConnection()); _logger->debug("AdaptiveURISelector: called %d",
_requestGroup->getNumConnection());
}
std::deque<std::string>& uris = fileEntry->getRemainingUris(); std::deque<std::string>& uris = fileEntry->getRemainingUris();
if (uris.empty() && _requestGroup->getNumConnection() <= 1) { if (uris.empty() && _requestGroup->getNumConnection() <= 1) {
// here we know the download will fail, trying to find previously // 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::transform(timeouts.begin(), timeouts.end(), std::back_inserter(uris),
std::mem_fun_ref(&URIResult::getURI)); std::mem_fun_ref(&URIResult::getURI));
for(std::deque<std::string>::const_iterator i = uris.begin(); i != uris.end(); if(_logger->debug()) {
++i) { for(std::deque<std::string>::const_iterator i = uris.begin();
_logger->debug("AdaptiveURISelector: will retry server with increased" i != uris.end(); ++i) {
" timeout (%d s): %s", _logger->debug("AdaptiveURISelector: will retry server with increased"
_requestGroup->getTimeout(), (*i).c_str()); " 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) { if(getNbTestedServers(uris) < 3) {
std::string notTested = getFirstNotTestedUri(uris); std::string notTested = getFirstNotTestedUri(uris);
if(notTested != A2STR::NIL) { if(notTested != A2STR::NIL) {
_logger->debug("AdaptiveURISelector: choosing the first non tested" if(_logger->debug()) {
" mirror: %s", notTested.c_str()); _logger->debug("AdaptiveURISelector: choosing the first non tested"
" mirror: %s", notTested.c_str());
}
--_nbServerToEvaluate; --_nbServerToEvaluate;
return notTested; return notTested;
} }
@ -144,16 +150,21 @@ std::string AdaptiveURISelector::selectOne(const std::deque<std::string>& uris)
std::string notTested = getFirstNotTestedUri(uris); std::string notTested = getFirstNotTestedUri(uris);
if(notTested != A2STR::NIL) { if(notTested != A2STR::NIL) {
/* Here we return the first untested mirror */ /* Here we return the first untested mirror */
_logger->debug("AdaptiveURISelector: choosing non tested mirror %s for" if(_logger->debug()) {
" connection #%d", notTested.c_str(), _nbConnections); _logger->debug("AdaptiveURISelector: choosing non tested mirror %s"
" for connection #%d",
notTested.c_str(), _nbConnections);
}
return notTested; return notTested;
} else { } else {
/* Here we return a mirror which need to be tested again */ /* Here we return a mirror which need to be tested again */
std::string toReTest = getFirstToTestUri(uris); std::string toReTest = getFirstToTestUri(uris);
if(toReTest != A2STR::NIL) { if(toReTest != A2STR::NIL) {
_logger->debug("AdaptiveURISelector: choosing mirror %s which has not" if(_logger->debug()) {
" been tested recently for connection #%d", _logger->debug("AdaptiveURISelector: choosing mirror %s which has"
toReTest.c_str(), _nbConnections); " not been tested recently for connection #%d",
toReTest.c_str(), _nbConnections);
}
return toReTest; return toReTest;
} else { } else {
return getBestMirror(uris); return getBestMirror(uris);
@ -176,15 +187,19 @@ std::string AdaptiveURISelector::getBestMirror
if (bests.size() < 2) { if (bests.size() < 2) {
std::string uri = getMaxDownloadSpeedUri(uris); std::string uri = getMaxDownloadSpeedUri(uris);
_logger->debug("AdaptiveURISelector: choosing the best mirror :" if(_logger->debug()) {
" %.2fKB/s %s (other mirrors are at least 25%% slower)", _logger->debug("AdaptiveURISelector: choosing the best mirror :"
(float) max/1024, uri.c_str()); " %.2fKB/s %s (other mirrors are at least 25%% slower)",
(float) max/1024, uri.c_str());
}
return uri; return uri;
} else { } else {
std::string uri = selectRandomUri(bests); std::string uri = selectRandomUri(bests);
_logger->debug("AdaptiveURISelector: choosing randomly one of the best" if(_logger->debug()) {
" mirrors (range [%.2fKB/s, %.2fKB/s]): %s", _logger->debug("AdaptiveURISelector: choosing randomly one of the best"
(float) min/1024, (float) max/1024, uri.c_str()); " mirrors (range [%.2fKB/s, %.2fKB/s]): %s",
(float) min/1024, (float) max/1024, uri.c_str());
}
return uri; return uri;
} }
} }

49
src/BtPieceMessage.cc
View File

@ -88,13 +88,18 @@ void BtPieceMessage::doReceivedAction() {
peer->snubbing(false); peer->snubbing(false);
PieceHandle piece = pieceStorage->getPiece(index); PieceHandle piece = pieceStorage->getPiece(index);
off_t offset = (off_t)index*_downloadContext->getPieceLength()+begin; off_t offset = (off_t)index*_downloadContext->getPieceLength()+begin;
logger->debug(MSG_PIECE_RECEIVED, if(logger->debug()) {
cuid, index, begin, blockLength, offset, slot.getBlockIndex()); logger->debug(MSG_PIECE_RECEIVED,
cuid, index, begin, blockLength, offset,
slot.getBlockIndex());
}
pieceStorage->getDiskAdaptor()->writeData(block, blockLength, offset); pieceStorage->getDiskAdaptor()->writeData(block, blockLength, offset);
piece->completeBlock(slot.getBlockIndex()); piece->completeBlock(slot.getBlockIndex());
logger->debug(MSG_PIECE_BITFIELD, cuid, if(logger->debug()) {
util::toHex(piece->getBitfield(), logger->debug(MSG_PIECE_BITFIELD, cuid,
piece->getBitfieldLength()).c_str()); util::toHex(piece->getBitfield(),
piece->getBitfieldLength()).c_str());
}
piece->updateHash(begin, block, blockLength); piece->updateHash(begin, block, blockLength);
dispatcher->removeOutstandingRequest(slot); dispatcher->removeOutstandingRequest(slot);
if(piece->pieceComplete()) { if(piece->pieceComplete()) {
@ -105,8 +110,10 @@ void BtPieceMessage::doReceivedAction() {
} }
} }
} else { } else {
logger->debug("CUID#%d - RequestSlot not found, index=%d, begin=%d", if(logger->debug()) {
cuid, index, begin); 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 pieceDataOffset =
(off_t)index*_downloadContext->getPieceLength()+begin; (off_t)index*_downloadContext->getPieceLength()+begin;
size_t writtenLength = sendPieceData(pieceDataOffset, blockLength); size_t writtenLength = sendPieceData(pieceDataOffset, blockLength);
logger->debug("msglength = %lu bytes", if(logger->debug()) {
static_cast<unsigned long>(getMessageHeaderLength()+ logger->debug("msglength = %lu bytes",
blockLength)); static_cast<unsigned long>(getMessageHeaderLength()+
blockLength));
}
peer->updateUploadLength(writtenLength); peer->updateUploadLength(writtenLength);
} else { } else {
ssize_t writtenLength = peerConnection->sendPendingData(); ssize_t writtenLength = peerConnection->sendPendingData();
@ -176,8 +185,10 @@ std::string BtPieceMessage::toString() const {
bool BtPieceMessage::checkPieceHash(const PieceHandle& piece) { bool BtPieceMessage::checkPieceHash(const PieceHandle& piece) {
if(piece->isHashCalculated()) { if(piece->isHashCalculated()) {
logger->debug("Hash is available!! index=%lu", if(logger->debug()) {
static_cast<unsigned long>(piece->getIndex())); logger->debug("Hash is available!! index=%lu",
static_cast<unsigned long>(piece->getIndex()));
}
return return
piece->getHashString()==_downloadContext->getPieceHash(piece->getIndex()); piece->getHashString()==_downloadContext->getPieceHash(piece->getIndex());
} else { } else {
@ -222,12 +233,9 @@ void BtPieceMessage::onChokingEvent(const BtChokingEvent& event)
if(!invalidate && if(!invalidate &&
!sendingInProgress && !sendingInProgress &&
!peer->isInAmAllowedIndexSet(index)) { !peer->isInAmAllowedIndexSet(index)) {
logger->debug(MSG_REJECT_PIECE_CHOKED, if(logger->debug()) {
cuid, logger->debug(MSG_REJECT_PIECE_CHOKED, cuid, index, begin, blockLength);
index, }
begin,
blockLength);
if(peer->isFastExtensionEnabled()) { if(peer->isFastExtensionEnabled()) {
BtMessageHandle rej = messageFactory->createRejectMessage(index, BtMessageHandle rej = messageFactory->createRejectMessage(index,
begin, begin,
@ -246,8 +254,9 @@ void BtPieceMessage::onCancelSendingPieceEvent
index == event.getIndex() && index == event.getIndex() &&
begin == event.getBegin() && begin == event.getBegin() &&
blockLength == event.getLength()) { blockLength == event.getLength()) {
logger->debug(MSG_REJECT_PIECE_CANCEL, if(logger->debug()) {
cuid, index, begin, blockLength); logger->debug(MSG_REJECT_PIECE_CANCEL, cuid, index, begin, blockLength);
}
if(peer->isFastExtensionEnabled()) { if(peer->isFastExtensionEnabled()) {
BtMessageHandle rej = messageFactory->createRejectMessage(index, BtMessageHandle rej = messageFactory->createRejectMessage(index,
begin, begin,

4
src/BtPortMessage.cc
View File

@ -72,7 +72,9 @@ void BtPortMessage::doReceivedAction()
{ {
if(!_taskFactory.isNull() && !_taskQueue.isNull()) { if(!_taskFactory.isNull() && !_taskQueue.isNull()) {
if(_port == 0) { if(_port == 0) {
logger->debug("Ignored port 0."); if(logger->debug()) {
logger->debug("Ignored port 0.");
}
return; return;
} }
// node id is random at this point. When ping reply received, new DHTNode // node id is random at this point. When ping reply received, new DHTNode

4
src/CreateRequestCommand.cc
View File

@ -111,7 +111,9 @@ bool CreateRequestCommand::prepareForRetry(time_t wait)
if(!_requestGroup->getPieceStorage().isNull()) { if(!_requestGroup->getPieceStorage().isNull()) {
_requestGroup->getSegmentMan()->cancelSegment(cuid); _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); SleepCommand* scom = new SleepCommand(cuid, e, _requestGroup, this, wait);
e->commands.push_back(scom); e->commands.push_back(scom);
return false; return false;

41
src/DHTAbstractNodeLookupTask.cc
View File

@ -71,16 +71,21 @@ void DHTAbstractNodeLookupTask::onReceived(const SharedHandle<DHTMessage>& messa
if(memcmp(_localNode->getID(), (*i)->_node->getID(), DHT_ID_LENGTH) != 0) { if(memcmp(_localNode->getID(), (*i)->_node->getID(), DHT_ID_LENGTH) != 0) {
_entries.push_front(*i); _entries.push_front(*i);
++count; ++count;
_logger->debug("Received nodes: id=%s, ip=%s", if(_logger->debug()) {
util::toHex((*i)->_node->getID(), DHT_ID_LENGTH).c_str(), _logger->debug("Received nodes: id=%s, ip=%s",
(*i)->_node->getIPAddress().c_str()); util::toHex((*i)->_node->getID(), DHT_ID_LENGTH).c_str(),
(*i)->_node->getIPAddress().c_str());
}
} }
} }
if(_logger->debug()) {
_logger->debug("%u node lookup entries added.", count); _logger->debug("%u node lookup entries added.", count);
}
std::stable_sort(_entries.begin(), _entries.end(), DHTIDCloser(_targetID)); std::stable_sort(_entries.begin(), _entries.end(), DHTIDCloser(_targetID));
_entries.erase(std::unique(_entries.begin(), _entries.end()), _entries.end()); _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) { if(_entries.size() > DHTBucket::K) {
_entries.erase(_entries.begin()+DHTBucket::K, _entries.end()); _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) void DHTAbstractNodeLookupTask::onTimeout(const SharedHandle<DHTNode>& node)
{ {
_logger->debug("node lookup message timeout for node ID=%s", if(_logger->debug()) {
util::toHex(node->getID(), DHT_ID_LENGTH).c_str()); _logger->debug("node lookup message timeout for node ID=%s",
util::toHex(node->getID(), DHT_ID_LENGTH).c_str());
}
--_inFlightMessage; --_inFlightMessage;
for(std::deque<SharedHandle<DHTNodeLookupEntry> >::iterator i = _entries.begin(); i != _entries.end(); ++i) { for(std::deque<SharedHandle<DHTNodeLookupEntry> >::iterator i = _entries.begin(); i != _entries.end(); ++i) {
if((*i)->_node == node) { if((*i)->_node == node) {
@ -107,15 +114,19 @@ void DHTAbstractNodeLookupTask::sendMessageAndCheckFinish()
sendMessage(); sendMessage();
} }
if(_inFlightMessage == 0) { if(_inFlightMessage == 0) {
_logger->debug("Finished node_lookup for node ID %s", if(_logger->debug()) {
util::toHex(_targetID, DHT_ID_LENGTH).c_str()); _logger->debug("Finished node_lookup for node ID %s",
util::toHex(_targetID, DHT_ID_LENGTH).c_str());
}
onFinish(); onFinish();
updateBucket(); updateBucket();
_finished = true; _finished = true;
} else { } else {
_logger->debug("%d in flight message for node ID %s", if(_logger->debug()) {
_inFlightMessage, _logger->debug("%d in flight message for node ID %s",
util::toHex(_targetID, DHT_ID_LENGTH).c_str()); _inFlightMessage,
util::toHex(_targetID, DHT_ID_LENGTH).c_str());
}
} }
} }
@ -151,7 +162,9 @@ void DHTAbstractNodeLookupTask::startup()
_inFlightMessage = 0; _inFlightMessage = 0;
sendMessage(); sendMessage();
if(_inFlightMessage == 0) { 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; _finished = true;
} }
} }

19
src/DHTBucket.cc
View File

@ -201,15 +201,16 @@ SharedHandle<DHTBucket> DHTBucket::split()
} }
_nodes = lNodes; _nodes = lNodes;
// TODO create toString() and use it. // TODO create toString() and use it.
_logger->debug("New bucket. prefixLength=%u, Range:%s-%s", if(_logger->debug()) {
static_cast<unsigned int>(rBucket->getPrefixLength()), _logger->debug("New bucket. prefixLength=%u, Range:%s-%s",
util::toHex(rBucket->getMinID(), DHT_ID_LENGTH).c_str(), static_cast<unsigned int>(rBucket->getPrefixLength()),
util::toHex(rBucket->getMaxID(), DHT_ID_LENGTH).c_str()); util::toHex(rBucket->getMinID(), DHT_ID_LENGTH).c_str(),
_logger->debug("Existing bucket. prefixLength=%u, Range:%s-%s", util::toHex(rBucket->getMaxID(), DHT_ID_LENGTH).c_str());
static_cast<unsigned int>(_prefixLength), _logger->debug("Existing bucket. prefixLength=%u, Range:%s-%s",
util::toHex(getMinID(), DHT_ID_LENGTH).c_str(), static_cast<unsigned int>(_prefixLength),
util::toHex(getMaxID(), DHT_ID_LENGTH).c_str()); util::toHex(getMinID(), DHT_ID_LENGTH).c_str(),
util::toHex(getMaxID(), DHT_ID_LENGTH).c_str());
}
return rBucket; return rBucket;
} }

7
src/DHTGetPeersCommand.cc
View File

@ -74,8 +74,11 @@ bool DHTGetPeersCommand::execute()
if(_task.isNull() && if(_task.isNull() &&
((_numRetry > 0 && _lastGetPeerTime.elapsed(RETRY_INTERVAL)) || ((_numRetry > 0 && _lastGetPeerTime.elapsed(RETRY_INTERVAL)) ||
_lastGetPeerTime.elapsed(GET_PEER_INTERVAL))) { _lastGetPeerTime.elapsed(GET_PEER_INTERVAL))) {
logger->debug("Issuing PeerLookup for infoHash=%s", if(logger->debug()) {
bittorrent::getInfoHashString(_requestGroup->getDownloadContext()).c_str()); logger->debug("Issuing PeerLookup for infoHash=%s",
bittorrent::getInfoHashString
(_requestGroup->getDownloadContext()).c_str());
}
_task = _taskFactory->createPeerLookupTask _task = _taskFactory->createPeerLookupTask
(_requestGroup->getDownloadContext(), _btRuntime, _peerStorage); (_requestGroup->getDownloadContext(), _btRuntime, _peerStorage);
_taskQueue->addPeriodicTask2(_task); _taskQueue->addPeriodicTask2(_task);

6
src/DHTMessageDispatcherImpl.cc
View File

@ -105,8 +105,10 @@ void DHTMessageDispatcherImpl::sendMessages()
} }
} }
_messageQueue.erase(_messageQueue.begin(), itr); _messageQueue.erase(_messageQueue.begin(), itr);
_logger->debug("%lu dht messages remaining in the queue.", if(_logger->debug()) {
static_cast<unsigned long>(_messageQueue.size())); _logger->debug("%lu dht messages remaining in the queue.",
static_cast<unsigned long>(_messageQueue.size()));
}
} }
size_t DHTMessageDispatcherImpl::countMessageInQueue() const size_t DHTMessageDispatcherImpl::countMessageInQueue() const

4
src/DHTMessageFactoryImpl.cc
View File

@ -236,7 +236,9 @@ DHTMessageFactoryImpl::createResponseMessage(const std::string& messageType,
util::itos(getInteger(e, 0).i()).c_str(), util::itos(getInteger(e, 0).i()).c_str(),
util::urlencode(getString(e, 1).s()).c_str()); util::urlencode(getString(e, 1).s()).c_str());
} else { } 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."); throw DL_ABORT_EX("Received Error DHT message.");
} else if(y.s() != DHTResponseMessage::R) { } else if(y.s() != DHTResponseMessage::R) {

30
src/DHTMessageTracker.cc
View File

@ -77,14 +77,18 @@ DHTMessageTracker::messageArrived(const BDE& dict,
throw DL_ABORT_EX(StringFormat("Malformed DHT message. From:%s:%u", throw DL_ABORT_EX(StringFormat("Malformed DHT message. From:%s:%u",
ipaddr.c_str(), port).str()); ipaddr.c_str(), port).str());
} }
_logger->debug("Searching tracker entry for TransactionID=%s, Remote=%s:%u", if(_logger->debug()) {
util::toHex(tid.s()).c_str(), ipaddr.c_str(), port); _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 = for(std::deque<SharedHandle<DHTMessageTrackerEntry> >::iterator i =
_entries.begin(); i != _entries.end(); ++i) { _entries.begin(); i != _entries.end(); ++i) {
if((*i)->match(tid.s(), ipaddr, port)) { if((*i)->match(tid.s(), ipaddr, port)) {
SharedHandle<DHTMessageTrackerEntry> entry = *i; SharedHandle<DHTMessageTrackerEntry> entry = *i;
_entries.erase(i); _entries.erase(i);
_logger->debug("Tracker entry found."); if(_logger->debug()) {
_logger->debug("Tracker entry found.");
}
SharedHandle<DHTNode> targetNode = entry->getTargetNode(); SharedHandle<DHTNode> targetNode = entry->getTargetNode();
SharedHandle<DHTMessage> message = SharedHandle<DHTMessage> message =
@ -93,13 +97,17 @@ DHTMessageTracker::messageArrived(const BDE& dict,
targetNode->getPort()); targetNode->getPort());
int64_t rtt = entry->getElapsedMillis(); 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); message->getRemoteNode()->updateRTT(rtt);
SharedHandle<DHTMessageCallback> callback = entry->getCallback(); SharedHandle<DHTMessageCallback> callback = entry->getCallback();
return std::pair<SharedHandle<DHTMessage>, SharedHandle<DHTMessageCallback> >(message, callback); 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> >(); return std::pair<SharedHandle<DHTMessage>, SharedHandle<DHTMessageCallback> >();
} }
@ -112,13 +120,17 @@ void DHTMessageTracker::handleTimeout()
SharedHandle<DHTMessageTrackerEntry> entry = *i; SharedHandle<DHTMessageTrackerEntry> entry = *i;
i = _entries.erase(i); i = _entries.erase(i);
SharedHandle<DHTNode> node = entry->getTargetNode(); SharedHandle<DHTNode> node = entry->getTargetNode();
_logger->debug("Message timeout: To:%s:%u", if(_logger->debug()) {
node->getIPAddress().c_str(), node->getPort()); _logger->debug("Message timeout: To:%s:%u",
node->getIPAddress().c_str(), node->getPort());
}
node->updateRTT(entry->getElapsedMillis()); node->updateRTT(entry->getElapsedMillis());
node->timeout(); node->timeout();
if(node->isBad()) { if(node->isBad()) {
_logger->debug("Marked bad: %s:%u", if(_logger->debug()) {
node->getIPAddress().c_str(), node->getPort()); _logger->debug("Marked bad: %s:%u",
node->getIPAddress().c_str(), node->getPort());
}
_routingTable->dropNode(node); _routingTable->dropNode(node);
} }
SharedHandle<DHTMessageCallback> callback = entry->getCallback(); SharedHandle<DHTMessageCallback> callback = entry->getCallback();

30
src/DHTPeerAnnounceStorage.cc
View File

@ -86,8 +86,11 @@ void
DHTPeerAnnounceStorage::addPeerAnnounce(const unsigned char* infoHash, DHTPeerAnnounceStorage::addPeerAnnounce(const unsigned char* infoHash,
const std::string& ipaddr, uint16_t port) const std::string& ipaddr, uint16_t port)
{ {
_logger->debug("Adding %s:%u to peer announce list: infoHash=%s", if(_logger->debug()) {
ipaddr.c_str(), port, util::toHex(infoHash, DHT_ID_LENGTH).c_str()); _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)); getPeerAnnounceEntry(infoHash)->addPeerAddrEntry(PeerAddrEntry(ipaddr, port));
} }
@ -123,27 +126,34 @@ public:
void DHTPeerAnnounceStorage::handleTimeout() void DHTPeerAnnounceStorage::handleTimeout()
{ {
_logger->debug("Now purge peer announces(%lu entries) which are timed out.", if(_logger->debug()) {
static_cast<unsigned long>(_entries.size())); _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()); std::for_each(_entries.begin(), _entries.end(), RemoveStalePeerAddrEntry());
_entries.erase(std::remove_if(_entries.begin(), _entries.end(), _entries.erase(std::remove_if(_entries.begin(), _entries.end(),
mem_fun_sh(&DHTPeerAnnounceEntry::empty)), mem_fun_sh(&DHTPeerAnnounceEntry::empty)),
_entries.end()); _entries.end());
_logger->debug("Currently %lu peer announce entries", if(_logger->debug()) {
static_cast<unsigned long>(_entries.size())); _logger->debug("Currently %lu peer announce entries",
static_cast<unsigned long>(_entries.size()));
}
} }
void DHTPeerAnnounceStorage::announcePeer() 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) { for(std::deque<SharedHandle<DHTPeerAnnounceEntry> >::iterator i = _entries.begin(); i != _entries.end(); ++i) {
if((*i)->getLastUpdated().elapsed(DHT_PEER_ANNOUNCE_INTERVAL)) { if((*i)->getLastUpdated().elapsed(DHT_PEER_ANNOUNCE_INTERVAL)) {
(*i)->notifyUpdate(); (*i)->notifyUpdate();
SharedHandle<DHTTask> task = _taskFactory->createPeerAnnounceTask((*i)->getInfoHash()); SharedHandle<DHTTask> task = _taskFactory->createPeerAnnounceTask((*i)->getInfoHash());
_taskQueue->addPeriodicTask2(task); _taskQueue->addPeriodicTask2(task);
_logger->debug("Added 1 peer announce: infoHash=%s", if(_logger->debug()) {
util::toHex((*i)->getInfoHash(), DHT_ID_LENGTH).c_str()); _logger->debug("Added 1 peer announce: infoHash=%s",
util::toHex((*i)->getInfoHash(), DHT_ID_LENGTH).c_str());
}
} }
} }
} }

26
src/DHTRoutingTable.cc
View File

@ -74,22 +74,30 @@ bool DHTRoutingTable::addGoodNode(const SharedHandle<DHTNode>& node)
bool DHTRoutingTable::addNode(const SharedHandle<DHTNode>& node, bool good) 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) { if(_localNode == node) {
_logger->debug("Adding node with the same ID with localnode is not" if(_logger->debug()) {
" allowed."); _logger->debug("Adding node with the same ID with localnode is not"
" allowed.");
}
return false; return false;
} }
BNode* bnode = BNode::findBNodeFor(_root, node->getID()); BNode* bnode = BNode::findBNodeFor(_root, node->getID());
SharedHandle<DHTBucket> bucket = bnode->getBucket(); SharedHandle<DHTBucket> bucket = bnode->getBucket();
while(1) { while(1) {
if(bucket->addNode(node)) { if(bucket->addNode(node)) {
_logger->debug("Added DHTNode."); if(_logger->debug()) {
_logger->debug("Added DHTNode.");
}
return true; return true;
} else if(bucket->splitAllowed()) { } else if(bucket->splitAllowed()) {
_logger->debug("Splitting bucket. Range:%s-%s", if(_logger->debug()) {
util::toHex(bucket->getMinID(), DHT_ID_LENGTH).c_str(), _logger->debug("Splitting bucket. Range:%s-%s",
util::toHex(bucket->getMaxID(), DHT_ID_LENGTH).c_str()); util::toHex(bucket->getMinID(), DHT_ID_LENGTH).c_str(),
util::toHex(bucket->getMaxID(), DHT_ID_LENGTH).c_str());
}
SharedHandle<DHTBucket> r = bucket->split(); SharedHandle<DHTBucket> r = bucket->split();
bnode->setBucket(SharedHandle<DHTBucket>()); bnode->setBucket(SharedHandle<DHTBucket>());
@ -108,7 +116,9 @@ bool DHTRoutingTable::addNode(const SharedHandle<DHTNode>& node, bool good)
} else { } else {
if(good) { if(good) {
bucket->cacheNode(node); 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; return false;
} }

7
src/DHTSetup.cc
View File

@ -118,9 +118,10 @@ void DHTSetup::setup(std::deque<Command*>& commands,
} }
localNode->setPort(port); localNode->setPort(port);
} }
_logger->debug("Initialized local node ID=%s", if(_logger->debug()) {
util::toHex(localNode->getID(), DHT_ID_LENGTH).c_str()); _logger->debug("Initialized local node ID=%s",
util::toHex(localNode->getID(), DHT_ID_LENGTH).c_str());
}
SharedHandle<DHTRoutingTable> routingTable(new DHTRoutingTable(localNode)); SharedHandle<DHTRoutingTable> routingTable(new DHTRoutingTable(localNode));
SharedHandle<DHTMessageFactoryImpl> factory(new DHTMessageFactoryImpl()); SharedHandle<DHTMessageFactoryImpl> factory(new DHTMessageFactoryImpl());

24
src/DefaultBtAnnounce.cc
View File

@ -211,7 +211,9 @@ void
DefaultBtAnnounce::processAnnounceResponse(const unsigned char* trackerResponse, DefaultBtAnnounce::processAnnounceResponse(const unsigned char* trackerResponse,
size_t trackerResponseLength) size_t trackerResponseLength)
{ {
logger->debug("Now processing tracker response."); if(logger->debug()) {
logger->debug("Now processing tracker response.");
}
const BDE dict = const BDE dict =
bencode::decode(trackerResponse, trackerResponseLength); bencode::decode(trackerResponse, trackerResponseLength);
if(!dict.isDict()) { if(!dict.isDict()) {
@ -229,17 +231,23 @@ DefaultBtAnnounce::processAnnounceResponse(const unsigned char* trackerResponse,
const BDE& tid = dict[BtAnnounce::TRACKER_ID]; const BDE& tid = dict[BtAnnounce::TRACKER_ID];
if(tid.isString()) { if(tid.isString()) {
trackerId = tid.s(); 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]; const BDE& ival = dict[BtAnnounce::INTERVAL];
if(ival.isInteger() && ival.i() > 0) { if(ival.isInteger() && ival.i() > 0) {
interval = ival.i(); interval = ival.i();
logger->debug("Interval:%d", interval); if(logger->debug()) {
logger->debug("Interval:%d", interval);
}
} }
const BDE& mival = dict[BtAnnounce::MIN_INTERVAL]; const BDE& mival = dict[BtAnnounce::MIN_INTERVAL];
if(mival.isInteger() && mival.i() > 0) { if(mival.isInteger() && mival.i() > 0) {
minInterval = mival.i(); minInterval = mival.i();
logger->debug("Min interval:%d", minInterval); if(logger->debug()) {
logger->debug("Min interval:%d", minInterval);
}
if(minInterval > interval) { if(minInterval > interval) {
minInterval = interval; minInterval = interval;
} }
@ -250,12 +258,16 @@ DefaultBtAnnounce::processAnnounceResponse(const unsigned char* trackerResponse,
const BDE& comp = dict[BtAnnounce::COMPLETE]; const BDE& comp = dict[BtAnnounce::COMPLETE];
if(comp.isInteger()) { if(comp.isInteger()) {
complete = comp.i(); complete = comp.i();
logger->debug("Complete:%d", complete); if(logger->debug()) {
logger->debug("Complete:%d", complete);
}
} }
const BDE& incomp = dict[BtAnnounce::INCOMPLETE]; const BDE& incomp = dict[BtAnnounce::INCOMPLETE];
if(incomp.isInteger()) { if(incomp.isInteger()) {
incomplete = incomp.i(); incomplete = incomp.i();
logger->debug("Incomplete:%d", incomplete); if(logger->debug()) {
logger->debug("Incomplete:%d", incomplete);
}
} }
const BDE& peerData = dict[BtAnnounce::PEERS]; const BDE& peerData = dict[BtAnnounce::PEERS];
if(peerData.isNone()) { if(peerData.isNone()) {

14
src/DefaultBtInteractive.cc
View File

@ -302,13 +302,17 @@ size_t DefaultBtInteractive::receiveMessages() {
void DefaultBtInteractive::decideInterest() { void DefaultBtInteractive::decideInterest() {
if(_pieceStorage->hasMissingPiece(peer)) { if(_pieceStorage->hasMissingPiece(peer)) {
if(!peer->amInterested()) { if(!peer->amInterested()) {
logger->debug(MSG_PEER_INTERESTED, cuid); if(logger->debug()) {
logger->debug(MSG_PEER_INTERESTED, cuid);
}
dispatcher-> dispatcher->
addMessageToQueue(messageFactory->createInterestedMessage()); addMessageToQueue(messageFactory->createInterestedMessage());
} }
} else { } else {
if(peer->amInterested()) { if(peer->amInterested()) {
logger->debug(MSG_PEER_NOT_INTERESTED, cuid); if(logger->debug()) {
logger->debug(MSG_PEER_NOT_INTERESTED, cuid);
}
dispatcher-> dispatcher->
addMessageToQueue(messageFactory->createNotInterestedMessage()); addMessageToQueue(messageFactory->createNotInterestedMessage());
} }
@ -377,8 +381,10 @@ void DefaultBtInteractive::cancelAllPiece() {
_utMetadataRequestTracker->getAllTrackedIndex(); _utMetadataRequestTracker->getAllTrackedIndex();
for(std::vector<size_t>::const_iterator i = metadataRequests.begin(); for(std::vector<size_t>::const_iterator i = metadataRequests.begin();
i != metadataRequests.end(); ++i) { i != metadataRequests.end(); ++i) {
logger->debug("Cancel metadata: piece=%lu", if(logger->debug()) {
static_cast<unsigned long>(*i)); logger->debug("Cancel metadata: piece=%lu",
static_cast<unsigned long>(*i));
}
_pieceStorage->cancelPiece(_pieceStorage->getPiece(*i)); _pieceStorage->cancelPiece(_pieceStorage->getPiece(*i));
} }
} }

48
src/DefaultBtMessageDispatcher.cc
View File

@ -64,7 +64,9 @@ DefaultBtMessageDispatcher::DefaultBtMessageDispatcher():
DefaultBtMessageDispatcher::~DefaultBtMessageDispatcher() DefaultBtMessageDispatcher::~DefaultBtMessageDispatcher()
{ {
logger->debug("DefaultBtMessageDispatcher::deleted"); if(logger->debug()) {
logger->debug("DefaultBtMessageDispatcher::deleted");
}
} }
void DefaultBtMessageDispatcher::addMessageToQueue(const BtMessageHandle& btMessage) void DefaultBtMessageDispatcher::addMessageToQueue(const BtMessageHandle& btMessage)
@ -144,11 +146,13 @@ public:
void operator()(const RequestSlot& slot) const void operator()(const RequestSlot& slot) const
{ {
_logger->debug(MSG_DELETING_REQUEST_SLOT, if(_logger->debug()) {
_cuid, _logger->debug(MSG_DELETING_REQUEST_SLOT,
slot.getIndex(), _cuid,
slot.getBlockIndex()); slot.getIndex(),
_logger->debug("index=%d, begin=%d", slot.getIndex(), slot.getBegin()); slot.getBlockIndex());
_logger->debug("index=%d, begin=%d", slot.getIndex(), slot.getBegin());
}
_piece->cancelBlock(slot.getBlockIndex()); _piece->cancelBlock(slot.getBlockIndex());
} }
}; };
@ -191,11 +195,13 @@ public:
void operator()(const RequestSlot& slot) const void operator()(const RequestSlot& slot) const
{ {
if(!_peer->isInPeerAllowedIndexSet(slot.getIndex())) { if(!_peer->isInPeerAllowedIndexSet(slot.getIndex())) {
_logger->debug(MSG_DELETING_REQUEST_SLOT_CHOKED, if(_logger->debug()) {
_cuid, _logger->debug(MSG_DELETING_REQUEST_SLOT_CHOKED,
slot.getIndex(), _cuid,
slot.getBlockIndex()); slot.getIndex(),
_logger->debug("index=%d, begin=%d", slot.getIndex(), slot.getBegin()); slot.getBlockIndex());
_logger->debug("index=%d, begin=%d", slot.getIndex(), slot.getBegin());
}
SharedHandle<Piece> piece = _pieceStorage->getPiece(slot.getIndex()); SharedHandle<Piece> piece = _pieceStorage->getPiece(slot.getIndex());
piece->cancelBlock(slot.getBlockIndex()); piece->cancelBlock(slot.getBlockIndex());
} }
@ -266,17 +272,21 @@ public:
void operator()(const RequestSlot& slot) void operator()(const RequestSlot& slot)
{ {
if(slot.isTimeout(_now, _requestTimeout)) { if(slot.isTimeout(_now, _requestTimeout)) {
_logger->debug(MSG_DELETING_REQUEST_SLOT_TIMEOUT, if(_logger->debug()) {
_cuid, _logger->debug(MSG_DELETING_REQUEST_SLOT_TIMEOUT,
slot.getBlockIndex()); _cuid,
_logger->debug("index=%d, begin=%d", slot.getIndex(), slot.getBegin()); slot.getBlockIndex());
_logger->debug("index=%d, begin=%d", slot.getIndex(), slot.getBegin());
}
slot.getPiece()->cancelBlock(slot.getBlockIndex()); slot.getPiece()->cancelBlock(slot.getBlockIndex());
_peer->snubbing(true); _peer->snubbing(true);
} else if(slot.getPiece()->hasBlock(slot.getBlockIndex())) { } else if(slot.getPiece()->hasBlock(slot.getBlockIndex())) {
_logger->debug(MSG_DELETING_REQUEST_SLOT_ACQUIRED, if(_logger->debug()) {
_cuid, _logger->debug(MSG_DELETING_REQUEST_SLOT_ACQUIRED,
slot.getBlockIndex()); _cuid,
_logger->debug("index=%d, begin=%d", slot.getIndex(), slot.getBegin()); slot.getBlockIndex());
_logger->debug("index=%d, begin=%d", slot.getIndex(), slot.getBegin());
}
_messageDispatcher->addMessageToQueue _messageDispatcher->addMessageToQueue
(_messageFactory->createCancelMessage(slot.getIndex(), (_messageFactory->createCancelMessage(slot.getIndex(),
slot.getBegin(), slot.getBegin(),

8
src/DefaultBtMessageReceiver.cc
View File

@ -54,12 +54,16 @@ DefaultBtMessageReceiver::DefaultBtMessageReceiver():
handshakeSent(false), handshakeSent(false),
logger(LogFactory::getInstance()) logger(LogFactory::getInstance())
{ {
logger->debug("DefaultBtMessageReceiver::instantiated"); if(logger->debug()) {
logger->debug("DefaultBtMessageReceiver::instantiated");
}
} }
DefaultBtMessageReceiver::~DefaultBtMessageReceiver() DefaultBtMessageReceiver::~DefaultBtMessageReceiver()
{ {
logger->debug("DefaultBtMessageReceiver::deleted"); if(logger->debug()) {
logger->debug("DefaultBtMessageReceiver::deleted");
}
} }
SharedHandle<BtHandshakeMessage> SharedHandle<BtHandshakeMessage>

4
src/DefaultBtProgressInfoFile.cc
View File

@ -247,7 +247,9 @@ void DefaultBtProgressInfoFile::load()
bool infoHashCheckEnabled = false; bool infoHashCheckEnabled = false;
if(extension[3]&1 && isTorrentDownload()) { if(extension[3]&1 && isTorrentDownload()) {
infoHashCheckEnabled = true; infoHashCheckEnabled = true;
_logger->debug("InfoHash checking enabled."); if(_logger->debug()) {
_logger->debug("InfoHash checking enabled.");
}
} }
uint32_t infoHashLength; uint32_t infoHashLength;

31
src/DefaultBtRequestFactory.cc
View File

@ -54,12 +54,16 @@ DefaultBtRequestFactory::DefaultBtRequestFactory():
cuid(0), cuid(0),
_logger(LogFactory::getInstance()) _logger(LogFactory::getInstance())
{ {
LogFactory::getInstance()->debug("DefaultBtRequestFactory::instantiated"); if(_logger->debug()) {
_logger->debug("DefaultBtRequestFactory::instantiated");
}
} }
DefaultBtRequestFactory::~DefaultBtRequestFactory() DefaultBtRequestFactory::~DefaultBtRequestFactory()
{ {
LogFactory::getInstance()->debug("DefaultBtRequestFactory::deleted"); if(_logger->debug()) {
_logger->debug("DefaultBtRequestFactory::deleted");
}
} }
void DefaultBtRequestFactory::addTargetPiece(const PieceHandle& piece) void DefaultBtRequestFactory::addTargetPiece(const PieceHandle& piece)
@ -154,11 +158,13 @@ void DefaultBtRequestFactory::createRequestMessages
size_t blockIndex; size_t blockIndex;
while(requests.size() < max && while(requests.size() < max &&
piece->getMissingUnusedBlockIndex(blockIndex)) { piece->getMissingUnusedBlockIndex(blockIndex)) {
_logger->debug("Creating RequestMessage index=%u, begin=%u, blockIndex=%u", if(_logger->debug()) {
piece->getIndex(), _logger->debug("Creating RequestMessage index=%u, begin=%u,"
blockIndex*piece->getBlockLength(), " blockIndex=%u",
blockIndex); piece->getIndex(),
blockIndex*piece->getBlockLength(),
blockIndex);
}
requests.push_back(messageFactory->createRequestMessage(piece, blockIndex)); requests.push_back(messageFactory->createRequestMessage(piece, blockIndex));
} }
} }
@ -193,10 +199,13 @@ void DefaultBtRequestFactory::createRequestMessagesOnEndGame
const size_t& blockIndex = *bitr; const size_t& blockIndex = *bitr;
if(!dispatcher->isOutstandingRequest(piece->getIndex(), if(!dispatcher->isOutstandingRequest(piece->getIndex(),
blockIndex)) { blockIndex)) {
_logger->debug("Creating RequestMessage index=%u, begin=%u, blockIndex=%u", if(_logger->debug()) {
piece->getIndex(), _logger->debug("Creating RequestMessage index=%u, begin=%u,"
blockIndex*piece->getBlockLength(), " blockIndex=%u",
blockIndex); piece->getIndex(),
blockIndex*piece->getBlockLength(),
blockIndex);
}
requests.push_back(messageFactory->createRequestMessage(piece, blockIndex)); requests.push_back(messageFactory->createRequestMessage(piece, blockIndex));
} }
} }

23
src/DefaultPeerStorage.cc
View File

@ -95,7 +95,10 @@ static size_t calculateMaxPeerListSize(const SharedHandle<BtRuntime>& btRuntime)
bool DefaultPeerStorage::addPeer(const PeerHandle& peer) { bool DefaultPeerStorage::addPeer(const PeerHandle& peer) {
if(isPeerAlreadyAdded(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; return false;
} }
size_t maxPeerListSize = calculateMaxPeerListSize(_btRuntime); size_t maxPeerListSize = calculateMaxPeerListSize(_btRuntime);
@ -111,8 +114,9 @@ void DefaultPeerStorage::addPeer(const Peers& peers) {
itr != peers.end(); ++itr) { itr != peers.end(); ++itr) {
const PeerHandle& peer = *itr; const PeerHandle& peer = *itr;
if(addPeer(peer)) { if(addPeer(peer)) {
logger->debug(MSG_ADDING_PEER, if(logger->debug()) {
peer->ipaddr.c_str(), peer->port); logger->debug(MSG_ADDING_PEER, peer->ipaddr.c_str(), peer->port);
}
} }
} }
} }
@ -205,7 +209,9 @@ TransferStat DefaultPeerStorage::calculateStat()
{ {
TransferStat stat; TransferStat stat;
if(_lastTransferStatMapUpdated.elapsedInMillis(250)) { if(_lastTransferStatMapUpdated.elapsedInMillis(250)) {
logger->debug("Updating TransferStat of PeerStorage"); if(logger->debug()) {
logger->debug("Updating TransferStat of PeerStorage");
}
_lastTransferStatMapUpdated.reset(); _lastTransferStatMapUpdated.reset();
_peerTransferStatMap.clear(); _peerTransferStatMap.clear();
std::deque<SharedHandle<Peer> > activePeers; std::deque<SharedHandle<Peer> > activePeers;
@ -236,7 +242,9 @@ TransferStat DefaultPeerStorage::calculateStat()
void DefaultPeerStorage::updateTransferStatFor(const SharedHandle<Peer>& peer) 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()]; _cachedTransferStat -= _peerTransferStatMap[peer->getID()];
TransferStat s = calculateStatFor(peer); TransferStat s = calculateStatFor(peer);
_cachedTransferStat += s; _cachedTransferStat += s;
@ -286,7 +294,10 @@ void DefaultPeerStorage::returnPeer(const PeerHandle& peer)
{ {
Peers::iterator itr = std::find(peers.begin(), peers.end(), peer); Peers::iterator itr = std::find(peers.begin(), peers.end(), peer);
if(itr == peers.end()) { 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 { } else {
peers.erase(itr); peers.erase(itr);

18
src/DefaultPieceStorage.cc
View File

@ -152,8 +152,10 @@ void DefaultPieceStorage::addUsedPiece(const PieceHandle& piece)
std::deque<SharedHandle<Piece> >::iterator i = std::deque<SharedHandle<Piece> >::iterator i =
std::lower_bound(usedPieces.begin(), usedPieces.end(), piece); std::lower_bound(usedPieces.begin(), usedPieces.end(), piece);
usedPieces.insert(i, piece); usedPieces.insert(i, piece);
logger->debug("usedPieces.size()=%lu", if(logger->debug()) {
static_cast<unsigned long>(usedPieces.size())); logger->debug("usedPieces.size()=%lu",
static_cast<unsigned long>(usedPieces.size()));
}
} }
PieceHandle DefaultPieceStorage::findUsedPiece(size_t index) const PieceHandle DefaultPieceStorage::findUsedPiece(size_t index) const
@ -471,7 +473,9 @@ bool DefaultPieceStorage::allDownloadFinished()
void DefaultPieceStorage::initStorage() void DefaultPieceStorage::initStorage()
{ {
if(downloadContext->getFileEntries().size() == 1) { if(downloadContext->getFileEntries().size() == 1) {
logger->debug("Instantiating DirectDiskAdaptor"); if(logger->debug()) {
logger->debug("Instantiating DirectDiskAdaptor");
}
DirectDiskAdaptorHandle directDiskAdaptor(new DirectDiskAdaptor()); DirectDiskAdaptorHandle directDiskAdaptor(new DirectDiskAdaptor());
directDiskAdaptor->setTotalLength(downloadContext->getTotalLength()); directDiskAdaptor->setTotalLength(downloadContext->getTotalLength());
directDiskAdaptor->setFileEntries(downloadContext->getFileEntries().begin(), directDiskAdaptor->setFileEntries(downloadContext->getFileEntries().begin(),
@ -486,7 +490,9 @@ void DefaultPieceStorage::initStorage()
directDiskAdaptor->setDiskWriter(writer); directDiskAdaptor->setDiskWriter(writer);
this->diskAdaptor = directDiskAdaptor; this->diskAdaptor = directDiskAdaptor;
} else { } else {
logger->debug("Instantiating MultiDiskAdaptor"); if(logger->debug()) {
logger->debug("Instantiating MultiDiskAdaptor");
}
MultiDiskAdaptorHandle multiDiskAdaptor(new MultiDiskAdaptor()); MultiDiskAdaptorHandle multiDiskAdaptor(new MultiDiskAdaptor());
multiDiskAdaptor->setFileEntries(downloadContext->getFileEntries().begin(), multiDiskAdaptor->setFileEntries(downloadContext->getFileEntries().begin(),
downloadContext->getFileEntries().end()); downloadContext->getFileEntries().end());
@ -574,7 +580,9 @@ void DefaultPieceStorage::removeAdvertisedPiece(time_t elapsed)
Haves::iterator itr = Haves::iterator itr =
std::find_if(haves.begin(), haves.end(), FindElapsedHave(elapsed)); std::find_if(haves.begin(), haves.end(), FindElapsedHave(elapsed));
if(itr != haves.end()) { 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()); haves.erase(itr, haves.end());
} }
} }

6
src/DownloadCommand.cc
View File

@ -211,8 +211,10 @@ bool DownloadCommand::executeInternal() {
_requestGroup->getDownloadContext()->getPieceHash(segment->getIndex()); _requestGroup->getDownloadContext()->getPieceHash(segment->getIndex());
if(_pieceHashValidationEnabled && !expectedPieceHash.empty()) { if(_pieceHashValidationEnabled && !expectedPieceHash.empty()) {
if(segment->isHashCalculated()) { if(segment->isHashCalculated()) {
logger->debug("Hash is available! index=%lu", if(logger->debug()) {
static_cast<unsigned long>(segment->getIndex())); logger->debug("Hash is available! index=%lu",
static_cast<unsigned long>(segment->getIndex()));
}
validatePieceHash(segment, expectedPieceHash, segment->getHashString()); validatePieceHash(segment, expectedPieceHash, segment->getHashString());
} else { } else {
_messageDigestContext->digestReset(); _messageDigestContext->digestReset();

12
src/DownloadEngine.cc
View File

@ -277,7 +277,9 @@ void DownloadEngine::poolSocket(const std::string& ipaddr,
if(_lastSocketPoolScan.elapsed(60)) { if(_lastSocketPoolScan.elapsed(60)) {
std::multimap<std::string, SocketPoolEntry> newPool; 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(); _lastSocketPoolScan.reset();
for(std::multimap<std::string, SocketPoolEntry>::iterator i = for(std::multimap<std::string, SocketPoolEntry>::iterator i =
_socketPool.begin(); i != _socketPool.end(); ++i) { _socketPool.begin(); i != _socketPool.end(); ++i) {
@ -285,9 +287,11 @@ void DownloadEngine::poolSocket(const std::string& ipaddr,
newPool.insert(*i); newPool.insert(*i);
} }
} }
logger->debug if(logger->debug()) {
("%lu entries removed.", logger->debug
static_cast<unsigned long>(_socketPool.size()-newPool.size())); ("%lu entries removed.",
static_cast<unsigned long>(_socketPool.size()-newPool.size()));
}
_socketPool = newPool; _socketPool = newPool;
} }
} }

19
src/EpollEventPoll.cc
View File

@ -405,7 +405,10 @@ bool EpollEventPoll::addEvents(sock_t socket,
&socketEntry->getEpEvent()); &socketEntry->getEpEvent());
} }
if(r == -1) { 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; return false;
} else { } else {
return true; return true;
@ -450,18 +453,24 @@ bool EpollEventPoll::deleteEvents(sock_t socket,
r = epoll_ctl(_epfd, EPOLL_CTL_MOD, (*i)->getSocket(), r = epoll_ctl(_epfd, EPOLL_CTL_MOD, (*i)->getSocket(),
&(*i)->getEpEvent()); &(*i)->getEpEvent());
if(r == -1) { if(r == -1) {
_logger->debug("Failed to delete socket event, but may be ignored:%s", if(_logger->debug()) {
strerror(errno)); _logger->debug("Failed to delete socket event, but may be ignored:%s",
strerror(errno));
}
} }
} }
if(r == -1) { 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; return false;
} else { } else {
return true; return true;
} }
} else { } 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; return false;
} }
} }

8
src/FileAllocationCommand.cc
View File

@ -61,9 +61,11 @@ bool FileAllocationCommand::executeInternal()
} }
_fileAllocationEntry->allocateChunk(); _fileAllocationEntry->allocateChunk();
if(_fileAllocationEntry->finished()) { if(_fileAllocationEntry->finished()) {
logger->debug(MSG_ALLOCATION_COMPLETED, if(logger->debug()) {
_timer.difference(), logger->debug(MSG_ALLOCATION_COMPLETED,
util::itos(_requestGroup->getTotalLength(), true).c_str()); _timer.difference(),
util::itos(_requestGroup->getTotalLength(), true).c_str());
}
_e->_fileAllocationMan->dropPickedEntry(); _e->_fileAllocationMan->dropPickedEntry();
std::deque<Command*> commands; std::deque<Command*> commands;

22
src/FileEntry.cc
View File

@ -242,8 +242,10 @@ void FileEntry::removeURIWhoseHostnameIs(const std::string& hostname)
newURIs.push_back(*itr); newURIs.push_back(*itr);
} }
} }
_logger->debug("Removed %d duplicate hostname URIs for path=%s", if(_logger->debug()) {
_uris.size()-newURIs.size(), getPath().c_str()); _logger->debug("Removed %d duplicate hostname URIs for path=%s",
_uris.size()-newURIs.size(), getPath().c_str());
}
_uris = newURIs; _uris = newURIs;
} }
@ -297,20 +299,24 @@ void FileEntry::reuseUri(size_t num)
errorUris.begin(), errorUris.end(), errorUris.begin(), errorUris.end(),
std::back_inserter(reusableURIs)); std::back_inserter(reusableURIs));
size_t ininum = reusableURIs.size(); size_t ininum = reusableURIs.size();
_logger->debug("Found %u reusable URIs", if(_logger->debug()) {
static_cast<unsigned int>(ininum)); _logger->debug("Found %u reusable URIs", static_cast<unsigned int>(ininum));
}
// Reuse at least num URIs here to avoid to // Reuse at least num URIs here to avoid to
// run this process repeatedly. // run this process repeatedly.
if(ininum > 0 && ininum < num) { if(ininum > 0 && ininum < num) {
_logger->debug("fewer than num=%u", if(_logger->debug()) {
num); _logger->debug("fewer than num=%u", num);
}
for(size_t i = 0; i < num/ininum; ++i) { for(size_t i = 0; i < num/ininum; ++i) {
_uris.insert(_uris.end(), reusableURIs.begin(), reusableURIs.end()); _uris.insert(_uris.end(), reusableURIs.begin(), reusableURIs.end());
} }
_uris.insert(_uris.end(), reusableURIs.begin(), _uris.insert(_uris.end(), reusableURIs.begin(),
reusableURIs.begin()+(num%ininum)); reusableURIs.begin()+(num%ininum));
_logger->debug("Duplication complete: now %u URIs for reuse", if(_logger->debug()) {
static_cast<unsigned int>(_uris.size())); _logger->debug("Duplication complete: now %u URIs for reuse",
static_cast<unsigned int>(_uris.size()));
}
} }
} }

14
src/FtpNegotiationCommand.cc
View File

@ -306,13 +306,19 @@ bool FtpNegotiationCommand::recvMdtm()
time_t t = lastModifiedTime.getTime(); time_t t = lastModifiedTime.getTime();
struct tm* tms = gmtime(&t); // returned struct is statically allocated. struct tm* tms = gmtime(&t); // returned struct is statically allocated.
if(tms) { 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 { } else {
logger->debug("gmtime() failed for MDTM result."); if(logger->debug()) {
logger->debug("gmtime() failed for MDTM result.");
}
} }
} else { } else {
logger->debug("MDTM response was returned, but it seems not to be a time" if(logger->debug()) {
" value as in specified in RFC3659."); logger->debug("MDTM response was returned, but it seems not to be a"
" time value as in specified in RFC3659.");
}
} }
} else { } else {
logger->info("CUID#%d - MDTM command failed.", cuid); logger->info("CUID#%d - MDTM command failed.", cuid);

7
src/HandshakeExtensionMessage.cc
View File

@ -163,8 +163,11 @@ HandshakeExtensionMessage::create(const unsigned char* data, size_t length)
EXTENSION_NAME.c_str(), length).str()); EXTENSION_NAME.c_str(), length).str());
} }
HandshakeExtensionMessageHandle msg(new HandshakeExtensionMessage()); HandshakeExtensionMessageHandle msg(new HandshakeExtensionMessage());
msg->_logger->debug("Creating HandshakeExtensionMessage from %s", if(LogFactory::getInstance()->debug()) {
util::urlencode(data, length).c_str()); LogFactory::getInstance()->debug
("Creating HandshakeExtensionMessage from %s",
util::urlencode(data, length).c_str());
}
const BDE dict = bencode::decode(data+1, length-1); const BDE dict = bencode::decode(data+1, length-1);
if(!dict.isDict()) { if(!dict.isDict()) {
throw DL_ABORT_EX("Unexpected payload format for extended message handshake"); throw DL_ABORT_EX("Unexpected payload format for extended message handshake");

4
src/HttpListenCommand.cc
View File

@ -79,7 +79,9 @@ bool HttpListenCommand::execute()
_e->commands.push_back(c); _e->commands.push_back(c);
} }
} catch(RecoverableException& e) { } 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); _e->commands.push_back(this);
return false; return false;

6
src/HttpServer.cc
View File

@ -165,9 +165,9 @@ void HttpServer::feedResponse(const std::string& status,
} }
header += "\r\n"; header += "\r\n";
if(_logger->debug()) {
_logger->debug("HTTP Server sends response:\n%s", header.c_str()); _logger->debug("HTTP Server sends response:\n%s", header.c_str());
}
_socketBuffer.feedSendBuffer(header); _socketBuffer.feedSendBuffer(header);
_socketBuffer.feedSendBuffer(text); _socketBuffer.feedSendBuffer(text);
} }

4
src/HttpSkipResponseCommand.cc
View File

@ -114,7 +114,9 @@ bool HttpSkipResponseCommand::executeInternal()
throw DL_RETRY_EX(EX_GOT_EOF); throw DL_RETRY_EX(EX_GOT_EOF);
} }
} catch(RecoverableException& e) { } catch(RecoverableException& e) {
logger->debug(EX_EXCEPTION_CAUGHT, e); if(logger->debug()) {
logger->debug(EX_EXCEPTION_CAUGHT, e);
}
return processResponse(); return processResponse();
} }

6
src/IteratableChunkChecksumValidator.cc
View File

@ -94,7 +94,11 @@ void IteratableChunkChecksumValidator::validateChunk()
_bitfield->unsetBit(_currentIndex); _bitfield->unsetBit(_currentIndex);
} }
} catch(RecoverableException& ex) { } 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); _bitfield->unsetBit(_currentIndex);
} }

7
src/Logger.h
View File

@ -187,6 +187,13 @@ public:
_stdoutField &= ~level; _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 } // namespace aria2

84
src/MSEHandshake.cc
View File

@ -104,10 +104,15 @@ MSEHandshake::HANDSHAKE_TYPE MSEHandshake::identifyHandshakeType()
} }
if(_rbuf[0] == BtHandshakeMessage::PSTR_LENGTH && if(_rbuf[0] == BtHandshakeMessage::PSTR_LENGTH &&
memcmp(BtHandshakeMessage::BT_PSTR, _rbuf+1, 19) == 0) { 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; return HANDSHAKE_LEGACY;
} else { } 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; return HANDSHAKE_ENCRYPTED;
} }
} }
@ -118,15 +123,18 @@ void MSEHandshake::initEncryptionFacility(bool initiator)
_dh = new DHKeyExchange(); _dh = new DHKeyExchange();
_dh->init(PRIME, PRIME_BITS, GENERATOR, 160); _dh->init(PRIME, PRIME_BITS, GENERATOR, 160);
_dh->generatePublicKey(); _dh->generatePublicKey();
_logger->debug("CUID#%d - DH initialized.", _cuid); if(_logger->debug()) {
_logger->debug("CUID#%d - DH initialized.", _cuid);
}
_initiator = initiator; _initiator = initiator;
} }
bool MSEHandshake::sendPublicKey() bool MSEHandshake::sendPublicKey()
{ {
if(_socketBuffer.sendBufferIsEmpty()) { 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]; unsigned char buffer[KEY_LENGTH+MAX_PAD_LENGTH];
_dh->getPublicKey(buffer, KEY_LENGTH); _dh->getPublicKey(buffer, KEY_LENGTH);
@ -145,7 +153,9 @@ bool MSEHandshake::receivePublicKey()
if(r > receiveNBytes(r)) { if(r > receiveNBytes(r)) {
return false; 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; // TODO handle exception. in catch, resbufLength = 0;
_dh->computeSecret(_secret, sizeof(_secret), _rbuf, _rbufLength); _dh->computeSecret(_secret, sizeof(_secret), _rbuf, _rbufLength);
// reset _rbufLength // reset _rbufLength
@ -249,7 +259,9 @@ uint16_t MSEHandshake::decodeLength16(const unsigned char* buffer)
bool MSEHandshake::sendInitiatorStep2() bool MSEHandshake::sendInitiatorStep2()
{ {
if(_socketBuffer.sendBufferIsEmpty()) { 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]; unsigned char md[20];
createReq1Hash(md); createReq1Hash(md);
_socketBuffer.feedSendBuffer(std::string(&md[0], &md[sizeof(md)])); _socketBuffer.feedSendBuffer(std::string(&md[0], &md[sizeof(md)]));
@ -335,8 +347,9 @@ bool MSEHandshake::findInitiatorVCMarker()
size_t toRead = _markerIndex+VC_LENGTH-_rbufLength; size_t toRead = _markerIndex+VC_LENGTH-_rbufLength;
_socket->readData(_rbuf+_rbufLength, toRead); _socket->readData(_rbuf+_rbufLength, toRead);
_rbufLength += toRead; _rbufLength += toRead;
if(_logger->debug()) {
_logger->debug("CUID#%d - VC marker found at %u", _cuid, _markerIndex); _logger->debug("CUID#%d - VC marker found at %u", _cuid, _markerIndex);
}
verifyVC(_rbuf+_markerIndex); verifyVC(_rbuf+_markerIndex);
// reset _rbufLength // reset _rbufLength
_rbufLength = 0; _rbufLength = 0;
@ -357,11 +370,15 @@ bool MSEHandshake::receiveInitiatorCryptoSelectAndPadDLength()
rbufptr, sizeof(cryptoSelect)); rbufptr, sizeof(cryptoSelect));
if(cryptoSelect[3]&CRYPTO_PLAIN_TEXT && if(cryptoSelect[3]&CRYPTO_PLAIN_TEXT &&
_option->get(PREF_BT_MIN_CRYPTO_LEVEL) == V_PLAIN) { _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; _negotiatedCryptoType = CRYPTO_PLAIN_TEXT;
} }
if(cryptoSelect[3]&CRYPTO_ARC4) { 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; _negotiatedCryptoType = CRYPTO_ARC4;
} }
if(_negotiatedCryptoType == CRYPTO_NONE) { if(_negotiatedCryptoType == CRYPTO_NONE) {
@ -427,8 +444,9 @@ bool MSEHandshake::findReceiverHashMarker()
size_t toRead = _markerIndex+20-_rbufLength; size_t toRead = _markerIndex+20-_rbufLength;
_socket->readData(_rbuf+_rbufLength, toRead); _socket->readData(_rbuf+_rbufLength, toRead);
_rbufLength += toRead; _rbufLength += toRead;
if(_logger->debug()) {
_logger->debug("CUID#%d - Hash marker found at %u.", _cuid, _markerIndex); _logger->debug("CUID#%d - Hash marker found at %u.", _cuid, _markerIndex);
}
verifyReq1Hash(_rbuf+_markerIndex); verifyReq1Hash(_rbuf+_markerIndex);
// reset _rbufLength // reset _rbufLength
_rbufLength = 0; _rbufLength = 0;
@ -452,8 +470,11 @@ bool MSEHandshake::receiveReceiverHashAndPadCLength
const BDE& torrentAttrs = (*i)->getAttribute(bittorrent::BITTORRENT); const BDE& torrentAttrs = (*i)->getAttribute(bittorrent::BITTORRENT);
createReq23Hash(md, torrentAttrs[bittorrent::INFO_HASH].uc()); createReq23Hash(md, torrentAttrs[bittorrent::INFO_HASH].uc());
if(memcmp(md, rbufptr, sizeof(md)) == 0) { if(memcmp(md, rbufptr, sizeof(md)) == 0) {
_logger->debug("CUID#%d - info hash found: %s", _cuid, if(_logger->debug()) {
util::toHex(torrentAttrs[bittorrent::INFO_HASH].s()).c_str()); _logger->debug("CUID#%d - info hash found: %s", _cuid,
util::toHex
(torrentAttrs[bittorrent::INFO_HASH].s()).c_str());
}
downloadContext = *i; downloadContext = *i;
break; break;
} }
@ -475,10 +496,14 @@ bool MSEHandshake::receiveReceiverHashAndPadCLength
// For now, choose ARC4. // For now, choose ARC4.
if(cryptoProvide[3]&CRYPTO_PLAIN_TEXT && if(cryptoProvide[3]&CRYPTO_PLAIN_TEXT &&
_option->get(PREF_BT_MIN_CRYPTO_LEVEL) == V_PLAIN) { _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; _negotiatedCryptoType = CRYPTO_PLAIN_TEXT;
} else if(cryptoProvide[3]&CRYPTO_ARC4) { } 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; _negotiatedCryptoType = CRYPTO_ARC4;
} }
if(_negotiatedCryptoType == CRYPTO_NONE) { if(_negotiatedCryptoType == CRYPTO_NONE) {
@ -502,7 +527,9 @@ bool MSEHandshake::receiveReceiverIALength()
return false; return false;
} }
_iaLength = decodeLength16(_rbuf); _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 // reset _rbufLength
_rbufLength = 0; _rbufLength = 0;
return true; return true;
@ -520,7 +547,9 @@ bool MSEHandshake::receiveReceiverIA()
delete [] _ia; delete [] _ia;
_ia = new unsigned char[_iaLength]; _ia = new unsigned char[_iaLength];
_decryptor->decrypt(_ia, _iaLength, _rbuf, _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 // reset _rbufLength
_rbufLength = 0; _rbufLength = 0;
return true; return true;
@ -559,10 +588,13 @@ bool MSEHandshake::sendReceiverStep2()
uint16_t MSEHandshake::verifyPadLength(const unsigned char* padlenbuf, const char* padName) 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); 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) { if(padLength > 512) {
throw DL_ABORT_EX throw DL_ABORT_EX
(StringFormat("Too large %s length: %u", padName, padLength).str()); (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) 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]; unsigned char vc[VC_LENGTH];
_decryptor->decrypt(vc, sizeof(vc), vcbuf, sizeof(vc)); _decryptor->decrypt(vc, sizeof(vc), vcbuf, sizeof(vc));
if(memcmp(VC, vc, sizeof(VC)) != 0) { 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) 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]; unsigned char md[20];
createReq1Hash(md); createReq1Hash(md);
if(memcmp(md, req1buf, sizeof(md)) != 0) { if(memcmp(md, req1buf, sizeof(md)) != 0) {

6
src/MetalinkPostDownloadHandler.cc
View File

@ -64,8 +64,10 @@ void MetalinkPostDownloadHandler::getNextRequestGroups
(std::deque<SharedHandle<RequestGroup> >& groups, (std::deque<SharedHandle<RequestGroup> >& groups,
RequestGroup* requestGroup) RequestGroup* requestGroup)
{ {
_logger->debug("Generating RequestGroups for Metalink file %s", if(_logger->debug()) {
requestGroup->getFirstFilePath().c_str()); _logger->debug("Generating RequestGroups for Metalink file %s",
requestGroup->getFirstFilePath().c_str());
}
SharedHandle<DiskAdaptor> diskAdaptor = SharedHandle<DiskAdaptor> diskAdaptor =
requestGroup->getPieceStorage()->getDiskAdaptor(); requestGroup->getPieceStorage()->getDiskAdaptor();
try { try {

32
src/MultiDiskAdaptor.cc
View File

@ -208,25 +208,29 @@ void MultiDiskAdaptor::resetDiskWriterEntries()
if(fileEntry->getLength() > 0) { if(fileEntry->getLength() > 0) {
off_t lastPieceStartOffset = off_t lastPieceStartOffset =
(fileEntry->getOffset()+fileEntry->getLength()-1)/pieceLength*pieceLength; (fileEntry->getOffset()+fileEntry->getLength()-1)/pieceLength*pieceLength;
logger->debug("Checking adjacent backward file to %s" if(logger->debug()) {
" whose lastPieceStartOffset+pieceLength=%lld", logger->debug("Checking adjacent backward file to %s"
fileEntry->getPath().c_str(), " whose lastPieceStartOffset+pieceLength=%lld",
lastPieceStartOffset+pieceLength); fileEntry->getPath().c_str(),
lastPieceStartOffset+pieceLength);
}
++itr; ++itr;
// adjacent backward files are not needed to be allocated. They // adjacent backward files are not needed to be allocated. They
// just requre DiskWriter // just requre DiskWriter
for(; itr != diskWriterEntries.end() && for(; itr != diskWriterEntries.end() &&
(!(*itr)->getFileEntry()->isRequested() || (!(*itr)->getFileEntry()->isRequested() ||
(*itr)->getFileEntry()->getLength() == 0); ++itr) { (*itr)->getFileEntry()->getLength() == 0); ++itr) {
logger->debug("file=%s, offset=%lld", if(logger->debug()) {
(*itr)->getFileEntry()->getPath().c_str(), logger->debug("file=%s, offset=%lld",
(*itr)->getFileEntry()->getOffset()); (*itr)->getFileEntry()->getPath().c_str(),
(*itr)->getFileEntry()->getOffset());
}
if((*itr)->getFileEntry()->getOffset() < if((*itr)->getFileEntry()->getOffset() <
static_cast<off_t>(lastPieceStartOffset+pieceLength)) { static_cast<off_t>(lastPieceStartOffset+pieceLength)) {
logger->debug("%s needs diskwriter", if(logger->debug()) {
(*itr)->getFileEntry()->getPath().c_str()); logger->debug("%s needs diskwriter",
(*itr)->getFileEntry()->getPath().c_str());
}
dwreq[(*itr)->getFileEntry()->getPath()] = true; dwreq[(*itr)->getFileEntry()->getPath()] = true;
} else { } else {
break; break;
@ -245,8 +249,10 @@ void MultiDiskAdaptor::resetDiskWriterEntries()
if((*i)->needsFileAllocation() || if((*i)->needsFileAllocation() ||
dwreq.find((*i)->getFileEntry()->getPath()) != dwreq.end() || dwreq.find((*i)->getFileEntry()->getPath()) != dwreq.end() ||
(*i)->fileExists()) { (*i)->fileExists()) {
logger->debug("Creating DiskWriter for filename=%s", if(logger->debug()) {
(*i)->getFilePath().c_str()); logger->debug("Creating DiskWriter for filename=%s",
(*i)->getFilePath().c_str());
}
(*i)->setDiskWriter(dwFactory.newDiskWriter((*i)->getFilePath())); (*i)->setDiskWriter(dwFactory.newDiskWriter((*i)->getFilePath()));
if(_directIOAllowed) { if(_directIOAllowed) {
(*i)->getDiskWriter()->allowDirectIO(); (*i)->getDiskWriter()->allowDirectIO();

17
src/PeerAbstractCommand.cc
View File

@ -73,9 +73,12 @@ PeerAbstractCommand::~PeerAbstractCommand()
bool PeerAbstractCommand::execute() bool PeerAbstractCommand::execute()
{ {
logger->debug("CUID#%d -" if(logger->debug()) {
" socket: read:%d, write:%d, hup:%d, err:%d, noCheck:%d", logger->debug("CUID#%d -"
cuid, _readEvent, _writeEvent, _hupEvent, _errorEvent, noCheck); " socket: read:%d, write:%d, hup:%d, err:%d, noCheck:%d",
cuid, _readEvent, _writeEvent, _hupEvent, _errorEvent,
noCheck);
}
if(exitBeforeExecute()) { if(exitBeforeExecute()) {
onAbort(); onAbort();
return true; return true;
@ -101,9 +104,11 @@ bool PeerAbstractCommand::execute()
onFailure(); onFailure();
return true; return true;
} catch(RecoverableException& err) { } catch(RecoverableException& err) {
logger->debug(MSG_TORRENT_DOWNLOAD_ABORTED, err, cuid); if(logger->debug()) {
logger->debug(MSG_PEER_BANNED, logger->debug(MSG_TORRENT_DOWNLOAD_ABORTED, err, cuid);
cuid, peer->ipaddr.c_str(), peer->port); logger->debug(MSG_PEER_BANNED,
cuid, peer->ipaddr.c_str(), peer->port);
}
onAbort(); onAbort();
return prepareForNextPeer(0); return prepareForNextPeer(0);
} }

35
src/PeerConnection.cc
View File

@ -70,7 +70,9 @@ ssize_t PeerConnection::sendMessage(const unsigned char* data,
size_t dataLength) size_t dataLength)
{ {
ssize_t writtenLength = sendData(data, dataLength, _encryptionEnabled); 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; return writtenLength;
} }
@ -88,8 +90,11 @@ bool PeerConnection::receiveMessage(unsigned char* data, size_t& dataLength) {
return false; return false;
} }
// we got EOF // we got EOF
logger->debug("CUID#%d - In PeerConnection::receiveMessage(), remain=%lu", if(logger->debug()) {
cuid, static_cast<unsigned long>(temp)); logger->debug("CUID#%d - In PeerConnection::receiveMessage(),"
" remain=%lu",
cuid, static_cast<unsigned long>(temp));
}
throw DL_ABORT_EX(EX_EOF_FROM_PEER); throw DL_ABORT_EX(EX_EOF_FROM_PEER);
} }
lenbufLength += remaining; lenbufLength += remaining;
@ -118,11 +123,13 @@ bool PeerConnection::receiveMessage(unsigned char* data, size_t& dataLength) {
return false; return false;
} }
// we got EOF // we got EOF
logger->debug("CUID#%d - In PeerConnection::receiveMessage()," if(logger->debug()) {
" payloadlen=%lu, remaining=%lu", logger->debug("CUID#%d - In PeerConnection::receiveMessage(),"
cuid, " payloadlen=%lu, remaining=%lu",
static_cast<unsigned long>(currentPayloadLength), cuid,
static_cast<unsigned long>(temp)); static_cast<unsigned long>(currentPayloadLength),
static_cast<unsigned long>(temp));
}
throw DL_ABORT_EX(EX_EOF_FROM_PEER); throw DL_ABORT_EX(EX_EOF_FROM_PEER);
} }
resbufLength += remaining; resbufLength += remaining;
@ -167,9 +174,11 @@ bool PeerConnection::receiveHandshake(unsigned char* data, size_t& dataLength,
return false; return false;
} }
// we got EOF // we got EOF
logger->debug if(logger->debug()) {
("CUID#%d - In PeerConnection::receiveHandshake(), remain=%lu", logger->debug
cuid, static_cast<unsigned long>(temp)); ("CUID#%d - In PeerConnection::receiveHandshake(), remain=%lu",
cuid, static_cast<unsigned long>(temp));
}
throw DL_ABORT_EX(EX_EOF_FROM_PEER); throw DL_ABORT_EX(EX_EOF_FROM_PEER);
} }
resbufLength += remaining; resbufLength += remaining;
@ -243,7 +252,9 @@ bool PeerConnection::sendBufferIsEmpty() const
ssize_t PeerConnection::sendPendingData() ssize_t PeerConnection::sendPendingData()
{ {
ssize_t writtenLength = _socketBuffer.send(); ssize_t writtenLength = _socketBuffer.send();
logger->debug("sent %d byte(s).", writtenLength); if(logger->debug()) {
logger->debug("sent %d byte(s).", writtenLength);
}
return writtenLength; return writtenLength;
} }

11
src/PeerListenCommand.cc
View File

@ -125,10 +125,13 @@ bool PeerListenCommand::execute() {
Command* command = Command* command =
new ReceiverMSEHandshakeCommand(cuid, peer, e, peerSocket); new ReceiverMSEHandshakeCommand(cuid, peer, e, peerSocket);
e->commands.push_back(command); e->commands.push_back(command);
logger->debug("Accepted the connection from %s:%u.", if(logger->debug()) {
peer->ipaddr.c_str(), logger->debug("Accepted the connection from %s:%u.",
peer->port); peer->ipaddr.c_str(),
logger->debug("Added CUID#%d to receive BitTorrent/MSE handshake.", cuid); peer->port);
logger->debug("Added CUID#%d to receive BitTorrent/MSE handshake.",
cuid);
}
} catch(RecoverableException& ex) { } catch(RecoverableException& ex) {
logger->debug(MSG_ACCEPT_FAILURE, ex, cuid); logger->debug(MSG_ACCEPT_FAILURE, ex, cuid);
} }

4
src/PeerReceiveHandshakeCommand.cc
View File

@ -142,7 +142,9 @@ bool PeerReceiveHandshakeCommand::executeInternal()
PeerInteractionCommand::RECEIVER_WAIT_HANDSHAKE, PeerInteractionCommand::RECEIVER_WAIT_HANDSHAKE,
_peerConnection); _peerConnection);
e->commands.push_back(command); 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; return true;

34
src/RequestGroup.cc
View File

@ -304,10 +304,12 @@ void RequestGroup::createInitialCommand
} else { } else {
// Open file in writable mode to allow the program // Open file in writable mode to allow the program
// truncate the file to _downloadContext->getTotalLength() // truncate the file to _downloadContext->getTotalLength()
_logger->debug("File size not match. File is opened in writable mode." if(_logger->debug()) {
" Expected:%s Actual:%s", _logger->debug("File size not match. File is opened in writable"
util::uitos(_downloadContext->getTotalLength()).c_str(), " mode. Expected:%s Actual:%s",
util::uitos(actualFileSize).c_str()); util::uitos(_downloadContext->getTotalLength()).c_str(),
util::uitos(actualFileSize).c_str());
}
} }
} }
// Call Load, Save and file allocation command here // Call Load, Save and file allocation command here
@ -450,7 +452,9 @@ void RequestGroup::initPieceStorage()
// Use LongestSequencePieceSelector when HTTP/FTP/BitTorrent // Use LongestSequencePieceSelector when HTTP/FTP/BitTorrent
// integrated downloads. Currently multi-file integrated // integrated downloads. Currently multi-file integrated
// download is not supported. // download is not supported.
_logger->debug("Using LongestSequencePieceSelector"); if(_logger->debug()) {
_logger->debug("Using LongestSequencePieceSelector");
}
ps->setPieceSelector ps->setPieceSelector
(SharedHandle<PieceSelector>(new LongestSequencePieceSelector())); (SharedHandle<PieceSelector>(new LongestSequencePieceSelector()));
} }
@ -807,8 +811,10 @@ void RequestGroup::releaseRuntimeResource(DownloadEngine* e)
void RequestGroup::preDownloadProcessing() void RequestGroup::preDownloadProcessing()
{ {
_logger->debug("Finding PreDownloadHandler for path %s.", if(_logger->debug()) {
getFirstFilePath().c_str()); _logger->debug("Finding PreDownloadHandler for path %s.",
getFirstFilePath().c_str());
}
try { try {
for(PreDownloadHandlers::const_iterator itr = _preDownloadHandlers.begin(); for(PreDownloadHandlers::const_iterator itr = _preDownloadHandlers.begin();
itr != _preDownloadHandlers.end(); ++itr) { itr != _preDownloadHandlers.end(); ++itr) {
@ -821,15 +827,19 @@ void RequestGroup::preDownloadProcessing()
_logger->error(EX_EXCEPTION_CAUGHT, ex); _logger->error(EX_EXCEPTION_CAUGHT, ex);
return; return;
} }
_logger->debug("No PreDownloadHandler found."); if(_logger->debug()) {
_logger->debug("No PreDownloadHandler found.");
}
return; return;
} }
void RequestGroup::postDownloadProcessing void RequestGroup::postDownloadProcessing
(std::deque<SharedHandle<RequestGroup> >& groups) (std::deque<SharedHandle<RequestGroup> >& groups)
{ {
_logger->debug("Finding PostDownloadHandler for path %s.", if(_logger->debug()) {
getFirstFilePath().c_str()); _logger->debug("Finding PostDownloadHandler for path %s.",
getFirstFilePath().c_str());
}
try { try {
for(PostDownloadHandlers::const_iterator itr = _postDownloadHandlers.begin(); for(PostDownloadHandlers::const_iterator itr = _postDownloadHandlers.begin();
itr != _postDownloadHandlers.end(); ++itr) { itr != _postDownloadHandlers.end(); ++itr) {
@ -841,7 +851,9 @@ void RequestGroup::postDownloadProcessing
} catch(RecoverableException& ex) { } catch(RecoverableException& ex) {
_logger->error(EX_EXCEPTION_CAUGHT, ex); _logger->error(EX_EXCEPTION_CAUGHT, ex);
} }
_logger->debug("No PostDownloadHandler found."); if(_logger->debug()) {
_logger->debug("No PostDownloadHandler found.");
}
} }
void RequestGroup::initializePreDownloadHandler() void RequestGroup::initializePreDownloadHandler()

26
src/RequestGroupMan.cc
View File

@ -345,9 +345,11 @@ public:
RequestGroups nextGroups; RequestGroups nextGroups;
group->postDownloadProcessing(nextGroups); group->postDownloadProcessing(nextGroups);
if(!nextGroups.empty()) { if(!nextGroups.empty()) {
_logger->debug if(_logger->debug()) {
("Adding %lu RequestGroups as a result of PostDownloadHandler.", _logger->debug
static_cast<unsigned long>(nextGroups.size())); ("Adding %lu RequestGroups as a result of PostDownloadHandler.",
static_cast<unsigned long>(nextGroups.size()));
}
_reservedGroups.insert(_reservedGroups.begin(), _reservedGroups.insert(_reservedGroups.begin(),
nextGroups.begin(), nextGroups.end()); nextGroups.begin(), nextGroups.end());
} }
@ -440,8 +442,10 @@ void RequestGroupMan::removeStoppedGroup(DownloadEngine* e)
size_t numRemoved = numPrev-_requestGroups.size(); size_t numRemoved = numPrev-_requestGroups.size();
if(numRemoved > 0) { if(numRemoved > 0) {
_logger->debug("%lu RequestGroup(s) deleted.", if(_logger->debug()) {
static_cast<unsigned long>(numRemoved)); _logger->debug("%lu RequestGroup(s) deleted.",
static_cast<unsigned long>(numRemoved));
}
} }
} }
@ -496,10 +500,14 @@ void RequestGroupMan::fillRequestGroupFromReserver(DownloadEngine* e)
executeStartHook(groupToAdd, e->option); executeStartHook(groupToAdd, e->option);
} catch(RecoverableException& ex) { } catch(RecoverableException& ex) {
_logger->error(EX_EXCEPTION_CAUGHT, 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()); std::for_each(commands.begin(), commands.end(), Deleter());
commands.clear(); commands.clear();
_logger->debug("Commands deleted"); if(_logger->debug()) {
_logger->debug("Commands deleted");
}
groupToAdd->releaseRuntimeResource(e); groupToAdd->releaseRuntimeResource(e);
_downloadResults.push_back(groupToAdd->createDownloadResult()); _downloadResults.push_back(groupToAdd->createDownloadResult());
} }
@ -509,7 +517,9 @@ void RequestGroupMan::fillRequestGroupFromReserver(DownloadEngine* e)
} }
if(count > 0) { if(count > 0) {
e->setNoWait(true); e->setNoWait(true);
_logger->debug("%d RequestGroup(s) added.", count); if(_logger->debug()) {
_logger->debug("%d RequestGroup(s) added.", count);
}
} }
} }

30
src/SegmentMan.cc
View File

@ -116,8 +116,9 @@ SegmentHandle SegmentMan::checkoutSegment(cuid_t cuid,
if(piece.isNull()) { if(piece.isNull()) {
return SharedHandle<Segment>(); 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; SegmentHandle segment;
if(piece->getLength() == 0) { if(piece->getLength() == 0) {
segment.reset(new GrowSegment(piece)); segment.reset(new GrowSegment(piece));
@ -126,19 +127,22 @@ SegmentHandle SegmentMan::checkoutSegment(cuid_t cuid,
} }
SegmentEntryHandle entry(new SegmentEntry(cuid, segment)); SegmentEntryHandle entry(new SegmentEntry(cuid, segment));
usedSegmentEntries.push_back(entry); usedSegmentEntries.push_back(entry);
if(logger->debug()) {
logger->debug("index=%d, length=%d, segmentLength=%d, writtenLength=%d", logger->debug("index=%d, length=%d, segmentLength=%d, writtenLength=%d",
segment->getIndex(), segment->getIndex(),
segment->getLength(), segment->getLength(),
segment->getSegmentLength(), segment->getSegmentLength(),
segment->getWrittenLength()); segment->getWrittenLength());
}
if(piece->getLength() > 0) { if(piece->getLength() > 0) {
std::map<size_t, size_t>::iterator positr = std::map<size_t, size_t>::iterator positr =
_segmentWrittenLengthMemo.find(segment->getIndex()); _segmentWrittenLengthMemo.find(segment->getIndex());
if(positr != _segmentWrittenLengthMemo.end()) { if(positr != _segmentWrittenLengthMemo.end()) {
const size_t writtenLength = (*positr).second; const size_t writtenLength = (*positr).second;
logger->debug("writtenLength(in memo)=%d, writtenLength=%d", if(logger->debug()) {
writtenLength, segment->getWrittenLength()); logger->debug("writtenLength(in memo)=%d, writtenLength=%d",
writtenLength, segment->getWrittenLength());
}
// If the difference between cached writtenLength and segment's // If the difference between cached writtenLength and segment's
// writtenLength is less than one block, we assume that these // writtenLength is less than one block, we assume that these
// missing bytes are already downloaded. // missing bytes are already downloaded.
@ -211,8 +215,10 @@ void SegmentMan::cancelSegment(const SharedHandle<Segment>& segment)
{ {
_pieceStorage->cancelPiece(segment->getPiece()); _pieceStorage->cancelPiece(segment->getPiece());
_segmentWrittenLengthMemo[segment->getIndex()] = segment->getWrittenLength(); _segmentWrittenLengthMemo[segment->getIndex()] = segment->getWrittenLength();
logger->debug("Memorized segment index=%u, writtenLength=%u", if(logger->debug()) {
segment->getIndex(), segment->getWrittenLength()); logger->debug("Memorized segment index=%u, writtenLength=%u",
segment->getIndex(), segment->getWrittenLength());
}
} }
void SegmentMan::cancelSegment(cuid_t cuid) { void SegmentMan::cancelSegment(cuid_t cuid) {

13
src/SelectEventPoll.cc
View File

@ -263,7 +263,10 @@ bool SelectEventPoll::addEvents(sock_t socket, Command* command,
} }
updateFdSet(); updateFdSet();
if(r == -1) { 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; return false;
} else { } else {
return true; return true;
@ -284,13 +287,17 @@ bool SelectEventPoll::deleteEvents(sock_t socket, Command* command,
} }
updateFdSet(); updateFdSet();
if(r == -1) { 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; return false;
} else { } else {
return true; return true;
} }
} else { } 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; return false;
} }
} }

42
src/ServerStat.cc
View File

@ -101,16 +101,20 @@ void ServerStat::updateSingleConnectionAvgSpeed(unsigned int downloadSpeed)
((1.0/5.0)*(float)downloadSpeed); ((1.0/5.0)*(float)downloadSpeed);
} }
if(avgDownloadSpeed < (int)(0.80*_singleConnectionAvgSpeed)) { if(avgDownloadSpeed < (int)(0.80*_singleConnectionAvgSpeed)) {
_logger->debug("ServerStat:%s: resetting counter since single connection" if(_logger->debug()) {
" speed dropped", getHostname().c_str()); _logger->debug("ServerStat:%s: resetting counter since single connection"
" speed dropped", getHostname().c_str());
}
_counter = 0; _counter = 0;
} }
_logger->debug("ServerStat:%s: _singleConnectionAvgSpeed old:%.2fKB/s" if(_logger->debug()) {
" new:%.2fKB/s last:%.2fKB/s", _logger->debug("ServerStat:%s: _singleConnectionAvgSpeed old:%.2fKB/s"
getHostname().c_str(), " new:%.2fKB/s last:%.2fKB/s",
(float) _singleConnectionAvgSpeed/1024, getHostname().c_str(),
(float) avgDownloadSpeed/1024, (float) _singleConnectionAvgSpeed/1024,
(float) downloadSpeed / 1024); (float) avgDownloadSpeed/1024,
(float) downloadSpeed / 1024);
}
_singleConnectionAvgSpeed = (int)avgDownloadSpeed; _singleConnectionAvgSpeed = (int)avgDownloadSpeed;
} }
@ -134,12 +138,14 @@ void ServerStat::updateMultiConnectionAvgSpeed(unsigned int downloadSpeed)
avgDownloadSpeed = ((4.0/5.0)*(float)_multiConnectionAvgSpeed) + avgDownloadSpeed = ((4.0/5.0)*(float)_multiConnectionAvgSpeed) +
((1.0/5.0)*(float)downloadSpeed); ((1.0/5.0)*(float)downloadSpeed);
} }
_logger->debug("ServerStat:%s: _multiConnectionAvgSpeed old:%.2fKB/s" if(_logger->debug()) {
" new:%.2fKB/s last:%.2fKB/s", _logger->debug("ServerStat:%s: _multiConnectionAvgSpeed old:%.2fKB/s"
getHostname().c_str(), " new:%.2fKB/s last:%.2fKB/s",
(float) _multiConnectionAvgSpeed/1024, getHostname().c_str(),
(float) avgDownloadSpeed/1024, (float) _multiConnectionAvgSpeed/1024,
(float) downloadSpeed / 1024); (float) avgDownloadSpeed/1024,
(float) downloadSpeed / 1024);
}
_multiConnectionAvgSpeed = (int)avgDownloadSpeed; _multiConnectionAvgSpeed = (int)avgDownloadSpeed;
} }
@ -172,9 +178,11 @@ void ServerStat::setStatus(const std::string& status)
void ServerStat::setStatusInternal(STATUS status) void ServerStat::setStatusInternal(STATUS status)
{ {
_logger->debug("ServerStat: set status %s for %s (%s)", if(_logger->debug()) {
STATUS_STRING[status].c_str(), _logger->debug("ServerStat: set status %s for %s (%s)",
_hostname.c_str(), _protocol.c_str()); STATUS_STRING[status].c_str(),
_hostname.c_str(), _protocol.c_str());
}
_status = status; _status = status;
_lastUpdated.reset(); _lastUpdated.reset();
} }

6
src/SimpleBtMessage.cc
View File

@ -57,8 +57,10 @@ void SimpleBtMessage::send() {
size_t msgLength = getMessageLength(); size_t msgLength = getMessageLength();
logger->info(MSG_SEND_PEER_MESSAGE, logger->info(MSG_SEND_PEER_MESSAGE,
cuid, peer->ipaddr.c_str(), peer->port, toString().c_str()); cuid, peer->ipaddr.c_str(), peer->port, toString().c_str());
logger->debug("msglength = %lu bytes", if(logger->debug()) {
static_cast<unsigned long>(msgLength)); logger->debug("msglength = %lu bytes",
static_cast<unsigned long>(msgLength));
}
peerConnection->sendMessage(msg, msgLength); peerConnection->sendMessage(msg, msgLength);
} else { } else {
peerConnection->sendPendingData(); peerConnection->sendPendingData();

16
src/SocketCore.cc
View File

@ -180,7 +180,9 @@ static sock_t bindInternal(int family, int socktype, int protocol,
return -1; return -1;
} }
if(::bind(fd, addr, addrlen) == -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); CLOSE(fd);
return -1; 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) { const_iterator i = _bindAddrs.begin(); i != _bindAddrs.end(); ++i) {
if(::bind(fd,reinterpret_cast<const struct sockaddr*>(&(*i).first), if(::bind(fd,reinterpret_cast<const struct sockaddr*>(&(*i).first),
(*i).second) == -1) { (*i).second) == -1) {
LogFactory::getInstance()->debug(EX_SOCKET_BIND, strerror(errno)); if(LogFactory::getInstance()->debug()) {
LogFactory::getInstance()->debug(EX_SOCKET_BIND, strerror(errno));
}
} else { } else {
bindSuccess = true; bindSuccess = true;
break; break;
@ -1142,7 +1146,9 @@ void SocketCore::useSelect()
void SocketCore::bindAddress(const std::string& iface) void SocketCore::bindAddress(const std::string& iface)
{ {
std::vector<std::pair<struct sockaddr_storage, socklen_t> > bindAddrs; 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 #ifdef HAVE_GETIFADDRS
// First find interface in interface addresses // First find interface in interface addresses
struct ifaddrs* ifaddr = 0; struct ifaddrs* ifaddr = 0;
@ -1229,7 +1235,9 @@ void SocketCore::bindAddress(const std::string& iface)
host, NI_MAXHOST, 0, NI_MAXSERV, host, NI_MAXHOST, 0, NI_MAXSERV,
NI_NUMERICHOST); NI_NUMERICHOST);
if(s == 0) { 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);
}
} }
} }
} }

21
src/TrackerWatcherCommand.cc
View File

@ -91,7 +91,9 @@ bool TrackerWatcherCommand::execute() {
} }
} }
if(_btAnnounce->noMoreAnnounce()) { if(_btAnnounce->noMoreAnnounce()) {
logger->debug("no more announce"); if(logger->debug()) {
logger->debug("no more announce");
}
return true; return true;
} }
if(_trackerRequestGroup.isNull()) { if(_trackerRequestGroup.isNull()) {
@ -106,7 +108,9 @@ bool TrackerWatcherCommand::execute() {
commands.clear(); commands.clear();
} }
e->addCommand(commands); e->addCommand(commands);
logger->debug("added tracker request command"); if(logger->debug()) {
logger->debug("added tracker request command");
}
} }
} else if(_trackerRequestGroup->downloadFinished()){ } else if(_trackerRequestGroup->downloadFinished()){
try { try {
@ -171,7 +175,10 @@ void TrackerWatcherCommand::processTrackerResponse
command->setPeerStorage(_peerStorage); command->setPeerStorage(_peerStorage);
command->setPieceStorage(_pieceStorage); command->setPieceStorage(_pieceStorage);
e->commands.push_back(command); 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 // If backup tracker is available, only try 2 times for each tracker
// and if they all fails, then try next one. // and if they all fails, then try next one.
if(backupTrackerIsAvailable(_requestGroup->getDownloadContext())) { if(backupTrackerIsAvailable(_requestGroup->getDownloadContext())) {
logger->debug("This is multi-tracker announce."); if(logger->debug()) {
logger->debug("This is multi-tracker announce.");
}
} else { } 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"); rg->getOption()->put(PREF_MAX_TRIES, "2");
// TODO When dry-run mode becomes available in BitTorrent, set // TODO When dry-run mode becomes available in BitTorrent, set

12
src/UTMetadataDataExtensionMessage.cc
View File

@ -70,8 +70,10 @@ std::string UTMetadataDataExtensionMessage::toString() const
void UTMetadataDataExtensionMessage::doReceivedAction() void UTMetadataDataExtensionMessage::doReceivedAction()
{ {
if(_tracker->tracks(_index)) { if(_tracker->tracks(_index)) {
_logger->debug("ut_metadata index=%lu found in tracking list", if(_logger->debug()) {
static_cast<unsigned long>(_index)); _logger->debug("ut_metadata index=%lu found in tracking list",
static_cast<unsigned long>(_index));
}
_tracker->remove(_index); _tracker->remove(_index);
_pieceStorage->getDiskAdaptor()->writeData _pieceStorage->getDiskAdaptor()->writeData
(reinterpret_cast<const unsigned char*>(_data.c_str()), _data.size(), (reinterpret_cast<const unsigned char*>(_data.c_str()), _data.size(),
@ -95,8 +97,10 @@ void UTMetadataDataExtensionMessage::doReceivedAction()
} }
} }
} else { } else {
_logger->debug("ut_metadata index=%lu is not tracked", if(_logger->debug()) {
static_cast<unsigned long>(_index)); _logger->debug("ut_metadata index=%lu is not tracked",
static_cast<unsigned long>(_index));
}
} }
} }

10
src/UTMetadataRequestFactory.cc
View File

@ -55,12 +55,16 @@ void UTMetadataRequestFactory::create
for(size_t index = 0; index < _dctx->getNumPieces() && num; ++index) { for(size_t index = 0; index < _dctx->getNumPieces() && num; ++index) {
SharedHandle<Piece> p = pieceStorage->getMissingPiece(index); SharedHandle<Piece> p = pieceStorage->getMissingPiece(index);
if(p.isNull()) { 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; continue;
} }
--num; --num;
_logger->debug("Creating ut_metadata request index=%lu", if(_logger->debug()) {
static_cast<unsigned long>(index)); _logger->debug("Creating ut_metadata request index=%lu",
static_cast<unsigned long>(index));
}
SharedHandle<UTMetadataRequestExtensionMessage> m SharedHandle<UTMetadataRequestExtensionMessage> m
(new UTMetadataRequestExtensionMessage (new UTMetadataRequestExtensionMessage
(_peer->getExtensionMessageID("ut_metadata"))); (_peer->getExtensionMessageID("ut_metadata")));

7
src/UTMetadataRequestTracker.cc
View File

@ -71,9 +71,10 @@ std::vector<size_t> UTMetadataRequestTracker::removeTimeoutEntry()
for(std::vector<RequestEntry>::iterator i = _trackedRequests.begin(); for(std::vector<RequestEntry>::iterator i = _trackedRequests.begin();
i != _trackedRequests.end();) { i != _trackedRequests.end();) {
if((*i).elapsed(TIMEOUT)) { if((*i).elapsed(TIMEOUT)) {
LogFactory::getInstance()->debug if(_logger->debug()) {
("ut_metadata request timeout. index=%lu", _logger->debug("ut_metadata request timeout. index=%lu",
static_cast<unsigned long>((*i)._index)); static_cast<unsigned long>((*i)._index));
}
indexes.push_back((*i)._index); indexes.push_back((*i)._index);
i = _trackedRequests.erase(i); i = _trackedRequests.erase(i);
} else { } else {

4
src/XmlRpcMethod.cc
View File

@ -70,7 +70,9 @@ XmlRpcResponse XmlRpcMethod::execute
try { try {
return XmlRpcResponse(0, process(req, e)); return XmlRpcResponse(0, process(req, e));
} catch(RecoverableException& e) { } catch(RecoverableException& e) {
_logger->debug(EX_EXCEPTION_CAUGHT, e); if(_logger->debug()) {
_logger->debug(EX_EXCEPTION_CAUGHT, e);
}
return XmlRpcResponse(1, createErrorResponse(e)); return XmlRpcResponse(1, createErrorResponse(e));
} }
} }