Changeset f0dc769


Ignore:
Timestamp:
Jan 17, 2016 7:22:55 PM (4 years ago)
Author:
zzz <zzz@…>
Branches:
master
Children:
07e85e0, ec274583
Parents:
71c4505
Message:

BuildHandler?: Disable removal of tunnel on next-hop timeout,
as it isn't reliable
cleanup and log tweaks

Files:
4 edited

Legend:

Unmodified
Added
Removed
  • history.txt

    r71c4505 rf0dc769  
     12016-01-17 zzz
     2 * BuildHandler: Disable tunnel removal on next-hop timeout
     3 * Console:
     4   - Fix mime type for svg in themes directory
     5   - Add zh_TW translation
     6 * Fortuna: Add getByte() method
     7 * i2psnark: add opendocument mime types
     8 * i2ptunnel: Remove unused stats
     9 * Utils: Move CachedIteratorArrayList from core to router
     10
    1112016-01-13 zzz
    212 * BuildHandler: More early-disconnect cases
  • router/java/src/net/i2p/router/RouterVersion.java

    r71c4505 rf0dc769  
    1919    public final static String ID = "Monotone";
    2020    public final static String VERSION = CoreVersion.VERSION;
    21     public final static long BUILD = 24;
     21    public final static long BUILD = 25;
    2222
    2323    /** for example "-test" */
  • router/java/src/net/i2p/router/tunnel/TunnelDispatcher.java

    r71c4505 rf0dc769  
    452452        if (cfg.isInbound()) {
    453453            TunnelId recvId = cfg.getConfig(cfg.getLength()-1).getReceiveTunnel();
    454             if (_log.shouldLog(Log.DEBUG))
    455                 _log.debug("removing our own inbound " + cfg);
     454            if (_log.shouldLog(Log.INFO))
     455                _log.info("removing our own inbound " + cfg);
    456456            TunnelParticipant participant = _participants.remove(recvId);
    457457            if (participant == null) {
     
    471471            }
    472472        } else {
    473             if (_log.shouldLog(Log.DEBUG))
    474                 _log.debug("removing our own outbound " + cfg);
     473            if (_log.shouldLog(Log.INFO))
     474                _log.info("removing our own outbound " + cfg);
    475475            TunnelId outId = cfg.getConfig(0).getSendTunnel();
    476476            TunnelGateway gw = _outboundGateways.remove(outId);
     
    499499        boolean removed = (null != _participatingConfig.remove(recvId));
    500500        if (removed) {
    501             if (_log.shouldLog(Log.DEBUG))
    502                 _log.debug("removing " + cfg /* , new Exception() */ );
     501            if (_log.shouldLog(Log.INFO))
     502                _log.info("removing " + cfg /* , new Exception() */ );
    503503        } else {
    504504            // this is normal, this can get called twice
  • router/java/src/net/i2p/router/tunnel/pool/BuildHandler.java

    r71c4505 rf0dc769  
    449449    private long handleRequest(BuildMessageState state) {
    450450        long timeSinceReceived = _context.clock().now()-state.recvTime;
    451         if (_log.shouldLog(Log.DEBUG))
    452             _log.debug(state.msg.getUniqueId() + ": handling request after " + timeSinceReceived);
     451        //if (_log.shouldLog(Log.DEBUG))
     452        //    _log.debug(state.msg.getUniqueId() + ": handling request after " + timeSinceReceived);
    453453       
    454454        Hash from = state.fromHash;
     
    493493        long lookupTime = System.currentTimeMillis()-beforeLookup;
    494494        if (lookupTime > 500 && _log.shouldLog(Log.WARN))
    495             _log.warn("Took too long to lookup the request: " + lookupTime + "/" + readPeerTime + " for message " + state.msg.getUniqueId() + " received " + (timeSinceReceived+decryptTime) + " ago");
     495            _log.warn("Took too long to lookup the request: " + lookupTime + "/" + readPeerTime + " for " + req);
    496496        if (nextPeerInfo == null) {
    497497            // limit concurrent next-hop lookups to prevent job queue overload attacks
     
    501501            if (current <= limit) {
    502502                if (_log.shouldLog(Log.DEBUG))
    503                     _log.debug("Request " + state.msg.getUniqueId() + '/' + req.readReceiveTunnelId() + '/' + req.readNextTunnelId()
     503                    _log.debug("Request " + req
    504504                               + " handled, lookup next peer " + nextPeer
    505505                               + " lookups: " + current + '/' + limit);
     
    509509                _currentLookups.decrementAndGet();
    510510                if (_log.shouldLog(Log.WARN))
    511                     _log.warn("Drop next hop lookup, limit " + limit);
     511                    _log.warn("Drop next hop lookup, limit " + limit + ": " + req);
    512512                _context.statManager().addRateData("tunnel.dropLookupThrottle", 1);
    513513            }
     
    520520            long handleTime = System.currentTimeMillis() - beforeHandle;
    521521            if (_log.shouldLog(Log.DEBUG))
    522                 _log.debug("Request " + state.msg.getUniqueId() + " handled and we know the next peer "
     522                _log.debug("Request " + req + " handled and we know the next peer "
    523523                           + nextPeer + " after " + handleTime
    524524                           + "/" + decryptTime + "/" + lookupTime + "/" + timeSinceReceived);
     
    561561            _currentLookups.decrementAndGet();
    562562            if (_log.shouldLog(Log.DEBUG))
    563                 _log.debug("Request " + _state.msg.getUniqueId() + " handled with a successful deferred lookup for the next peer " + _nextPeer);
     563                _log.debug("Request " + _state.msg.getUniqueId() + " handled with a successful deferred lookup: " + _req);
    564564
    565565            RouterInfo ri = getContext().netDb().lookupRouterInfoLocally(_nextPeer);
     
    569569            } else {
    570570                if (_log.shouldLog(Log.WARN))
    571                     _log.warn("Deferred successfully, but we couldnt find " + _nextPeer);
     571                    _log.warn("Deferred successfully, but we couldnt find " + _nextPeer + "? " + _req);
    572572                getContext().statManager().addRateData("tunnel.buildLookupSuccess", 0);
    573573            }
     
    594594            getContext().statManager().addRateData("tunnel.rejectTimeout", 1);
    595595            getContext().statManager().addRateData("tunnel.buildLookupSuccess", 0);
    596             // logging commented out so class can be static
    597             //if (_log.shouldLog(Log.WARN))
    598             //    _log.warn("Request " + _state.msg.getUniqueId()
    599             //              + " could no be satisfied, as the next peer could not be found: " + _nextPeer.toBase64());
     596            if (_log.shouldLog(Log.WARN))
     597                _log.warn("Next hop lookup failure: " + _req);
    600598
    601599            // ???  should we blame the peer here?   getContext().profileManager().tunnelTimedOut(_nextPeer);
    602600            getContext().messageHistory().tunnelRejected(_state.fromHash, new TunnelId(_req.readReceiveTunnelId()), _nextPeer,
    603                                                          "rejected because we couldn't find " + _nextPeer + ": " +
    604                                                          _state.msg.getUniqueId() + "/" + _req.readNextTunnelId());
     601                                                         // this is all disabled anyway
     602                                                         //"rejected because we couldn't find " + _nextPeer + ": " +
     603                                                         //_state.msg.getUniqueId() + "/" + _req.readNextTunnelId());
     604                                                         "lookup fail");
    605605        }
    606606    }
     
    655655        if (isInGW && isOutEnd) {
    656656            _context.statManager().addRateData("tunnel.rejectHostile", 1);
    657             _log.error("Dropping build request, IBGW+OBEP");
     657            _log.error("Dropping build request, IBGW+OBEP: " + req);
    658658            if (from != null)
    659659                _context.commSystem().mayDisconnect(from);
     
    668668            // old i2pd
    669669            if (_log.shouldWarn())
    670                 _log.warn("Dropping build request, we are the next hop");
     670                _log.warn("Dropping build request, we are the next hop: " + req);
    671671            if (from != null)
    672672                _context.commSystem().mayDisconnect(from);
     
    679679            if (from == null || _context.routerHash().equals(from)) {
    680680                _context.statManager().addRateData("tunnel.rejectHostile", 1);
    681                 _log.error("Dropping build request, we are the previous hop");
     681                _log.error("Dropping build request, we are the previous hop: " + req);
    682682                return;
    683683            }
     
    690690                _context.statManager().addRateData("tunnel.rejectHostile", 1);
    691691                if (_log.shouldLog(Log.WARN))
    692                     _log.warn("Dropping build request with the same previous and next hop");
     692                    _log.warn("Dropping build request with the same previous and next hop: " + req);
    693693                _context.commSystem().mayDisconnect(from);
    694694                return;
     
    705705            _context.statManager().addRateData("tunnel.rejectTooOld", 1);
    706706            if (_log.shouldLog(Log.WARN))
    707                 _log.warn("Dropping build request too old... replay attack? " + DataHelper.formatDuration(timeDiff));
     707                _log.warn("Dropping build request too old... replay attack? " + DataHelper.formatDuration(timeDiff) + ": " + req);
    708708            if (from != null)
    709709                _context.commSystem().mayDisconnect(from);
     
    713713            _context.statManager().addRateData("tunnel.rejectFuture", 1);
    714714            if (_log.shouldLog(Log.WARN))
    715                 _log.warn("Dropping build request too far in future " + DataHelper.formatDuration(0 - timeDiff));
     715                _log.warn("Dropping build request too far in future " + DataHelper.formatDuration(0 - timeDiff) + ": " + req);
    716716            if (from != null)
    717717                _context.commSystem().mayDisconnect(from);
     
    792792            if (from != null && _throttler.shouldThrottle(from)) {
    793793                if (_log.shouldLog(Log.WARN))
    794                     _log.warn("Rejecting tunnel (hop throttle), previous hop: " + from);
     794                    _log.warn("Rejecting tunnel (hop throttle), previous hop: " + from + ": " + req);
    795795                // no setTunnelStatus() indication
    796796                _context.statManager().addRateData("tunnel.rejectHopThrottle", 1);
     
    801801            _throttler.shouldThrottle(nextPeer)) {
    802802            if (_log.shouldLog(Log.WARN))
    803                 _log.warn("Rejecting tunnel (hop throttle), next hop: " + nextPeer);
     803                _log.warn("Rejecting tunnel (hop throttle), next hop: " + req);
    804804            _context.statManager().addRateData("tunnel.rejectHopThrottle", 1);
    805805            // no setTunnelStatus() indication
    806806            response = TunnelHistory.TUNNEL_REJECT_BANDWIDTH;
    807807        }
    808 
    809         if (_log.shouldLog(Log.DEBUG))
    810             _log.debug("Responding to " + state.msg.getUniqueId() + "/" + ourId
    811                        + " after " + recvDelay + " with " + response
    812                        + " from " + (from != null ? from : "tunnel"));
    813808
    814809        HopConfig cfg = null;
     
    850845            if (success) {
    851846                if (_log.shouldLog(Log.DEBUG))
    852                     _log.debug("Joining " + state.msg.getUniqueId() + "/" + cfg.getReceiveTunnel() + "/" + recvDelay + " as " + (isOutEnd ? "outbound endpoint" : isInGW ? "inbound gw" : "participant"));
     847                    _log.debug("Joining: " + req);
    853848            } else {
    854849                // Dup Tunnel ID. This can definitely happen (birthday paradox).
     
    858853                _context.statManager().addRateData("tunnel.rejectDupID", 1);
    859854                if (_log.shouldLog(Log.WARN))
    860                     _log.warn("DUP ID failure " + state.msg.getUniqueId() + "/" + cfg.getReceiveTunnel() + " as " + (isOutEnd ? "outbound endpoint" : isInGW ? "inbound gw" : "participant"));
     855                    _log.warn("DUP ID failure: " + req);
    861856            }
    862857        }
     
    867862            _context.statManager().addRateData("tunnel.reject." + response, 1);
    868863            _context.messageHistory().tunnelRejected(from, new TunnelId(ourId), nextPeer,
    869                                                      "rejecting for " + response + ": " +
    870                                                      state.msg.getUniqueId() + "/" + ourId + "/" + req.readNextTunnelId() + " delay " +
    871                                                      recvDelay + " as " +
    872                                                      (isOutEnd ? "outbound endpoint" : isInGW ? "inbound gw" : "participant"));
     864                                                     // this is all disabled anyway
     865                                                     //"rejecting for " + response + ": " +
     866                                                     //state.msg.getUniqueId() + "/" + ourId + "/" + req.readNextTunnelId() + " delay " +
     867                                                     //recvDelay + " as " +
     868                                                     //(isOutEnd ? "outbound endpoint" : isInGW ? "inbound gw" : "participant"));
     869                                                     Integer.toString(response));
    873870            if (from != null)
    874871                _context.commSystem().mayDisconnect(from);
     
    882879                _context.statManager().addRateData("tunnel.dropConnLimits", 1);
    883880                if (_log.shouldLog(Log.WARN))
    884                     _log.warn("Not sending rejection due to conn limits");
     881                    _log.warn("Not sending rejection due to conn limits: " + req);
    885882                return;
    886883            }
     
    889886            _context.commSystem().mayDisconnect(from);
    890887        }
     888
     889        if (_log.shouldLog(Log.DEBUG))
     890            _log.debug("Responding to " + state.msg.getUniqueId()
     891                       + " after " + recvDelay + " with " + response
     892                       + " from " + (from != null ? from : "tunnel") + ": " + req);
    891893
    892894        EncryptedBuildRecord reply = BuildResponseRecord.create(_context, response, req.readReplyKey(), req.readReplyIV(), state.msg.getUniqueId());
     
    905907
    906908        if (_log.shouldLog(Log.DEBUG))
    907             _log.debug("Read slot " + ourSlot + " containing our hop @ " + _context.routerHash()
    908                       + " accepted? " + response + " receiving on " + ourId
    909                       + " sending to " + nextId
    910                       + " on " + nextPeer
    911                       + " inGW? " + isInGW + " outEnd? " + isOutEnd
    912                       + " recvDelay " + recvDelay + " replyMessage " + req.readReplyMessageId()
    913                       + " replyKey " + req.readReplyKey() + " replyIV " + Base64.encode(req.readReplyIV()));
     909            _log.debug("Read slot " + ourSlot + " containing: " + req
     910                      + " accepted? " + response
     911                      + " recvDelay " + recvDelay + " replyMessage " + req.readReplyMessageId());
    914912
    915913        // now actually send the response
     914        long expires = _context.clock().now() + NEXT_HOP_SEND_TIMEOUT;
    916915        if (!isOutEnd) {
    917916            state.msg.setUniqueId(req.readReplyMessageId());
    918             state.msg.setMessageExpiration(_context.clock().now() + NEXT_HOP_SEND_TIMEOUT);
    919             OutNetMessage msg = new OutNetMessage(_context, state.msg, state.msg.getMessageExpiration(), PRIORITY, nextPeerInfo);
     917            state.msg.setMessageExpiration(expires);
     918            OutNetMessage msg = new OutNetMessage(_context, state.msg, expires, PRIORITY, nextPeerInfo);
    920919            if (response == 0)
    921920                msg.setOnFailedSendJob(new TunnelBuildNextHopFailJob(_context, cfg));
     
    933932                replyMsg.setRecord(i, state.msg.getRecord(i));
    934933            replyMsg.setUniqueId(req.readReplyMessageId());
    935             replyMsg.setMessageExpiration(_context.clock().now() + NEXT_HOP_SEND_TIMEOUT);
     934            replyMsg.setMessageExpiration(expires);
    936935            TunnelGatewayMessage m = new TunnelGatewayMessage(_context);
    937936            m.setMessage(replyMsg);
    938             m.setMessageExpiration(replyMsg.getMessageExpiration());
     937            m.setMessageExpiration(expires);
    939938            m.setTunnelId(new TunnelId(nextId));
    940939            if (_context.routerHash().equals(nextPeer)) {
     
    942941                if (_log.shouldLog(Log.DEBUG))
    943942                    _log.debug("We are the reply gateway for " + nextId
    944                               + " when replying to replyMessage " + req.readReplyMessageId());
     943                              + " when replying to replyMessage " + req);
    945944                _context.tunnelDispatcher().dispatch(m);
    946945            } else {
    947946                // ok, the gateway is some other peer, shove 'er across
    948                 OutNetMessage outMsg = new OutNetMessage(_context, m, m.getMessageExpiration(), PRIORITY, nextPeerInfo);
     947                OutNetMessage outMsg = new OutNetMessage(_context, m, expires, PRIORITY, nextPeerInfo);
    949948                if (response == 0)
    950949                    outMsg.setOnFailedSendJob(new TunnelBuildNextHopFailJob(_context, cfg));
     
    973972            long reqId = receivedMessage.getUniqueId();
    974973            PooledTunnelCreatorConfig cfg = _exec.removeFromBuilding(reqId);
    975             if (_log.shouldLog(Log.DEBUG))
    976                 _log.debug("Receive tunnel build message " + reqId + " from "
    977                            + (from != null ? from.calculateHash() : fromHash != null ? fromHash : "tunnels")
    978                            + ", found matching tunnel? " + (cfg != null));
     974            //if (_log.shouldLog(Log.DEBUG))
     975            //    _log.debug("Receive tunnel build message " + reqId + " from "
     976            //               + (from != null ? from.calculateHash() : fromHash != null ? fromHash : "tunnels")
     977            //               + ", found matching tunnel? " + (cfg != null));
    979978            if (cfg != null) {
    980979                if (!cfg.isInbound()) {
     
    11721171
    11731172        public void runJob() {
    1174             getContext().tunnelDispatcher().remove(_cfg);
     1173            //  TODO
     1174            //  This doesn't seem to be a reliable indication of actual failure,
     1175            //  as we sometimes get subsequent tunnel messages.
     1176            //  Until this is investigated and fixed, don't remove the tunnel.
     1177            //getContext().tunnelDispatcher().remove(_cfg);
    11751178            getContext().statManager().addRateData("tunnel.rejectTimeout2", 1);
    11761179            Log log = getContext().logManager().getLog(BuildHandler.class);
Note: See TracChangeset for help on using the changeset viewer.