Spring Integration DSL Tcp: How to prevent excessive logging of Connection refused on the client side

Question

I made both client and server able to wait for each other to connect, so they can be started independently in any order. The solution described here does exactly that, out of the box, BUT client side keeps printing massive stack traces into our logs, with java.net.ConnectException: Connection refused: connect, followed by 46 lines long stack trace, until server is up and connection happens. This is not ideal.

My question is: how to apply my custom logic to fine tune what to log and when.

What I find so far is that logs are printed by org.springframework.integration.handler.LoggingHandler. This acts as sort of error channel and errors are always dispatched there. I cannot find where is this one set so I can, for example, replace it with my own implementation. I managed to configure my own default error channel, but that channel was added alongside the preconfigured LoggingHandler channel, not replacing it.

The other approach could be to set much longer timeout when first message is send. I am struggling with that too. I tried to set it on outboundGateway, as .handle(Tcp.outboundGateway(clientConnectionFactory).remoteTimeout(1_000_000L)) but that didn't have any effect.

Espinosa Espinosa · Accepted Answer · 2019-03-19T03:14:40

OK, Solved.

The problem was not really in LoggingHandler or any error channel, but that org.springframework.integration.ip.tcp.connection.TcpNetClientConnectionFactory.createSocket() throws exception if server is not immediately ready, and TcpOutboundGateway then logs this exception it an old fashioned way; and only then is the error dispatched to errorChannel where it can be reacted on; and the default SI reaction is to print it again :) That is what I initially didn't notice, the exception is logged twice. The second log can be prevented by using custom error message handler but not the first one.

The TcpNetClientConnectionFactory.createSocket() call default Java's createSocket() and there is not option to set timeout. If the recipient is not ready, the method call fails nearly immediately. See JDK's enhancement request JDK-4414843.

Possible solution is to override TcpNetClientConnectionFactory.createSocket() to repeat connection attempts to server until it's successful.

WaitingTcpNetClientConnectionFactory

public class WaitingTcpNetClientConnectionFactory extends TcpNetClientConnectionFactory {
    private final SocketConnectionListener socketConnectionListener;
    private final int waitBetweenAttemptsInMs;
    private final Logger log = LogManager.getLogger();

    public WaitingTcpNetClientConnectionFactory(
            String host, int port, 
            int waitBetweenAttemptsInMs, 
            SocketConnectionListener socketConnectionListener) {
        super(host, port);
        this.waitBetweenAttemptsInMs = waitBetweenAttemptsInMs;
        this.socketConnectionListener = socketConnectionListener;
    }

    @Override
    protected Socket createSocket(String host, int port) throws IOException {
        Socket socket = null;
        while (socket == null) {
            try {
                socket = super.createSocket(host, port);
                socketConnectionListener.onConnectionOpen();
            } catch (ConnectException ce) {
                socketConnectionListener.onConnectionFailure();
                log.warn("server " + host + ":" + port + " is not ready yet ..waiting");
                try {
                    Thread.sleep(waitBetweenAttemptsInMs);
                } catch (InterruptedException ie) {
                    Thread.currentThread().interrupt();
                    throw new IOException("interrupted while wating between connection attempts", ie);
                }
            }
        }
        return socket;
    }
}

As an extra bonus I also sets success or failure to provided SocketConnectionListener, my very own custom interface, so other parts of application can synchronise with it; for example wait with streaming until server/peer node is ready.

Use WaitingTcpNetClientConnectionFactory same way as TcpNetClientConnectionFactory.

HeartbeatClientConfig (only relevant bit):

@Bean
public TcpNetClientConnectionFactory clientConnectionFactory(
        ConnectionStatus connectionStatus) {
    TcpNetClientConnectionFactory connectionFactory = new WaitingTcpNetClientConnectionFactory("localhost", 7777, 2000, connectionStatus);
    connectionFactory.setSerializer(new ByteArrayLengthHeaderSerializer());
    connectionFactory.setDeserializer(new ByteArrayLengthHeaderSerializer());
    return connectionFactory;
}

Now it just prints:

INFO [           main] o.b.e.d.s.h.client.HeartbeatClientRun    : Started HeartbeatClientRun in 1.042 seconds (JVM running for 1.44)
WARN [ask-scheduler-1] h.c.WaitingTcpNetClientConnectionFactory : server localhost:7777 is not ready yet ..waiting
WARN [ask-scheduler-1] h.c.WaitingTcpNetClientConnectionFactory : server localhost:7777 is not ready yet ..waiting
WARN [ask-scheduler-1] h.c.WaitingTcpNetClientConnectionFactory : server localhost:7777 is not ready yet ..waiting
WARN [ask-scheduler-1] h.c.WaitingTcpNetClientConnectionFactory : server localhost:7777 is not ready yet ..waiting

As usual, full project sources are available on my git, here is the relevant commit.

Spring Integration DSL Tcp: How to prevent excessive logging of Connection refused on the client side

1 Answers