pool: fix ftp mover to provide better logging when failing to connect

The FTP mover suffers from a log-and-throw anti-pattern resulting in
problems being logged twice.

Another issue is the lack of information about which address(es)
could not be contacted.

This patch addresses these two failures: the resulting transfer
failure is logged once (rather than twice) and connection
errors now also include the IP address and port number.

Patch: https://rb.dcache.org/r/8356
Acked-by: Albert Rossi
Acked-by: Gerd Behrmann
Target: master
Request: 2.13
Request: 2.12
Request: 2.11
Request: 2.10

modules/cells/src/main/java/dmg/util/Exceptions.java

@@ -1,10 +1,18 @@
 package dmg.util;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+import java.lang.reflect.Constructor;
+import java.lang.reflect.InvocationTargetException;
+
 /**
  * Contains static utility methods for exceptions.
  */
 public class Exceptions
 {
+    private static final Logger LOG = LoggerFactory.getLogger(Exceptions.class);
+
     private Exceptions()
     {
     }
@@ -23,4 +31,58 @@ public static String getMessageWithCauses(Throwable t)
         }
         return msg.toString();
     }
+
+
+    /**
+     * Wrap the supplied Exception with an exception with message and
+     * cause.  This method attempts to wrap {@literal cause} with an exception of
+     * the same type.  If possible, the wrapped exception is created with
+     * {@literal cause} as the cause, otherwise the single-String constructor is
+     * used.  If neither constructor is available then the method will attempt
+     * to construct the wrapping exception from the super-class.
+     * This continues until either a wrapping exception is constructed or the
+     * enclosingType is reached.  If enclosingType does not support wrapping
+     * then {@literal cause} is returned and a warning is logged.
+     * <p />
+     * Note that the wrapped exception will contain only a message and possibly
+     * the {@literal cause} as the triggering exception; in particular, any
+     * additional information from {@literal cause} is not copied into the
+     * wrapped exception.
+     */
+    public static <T extends Exception> T wrap(String message, T cause, Class<T> enclosingType)
+    {
+        ReflectiveOperationException lastException = null;
+
+        Class type = cause.getClass();
+        while (enclosingType.isAssignableFrom(type)) {
+            try {
+                Constructor<? extends T> c = type.getConstructor(String.class, Throwable.class);
+                return c.newInstance(message, cause);
+            } catch (InvocationTargetException | IllegalAccessException |
+                    InstantiationException | NoSuchMethodException e) {
+                lastException = e;
+            }
+
+            try {
+                Constructor<? extends T> c = type.getConstructor(String.class);
+                return c.newInstance(message);
+            } catch (InvocationTargetException | IllegalAccessException |
+                    InstantiationException | NoSuchMethodException e) {
+                lastException = e;
+            }
+
+            type = type.getSuperclass();
+        }
+
+        if (lastException == null) {
+            /* This should never happen */
+            LOG.error("Failed to wrap exception with message {}: " +
+                    "exception {} not subclass of {}", message, cause.getClass().getCanonicalName(),
+                    enclosingType.getCanonicalName());
+        } else {
+            LOG.error("Failed to wrap exception with message {}: {}", message, lastException.getMessage());
+        }
+
+        return cause;
+    }
 }

modules/cells/src/test/java/dmg/util/ExceptionsTests.java

