diff --git a/router/java/src/net/i2p/router/tunnel/BatchedPreprocessor.java b/router/java/src/net/i2p/router/tunnel/BatchedPreprocessor.java index 4533956d37..cee4653f0a 100644 --- a/router/java/src/net/i2p/router/tunnel/BatchedPreprocessor.java +++ b/router/java/src/net/i2p/router/tunnel/BatchedPreprocessor.java @@ -46,25 +46,12 @@ import net.i2p.util.Log; */ public class BatchedPreprocessor extends TrivialPreprocessor { private long _pendingSince; - private String _name; + private final String _name; public BatchedPreprocessor(RouterContext ctx, String name) { super(ctx); - _log = ctx.logManager().getLog(BatchedPreprocessor.class); _name = name; - _pendingSince = 0; - ctx.statManager().createRateStat("tunnel.batchMultipleCount", "How many messages are batched into a tunnel message", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); - ctx.statManager().createRateStat("tunnel.batchDelay", "How many messages were pending when the batching waited", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); - ctx.statManager().createRateStat("tunnel.batchDelaySent", "How many messages were flushed when the batching delay completed", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); - ctx.statManager().createRateStat("tunnel.batchCount", "How many groups of messages were flushed together", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); - ctx.statManager().createRateStat("tunnel.batchDelayAmount", "How long we should wait before flushing the batch", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); - ctx.statManager().createRateStat("tunnel.batchFlushRemaining", "How many messages remain after flushing", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); - ctx.statManager().createRateStat("tunnel.writeDelay", "How long after a message reaches the gateway is it processed (lifetime is size)", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); - ctx.statManager().createRateStat("tunnel.batchSmallFragments", "How many outgoing pad bytes are in small fragments?", - "Tunnels", new long[] { 10*60*1000l, 60*60*1000l }); - ctx.statManager().createRateStat("tunnel.batchFullFragments", "How many outgoing tunnel messages use the full data area?", - "Tunnels", new long[] { 10*60*1000l, 60*60*1000l }); - ctx.statManager().createRateStat("tunnel.batchFragmentation", "Avg. number of fragments per msg", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); + // all createRateStat() moved to TunnelDispatcher } /** 1003 */ @@ -426,7 +413,8 @@ public class BatchedPreprocessor extends TrivialPreprocessor { int later = msg.getData().length - msg.getOffset(); if (later > 0) frag--; - _log.debug("writing " + msg.getMessageId() + " fragment " + frag + if (_log.shouldLog(Log.DEBUG)) + _log.debug("writing " + msg.getMessageId() + " fragment " + frag + ", ending at " + offset + " prev " + prevOffset + " leaving " + later + " bytes for later"); } diff --git a/router/java/src/net/i2p/router/tunnel/InboundGatewayReceiver.java b/router/java/src/net/i2p/router/tunnel/InboundGatewayReceiver.java index ab39adf891..204fc10877 100644 --- a/router/java/src/net/i2p/router/tunnel/InboundGatewayReceiver.java +++ b/router/java/src/net/i2p/router/tunnel/InboundGatewayReceiver.java @@ -7,33 +7,43 @@ import net.i2p.router.OutNetMessage; import net.i2p.router.RouterContext; /** - * + * Handle messages at the IBGW */ -public class InboundGatewayReceiver implements TunnelGateway.Receiver { - private RouterContext _context; - private HopConfig _config; +class InboundGatewayReceiver implements TunnelGateway.Receiver { + private final RouterContext _context; + private final HopConfig _config; private RouterInfo _target; + private static final long MAX_LOOKUP_TIME = 15*1000; + public InboundGatewayReceiver(RouterContext ctx, HopConfig cfg) { _context = ctx; _config = cfg; + // all createRateStat() in TunnelDispatcher } + public long receiveEncrypted(byte[] encrypted) { return receiveEncrypted(encrypted, false); } + public long receiveEncrypted(byte[] encrypted, boolean alreadySearched) { if (!alreadySearched) _config.incrementProcessedMessages(); if (_target == null) { _target = _context.netDb().lookupRouterInfoLocally(_config.getSendTo()); if (_target == null) { + // It should be rare to forget the router info for the next peer ReceiveJob j = null; - if (!alreadySearched) + if (alreadySearched) + _context.statManager().addRateData("tunnel.inboundLookupSuccess", 0, 0); + else j = new ReceiveJob(_context, encrypted); - _context.netDb().lookupRouterInfo(_config.getSendTo(), j, j, 5*1000); + _context.netDb().lookupRouterInfo(_config.getSendTo(), j, j, MAX_LOOKUP_TIME); return -1; } } + if (alreadySearched) + _context.statManager().addRateData("tunnel.inboundLookupSuccess", 1, 0); // We do this before the preprocessor now (i.e. before fragmentation) //if (_context.tunnelDispatcher().shouldDropParticipatingMessage("IBGW", encrypted.length)) @@ -53,12 +63,15 @@ public class InboundGatewayReceiver implements TunnelGateway.Receiver { } private class ReceiveJob extends JobImpl { - private byte[] _encrypted; + private final byte[] _encrypted; + public ReceiveJob(RouterContext ctx, byte data[]) { super(ctx); _encrypted = data; } - public String getName() { return "lookup first hop"; } + + public String getName() { return "IBGW lookup first hop"; } + public void runJob() { receiveEncrypted(_encrypted, true); } diff --git a/router/java/src/net/i2p/router/tunnel/OutboundMessageDistributor.java b/router/java/src/net/i2p/router/tunnel/OutboundMessageDistributor.java index 799b59b6b0..61c42783cb 100644 --- a/router/java/src/net/i2p/router/tunnel/OutboundMessageDistributor.java +++ b/router/java/src/net/i2p/router/tunnel/OutboundMessageDistributor.java @@ -19,12 +19,13 @@ public class OutboundMessageDistributor { private final int _priority; private final Log _log; - private static final int MAX_DISTRIBUTE_TIME = 10*1000; + private static final long MAX_DISTRIBUTE_TIME = 15*1000; public OutboundMessageDistributor(RouterContext ctx, int priority) { _context = ctx; _priority = priority; _log = ctx.logManager().getLog(OutboundMessageDistributor.class); + // all createRateStat() in TunnelDispatcher } public void distribute(I2NPMessage msg, Hash target) { @@ -34,10 +35,12 @@ public class OutboundMessageDistributor { public void distribute(I2NPMessage msg, Hash target, TunnelId tunnel) { RouterInfo info = _context.netDb().lookupRouterInfoLocally(target); if (info == null) { - if (_log.shouldLog(Log.DEBUG)) - _log.debug("outbound distributor to " + target.toBase64().substring(0,4) + if (_log.shouldLog(Log.INFO)) + _log.info("outbound distributor to " + target + "." + (tunnel != null ? tunnel.getTunnelId() + "" : "") + ": no info locally, searching..."); + // TODO - should we set the search timeout based on the message timeout, + // or is that a bad idea due to clock skews? _context.netDb().lookupRouterInfo(target, new DistributeJob(_context, msg, target, tunnel), null, MAX_DISTRIBUTE_TIME); return; } else { @@ -68,7 +71,7 @@ public class OutboundMessageDistributor { out.setPriority(_priority); if (_log.shouldLog(Log.DEBUG)) - _log.debug("queueing outbound message to " + target.getIdentity().calculateHash().toBase64().substring(0,4)); + _log.debug("queueing outbound message to " + target.getIdentity().calculateHash()); _context.outNetMessagePool().add(out); } } @@ -85,24 +88,26 @@ public class OutboundMessageDistributor { _tunnel = id; } - public String getName() { return "Distribute outbound message"; } + public String getName() { return "OBEP distribute after lookup"; } public void runJob() { RouterInfo info = getContext().netDb().lookupRouterInfoLocally(_target); + int stat; if (info != null) { if (_log.shouldLog(Log.DEBUG)) - _log.debug("outbound distributor to " + _target.toBase64().substring(0,4) + _log.debug("outbound distributor to " + _target + "." + (_tunnel != null ? _tunnel.getTunnelId() + "" : "") + ": found on search"); distribute(_message, info, _tunnel); + stat = 1; } else { - // TODO add a stat here if (_log.shouldLog(Log.WARN)) - _log.warn("outbound distributor to " + _target.toBase64().substring(0,4) + _log.warn("outbound distributor to " + _target + "." + (_tunnel != null ? _tunnel.getTunnelId() + "" : "") + ": NOT found on search"); + stat = 0; } + _context.statManager().addRateData("tunnel.distributeLookupSuccess", stat, 0); } - } } diff --git a/router/java/src/net/i2p/router/tunnel/OutboundReceiver.java b/router/java/src/net/i2p/router/tunnel/OutboundReceiver.java index 02c3f0f169..28f0c54368 100644 --- a/router/java/src/net/i2p/router/tunnel/OutboundReceiver.java +++ b/router/java/src/net/i2p/router/tunnel/OutboundReceiver.java @@ -8,6 +8,7 @@ import net.i2p.router.RouterContext; import net.i2p.util.Log; /** + * We are the outbound gateway - we created this outbound tunnel. * Receive the outbound message after it has been preprocessed and encrypted, * then forward it on to the first hop in the tunnel. * @@ -18,11 +19,14 @@ class OutboundReceiver implements TunnelGateway.Receiver { private final TunnelCreatorConfig _config; private RouterInfo _nextHopCache; + private static final long MAX_LOOKUP_TIME = 15*1000; + public OutboundReceiver(RouterContext ctx, TunnelCreatorConfig cfg) { _context = ctx; _log = ctx.logManager().getLog(OutboundReceiver.class); _config = cfg; _nextHopCache = _context.netDb().lookupRouterInfoLocally(_config.getPeer(1)); + // all createRateStat() in TunnelDispatcher } public long receiveEncrypted(byte encrypted[]) { @@ -40,11 +44,12 @@ class OutboundReceiver implements TunnelGateway.Receiver { send(msg, ri); return msg.getUniqueId(); } else { - // TODO add a stat here + // It should be rare to forget the router info for a peer in our own tunnel. if (_log.shouldLog(Log.WARN)) - _log.warn("lookup of " + _config.getPeer(1).toBase64().substring(0,4) + _log.warn("lookup of " + _config.getPeer(1) + " required for " + msg); - _context.netDb().lookupRouterInfo(_config.getPeer(1), new SendJob(_context, msg), new FailedJob(_context), 10*1000); + _context.netDb().lookupRouterInfo(_config.getPeer(1), new SendJob(_context, msg), + new FailedJob(_context), MAX_LOOKUP_TIME); return -1; } } @@ -69,17 +74,22 @@ class OutboundReceiver implements TunnelGateway.Receiver { _msg = msg; } - public String getName() { return "forward a tunnel message"; } + public String getName() { return "OBGW send after lookup"; } public void runJob() { RouterInfo ri = _context.netDb().lookupRouterInfoLocally(_config.getPeer(1)); if (_log.shouldLog(Log.DEBUG)) - _log.debug("lookup of " + _config.getPeer(1).toBase64().substring(0,4) + _log.debug("lookup of " + _config.getPeer(1) + " successful? " + (ri != null)); + int stat; if (ri != null) { _nextHopCache = ri; send(_msg, ri); + stat = 1; + } else { + stat = 0; } + _context.statManager().addRateData("tunnel.outboundLookupSuccess", stat, 0); } } @@ -88,13 +98,13 @@ class OutboundReceiver implements TunnelGateway.Receiver { super(ctx); } - public String getName() { return "failed looking for our outbound gateway"; } + public String getName() { return "OBGW lookup fail"; } public void runJob() { - // TODO add a stat here if (_log.shouldLog(Log.WARN)) - _log.warn("lookup of " + _config.getPeer(1).toBase64().substring(0,4) + _log.warn("lookup of " + _config.getPeer(1) + " failed for " + _config); + _context.statManager().addRateData("tunnel.outboundLookupSuccess", 0, 0); } } } diff --git a/router/java/src/net/i2p/router/tunnel/TrivialPreprocessor.java b/router/java/src/net/i2p/router/tunnel/TrivialPreprocessor.java index ae120c18f8..1840b0dc87 100644 --- a/router/java/src/net/i2p/router/tunnel/TrivialPreprocessor.java +++ b/router/java/src/net/i2p/router/tunnel/TrivialPreprocessor.java @@ -20,8 +20,8 @@ import net.i2p.util.Log; * See FragmentHandler Javadoc for tunnel message fragment format */ public class TrivialPreprocessor implements TunnelGateway.QueuePreprocessor { - protected RouterContext _context; - protected Log _log; + protected final RouterContext _context; + protected final Log _log; public static final int PREPROCESSED_SIZE = 1024; protected static final int IV_SIZE = HopProcessor.IV_LENGTH; @@ -39,7 +39,7 @@ public class TrivialPreprocessor implements TunnelGateway.QueuePreprocessor { public TrivialPreprocessor(RouterContext ctx) { _context = ctx; - _log = ctx.logManager().getLog(TrivialPreprocessor.class); + _log = ctx.logManager().getLog(getClass()); } /** how long do we want to wait before flushing */ diff --git a/router/java/src/net/i2p/router/tunnel/TrivialRouterPreprocessor.java b/router/java/src/net/i2p/router/tunnel/TrivialRouterPreprocessor.java index 6ddf636e4f..e8437eb8e0 100644 --- a/router/java/src/net/i2p/router/tunnel/TrivialRouterPreprocessor.java +++ b/router/java/src/net/i2p/router/tunnel/TrivialRouterPreprocessor.java @@ -10,14 +10,12 @@ import net.i2p.router.RouterContext; * @deprecated unused */ public class TrivialRouterPreprocessor extends TrivialPreprocessor { - private RouterContext _routerContext; public TrivialRouterPreprocessor(RouterContext ctx) { super(ctx); - _routerContext = ctx; } protected void notePreprocessing(long messageId, int numFragments, int totalLength, List messageIds) { - _routerContext.messageHistory().fragmentMessage(messageId, numFragments, totalLength, messageIds, null); + _context.messageHistory().fragmentMessage(messageId, numFragments, totalLength, messageIds, null); } } diff --git a/router/java/src/net/i2p/router/tunnel/TunnelDispatcher.java b/router/java/src/net/i2p/router/tunnel/TunnelDispatcher.java index a9e10b8b7c..d69b501089 100644 --- a/router/java/src/net/i2p/router/tunnel/TunnelDispatcher.java +++ b/router/java/src/net/i2p/router/tunnel/TunnelDispatcher.java @@ -52,9 +52,6 @@ public class TunnelDispatcher implements Service { _participants = new ConcurrentHashMap(); _inboundGateways = new ConcurrentHashMap(); _participatingConfig = new ConcurrentHashMap(); - _lastParticipatingExpiration = 0; - _lastDropTime = 0; - _validator = null; _pumper = new TunnelGatewayPumper(ctx); _leaveJob = new LeaveTunnel(ctx); ctx.statManager().createRequiredRateStat("tunnel.participatingTunnels", @@ -107,7 +104,7 @@ public class TunnelDispatcher implements Service { new long[] { 60*1000l, 60*60*1000l }); ctx.statManager().createRateStat("tunnel.dispatchOutboundZeroHopTime", "How long it takes to dispatch an outbound message through a zero hop tunnel", "Tunnels", - new long[] { 60*1000l, 60*60*1000l }); + new long[] { 60*60*1000l }); ctx.statManager().createRequiredRateStat("tunnel.participatingBandwidth", "Participating traffic received (Bytes/sec)", "Tunnels", new long[] { 60*1000l, 60*10*1000l }); @@ -129,6 +126,27 @@ public class TunnelDispatcher implements Service { ctx.statManager().createRateStat("tunnel.failedPartially", "How many messages are sent through a tunnel that only failed partially (period == failures)?", "Tunnels", new long[] { 60*1000l, 10*60*1000l, 60*60*1000l }); + // following are for BatchedPreprocessor + ctx.statManager().createRateStat("tunnel.batchMultipleCount", "How many messages are batched into a tunnel message", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); + ctx.statManager().createRateStat("tunnel.batchDelay", "How many messages were pending when the batching waited", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); + ctx.statManager().createRateStat("tunnel.batchDelaySent", "How many messages were flushed when the batching delay completed", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); + ctx.statManager().createRateStat("tunnel.batchCount", "How many groups of messages were flushed together", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); + ctx.statManager().createRateStat("tunnel.batchDelayAmount", "How long we should wait before flushing the batch", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); + ctx.statManager().createRateStat("tunnel.batchFlushRemaining", "How many messages remain after flushing", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); + ctx.statManager().createRateStat("tunnel.writeDelay", "How long after a message reaches the gateway is it processed (lifetime is size)", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); + ctx.statManager().createRateStat("tunnel.batchSmallFragments", "How many outgoing pad bytes are in small fragments?", + "Tunnels", new long[] { 10*60*1000l, 60*60*1000l }); + ctx.statManager().createRateStat("tunnel.batchFullFragments", "How many outgoing tunnel messages use the full data area?", + "Tunnels", new long[] { 10*60*1000l, 60*60*1000l }); + ctx.statManager().createRateStat("tunnel.batchFragmentation", "Avg. number of fragments per msg", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); + // following is for OutboundMessageDistributor + ctx.statManager().createRateStat("tunnel.distributeLookupSuccess", "Was a deferred lookup successful?", "Tunnels", new long[] { 60*60*1000 }); + // following is for OutboundReceiver + ctx.statManager().createRateStat("tunnel.outboundLookupSuccess", "Was a deferred lookup successful?", "Tunnels", new long[] { 60*60*1000 }); + // following is for InboundGatewayReceiver + ctx.statManager().createRateStat("tunnel.inboundLookupSuccess", "Was a deferred lookup successful?", "Tunnels", new long[] { 60*60*1000 }); + // following is for TunnelParticipant + ctx.statManager().createRateStat("tunnel.participantLookupSuccess", "Was a deferred lookup successful?", "Tunnels", new long[] { 60*60*1000 }); } /** for IBGW */ @@ -171,6 +189,7 @@ public class TunnelDispatcher implements Service { _context.messageHistory().tunnelJoined("outboundZeroHop", cfg); } } + /** * We are the inbound endpoint - we created this tunnel */ @@ -210,6 +229,7 @@ public class TunnelDispatcher implements Service { _lastParticipatingExpiration = cfg.getExpiration(); _leaveJob.add(cfg); } + /** * We are the outbound endpoint in this tunnel, and did not create it * diff --git a/router/java/src/net/i2p/router/tunnel/TunnelParticipant.java b/router/java/src/net/i2p/router/tunnel/TunnelParticipant.java index 54f22ce1c9..7bd2cb654e 100644 --- a/router/java/src/net/i2p/router/tunnel/TunnelParticipant.java +++ b/router/java/src/net/i2p/router/tunnel/TunnelParticipant.java @@ -18,21 +18,34 @@ import net.i2p.util.Log; * which it will then selectively forward. */ public class TunnelParticipant { - private RouterContext _context; - private Log _log; - private HopConfig _config; - private HopProcessor _processor; - private InboundEndpointProcessor _inboundEndpointProcessor; - private InboundMessageDistributor _inboundDistributor; - private FragmentHandler _handler; + private final RouterContext _context; + private final Log _log; + private final HopConfig _config; + private final HopProcessor _processor; + private final InboundEndpointProcessor _inboundEndpointProcessor; + private final InboundMessageDistributor _inboundDistributor; + private final FragmentHandler _handler; private RouterInfo _nextHopCache; + private static final long MAX_LOOKUP_TIME = 15*1000; + /** for next hop when a tunnel is first created */ + private static final long LONG_MAX_LOOKUP_TIME = 30*1000; + + /** not an inbound endpoint */ public TunnelParticipant(RouterContext ctx, HopConfig config, HopProcessor processor) { this(ctx, config, processor, null); } + + /** inbound endpoint */ public TunnelParticipant(RouterContext ctx, InboundEndpointProcessor inEndProc) { this(ctx, null, null, inEndProc); } + + /** + * @param config may be null (inbound endpoint if null) + * @param processor may be null (inbound endpoint if null) + * @param inEndProc may be null (inbound endpoint if non-null) + */ private TunnelParticipant(RouterContext ctx, HopConfig config, HopProcessor processor, InboundEndpointProcessor inEndProc) { _context = ctx; _log = ctx.logManager().getLog(TunnelParticipant.class); @@ -40,23 +53,32 @@ public class TunnelParticipant { _processor = processor; if ( (config == null) || (config.getSendTo() == null) ) _handler = new RouterFragmentHandler(ctx, new DefragmentedHandler()); + else + _handler = null; // final + _inboundEndpointProcessor = inEndProc; if (inEndProc != null) _inboundDistributor = new InboundMessageDistributor(ctx, inEndProc.getDestination()); + else + _inboundDistributor = null; // final if ( (_config != null) && (_config.getSendTo() != null) ) { _nextHopCache = _context.netDb().lookupRouterInfoLocally(_config.getSendTo()); if (_nextHopCache == null) - _context.netDb().lookupRouterInfo(_config.getSendTo(), new Found(_context), null, 60*1000); + _context.netDb().lookupRouterInfo(_config.getSendTo(), new Found(_context), null, LONG_MAX_LOOKUP_TIME); } + // all createRateStat() in TunnelDispatcher } private class Found extends JobImpl { public Found(RouterContext ctx) { super(ctx); } public String getName() { return "Next hop info found"; } public void runJob() { - if (_nextHopCache == null) + if (_nextHopCache == null) { _nextHopCache = _context.netDb().lookupRouterInfoLocally(_config.getSendTo()); + // nothing for failure since fail job is null + _context.statManager().addRateData("tunnel.participantLookupSuccess", 1, 0); + } } } @@ -84,17 +106,19 @@ public class TunnelParticipant { ri = _context.netDb().lookupRouterInfoLocally(_config.getSendTo()); if (ri != null) { if (_log.shouldLog(Log.DEBUG)) - _log.debug("Send off to nextHop directly (" + _config.getSendTo().toBase64().substring(0,4) + _log.debug("Send off to nextHop directly (" + _config.getSendTo() + " for " + msg); send(_config, msg, ri); // see comments below //if (_config != null) // incrementThroughput(_config.getReceiveFrom()); } else { + // It should be rare to forget the router info for the next peer if (_log.shouldLog(Log.WARN)) - _log.warn("Lookup the nextHop (" + _config.getSendTo().toBase64().substring(0,4) + _log.warn("Lookup the nextHop (" + _config.getSendTo() + " for " + msg); - _context.netDb().lookupRouterInfo(_config.getSendTo(), new SendJob(_context, msg), new TimeoutJob(_context, msg), 10*1000); + _context.netDb().lookupRouterInfo(_config.getSendTo(), new SendJob(_context, msg), + new TimeoutJob(_context, msg), MAX_LOOKUP_TIME); } } else { _inboundEndpointProcessor.getConfig().incrementProcessedMessages(); @@ -139,6 +163,7 @@ public class TunnelParticipant { else return 0; } + public int getFailedCount() { if (_handler != null) return _handler.getFailedCount(); @@ -176,36 +201,46 @@ public class TunnelParticipant { } private class SendJob extends JobImpl { - private TunnelDataMessage _msg; + private final TunnelDataMessage _msg; + public SendJob(RouterContext ctx, TunnelDataMessage msg) { super(ctx); _msg = msg; } - public String getName() { return "forward a tunnel message"; } + + public String getName() { return "Participant send after lookup"; } + public void runJob() { if (_nextHopCache != null) { send(_config, _msg, _nextHopCache); } else { RouterInfo ri = _context.netDb().lookupRouterInfoLocally(_config.getSendTo()); + int stat; if (ri != null) { _nextHopCache = ri; send(_config, _msg, ri); + stat = 1; } else { - if (_log.shouldLog(Log.ERROR)) - _log.error("Lookup the nextHop (" + _config.getSendTo().toBase64().substring(0,4) + if (_log.shouldLog(Log.WARN)) + _log.warn("Lookup the nextHop (" + _config.getSendTo() + " failed! where do we go for " + _config + "? msg dropped: " + _msg); + stat = 0; } + _context.statManager().addRateData("tunnel.participantLookupSuccess", stat, 0); } } } private class TimeoutJob extends JobImpl { - private TunnelDataMessage _msg; + private final TunnelDataMessage _msg; + public TimeoutJob(RouterContext ctx, TunnelDataMessage msg) { super(ctx); _msg = msg; } - public String getName() { return "timeout looking for next hop info"; } + + public String getName() { return "Participant next hop lookup timeout"; } + public void runJob() { if (_nextHopCache != null) return; @@ -213,14 +248,15 @@ public class TunnelParticipant { RouterInfo ri = _context.netDb().lookupRouterInfoLocally(_config.getSendTo()); if (ri != null) { _nextHopCache = ri; - if (_log.shouldLog(Log.ERROR)) - _log.error("Lookup the nextHop (" + _config.getSendTo().toBase64().substring(0,4) + if (_log.shouldLog(Log.WARN)) + _log.warn("Lookup the nextHop (" + _config.getSendTo() + " failed, but we found it!! where do we go for " + _config + "? msg dropped: " + _msg); } else { - if (_log.shouldLog(Log.ERROR)) - _log.error("Lookup the nextHop (" + _config.getSendTo().toBase64().substring(0,4) + if (_log.shouldLog(Log.WARN)) + _log.warn("Lookup the nextHop (" + _config.getSendTo() + " failed! where do we go for " + _config + "? msg dropped: " + _msg); } + _context.statManager().addRateData("tunnel.participantLookupSuccess", 0, 0); } } diff --git a/router/java/src/net/i2p/router/tunnel/pool/BuildHandler.java b/router/java/src/net/i2p/router/tunnel/pool/BuildHandler.java index 247e45f6ca..83ce4712ac 100644 --- a/router/java/src/net/i2p/router/tunnel/pool/BuildHandler.java +++ b/router/java/src/net/i2p/router/tunnel/pool/BuildHandler.java @@ -90,6 +90,7 @@ class BuildHandler { _context.statManager().createRateStat("tunnel.receiveRejectionCritical", "How often we are rejected due to critical failure?", "Tunnels", new long[] { 10*60*1000l, 60*60*1000l, 24*60*60*1000l }); _context.statManager().createRateStat("tunnel.corruptBuildReply", "", "Tunnels", new long[] { 24*60*60*1000l }); + ctx.statManager().createRateStat("tunnel.buildLookupSuccess", "Was a deferred lookup successful?", "Tunnels", new long[] { 60*60*1000 }); _processor = new BuildMessageProcessor(ctx); _throttler = new ParticipatingThrottler(ctx); @@ -104,7 +105,7 @@ class BuildHandler { } private static final int MAX_HANDLE_AT_ONCE = 2; - private static final int NEXT_HOP_LOOKUP_TIMEOUT = 5*1000; + private static final int NEXT_HOP_LOOKUP_TIMEOUT = 15*1000; /** * Blocking call to handle a few of the pending inbound requests, returning how many @@ -197,7 +198,7 @@ class BuildHandler { _context.statManager().addRateData("tunnel.tierReject" + bwTier, 1, 0); } if (_log.shouldLog(Log.INFO)) - _log.info(msg.getUniqueId() + ": Peer " + peer.toBase64() + " replied with status " + howBad); + _log.info(msg.getUniqueId() + ": Peer " + peer + " replied with status " + howBad); if (howBad == 0) { // w3wt @@ -300,8 +301,9 @@ class BuildHandler { if (nextPeerInfo == null) { if (_log.shouldLog(Log.DEBUG)) _log.debug("Request " + state.msg.getUniqueId() + "/" + req.readReceiveTunnelId() + "/" + req.readNextTunnelId() - + " handled, looking for the next peer " + nextPeer.toBase64()); - _context.netDb().lookupRouterInfo(nextPeer, new HandleReq(_context, state, req, nextPeer), new TimeoutReq(_context, state, req, nextPeer), NEXT_HOP_LOOKUP_TIMEOUT); + + " handled, looking for the next peer " + nextPeer); + _context.netDb().lookupRouterInfo(nextPeer, new HandleReq(_context, state, req, nextPeer), + new TimeoutReq(_context, state, req, nextPeer), NEXT_HOP_LOOKUP_TIMEOUT); return -1; } else { long beforeHandle = System.currentTimeMillis(); @@ -309,7 +311,7 @@ class BuildHandler { long handleTime = System.currentTimeMillis() - beforeHandle; if (_log.shouldLog(Log.DEBUG)) _log.debug("Request " + state.msg.getUniqueId() + " handled and we know the next peer " - + nextPeer.toBase64() + " after " + handleTime + + nextPeer + " after " + handleTime + "/" + decryptTime + "/" + lookupTime + "/" + timeSinceReceived); return handleTime; } @@ -344,13 +346,17 @@ class BuildHandler { public String getName() { return "Deferred tunnel join processing"; } public void runJob() { if (_log.shouldLog(Log.DEBUG)) - _log.debug("Request " + _state.msg.getUniqueId() + " handled with a successful deferred lookup for the next peer " + _nextPeer.toBase64()); + _log.debug("Request " + _state.msg.getUniqueId() + " handled with a successful deferred lookup for the next peer " + _nextPeer); RouterInfo ri = getContext().netDb().lookupRouterInfoLocally(_nextPeer); - if (ri != null) + if (ri != null) { handleReq(ri, _state, _req, _nextPeer); - else if (_log.shouldLog(Log.WARN)) - _log.warn("Deferred successfully, but we couldnt find " + _nextPeer.toBase64() + "?"); + getContext().statManager().addRateData("tunnel.buildLookupSuccess", 1, 0); + } else { + if (_log.shouldLog(Log.WARN)) + _log.warn("Deferred successfully, but we couldnt find " + _nextPeer); + getContext().statManager().addRateData("tunnel.buildLookupSuccess", 0, 0); + } } } @@ -367,6 +373,7 @@ class BuildHandler { public String getName() { return "Timeout looking for next peer for tunnel join"; } public void runJob() { getContext().statManager().addRateData("tunnel.rejectTimeout", 1, 0); + getContext().statManager().addRateData("tunnel.buildLookupSuccess", 0, 0); // logging commented out so class can be static //if (_log.shouldLog(Log.WARN)) // _log.warn("Request " + _state.msg.getUniqueId() @@ -374,7 +381,7 @@ class BuildHandler { // ??? should we blame the peer here? getContext().profileManager().tunnelTimedOut(_nextPeer); getContext().messageHistory().tunnelRejected(_state.fromHash, new TunnelId(_req.readReceiveTunnelId()), _nextPeer, - "rejected because we couldn't find " + _nextPeer.toBase64() + ": " + + "rejected because we couldn't find " + _nextPeer + ": " + _state.msg.getUniqueId() + "/" + _req.readNextTunnelId()); } } @@ -524,8 +531,8 @@ class BuildHandler { if (_log.shouldLog(Log.DEBUG)) _log.debug("Responding to " + state.msg.getUniqueId() + "/" + ourId + " after " + recvDelay + "/" + proactiveDrops + " with " + response - + " from " + (state.fromHash != null ? state.fromHash.toBase64() : - state.from != null ? state.from.calculateHash().toBase64() : "tunnel")); + + " from " + (state.fromHash != null ? state.fromHash : + state.from != null ? state.from.calculateHash() : "tunnel")); HopConfig cfg = null; if (response == 0) { @@ -600,13 +607,13 @@ class BuildHandler { } if (_log.shouldLog(Log.DEBUG)) - _log.debug("Read slot " + ourSlot + " containing our hop @ " + _context.routerHash().toBase64() + _log.debug("Read slot " + ourSlot + " containing our hop @ " + _context.routerHash() + " accepted? " + response + " receiving on " + ourId + " sending to " + nextId - + " on " + nextPeer.toBase64() + + " on " + nextPeer + " inGW? " + isInGW + " outEnd? " + isOutEnd + " time difference " + (now-time) + " recvDelay " + recvDelay + " replyMessage " + req.readReplyMessageId() - + " replyKey " + req.readReplyKey().toBase64() + " replyIV " + Base64.encode(req.readReplyIV())); + + " replyKey " + req.readReplyKey() + " replyIV " + Base64.encode(req.readReplyIV())); // now actually send the response if (!isOutEnd) { @@ -672,7 +679,7 @@ class BuildHandler { PooledTunnelCreatorConfig cfg = _exec.removeFromBuilding(reqId); if (_log.shouldLog(Log.DEBUG)) _log.debug("Receive tunnel build message " + reqId + " from " - + (from != null ? from.calculateHash().toBase64() : fromHash != null ? fromHash.toBase64() : "tunnels") + + (from != null ? from.calculateHash() : fromHash != null ? fromHash : "tunnels") + ", found matching tunnel? " + (cfg != null)); if (cfg != null) { if (!cfg.isInbound()) { @@ -762,7 +769,7 @@ class BuildHandler { public Job createJob(I2NPMessage receivedMessage, RouterIdentity from, Hash fromHash) { if (_log.shouldLog(Log.DEBUG)) _log.debug("Receive tunnel build reply message " + receivedMessage.getUniqueId() + " from " - + (fromHash != null ? fromHash.toBase64() : from != null ? from.calculateHash().toBase64() : "a tunnel")); + + (fromHash != null ? fromHash : from != null ? from.calculateHash() : "a tunnel")); handleReply(new BuildReplyMessageState(receivedMessage)); return _buildReplyMessageHandlerJob; }