-
-
Notifications
You must be signed in to change notification settings - Fork 16.3k
ChannelException when releasing external resources (Windows, Oracle JDK) #395
Description
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 ?