Example #1
0
  /**
   * 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);
  }
Example #2
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;
  }