ChannelException when releasing external resources (Windows, Oracle JDK) #395
Comments
|
I don't think it's your fault but there's a bug in JDK NIO implementation in Windows probably. It is basically saying that it failed to create a new Selector, which should not really happen. Without a selector, Netty can't do any I/O. |
|
I will close it for now.. |
|
+1 for this issue, I get the same stack in my client when I try to connect to my server and without a network connection (cable disconnected). No solution found for this? |
|
No real solution, but a few more observations. Waiting a bit before releasing the resources usually help preventing triggering the issue. Netty 3.5.5.Final stacktrace: As one can see in the stacktrace, at some point the timeout handling triggers the issue notification to listeners. That's when the So since the future is completed my code just goes on to release the So now maybe there is a specificity due to the Oracle JVM implementation on windows, but when releasing the So, is there a way in netty to wait for any pending action inside the channel pipeline (before releasing the resources) ? |
|
Tested with OpenJDK 6 under Ubuntu: waiting inside So it would look like the netty stacktrace under Windows is a side effect (Oracle implementation that does something that can be interrupted, unlike OpenJDK ?), and that the real issue is that the connection timeout actions can take place while the application has already been notified of the connection failure: hence a possible race condition with resource cleanup. |
ghost
assigned
|
Not quite yet it seems: From the source code lines in the staktrace, it looks like at the time of execution the |
|
@suiryc thanks for testing.. could you please grab the latest snapshot again and test ? |
|
Thanks for the fixes. The latest snapshot do not trigger the selector creation issue anymore. There is still an interrupt for code that may be Anyway I guess having such kind of code may not be what people should do in such a place (exception handling), so maybe someone will have to open a new ticket if he believes this behaviour should be changed. |
|
@suiryc thanks for the confirm. So we can finally close this and have the fix included. YAY! |
|
There is one issue left now.. We need to handle the case when a Channel will be registered on an AbstractNioWorker which was shutdown. Sent from my iPhone. Excuse any typos.... Am 03.09.2012 um 21:43 schrieb Julien Coloos notifications@github.com:
|
|
I had managed to avoid the stack (don't ask me how) but thanks @normanmaurer |
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:
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class DiscardClientHandler extends SimpleChannelHandler {
}
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 {
}
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 moreThis 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 ?
The text was updated successfully, but these errors were encountered: