/** * 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; }