[#911] Report the replication connections which used to be dropped in silence

opendj-doc-generated-ref/src/main/asciidoc/admin-guide/chap-troubleshooting.adoc

@@ -781,10 +781,25 @@ That said, you may encounter errors. Replication uses its own error log file, `l
  are misconfigured: check that the certificate nickname configured in the
  crypto manager exists in the ads-truststore, and that every server of the
  topology trusts the certificates of the other servers. At most one such
- failure is logged as a warning every 5 minutes; the others go to the debug
- log, which is disabled by default (0 since the previous warning).
+ failure is logged as a warning every 5 minutes; the others are recorded with
+ the information severity, which the replication log publishes and the error
+ log does not (0 since the previous warning).
  The error was: Remote host closed connection during handshake
 ----
+A connection can also fail before it becomes a replication session for a reason which is not a failed handshake, and further messages report that:
+
+* `Replication server RS(1) accepted a connection from ... but could not start a replication session on it, and closed it` reports an inbound connection dropped for such a reason. An `ads-truststore` which was deleted, truncated, or made unreadable after the server started fails every inbound connection this way: the file is read again for each of them, so a server which is running is not a server whose trust store is still there.
+
+* `Replication server RS(1) could not accept a connection on ...` reports a failure of the listen socket itself, the process running out of file descriptors being the usual one. When such a failure repeats at once, the listen thread waits 100 ms before accepting again, so that it does not spin on it.
+
+* `Replication server RS(1) could not connect to replication server ... for domain ...` reports the outgoing half, which used to be visible only in the log of the peer, that is on the machine whose configuration is right. It is logged once for each outage, and the end of the outage is reported by one of two messages, so a replication server stopped for maintenance costs two lines rather than one every few seconds. `Replication server RS(1) connected to replication server ...` reports a peer which answered and completed the handshake, which is a replication session. `Replication server RS(1) reached replication server ... but the handshake with it did not complete` reports a peer which answered on its replication port while the handshake did not complete: the outage is over, and there is still nothing replicating over that connection. Where this server ended the handshake, whether it rejected the peer or the peer went away while the handshake was running, the reason is logged next to that message; where nothing is logged next to it, the handshake was ended by the peer, which may have logged no reason of its own either -- a shutdown under way, or a connection the two servers made to each other at the same time, of which one is dropped while the other one serves the domain. Two replication servers which share a server id are reported by the reason logged for the handshake, which is logged whether or not the outgoing message above accompanies it: that message follows an outage which was reported, and two servers which have been reachable since they started never opened one. A session established afterwards is reported in its turn. A session lost later is not reported by these messages: the loss is logged where the reader of that session ends, and the next of these comes when the peer can no longer be reached at all. A replication server which cannot be reached, or whose handshake does not complete, is left alone for a few passes of the connect thread before it is tried again, and it is left alone for every domain: the domain named is the one the failed attempt was for rather than the only one affected. The domain whose attempt failed is also the one retried, so for as long as the condition lasts the other domains of that peer are not dialled from this server again -- they are served by the connection the peer makes to this server, replication servers dialling each other both ways, and only where the peer is up to make it: a peer which is down serves none of its domains anyway.
+
+* On the directory server side, the reason each replication server could not be used is now logged for every one of them, before the `was unable to connect to any replication servers for domain` summary which names none: `Please check that there is a replication server listening at this address` for a refused connection, `timed out while connecting to replication server` for an unanswered one, and `encountered an unexpected error while connecting to replication server` followed by the cause for the rest, a rejected certificate included. Only the summary used to be logged when no replication server answered at all.
+
+The failed handshake above and the first of these are reported once for every connection which reaches the replication port, and the second once for every failed `accept()`, which on a process out of file descriptors is as often as the listen loop can turn. Each of the three is therefore logged as a warning at most once every five minutes, and each warning reports how many failures it stands for.
+
+The failures those warnings suppress are still recorded, with the `information` severity. `logs/replication` publishes that severity for replication messages, so the suppressed records are there rather than nowhere; `logs/errors` does not publish it. To have them in the error log as well, add `info`, which is the name that severity goes by in the configuration, to the `default-severity` property of the error log publisher. They do not go to the debug log.
+
 OpenDJ maintains historical information about changes in order to bring replicas up to date, and to resolve replication conflicts. To prevent historical information from growing without limit, OpenDJ purges historical information after a configurable delay (`replication-purge-delay`, default: 3 days). A replica can become irrevocably out of sync if you restore it from a backup archive older than the purge delay, or if you stop it for longer than the purge delay. If this happens to you, disable the replica, and then reinitialize it from a recent backup or from a server that is up to date.
 
 

opendj-server-legacy/src/main/java/org/opends/server/replication/protocol/ReplSessionSecurity.java

@@ -24,7 +24,6 @@
 import java.net.Socket;
 import java.util.SortedSet;
 import java.util.concurrent.TimeUnit;
-import java.util.concurrent.atomic.AtomicLong;
 
 import javax.net.ssl.SSLContext;
 import javax.net.ssl.SSLException;
@@ -35,6 +34,7 @@
 import org.forgerock.opendj.config.server.ConfigException;
 import org.opends.server.core.DirectoryServer;
 import org.opends.server.types.CryptoManager;
+import org.opends.server.util.FailureLogThrottle;
 
 /**
  * This class represents the security configuration for replication protocol
@@ -55,24 +55,18 @@ public final class ReplSessionSecurity
    * Minimum interval, in minutes, between two warnings about a failed SSL handshake
    * on the replication port. Every connection which is not a replication peer fails
    * the handshake, network probes included, so only the first failure of an interval
-   * is logged as a warning and the following ones are logged at debug level.
+   * is logged as a warning and the following ones are recorded with the information
+   * severity, which the replication log publishes and the error log does not.
    */
   private static final long HANDSHAKE_FAILURE_WARN_INTERVAL_MINUTES = 5;
 
   /** Package private for testing. */
   static final long HANDSHAKE_FAILURE_WARN_INTERVAL_NANOS =
       TimeUnit.MINUTES.toNanos(HANDSHAKE_FAILURE_WARN_INTERVAL_MINUTES);
 
-  /**
-   * Value of {@link System#nanoTime()} at which the last handshake failure was
-   * logged as a warning. It starts one interval in the past so that the first
-   * failure is warned about.
-   */
-  private final AtomicLong lastHandshakeFailureWarnNanos =
-      new AtomicLong(System.nanoTime() - HANDSHAKE_FAILURE_WARN_INTERVAL_NANOS);
-
-  /** Number of handshake failures logged at debug level since the last warning. */
-  private final AtomicLong suppressedHandshakeFailures = new AtomicLong();
+  /** Bounds how often a failed handshake is warned about. */
+  private final FailureLogThrottle handshakeFailures =
+      new FailureLogThrottle(HANDSHAKE_FAILURE_WARN_INTERVAL_MINUTES, TimeUnit.MINUTES);
 
   /**
    * Whether replication sessions use SSL encryption.
@@ -300,8 +294,9 @@ public Session createServerSession(final Socket socket,
   /**
    * Logs a failed SSL handshake on the replication port, as a warning for the
    * first failure of each {@link #HANDSHAKE_FAILURE_WARN_INTERVAL_MINUTES}
-   * interval and at debug level for the following ones. The warning reports how
-   * many failures were logged at debug level before it, so that a single line
+   * interval and with the information severity for the following ones, which the
+   * replication log publishes and the error log does not. The warning reports how
+   * many failures were recorded that way before it, so that a single line
    * cannot be mistaken for a single failed connection. That count looks backwards
    * only: the failures which follow the last warning of a burst are counted but
    * never reported, as nothing flushes the count when the failures stop.
@@ -330,28 +325,22 @@ private void logHandshakeFailure(final Socket socket, final SSLException e)
 
   /**
    * Records a handshake failure which happened at the provided time and tells how it
-   * must be logged, together with the number of failures logged at debug level since
-   * the previous warning.
+   * must be logged, together with the number of failures suppressed since the previous
+   * warning.
    * <p>
    * Package private for testing.
    *
    * @param nowNanos
    *          The value of {@link System#nanoTime()} at which the handshake failed.
    * @return A number greater than or equal to zero if this failure is to be logged as a
-   *         warning, which is then the number of failures logged at debug level since
-   *         the previous warning, or {@code -count - 1} if this failure is itself to be
-   *         logged at debug level, where {@code count} is the number of failures logged
-   *         at debug level since the previous warning, this one included.
+   *         warning, which is then the number of failures suppressed since the previous
+   *         warning, or {@code -count - 1} if this failure is itself to be suppressed,
+   *         where {@code count} is the number of failures suppressed since the previous
+   *         warning, this one included.
    */
   long recordHandshakeFailure(final long nowNanos)
   {
-    final long lastWarn = lastHandshakeFailureWarnNanos.get();
-    if (nowNanos - lastWarn >= HANDSHAKE_FAILURE_WARN_INTERVAL_NANOS
-        && lastHandshakeFailureWarnNanos.compareAndSet(lastWarn, nowNanos))
-    {
-      return suppressedHandshakeFailures.getAndSet(0);
-    }
-    return -suppressedHandshakeFailures.incrementAndGet() - 1;
+    return handshakeFailures.record(nowNanos);
   }
 
   /**