@@ -0,0 +1,122 @@
+package dmg.util;
+
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.Logger;
+import ch.qos.logback.classic.LoggerContext;
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.read.ListAppender;
+import org.ietf.jgss.GSSException;
+import org.junit.Before;
+import org.junit.Test;
+import org.slf4j.LoggerFactory;
+
+import java.io.IOException;
+import java.net.SocketException;
+import java.util.List;
+
+import static org.junit.Assert.assertThat;
+import static org.hamcrest.Matchers.*;
+
+/**
+ *  Tests for utility methods in Exceptions.
+ */
+public class ExceptionsTests
+{
+    private List<ILoggingEvent> _log;
+
+    @Before
+    public void setup()
+    {
+        LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory();
+        context.reset();
+
+        ListAppender<ILoggingEvent> appender = new ListAppender<>();
+        appender.setContext(context);
+        appender.setName("appender");
+        appender.start();
+        _log = appender.list;
+
+        Logger logger = context.getLogger(Logger.ROOT_LOGGER_NAME);
+        logger.addAppender(appender);
+        logger.setLevel(Level.WARN);
+    }
+
+    @Test
+    public void shouldWrapWithCauseInSimpleCase()
+    {
+        IOException cause = new IOException("Something went wrong");
+
+        IOException wrapped = Exceptions.wrap("Wrapped message", cause, IOException.class);
+
+        assertThat(wrapped, is(notNullValue()));
+        assertThat(wrapped.getMessage(), is(equalTo("Wrapped message")));
+        assertThat(wrapped.getCause(), is(cause));
+        assertThat(wrapped.getClass(), is(equalTo(IOException.class)));
+
+        assertThat(_log, is(empty()));
+    }
+
+    @Test
+    public void shouldWrapWithCauseInBroaderContext()
+    {
+        IOException cause = new IOException("Something went wrong");
+
+        Exception wrapped = Exceptions.wrap("Wrapped message", cause, Exception.class);
+
+        assertThat(wrapped, is(notNullValue()));
+        assertThat(wrapped.getMessage(), is(equalTo("Wrapped message")));
+        assertThat(wrapped.getCause(), is(cause));
+        assertThat(wrapped.getClass(), is(equalTo(IOException.class)));
+
+        assertThat(_log, is(empty()));
+    }
+
+    @Test
+    public void shouldWapWithMessageIfExceptionHasNoStringThrowableConstructor()
+    {
+        // Note: SocketException has no (String,Throwable) constructor, but has
+        // a (String) constructor.
+
+        SocketException cause = new SocketException("Something went wrong");
+
+        Exception wrapped = Exceptions.wrap("Wrapped message", cause, SocketException.class);
+
+        assertThat(wrapped, is(notNullValue()));
+        assertThat(wrapped.getMessage(), is(equalTo("Wrapped message")));
+        assertThat(wrapped.getCause(), is(nullValue()));
+        assertThat(wrapped.getClass(), is(equalTo(SocketException.class)));
+
+        assertThat(_log, is(empty()));
+    }
+
+    @Test
+    public void shouldUseBroaderExceptionIfCannotWrap()
+    {
+        // Note: GSSException has neither a (String,Throwable) constructor, nor
+        // a (String) constructor.
+        GSSException cause = new GSSException(GSSException.BAD_MECH);
+
+        Exception wrapped = Exceptions.wrap("Wrapped message", cause, Exception.class);
+
+        assertThat(wrapped, is(notNullValue()));
+        assertThat(wrapped.getMessage(), is(equalTo("Wrapped message")));
+        assertThat(wrapped.getCause(), is(cause));
+        assertThat(wrapped.getClass(), is(equalTo(Exception.class)));
+
+        assertThat(_log, is(empty()));
+    }
+
+    @Test
+    public void shouldUseCauseIfCannotWrap()
+    {
+        // Note: GSSException has neither a (String,Throwable) constructor, nor
+        // a (String) constructor.
+        GSSException cause = new GSSException(GSSException.BAD_MECH);
+
+        GSSException wrapped = Exceptions.wrap("Wrapped message", cause, GSSException.class);
+
+        assertThat(wrapped, is(cause));
+
+        assertThat(_log, is(not(empty())));
+    }
+}

modules/dcache-ftp/src/main/java/org/dcache/ftp/data/Mode.java

@@ -1,5 +1,7 @@
 package org.dcache.ftp.data;
 
+import com.google.common.collect.Iterables;
+import com.google.common.net.InetAddresses;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
@@ -18,6 +20,7 @@
 import java.util.HashSet;
 import java.util.Map;
 import java.util.Set;
+import java.util.stream.Collectors;
 
 import org.dcache.pool.repository.RepositoryChannel;
 
