/**
* Only call this with nonzero status, i.e. for outbound messages whose MessageState may be queued
* on _sendingStates.
*
* <p>Even when using sendBestEffort(), this is a waste, because the MessageState is removed from
* _sendingStates immediately and so the lookup here fails. And iterating through the HashSet
* instead of having a map is bad too.
*
* <p>This is now pretty much avoided since streaming now sets i2cp.messageReliability = none,
* which forces sendNoEffort() instead of sendBestEffort(), so the router won't send us any MSM's
* for outbound traffic.
*
* @param status != 0
*/
@Override
public void receiveStatus(int msgId, long nonce, int status) {
if (_log.shouldLog(Log.DEBUG))
_log.debug(getPrefix() + "Received status " + status + " for msgId " + msgId + " / " + nonce);
MessageState state = null;
long beforeSync = _context.clock().now();
long inSync = 0;
synchronized (_sendingStates) {
inSync = _context.clock().now();
for (Iterator iter = _sendingStates.iterator(); iter.hasNext(); ) {
state = (MessageState) iter.next();
if (_log.shouldLog(Log.DEBUG))
_log.debug(getPrefix() + "State " + state.getMessageId() + " / " + state.getNonce());
if (state.getNonce() == nonce) {
if (_log.shouldLog(Log.DEBUG)) _log.debug(getPrefix() + "Found a matching state");
break;
} else if ((state.getMessageId() != null)
&& (state.getMessageId().getMessageId() == msgId)) {
if (_log.shouldLog(Log.DEBUG))
_log.debug(getPrefix() + "Found a matching state by msgId");
break;
} else {
if (_log.shouldLog(Log.DEBUG)) _log.debug(getPrefix() + "State does not match");
state = null;
}
}
}
long afterSync = _context.clock().now();
if (_log.shouldLog(Log.DEBUG))
_log.debug(
"receiveStatus("
+ msgId
+ ", "
+ nonce
+ ", "
+ status
+ "): sync: "
+ (inSync - beforeSync)
+ "ms, check: "
+ (afterSync - inSync));
if (state != null) {
if (state.getMessageId() == null) {
MessageId id = new MessageId();
id.setMessageId(msgId);
state.setMessageId(id);
}
state.receive(status);
long lifetime = state.getElapsed();
switch (status) {
case 1:
_context.statManager().addRateData("i2cp.receiveStatusTime.1", lifetime, 0);
break;
// best effort codes unused
// case 2:
// _context.statManager().addRateData("i2cp.receiveStatusTime.2", lifetime, 0);
// break;
// case 3:
// _context.statManager().addRateData("i2cp.receiveStatusTime.3", lifetime, 0);
// break;
case 4:
_context.statManager().addRateData("i2cp.receiveStatusTime.4", lifetime, 0);
break;
case 5:
_context.statManager().addRateData("i2cp.receiveStatusTime.5", lifetime, 0);
break;
}
} else {
if (_log.shouldLog(Log.INFO))
_log.info(
getPrefix()
+ "No matching state for messageId "
+ msgId
+ " / "
+ nonce
+ " w/ status = "
+ status);
}
_context
.statManager()
.addRateData("i2cp.receiveStatusTime", _context.clock().now() - beforeSync, 0);
}
/**
* TODO - Don't need to save MessageState since actuallyWait is false... But for now just use
* sendNoEffort() instead.
*
* @param flags to be passed to the router
* @since 0.8.4
*/
protected boolean sendBestEffort(Destination dest, byte payload[], long expires, int flags)
throws I2PSessionException {
// SessionKey key = null;
// SessionKey newKey = null;
// SessionTag tag = null;
// Set sentTags = null;
// int oldTags = 0;
long begin = _context.clock().now();
/**
* ********* if (I2CPMessageProducer.END_TO_END_CRYPTO) { if (_log.shouldLog(Log.DEBUG))
* _log.debug("begin sendBestEffort"); key =
* _context.sessionKeyManager().getCurrentKey(dest.getPublicKey()); if
* (_log.shouldLog(Log.DEBUG)) _log.debug("key fetched"); if (key == null) key =
* _context.sessionKeyManager().createSession(dest.getPublicKey()); tag =
* _context.sessionKeyManager().consumeNextAvailableTag(dest.getPublicKey(), key); if
* (_log.shouldLog(Log.DEBUG)) _log.debug("tag consumed"); sentTags = null; oldTags =
* _context.sessionKeyManager().getAvailableTags(dest.getPublicKey(), key); long availTimeLeft =
* _context.sessionKeyManager().getAvailableTimeLeft(dest.getPublicKey(), key);
*
* <p>if ( (tagsSent == null) || (tagsSent.isEmpty()) ) { if (oldTags < NUM_TAGS) { sentTags =
* createNewTags(NUM_TAGS); if (_log.shouldLog(Log.DEBUG)) _log.debug("** sendBestEffort only
* had " + oldTags + " with " + availTimeLeft + ", adding " + NUM_TAGS + ": " + sentTags); }
* else if (availTimeLeft < 2 * 60 * 1000) { // if we have > 50 tags, but they expire in under 2
* minutes, we want more sentTags = createNewTags(NUM_TAGS); if (_log.shouldLog(Log.DEBUG))
* _log.debug(getPrefix() + "Tags expiring in " + availTimeLeft + ", adding " + NUM_TAGS + " new
* ones: " + sentTags); //_log.error("** sendBestEffort available time left " + availTimeLeft);
* } else { if (_log.shouldLog(Log.DEBUG)) _log.debug("sendBestEffort old tags: " + oldTags + "
* available time left: " + availTimeLeft); } } else { if (_log.shouldLog(Log.DEBUG))
* _log.debug("sendBestEffort is sending " + tagsSent.size() + " with " + availTimeLeft + "ms
* left, " + oldTags + " tags known and " + (tag == null ? "no tag" : " a valid tag")); }
*
* <p>if (false) // rekey newKey = _context.keyGenerator().generateSessionKey();
*
* <p>if ( (tagsSent != null) && (!tagsSent.isEmpty()) ) { if (sentTags == null) sentTags = new
* HashSet(); sentTags.addAll(tagsSent); } } else { // not using end to end crypto, so don't
* ever bundle any tags } ********
*/
// if (_log.shouldLog(Log.DEBUG)) _log.debug("before creating nonce");
long nonce = _context.random().nextInt(Integer.MAX_VALUE - 1) + 1;
// if (_log.shouldLog(Log.DEBUG)) _log.debug("before sync state");
MessageState state = new MessageState(_context, nonce, getPrefix());
// state.setKey(key);
// state.setTags(sentTags);
// state.setNewKey(newKey);
state.setTo(dest);
// if (_log.shouldLog(Log.DEBUG)) _log.debug(getPrefix() + "Setting key = " + key);
// if (keyUsed != null) {
// if (I2CPMessageProducer.END_TO_END_CRYPTO) {
// if (newKey != null)
// keyUsed.setData(newKey.getData());
// else
// keyUsed.setData(key.getData());
// } else {
// keyUsed.setData(SessionKey.INVALID_KEY.getData());
// }
// }
// if (tagsSent != null) {
// if (sentTags != null) {
// tagsSent.addAll(sentTags);
// }
// }
// if (_log.shouldLog(Log.DEBUG)) _log.debug("before sync state");
long beforeSendingSync = _context.clock().now();
long inSendingSync = 0;
synchronized (_sendingStates) {
inSendingSync = _context.clock().now();
_sendingStates.add(state);
}
long afterSendingSync = _context.clock().now();
if (_log.shouldLog(Log.DEBUG))
_log.debug(
getPrefix()
+ "Adding sending state "
+ state.getMessageId()
+ " / "
+ state.getNonce()
+ " for best effort "
+ " sync took "
+ (inSendingSync - beforeSendingSync)
+ " add took "
+ (afterSendingSync - inSendingSync));
// _producer.sendMessage(this, dest, nonce, payload, tag, key, sentTags, newKey, expires);
_producer.sendMessage(this, dest, nonce, payload, expires, flags);
// since this is 'best effort', all we're waiting for is a status update
// saying that the router received it - in theory, that should come back
// immediately, but in practice can take up to a second (though usually
// much quicker). setting this to false will short-circuit that delay
boolean actuallyWait = false; // true;
long beforeWaitFor = _context.clock().now();
if (actuallyWait)
state.waitFor(
MessageStatusMessage.STATUS_SEND_ACCEPTED, _context.clock().now() + getTimeout());
// long afterWaitFor = _context.clock().now();
// long inRemovingSync = 0;
synchronized (_sendingStates) {
// inRemovingSync = _context.clock().now();
_sendingStates.remove(state);
}
long afterRemovingSync = _context.clock().now();
boolean found = !actuallyWait || state.received(MessageStatusMessage.STATUS_SEND_ACCEPTED);
if (_log.shouldLog(Log.DEBUG))
_log.debug(
getPrefix()
+ "After waitFor sending state "
+ state.getMessageId()
+ " / "
+ state.getNonce()
+ " found = "
+ found);
long timeToSend = afterRemovingSync - beforeSendingSync;
if ((timeToSend > 10 * 1000) && (_log.shouldLog(Log.WARN))) {
_log.warn("wtf, took " + timeToSend + "ms to send the message?!", new Exception("baz"));
}
if ((afterRemovingSync - begin > 500) && (_log.shouldLog(Log.WARN))) {
_log.warn(
"Took "
+ (afterRemovingSync - begin)
+ "ms to sendBestEffort, "
+ (afterSendingSync - begin)
+ "ms to prepare, "
+ (beforeWaitFor - afterSendingSync)
+ "ms to send, "
+ (afterRemovingSync - beforeWaitFor)
+ "ms waiting for reply");
}
_context
.statManager()
.addRateData("i2cp.sendBestEffortTotalTime", afterRemovingSync - begin, 0);
// _context.statManager().addRateData("i2cp.sendBestEffortStage0", beforeSendingSync- begin, 0);
// _context.statManager().addRateData("i2cp.sendBestEffortStage1", afterSendingSync-
// beforeSendingSync, 0);
// _context.statManager().addRateData("i2cp.sendBestEffortStage2", beforeWaitFor-
// afterSendingSync, 0);
// _context.statManager().addRateData("i2cp.sendBestEffortStage3", afterWaitFor- beforeWaitFor,
// 0);
// _context.statManager().addRateData("i2cp.sendBestEffortStage4", afterRemovingSync-
// afterWaitFor, 0);
if (found) {
if (_log.shouldLog(Log.INFO))
_log.info(
getPrefix()
+ "Message sent after "
+ state.getElapsed()
+ "ms with "
+ payload.length
+ " bytes");
} else {
if (_log.shouldLog(Log.INFO))
_log.info(
getPrefix()
+ "Message send failed after "
+ state.getElapsed()
+ "ms with "
+ payload.length
+ " bytes");
if (_log.shouldLog(Log.ERROR))
_log.error(
getPrefix() + "Never received *accepted* from the router! dropping and reconnecting");
disconnect();
return false;
}
return found;
}
