i2psnark: Don't mark torrent BAD on I2CP errors (ticket #2725)

Logging:
 - Log to wrapper log after log manager shutdown (ticket #2725)
 - sync methods
Router:
 - Allow clients more time to get disconnect messages at shutdown (ticket #2725)
 - Don't delete router context at shutdown, to prevent a late
   creation of a new app context (ticket #2725)
 - Don't try to delete ping file on Android
javadocs

apps/i2psnark/java/src/org/klomp/snark/Snark.java

@@ -304,6 +304,7 @@ public class Snark
    * Will not start itself. Caller must call startTorrent() if desired.
    *
    * @throws RuntimeException via fatal()
+   * @throws RouterException via fatalRouter()
    */
   public Snark(I2PSnarkUtil util, String torrent, String ip, int user_port,
         StorageListener slistener, CoordinatorListener clistener,
@@ -321,6 +322,7 @@ public class Snark
    *
    * @param baseFile if null, use rootDir/torrentName; if non-null, use it instead
    * @throws RuntimeException via fatal()
+   * @throws RouterException via fatalRouter()
    * @since 0.9.11
    */
   public Snark(I2PSnarkUtil util, String torrent, String ip, int user_port,
@@ -399,7 +401,7 @@ public class Snark
             fatal("'" + torrent + "' exists,"
                   + " but is not a valid torrent metainfo file."
                   + System.getProperty("line.separator"), ioe);
-                 else
+          else
             fatal("I2PSnark does not support creating and tracking a torrent at the moment");
         /*
             {
@@ -424,7 +426,7 @@ public class Snark
         else
           fatal("Cannot open '" + torrent + "'", ioe);
       } catch (OutOfMemoryError oom) {
-          fatal("ERROR - Out of memory, cannot create torrent " + torrent + ": " + oom.getMessage());
+          fatalRouter("ERROR - Out of memory, cannot create torrent " + torrent + ": " + oom.getMessage(), oom);
       } finally {
           if (in != null)
               try { in.close(); } catch (IOException ioe) {}
@@ -496,6 +498,7 @@ public class Snark
    *
    *  @param ignored used to be autostart
    *  @throws RuntimeException via fatal()
+   *  @throws RouterException via fatalRouter()
    *  @since 0.8.4, removed in 0.9.36, restored in 0.9.45 with boolean param now ignored
    */
   protected Snark(I2PSnarkUtil util, String torrent, byte[] ih, String trackerURL,
@@ -513,6 +516,7 @@ public class Snark
    *  @param ih 20-byte info hash
    *  @param trackerURL may be null
    *  @throws RuntimeException via fatal()
+   *  @throws RouterException via fatalRouter()
    *  @since 0.8.4
    */
   public Snark(I2PSnarkUtil util, String torrent, byte[] ih, String trackerURL,
@@ -556,7 +560,12 @@ public class Snark
     rv[9] = snark;
     rv[10] = snark;
     rv[11] = snark;
-    I2PAppContext.getGlobalContext().random().nextBytes(rv, 12, 8);
+    try {
+        I2PAppContext.getGlobalContext().random().nextBytes(rv, 12, 8);
+    } catch (IllegalStateException ise) {
+        // random is shut down
+        throw new RouterException("Router shutdown", ise);
+    }
     return rv;
   }
 
@@ -565,6 +574,7 @@ public class Snark
    * Blocks if tunnel is not yet open.
    *
    * @throws RuntimeException via fatal()
+   * @throws RouterException via fatalRouter()
    */
   public synchronized void startTorrent() {
       if (!stopped)
@@ -580,11 +590,12 @@ public class Snark
 
   private void x_startTorrent() {
     boolean ok = _util.connect();
-    if (!ok) fatal("Unable to connect to I2P");
+    if (!ok)
+        fatalRouter("Unable to connect to I2P", null);
     if (coordinator == null) {
         I2PServerSocket serversocket = _util.getServerSocket();
         if (serversocket == null)
-            fatal("Unable to listen for I2P connections");
+            fatalRouter("Unable to listen for I2P connections", null);
         else {
             Destination d = serversocket.getManager().getSession().getMyDestination();
             if (_log.shouldLog(Log.INFO))
@@ -1217,21 +1228,18 @@ public class Snark
 
   /**
    * Aborts program abnormally.
+   * @throws RuntimeException always
    */
-  private void fatal(String s)
+  private void fatal(String s) throws RuntimeException {
-  {
     fatal(s, null);
   }
 
   /**
    * Aborts program abnormally.
+   * @throws RuntimeException always
    */
-  private void fatal(String s, Throwable t)
+  private void fatal(String s, Throwable t) throws RuntimeException {
-  {
     _log.error(s, t);
-    //System.err.println("snark: " + s + ((t == null) ? "" : (": " + t)));
-    //if (debug >= INFO && t != null)
-    //  t.printStackTrace();
     stopTorrent();
     if (t != null)
         s += ": " + t;
@@ -1240,6 +1248,29 @@ public class Snark
     throw new RuntimeException(s, t);
   }
 
+  /**
+   * Throws a unique exception class to blame the router that can be caught by SnarkManager
+   * @throws RouterException always
+   * @since 0.9.46
+   */
+  private void fatalRouter(String s, Throwable t) throws RouterException {
+    _log.error(s, t);
+    stopTorrent();
+    if (completeListener != null)
+        completeListener.fatal(this, s);
+    throw new RouterException(s, t);
+  }
+
+  /**
+   * A unique exception class to blame the router that can be caught by SnarkManager
+   * @since 0.9.46
+   */
+  static class RouterException extends RuntimeException {
+      public RouterException(String s) { super(s); }
+      public RouterException(String s, Throwable t) { super(s, t); }
+  }
+
+
   /** CoordinatorListener - this does nothing */
   public void peerChange(PeerCoordinator coordinator, Peer peer)
   {
@@ -1421,6 +1452,9 @@ public class Snark
     return totalUploaders > limit;
   }
 
+  /**
+   *  Is i2psnark as a whole over its limit?
+   */
   public boolean overUpBWLimit() {
     if (_peerCoordinatorSet == null)
       return false;
@@ -1435,6 +1469,9 @@ public class Snark
     return total > limit;
   }
 
+  /**
+   * Is a particular peer who has this recent download rate (in Bps) over our upstream bandwidth limit?
+   */
   public boolean overUpBWLimit(long total) {
     long limit = 1024l * _util.getMaxUpBW();
     return total > limit;

apps/i2psnark/java/src/org/klomp/snark/SnarkManager.java

@@ -1659,8 +1659,9 @@ public class SnarkManager implements CompleteListener, ClientApp {
                     disableTorrentFile(filename);
                     return false;
                 } catch (OutOfMemoryError oom) {
-                    addMessage(_t("ERROR - Out of memory, cannot create torrent from {0}", sfile.getName()) + ": " + oom.getLocalizedMessage());
+                    String s = _t("ERROR - Out of memory, cannot create torrent from {0}", sfile.getName()) + ": " + oom.getLocalizedMessage();
-                    return false;
+                    addMessage(s);
+                    throw new Snark.RouterException(s, oom);
                 } finally {
                     if (fis != null) try { fis.close(); } catch (IOException ioe) {}
                 }
@@ -2734,6 +2735,10 @@ public class SnarkManager implements CompleteListener, ClientApp {
                         disableTorrentFile(name);
                         rv = false;
                     }
+                } catch (Snark.RouterException e) {
+                    addMessage(_t("Error: Could not add the torrent {0}", name) + ": " + e);
+                    _log.error("Unable to add the torrent " + name, e);
+                    return false;
                 } catch (RuntimeException e) {
                     addMessage(_t("Error: Could not add the torrent {0}", name) + ": " + e);
                     _log.error("Unable to add the torrent " + name, e);

core/java/src/net/i2p/util/LogManager.java

@@ -98,6 +98,7 @@ public class LogManager implements Flushable {
     private final ConcurrentHashMap<Object, Log> _logs;
     /** who clears and writes our records */
     private LogWriter _writer;
+    private volatile boolean _shutdown;
 
     /** 
      * default log level for logs that aren't explicitly controlled 
@@ -151,6 +152,7 @@ public class LogManager implements Flushable {
         // In the router context, we have to rotate to a new log file at startup or the logs.jsp
         // page will display the old log.
         if (context.isRouterContext()) {
+            // FIXME don't start thread in constructor
             startLogWriter();
         } else {
             // Only in App Context.
@@ -284,6 +286,18 @@ public class LogManager implements Flushable {
      * massive logging load as a way of throttling logging threads.
      */
     void addRecord(LogRecord record) {
+        if (_shutdown && !SystemVersion.isAndroid()) {
+            // Log to wrapper log, for those very-hard-to-debug problems
+            // that happen after LogManager shutdown
+            if (_context.isRouterContext() ||
+                (_displayOnScreen && _onScreenLimit <= record.getPriority())) {
+                // wrapper logs already do time stamps
+                boolean showDate = !SystemVersion.hasWrapper();
+                System.out.print("(shutdown) " + LogRecordFormatter.formatRecord(this, record, showDate));
+            }
+            return;
+        }
+
         if ((!_context.isRouterContext()) && _writer == null)
             startLogWriter();
 
@@ -331,7 +345,7 @@ public class LogManager implements Flushable {
     /**
      * Do not log here, deadlock of LogWriter via rereadConfig().
      */
-    private void loadConfig() {
+    private synchronized void loadConfig() {
         File cfgFile = _locationFile;
         if (!cfgFile.exists()) {
             if (!_alreadyNoticedMissingConfig) {
@@ -659,7 +673,7 @@ public class LogManager implements Flushable {
     }
 
     /** @return success */
-    public boolean saveConfig() {
+    public synchronized boolean saveConfig() {
         Properties props = createConfig();
         try {
             DataHelper.storeProps(props, _locationFile);
@@ -775,7 +789,8 @@ public class LogManager implements Flushable {
         }
     }
 
-    public void shutdown() {
+    public synchronized void shutdown() {
+        _shutdown = true;
         if (_writer != null) {
             //_log.log(Log.WARN, "Shutting down logger");
             // try to prevent out-of-order logging at shutdown

history.txt

@@ -1,6 +1,16 @@
+2020-04-24 zzz
+ * i2psnark: Don't mark torrent BAD on I2CP errors (ticket #2725)
+ * Logging: Log to wrapper log after log manager shutdown (ticket #2725)
+ * Router:
+   - Allow more time to send disconnect messages at shutdown (ticket #2725)
+   - Don't delete router context at shutdown, to prevent a late
+     creation of a new app context (ticket #2725)
+
 2020-04-23 zzz
  * Ratchet: Fixes and parameter adjustments
+ * Router: Check for key certs in dests (proposal 145)
  * Streaming: Reduce TCB cache time
+ * SusiDNS: Fix typo that broke the add form
 
 2020-04-21 zzz
  * Router: Fix logging NPE (thx zlatinb)

router/java/src/net/i2p/router/Router.java

@@ -188,6 +188,9 @@ public class Router implements RouterClock.ClockShiftListener {
      *  You must call runRouter() after any constructor to start things up.
      *
      *  Config file name is "router.config" unless router.configLocation set in system properties.
+     *
+     *  See two-arg constructor for more information.
+     *
      *  @throws IllegalStateException since 0.9.19 if another router with this config is running
      */
     public Router() { this(null, null); }
@@ -199,6 +202,8 @@ public class Router implements RouterClock.ClockShiftListener {
      *
      *  Config file name is "router.config" unless router.configLocation set in envProps or system properties.
      *
+     *  See two-arg constructor for more information.
+     *
      *  @param envProps may be null
      *  @throws IllegalStateException since 0.9.19 if another router with this config is running
      */
@@ -209,6 +214,8 @@ public class Router implements RouterClock.ClockShiftListener {
      *  RouterContext is created but not initialized.
      *  You must call runRouter() after any constructor to start things up.
      *
+     *  See two-arg constructor for more information.
+     *
      *  @param configFilename may be null
      *  @throws IllegalStateException since 0.9.19 if another router with this config is running
      */
@@ -237,7 +244,7 @@ public class Router implements RouterClock.ClockShiftListener {
      *  in this constructor.
      *  If files in an existing config dir indicate that another router is already running
      *  with this directory, the constructor will delay for several seconds to be sure,
-     *  and then call System.exit(-1).
+     *  and then throw an IllegalStateException.
      *
      *  @param configFilename may be null
      *  @param envProps may be null
@@ -1476,7 +1483,23 @@ public class Router implements RouterClock.ClockShiftListener {
         }
 
         _context.removeShutdownTasks();
+
+        // All in-JVM clients should be gone by now,
+        // unless they are stuck waiting for tunnels.
+        // If we have any of those, or external clients,
+        // we will wait below for the I2CP disconnect messages to get to them.
+        boolean waitForClients = _killVMOnEnd && !_context.clientManager().listClients().isEmpty();
+        if (_log.shouldWarn())
+            _log.warn("Stopping ClientManager");
         try { _context.clientManager().shutdown(); } catch (Throwable t) { _log.error("Error shutting down the client manager", t); }
+        if (waitForClients) {
+            // Give time for the disconnect messages to get to them
+            // so they can shut down correctly before the JVM goes away
+            try { Thread.sleep(1500); } catch (InterruptedException ie) {}
+            if (_log.shouldWarn())
+                _log.warn("Done waiting for clients to disconnect");
+        }
+
         try { _context.namingService().shutdown(); } catch (Throwable t) { _log.error("Error shutting down the naming service", t); }
         try { _context.jobQueue().shutdown(); } catch (Throwable t) { _log.error("Error shutting down the job queue", t); }
         try { _context.tunnelManager().shutdown(); } catch (Throwable t) { _log.error("Error shutting down the tunnel manager", t); }
@@ -1541,9 +1564,16 @@ public class Router implements RouterClock.ClockShiftListener {
                 killKeys();
         }
 
-        File f = getPingFile();
+        if (!SystemVersion.isAndroid()) {
-        f.delete();
+            File f = getPingFile();
-        if (RouterContext.getContexts().isEmpty())
+            f.delete();
+        }
+
+        // Only do this on Android. On desktop, rogue threads
+        // may create a new I2PAppContext before the JVM stops
+        // if we delete this one.
+        //if (RouterContext.getContexts().isEmpty())
+        if (SystemVersion.isAndroid())
             RouterContext.killGlobalContext();
 
         // Since 0.8.8, for Android and the wrapper

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 = 12;
+    public final static long BUILD = 13;
 
     /** for example "-test" */
     public final static String EXTRA = "";