@@ -48,7 +51,7 @@ public abstract class Mode extends AbstractMultiplexerListener
     private final ByteBuffer        _buffer = ByteBuffer.allocate(8192);
 
     /** The address to connect to for outgoing connections. */
-    private   SocketAddress     _address;
+    private   InetSocketAddress     _address;
 
     /** The channel used for incomming connections. */
     private   ServerSocketChannel _channel;
@@ -305,12 +308,21 @@ protected void registerOutgoing(Multiplexer multiplexer)
                     connect(multiplexer, key);
                 }
             } catch (IOException e) {
+                SocketAddress remoteAddress = channel.getRemoteAddress();
+
                 // Any error is logged, but otherwise ignored.  As
                 // long as at least one connection succeeds, the
                 // transfer can be completed.
                 channel.close();
                 lastException = e;
-                LOGGER.warn(e.toString());
+                String displayAddress;
+                if (remoteAddress instanceof InetSocketAddress) {
+                    InetSocketAddress ia = (InetSocketAddress) remoteAddress;
+                    displayAddress = InetAddresses.toUriString(ia.getAddress()) + ":" + ia.getPort();
+                } else {
+                    displayAddress = remoteAddress.toString();
+                }
+                LOGGER.warn("Problem with {}: {}", displayAddress, e.getMessage());
                 _failed++;
 
                 if (allConnectionsEstablished()) {
@@ -324,6 +336,26 @@ protected void registerOutgoing(Multiplexer multiplexer)
         }
     }
 
+    public String getRemoteAddressDescription()
+    {
+        switch (_direction) {
+        case Outgoing:
+            if (_address == null) {
+                return null;
+            }
+            return InetAddresses.toUriString(_address.getAddress()) + ":" + _address.getPort();
+
+        case Incomming:
+            Set<String> addresses = _remoteAddresses.stream().map(a ->
+                    InetAddresses.toUriString(a.getAddress()) + ":" + a.getPort()).
+                    collect(Collectors.toSet());
+            return addresses.size() == 1 ? Iterables.getOnlyElement(addresses) :
+                    addresses.toString();
+        }
+
+        return null;
+    }
+
     /**
      * Register the mode for incomming connections.
      */

modules/dcache-ftp/src/main/java/org/dcache/pool/movers/GFtpProtocol_2_nio.java

@@ -5,9 +5,15 @@
 import org.slf4j.LoggerFactory;
 
 import java.io.IOException;
+import java.net.BindException;
+import java.net.ConnectException;
 import java.net.InetAddress;
 import java.net.InetSocketAddress;
+import java.net.NoRouteToHostException;
+import java.net.PortUnreachableException;
 import java.net.ProtocolFamily;
+import java.net.SocketException;
+import java.net.UnknownHostException;
 import java.nio.channels.ClosedByInterruptException;
 import java.nio.channels.ServerSocketChannel;
 import java.security.MessageDigest;
@@ -22,6 +28,7 @@
 import dmg.cells.nucleus.CellEndpoint;
 import dmg.cells.nucleus.CellMessage;
 import dmg.cells.nucleus.CellPath;
+import dmg.util.Exceptions;
 
 import org.dcache.ftp.data.BlockLog;
 import org.dcache.ftp.data.ConnectionMonitor;
@@ -313,11 +320,15 @@ public void transfer(RepositoryChannel fileChannel, Role role,
              */
             Thread.interrupted();
             throw new InterruptedException();
-        } catch (InterruptedException | FTPException e) {
-            throw e;
+        } catch (BindException | ConnectException | NoRouteToHostException |
+                PortUnreachableException | UnknownHostException e) {
+            throw Exceptions.wrap("Failed to connect " +
+                    mode.getRemoteAddressDescription() + ": " + e.getMessage(),
+                    e, IOException.class);
         } catch (IOException e) {
-            _log.error(e.toString());
-            throw e;
+            throw Exceptions.wrap("Problem while connected to " +
+                    mode.getRemoteAddressDescription() + ": " + e.getMessage(),
+                    e, IOException.class);
         } finally {
             _inProgress = false;