From 82ac0db333168292df4220bc0b0fb7e7d7a1f5c5 Mon Sep 17 00:00:00 2001 From: zzz Date: Sat, 15 Oct 2011 17:30:24 +0000 Subject: [PATCH] * BuildExecutor: Add tunnel.buildConfigTime stat * FloodfillMonitorJob: Log tweak (ticket #533) * I2CP: Improve error message (ticket #533) * JobQueue: - Log error when queue is out of order - Log tweaks * FloodfillPeerSelector: Fix stat NPE (tickets #534,535) * RouterThrottle: - Fix stat NPE (tickets #534,535) - Increase max tunnels and max delay again * OutNetMessagePool: Log tweak (ticket #533) * Router: - Add OOM help (ticket #533) - Prevent parallel shutdowns after multiple OOMs (tickets #534,535) --- .../src/net/i2p/client/I2PSessionImpl.java | 2 +- history.txt | 28 +++++++++++++++++++ router/java/src/net/i2p/router/JobQueue.java | 17 ++++++++--- .../src/net/i2p/router/OutNetMessagePool.java | 5 ++-- router/java/src/net/i2p/router/Router.java | 11 +++++++- .../net/i2p/router/RouterThrottleImpl.java | 8 ++++-- .../src/net/i2p/router/RouterVersion.java | 2 +- .../kademlia/FloodfillMonitorJob.java | 6 ++-- .../kademlia/FloodfillPeerSelector.java | 14 ++++++---- .../peermanager/ProfilePersistenceHelper.java | 4 +-- .../i2p/router/tunnel/pool/BuildExecutor.java | 4 +++ 11 files changed, 78 insertions(+), 23 deletions(-) diff --git a/core/java/src/net/i2p/client/I2PSessionImpl.java b/core/java/src/net/i2p/client/I2PSessionImpl.java index 5ccb2de254..f1d0b9ed92 100644 --- a/core/java/src/net/i2p/client/I2PSessionImpl.java +++ b/core/java/src/net/i2p/client/I2PSessionImpl.java @@ -395,7 +395,7 @@ abstract class I2PSessionImpl implements I2PSession, I2CPMessageReader.I2CPMessa _producer.disconnect(this); } catch (I2PSessionException ipe) {} closeSocket(); - throw new IOException("No tunnels built after waiting 5 minutes... are there network problems?"); + throw new IOException("No tunnels built after waiting 5 minutes. Your network connection may be down, or there is severe network congestion."); } synchronized (_leaseSetWait) { try { diff --git a/history.txt b/history.txt index 7784c29992..9803de362d 100644 --- a/history.txt +++ b/history.txt @@ -1,3 +1,31 @@ +* 2011-10-15 zzz + * BuildExecutor: Add tunnel.buildConfigTime stat + * configupdate.jsp: + - Fix setting to 'never' (ticket #523) + - Fix always saying trusted keys changed + - Parameterize tags + * EepGet: + - Add gunzip support (nonproxied only) + - Clean up progress formatting + * FloodfillMonitorJob: Log tweak (ticket #533) + * I2CP: Improve error message (ticket #533) + * JobQueue: + - Log error when queue is out of order + - Log tweaks + * FloodfillPeerSelector: Fix stat NPE (tickets #534,535) + * RouterThrottle: + - Fix stat NPE (tickets #534,535) + - Increase max tunnels and max delay again + * OutNetMessagePool: Log tweak (ticket #533) + * Router: + - Add OOM help (ticket #533) + - Prevent parallel shutdowns after multiple OOMs (tickets #534,535) + * Stats: Add API methods for zero duration + * SSLEepGet: + - Add gunzip support + - Increase buffer size + * SSU: Fix concurrency errors (ticket #536) + * 2011-10-13 kytv * Updated translations from Transifex - Swedish: debconf and i2psnark diff --git a/router/java/src/net/i2p/router/JobQueue.java b/router/java/src/net/i2p/router/JobQueue.java index 6d3ba6fcb3..53ebec2da1 100644 --- a/router/java/src/net/i2p/router/JobQueue.java +++ b/router/java/src/net/i2p/router/JobQueue.java @@ -172,7 +172,9 @@ public class JobQueue { // alreadyExists = true; // Always remove and re-add, since it needs to be // re-sorted in the TreeSet. - _timedJobs.remove(job); + boolean removed = _timedJobs.remove(job); + if (removed && _log.shouldLog(Log.WARN)) + _log.warn("Rescheduling job: " + job); } if ((!alreadyExists) && shouldDrop(job, numReady)) { @@ -197,9 +199,8 @@ public class JobQueue { _context.statManager().addRateData("jobQueue.readyJobs", numReady, 0); if (dropped) { - _context.statManager().addRateData("jobQueue.droppedJobs", 1, 1); - if (_log.shouldLog(Log.ERROR)) - _log.error("Dropping job due to overload! # ready jobs: " + _context.statManager().addRateData("jobQueue.droppedJobs", 1, 0); + _log.logAlways(Log.WARN, "Dropping job due to overload! # ready jobs: " + numReady + ": job = " + job); } } @@ -461,10 +462,18 @@ public class JobQueue { long timeToWait = -1; try { synchronized (_jobLock) { + Job lastJob = null; + long lastTime = Long.MIN_VALUE; for (Iterator iter = _timedJobs.iterator(); iter.hasNext(); ) { Job j = iter.next(); // find jobs due to start before now long timeLeft = j.getTiming().getStartAfter() - now; + if (lastJob != null && lastTime > j.getTiming().getStartAfter()) { + _log.error("Job " + lastJob + " out of order with job " + j + + " difference of " + DataHelper.formatDuration(lastTime - j.getTiming().getStartAfter())); + } + lastJob = j; + lastTime = lastJob.getTiming().getStartAfter(); if (timeLeft <= 0) { if (j instanceof JobImpl) ((JobImpl)j).madeReady(); diff --git a/router/java/src/net/i2p/router/OutNetMessagePool.java b/router/java/src/net/i2p/router/OutNetMessagePool.java index 6558a9b3ec..11a8da8102 100644 --- a/router/java/src/net/i2p/router/OutNetMessagePool.java +++ b/router/java/src/net/i2p/router/OutNetMessagePool.java @@ -66,11 +66,12 @@ public class OutNetMessagePool { return false; } if (msg.getPriority() < 0) { - _log.warn("Priority less than 0? sounds like nonsense to me... " + msg, new Exception("Negative priority")); + _log.error("Priority less than 0? sounds like nonsense to me... " + msg, new Exception()); return false; } if (msg.getExpiration() <= _context.clock().now()) { - _log.error("Already expired! wtf: " + msg, new Exception("Expired message")); + if (_log.shouldLog(Log.WARN)) + _log.warn("Dropping expired outbound msg: " + msg, new Exception()); return false; } return true; diff --git a/router/java/src/net/i2p/router/Router.java b/router/java/src/net/i2p/router/Router.java index 043f527bc8..e3a7619249 100644 --- a/router/java/src/net/i2p/router/Router.java +++ b/router/java/src/net/i2p/router/Router.java @@ -74,6 +74,8 @@ public class Router implements RouterClock.ClockShiftListener { private int _gracefulExitCode; private I2PThread.OOMEventListener _oomListener; private ShutdownHook _shutdownHook; + /** non-cancellable shutdown has begun */ + private volatile boolean _shutdownInProgress; private final I2PThread _gracefulShutdownDetector; private final RouterWatchdog _watchdog; private final Thread _watchdogThread; @@ -275,7 +277,10 @@ public class Router implements RouterClock.ClockShiftListener { _oomListener = new I2PThread.OOMEventListener() { public void outOfMemory(OutOfMemoryError oom) { clearCaches(); - _log.log(Log.CRIT, "Thread ran out of memory", oom); + _log.log(Log.CRIT, "Thread ran out of memory, shutting down I2P", oom); + // prevent multiple parallel shutdowns (when you OOM, you OOM a lot...) + if (_shutdownInProgress) + return; for (int i = 0; i < 5; i++) { // try this 5 times, in case it OOMs try { _log.log(Log.CRIT, "free mem: " + Runtime.getRuntime().freeMemory() + @@ -285,6 +290,7 @@ public class Router implements RouterClock.ClockShiftListener { // gobble } } + _log.log(Log.CRIT, "To prevent future shutdowns, increase wrapper.java.maxmemory in $I2P/wrapper.config"); shutdown(EXIT_OOM); } }; @@ -999,6 +1005,9 @@ public class Router implements RouterClock.ClockShiftListener { * Shutdown with no chance of cancellation */ public void shutdown(int exitCode) { + if (_shutdownInProgress) + return; + _shutdownInProgress = true; if (_shutdownHook != null) { try { Runtime.getRuntime().removeShutdownHook(_shutdownHook); diff --git a/router/java/src/net/i2p/router/RouterThrottleImpl.java b/router/java/src/net/i2p/router/RouterThrottleImpl.java index 2103e945c3..66fcee6732 100644 --- a/router/java/src/net/i2p/router/RouterThrottleImpl.java +++ b/router/java/src/net/i2p/router/RouterThrottleImpl.java @@ -31,14 +31,14 @@ class RouterThrottleImpl implements RouterThrottle { private static int THROTTLE_EVENT_LIMIT = 30; private static final String PROP_MAX_TUNNELS = "router.maxParticipatingTunnels"; - private static final int DEFAULT_MAX_TUNNELS = 3500; + private static final int DEFAULT_MAX_TUNNELS = 5000; private static final String PROP_DEFAULT_KBPS_THROTTLE = "router.defaultKBpsThrottle"; private static final String PROP_MAX_PROCESSINGTIME = "router.defaultProcessingTimeThrottle"; /** * TO BE FIXED - SEE COMMENTS BELOW */ - private static final int DEFAULT_MAX_PROCESSINGTIME = 1750; + private static final int DEFAULT_MAX_PROCESSINGTIME = 2250; /** tunnel acceptance */ public static final int TUNNEL_ACCEPT = 0; @@ -113,7 +113,9 @@ class RouterThrottleImpl implements RouterThrottle { // counterintuitively be more when there is low traffic) // Change the stat or pick a better stat. RateStat rs = _context.statManager().getRate("transport.sendProcessingTime"); - Rate r = rs.getRate(60*1000); + Rate r = null; + if (rs != null) + r = rs.getRate(60*1000); //Reject tunnels if the time to process messages and send them is too large. Too much time implies congestion. if(r != null) { diff --git a/router/java/src/net/i2p/router/RouterVersion.java b/router/java/src/net/i2p/router/RouterVersion.java index a411b00998..87e5bffca0 100644 --- a/router/java/src/net/i2p/router/RouterVersion.java +++ b/router/java/src/net/i2p/router/RouterVersion.java @@ -18,7 +18,7 @@ public class RouterVersion { /** deprecated */ public final static String ID = "Monotone"; public final static String VERSION = CoreVersion.VERSION; - public final static long BUILD = 0; + public final static long BUILD = 1; /** for example "-test" */ public final static String EXTRA = ""; diff --git a/router/java/src/net/i2p/router/networkdb/kademlia/FloodfillMonitorJob.java b/router/java/src/net/i2p/router/networkdb/kademlia/FloodfillMonitorJob.java index c2c2da2bf4..5c719d76ca 100644 --- a/router/java/src/net/i2p/router/networkdb/kademlia/FloodfillMonitorJob.java +++ b/router/java/src/net/i2p/router/networkdb/kademlia/FloodfillMonitorJob.java @@ -144,8 +144,7 @@ class FloodfillMonitorJob extends JobImpl { if (good < MIN_FF && happy) { if (!wasFF) { _lastChanged = now; - if (_log.shouldLog(Log.ERROR)) - _log.error("Only " + good + " ff peers and we want " + MIN_FF + " so we are becoming floodfill"); + _log.logAlways(Log.INFO, "Only " + good + " ff peers and we want " + MIN_FF + " so we are becoming floodfill"); } return true; } @@ -154,8 +153,7 @@ class FloodfillMonitorJob extends JobImpl { if (good > MAX_FF || (good > MIN_FF && !happy)) { if (wasFF) { _lastChanged = now; - if (_log.shouldLog(Log.ERROR)) - _log.error("Have " + good + " ff peers and we need only " + MIN_FF + " to " + MAX_FF + + _log.logAlways(Log.INFO, "Have " + good + " ff peers and we need only " + MIN_FF + " to " + MAX_FF + " so we are disabling floodfill; reachable? " + happy); } return false; diff --git a/router/java/src/net/i2p/router/networkdb/kademlia/FloodfillPeerSelector.java b/router/java/src/net/i2p/router/networkdb/kademlia/FloodfillPeerSelector.java index 2312049d64..f2cc42656b 100644 --- a/router/java/src/net/i2p/router/networkdb/kademlia/FloodfillPeerSelector.java +++ b/router/java/src/net/i2p/router/networkdb/kademlia/FloodfillPeerSelector.java @@ -193,12 +193,16 @@ class FloodfillPeerSelector extends PeerSelector { int found = 0; long now = _context.clock().now(); - double maxFailRate; + double maxFailRate = 100; if (_context.router().getUptime() > 60*60*1000) { - double currentFailRate = _context.statManager().getRate("peer.failedLookupRate").getRate(60*60*1000).getAverageValue(); - maxFailRate = Math.max(0.20d, 1.5d * currentFailRate); - } else { - maxFailRate = 100d; // disable + RateStat rs = _context.statManager().getRate("peer.failedLookupRate"); + if (rs != null) { + Rate r = rs.getRate(60*60*1000); + if (r != null) { + double currentFailRate = r.getAverageValue(); + maxFailRate = Math.max(0.20d, 1.5d * currentFailRate); + } + } } // 8 == FNDF.MAX_TO_FLOOD + 1 diff --git a/router/java/src/net/i2p/router/peermanager/ProfilePersistenceHelper.java b/router/java/src/net/i2p/router/peermanager/ProfilePersistenceHelper.java index d299c29194..3cce57c47d 100644 --- a/router/java/src/net/i2p/router/peermanager/ProfilePersistenceHelper.java +++ b/router/java/src/net/i2p/router/peermanager/ProfilePersistenceHelper.java @@ -216,8 +216,8 @@ class ProfilePersistenceHelper { long lastSentToSuccessfully = getLong(props, "lastSentToSuccessfully"); if (isExpired(lastSentToSuccessfully)) { - if (_log.shouldLog(Log.WARN)) - _log.warn("Dropping old profile for " + file.getName() + + if (_log.shouldLog(Log.INFO)) + _log.info("Dropping old profile " + file.getName() + ", since we haven't heard from them in a long time"); file.delete(); return null; diff --git a/router/java/src/net/i2p/router/tunnel/pool/BuildExecutor.java b/router/java/src/net/i2p/router/tunnel/pool/BuildExecutor.java index 6642ecaafb..4a084b814d 100644 --- a/router/java/src/net/i2p/router/tunnel/pool/BuildExecutor.java +++ b/router/java/src/net/i2p/router/tunnel/pool/BuildExecutor.java @@ -61,6 +61,7 @@ class BuildExecutor implements Runnable { _context.statManager().createRequiredRateStat("tunnel.buildExploratoryReject", "Response time for rejection (ms)", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); _context.statManager().createRequiredRateStat("tunnel.buildClientReject", "Response time for rejection (ms)", "Tunnels", new long[] { 10*60*1000, 60*60*1000 }); _context.statManager().createRequiredRateStat("tunnel.buildRequestTime", "Time to build a tunnel request (ms)", "Tunnels", new long[] { 60*1000, 10*60*1000 }); + _context.statManager().createRateStat("tunnel.buildConfigTime", "Time to build a tunnel request (ms)", "Tunnels", new long[] { 60*1000, 10*60*1000 }); _context.statManager().createRateStat("tunnel.buildRequestZeroHopTime", "How long it takes to build a zero hop tunnel", "Tunnels", new long[] { 60*1000, 10*60*1000 }); _context.statManager().createRateStat("tunnel.pendingRemaining", "How many inbound requests are pending after a pass (period is how long the pass takes)?", "Tunnels", new long[] { 60*1000, 10*60*1000 }); _context.statManager().createRateStat("tunnel.buildFailFirstHop", "How often we fail to build a OB tunnel because we can't contact the first hop", "Tunnels", new long[] { 60*1000, 10*60*1000 }); @@ -327,6 +328,7 @@ class BuildExecutor implements Runnable { TunnelPool pool = wanted.remove(0); //if (pool.countWantedTunnels() <= 0) // continue; + long bef = System.currentTimeMillis(); PooledTunnelCreatorConfig cfg = pool.configureNewTunnel(); if (cfg != null) { // 0hops are taken care of above, these are nonstandard 0hops @@ -337,6 +339,8 @@ class BuildExecutor implements Runnable { pool.buildComplete(cfg); continue; } + long pTime = System.currentTimeMillis() - bef; + _context.statManager().addRateData("tunnel.buildConfigTime", pTime, 0); if (_log.shouldLog(Log.DEBUG)) _log.debug("Configuring new tunnel " + i + " for " + pool + ": " + cfg); buildTunnel(pool, cfg);