Skip to content

ChannelException when releasing external resources (Windows, Oracle JDK) #395

@suiryc

Description

@suiryc

On Windows with Oracle JDK, starting with netty 3.4.0 (3.3.1 is fine) I see strange issues in logs, generally along client connection timeouts.
After some testing I could reproduce it with this dummy client:

  • DiscardClientHandler.java
    import org.jboss.netty.channel.ChannelHandlerContext;
    import org.jboss.netty.channel.ExceptionEvent;
    import org.jboss.netty.channel.MessageEvent;
    import org.jboss.netty.channel.SimpleChannelHandler;
    
    

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class DiscardClientHandler extends SimpleChannelHandler {

private static Logger LOGGER = LoggerFactory.getLogger(DiscardClientHandler.class);

@Override
public void messageReceived(ChannelHandlerContext ctx, MessageEvent e) {
}

@Override
public void exceptionCaught(ChannelHandlerContext ctx, ExceptionEvent e) {
    LOGGER.error("Caught exception: " + e.getCause().getMessage(), e.getCause());
    e.getChannel().close();
}

}

  • Test.java
    import java.net.InetSocketAddress;
    import java.util.concurrent.Executors;
    
    

import org.jboss.netty.bootstrap.ClientBootstrap;
import org.jboss.netty.channel.Channel;
import org.jboss.netty.channel.ChannelFactory;
import org.jboss.netty.channel.ChannelFuture;
import org.jboss.netty.channel.ChannelPipeline;
import org.jboss.netty.channel.ChannelPipelineFactory;
import org.jboss.netty.channel.Channels;
import org.jboss.netty.channel.socket.nio.NioClientSocketChannelFactory;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Test {

private static Logger LOGGER = LoggerFactory.getLogger(Test.class);

public static void main(String[] args) {
    String host = "1.1.1.1";
    int port = 1234;
    int loop = 0;

    ChannelFactory factory = new NioClientSocketChannelFactory(
        Executors.newCachedThreadPool(),
        Executors.newCachedThreadPool()
    );

    ClientBootstrap bootstrap = new ClientBootstrap(factory);

    bootstrap.setPipelineFactory(new ChannelPipelineFactory() {
        public ChannelPipeline getPipeline() {
            return Channels.pipeline(new DiscardClientHandler());
        }
    });

    bootstrap.setOption("connectTimeoutMillis", new Integer(1000));

    for (loop = 1; loop <= 2; loop++) {
        ChannelFuture future = bootstrap.connect(new InetSocketAddress(host, port));
        future.awaitUninterruptibly();
        if (!future.isSuccess()) {
            LOGGER.error("Failed to connect: " + future.getCause().getMessage(), future.getCause());
        }
        else {
            Channel channel = future.getChannel();
            channel.close();
            channel.getCloseFuture().awaitUninterruptibly();
        }
    }

    factory.releaseExternalResources();
}

}

With netty 3.3.1, I catch (as expected) the connection timeout:

18:35:01.273 [main] ERROR Test - Failed to connect: connection timed out
java.net.ConnectException: connection timed out
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.processConnectTimeout(NioClientSocketPipelineSink.java:387) ~[netty-3.3.1.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.run(NioClientSocketPipelineSink.java:291) ~[netty-3.3.1.Final.jar:na]
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source) ~[na:1.6.0_32]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[na:1.6.0_32]
    at java.lang.Thread.run(Unknown Source) ~[na:1.6.0_32]
18:35:01.273 [New I/O client boss #1-1] ERROR DiscardClientHandler - Caught exception: connection timed out
java.net.ConnectException: connection timed out
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.processConnectTimeout(NioClientSocketPipelineSink.java:387) ~[netty-3.3.1.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.run(NioClientSocketPipelineSink.java:291) ~[netty-3.3.1.Final.jar:na]
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source) [na:1.6.0_32]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [na:1.6.0_32]
    at java.lang.Thread.run(Unknown Source) [na:1.6.0_32]

With netty 3.4.0 (up to current 3.5.0), I also see the following unexpected netty log:

12 juin 2012 18:36:04 org.jboss.netty.channel.DefaultChannelPipeline
ATTENTION: An exception was thrown by an exception handler.
org.jboss.netty.channel.ChannelException: Failed to create a selector.
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.start(AbstractNioWorker.java:163)
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.executeInIoThread(AbstractNioWorker.java:315)
    at org.jboss.netty.channel.socket.nio.NioWorker.executeInIoThread(NioWorker.java:35)
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.executeInIoThread(AbstractNioWorker.java:299)
    at org.jboss.netty.channel.socket.nio.NioWorker.executeInIoThread(NioWorker.java:35)
    at org.jboss.netty.channel.socket.nio.AbstractNioChannelSink.execute(AbstractNioChannelSink.java:34)
    at org.jboss.netty.channel.Channels.fireExceptionCaughtLater(Channels.java:504)
    at org.jboss.netty.channel.AbstractChannelSink.exceptionCaught(AbstractChannelSink.java:47)
    at org.jboss.netty.channel.Channels.close(Channels.java:821)
    at org.jboss.netty.channel.AbstractChannel.close(AbstractChannel.java:195)
    at org.jboss.netty.channel.ChannelFutureListener$2.operationComplete(ChannelFutureListener.java:52)
    at org.jboss.netty.channel.DefaultChannelFuture.notifyListener(DefaultChannelFuture.java:428)
    at org.jboss.netty.channel.DefaultChannelFuture.notifyListeners(DefaultChannelFuture.java:414)
    at org.jboss.netty.channel.DefaultChannelFuture.setFailure(DefaultChannelFuture.java:381)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.processConnectTimeout(NioClientSocketPipelineSink.java:394)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.run(NioClientSocketPipelineSink.java:289)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    at java.lang.Thread.run(Unknown Source)
Caused by: java.io.IOException: Unable to establish loopback connection
    at sun.nio.ch.PipeImpl$Initializer.run(Unknown Source)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.nio.ch.PipeImpl.(Unknown Source)
    at sun.nio.ch.SelectorProviderImpl.openPipe(Unknown Source)
    at java.nio.channels.Pipe.open(Unknown Source)
    at sun.nio.ch.WindowsSelectorImpl.(Unknown Source)
    at sun.nio.ch.WindowsSelectorProvider.openSelector(Unknown Source)
    at java.nio.channels.Selector.open(Unknown Source)
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.start(AbstractNioWorker.java:161)
    ... 18 more
Caused by: java.nio.channels.ClosedByInterruptException
    at java.nio.channels.spi.AbstractInterruptibleChannel.end(Unknown Source)
    at sun.nio.ch.SocketChannelImpl.connect(Unknown Source)
    at java.nio.channels.SocketChannel.open(Unknown Source)
    ... 27 more

This happens on Windows (Oracle JDK, 6 or 7), but not on Ubuntu (OpenJDK 6).
Also the log generally only appears after at least two connections attempts, and is triggered by releaseExternalResources on the channel factory.
I don't know if this is a side effect, but when this happen in a more complex netty configuration it seems a thread remains stuck somewhere because the JVM usually does not stop by itself after resource releasing.

Some search on the intermediate error "Unable to establish loopback connection" shows that it could have been related to a firewall issue. But I did not see anything particular in my firewall logs, and disabling it did not change the outcome.
Is this a bug, or is there something wrong with the way I use netty here ?

Metadata

Metadata

Assignees

Labels

No labels
No labels

Type

No type

Projects

No projects

Milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions