[오류처리] Ning + Jetty 조합에서 Unable to establish loopback connection 오류 발생할 때

<div class="markdown-body"> <br /> <h3 id="발생-환경"> 발생 환경</h3> <br /> 현재 프로젝트에서 Dropwizard를 적용하고 있는데, Mesos와 연계할 부분이 생겨서 Mesos Client를 구성하고 Ning을 사용해서 비동기 Http 클라이언트를 구성하였다. 그런데 디버그 모드일 때는 상관이 없지만 (아마도 처리가 되는 시간적인 부분이 있는 듯 하다) 실행에서 <code>java.io.IOException: Unable to establish loopback connection</code> 오류가 발생하는 것을 확인하였다.<br /> <br /> <h3 id="오류-메시지"> 오류 메시지</h3> <br /> <blockquote> 4047 ERROR 2015-02-26 14:01:13 [main] com.ning.http.client.AsyncHttpClient[loadDefaultProvider:561] -Unable to instantiate provider com.ning.http.client.providers.netty.NettyAsyncHttpProvider. Trying other providers. <br /> 4053 ERROR 2015-02-26 14:01:13 [main] com.ning.http.client.AsyncHttpClient[loadDefaultProvider:564] -org.jboss.netty.channel.ChannelException: Failed to create a selector. <br /> org.jboss.netty.channel.ChannelException: Failed to create a selector. <br /> at org.jboss.netty.channel.socket.nio.AbstractNioSelector.openSelector(AbstractNioSelector.java:343) ~[netty-3.9.2.Final.jar:na] <br /> at org.jboss.netty.channel.socket.nio.AbstractNioSelector.(AbstractNioSelector.java:100) ~[netty-3.9.2.Final.jar:na] <br /> at org.jboss.netty.channel.socket.nio.AbstractNioWorker.(AbstractNioWorker.java:52) ~[netty-3.9.2.Final.jar:na] <br /> at org.jboss.netty.channel.socket.nio.NioWorker.(NioWorker.java:45) ~[netty-3.9.2.Final.jar:na] <br /> at org.jboss.netty.channel.socket.nio.NioWorkerPool.createWorker(NioWorkerPool.java:45) ~[netty-3.9.2.Final.jar:na] <br /> at org.jboss.netty.channel.socket.nio.NioWorkerPool.createWorker(NioWorkerPool.java:28) ~[netty-3.9.2.Final.jar:na] <br /> at org.jboss.netty.channel.socket.nio.AbstractNioWorkerPool.newWorker(AbstractNioWorkerPool.java:143) ~[netty-3.9.2.Final.jar:na] <br /> at org.jboss.netty.channel.socket.nio.AbstractNioWorkerPool.init(AbstractNioWorkerPool.java:81) ~[netty-3.9.2.Final.jar:na] <br /> at org.jboss.netty.channel.socket.nio.NioWorkerPool.(NioWorkerPool.java:39) ~[netty-3.9.2.Final.jar:na] <br /> at org.jboss.netty.channel.socket.nio.NioWorkerPool.(NioWorkerPool.java:33) ~[netty-3.9.2.Final.jar:na] <br /> at org.jboss.netty.channel.socket.nio.NioClientSocketChannelFactory.(NioClientSocketChannelFactory.java:151) ~[netty-3.9.2.Final.jar:na] <br /> at org.jboss.netty.channel.socket.nio.NioClientSocketChannelFactory.(NioClientSocketChannelFactory.java:133) ~[netty-3.9.2.Final.jar:na] <br /> at com.ning.http.client.providers.netty.NettyAsyncHttpProvider.(NettyAsyncHttpProvider.java:261) ~[async-http-client-1.8.12.jar:na] <br /> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:1.7.0_67] <br /> at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) ~[na:1.7.0_67] <br /> at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.7.0_67] <br /> at java.lang.reflect.Constructor.newInstance(Constructor.java:526) ~[na:1.7.0_67] <br /> at com.ning.http.client.AsyncHttpClient.loadDefaultProvider(AsyncHttpClient.java:554) [async-http-client-1.8.12.jar:na] <br /> at com.ning.http.client.AsyncHttpClient.(AsyncHttpClient.java:187) [async-http-client-1.8.12.jar:na] <br /> at com.msfl.framework.web.NingAsyncHttpClient.(NingAsyncHttpClient.java:71) [classes/:na] <br /> at com.msfl.framework.web.NingHttpClient.(NingHttpClient.java:48) [classes/:na] <br /> at com.msfl.platform.mesos.client.McpMesosClientModule.configure(McpMesosClientModule.java:67) [MesosClient-0.0.1-SNAPSHOT.jar:na] <br /> at com.google.inject.AbstractModule.configure(AbstractModule.java:62) [guice-4.0-beta5.jar:na] <br /> at com.google.inject.spi.Elements<script id="MathJax-Element-4" type="math/tex">RecordingBinder.install(Elements.java:253) [guice-4.0-beta5.jar:na] at com.msfl.platform.mcp.service.McpServiceModule.configure(McpServiceModule.java:81) [classes/:na] at com.msfl.platform.mcp.service.McpServiceModule.configure(McpServiceModule.java:1) [classes/:na] at com.msfl.platform.mcp.guice.ConfigurationAwareModule.configure(ConfigurationAwareModule.java:60) [classes/:na] at com.google.inject.spi.Elements</script>RecordingBinder.install(Elements.java:253) [guice-4.0-beta5.jar:na] <br /> at com.google.inject.spi.Elements.getElements(Elements.java:108) [guice-4.0-beta5.jar:na] <br /> at com.google.inject.internal.InjectorShell<script id="MathJax-Element-5" type="math/tex">Builder.build(InjectorShell.java:135) [guice-4.0-beta5.jar:na] at com.google.inject.internal.InternalInjectorCreator.build(InternalInjectorCreator.java:104) [guice-4.0-beta5.jar:na] at com.google.inject.Guice.createInjector(Guice.java:96) [guice-4.0-beta5.jar:na] at com.msfl.platform.mcp.guice.GuiceBundle.run(GuiceBundle.java:137) [classes/:na] at com.msfl.platform.mcp.guice.GuiceBundle.run(GuiceBundle.java:1) [classes/:na] at io.dropwizard.setup.Bootstrap.run(Bootstrap.java:176) [dropwizard-core-0.7.1.jar:0.7.1] at io.dropwizard.cli.EnvironmentCommand.run(EnvironmentCommand.java:41) [dropwizard-core-0.7.1.jar:0.7.1] at io.dropwizard.cli.ConfiguredCommand.run(ConfiguredCommand.java:76) [dropwizard-core-0.7.1.jar:0.7.1] at io.dropwizard.cli.Cli.run(Cli.java:70) [dropwizard-core-0.7.1.jar:0.7.1] at io.dropwizard.Application.run(Application.java:72) [dropwizard-core-0.7.1.jar:0.7.1] at com.msfl.platform.mcp.service.McpService.main(McpService.java:182) [classes/:na] Caused by: java.io.IOException: Unable to establish loopback connection at sun.nio.ch.PipeImpl</script>Initializer.run(PipeImpl.java:125) ~[na:1.7.0_67] <br /> at sun.nio.ch.PipeImpl<script id="MathJax-Element-6" type="math/tex">Initializer.run(PipeImpl.java:69) ~[na:1.7.0_67] at java.security.AccessController.doPrivileged(Native Method) ~[na:1.7.0_67] at sun.nio.ch.PipeImpl.(PipeImpl.java:141) ~[na:1.7.0_67] at sun.nio.ch.SelectorProviderImpl.openPipe(SelectorProviderImpl.java:50) ~[na:1.7.0_67] at java.nio.channels.Pipe.open(Pipe.java:150) ~[na:1.7.0_67] at sun.nio.ch.WindowsSelectorImpl.(WindowsSelectorImpl.java:127) ~[na:1.7.0_67] at sun.nio.ch.WindowsSelectorProvider.openSelector(WindowsSelectorProvider.java:44) ~[na:1.7.0_67] at java.nio.channels.Selector.open(Selector.java:227) ~[na:1.7.0_67] at org.jboss.netty.channel.socket.nio.SelectorUtil.open(SelectorUtil.java:63) ~[netty-3.9.2.Final.jar:na] at org.jboss.netty.channel.socket.nio.AbstractNioSelector.openSelector(AbstractNioSelector.java:341) ~[netty-3.9.2.Final.jar:na] … 39 common frames omitted Caused by: java.net.ConnectException: Connection refused: connect at sun.nio.ch.Net.connect0(Native Method) ~[na:1.7.0_67] at sun.nio.ch.Net.connect(Net.java:465) ~[na:1.7.0_67] at sun.nio.ch.Net.connect(Net.java:457) ~[na:1.7.0_67] at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:670) ~[na:1.7.0_67] at java.nio.channels.SocketChannel.open(SocketChannel.java:184) ~[na:1.7.0_67] at sun.nio.ch.PipeImpl</script>Initializer.run(PipeImpl.java:97) ~[na:1.7.0_67] <br /> … 49 common frames omitted</blockquote> <br /> <h3 id="원인-유추"> 원인 유추</h3> <br /> 문제는 모듈 초기화 시점 (Google Guice 사용)에 AsyncHttpClient 를 생성하는 시점과 실제 생성된 객체를 사용하는 시점이 다르다는 점이고, 오류는 초기화 시점에 발생한다. 물론 그 이후에 실제 사용할 때는 별다른 문제가 없다. (이런 증상 때문에 시간적인 문제라고 유추하고 있다. ㅠㅠ)<br /> <br /> <h3 id="해결-방법"> 해결 방법</h3> <br /> 정확한 해결방법이라고 볼 수는 없지만 JVM이 시작할 때 IP version prefs를 처리할 때 IPv6를 사용하기 때문인 것으로 보인다. 즉 Loopback <br /> <br /> 연결을 처리하면서 IPv6를 먼저 처리하고 실패 후에 IPv4를 시도하는 것으로 보인다는 것이다. 따라서 이런 상황에서는 IPv4를 사용하도록 JVM 옵션을 설정하면 된다.<br /> <br /> <pre class="prettyprint"><code class="language-text hljs haml">-<span class="ruby"><span class="hljs-constant">Djava</span>.net.perferIPv4Stack=<span class="hljs-keyword">true</span></span></code></pre> <br /> 위의 옵션을 주고 실행을 하면 위에서 발생했던 오류는 해결이 된다. 위에서 언급한 발생 상황뿐만 아니라 아래와 같이 유사한 오류 메시지들이 발생하는 경우라면 적용해 보는 것이 좋다.<br /> <br /> <ul> <li>java.net.ConnectionException: Connection refused: connect 오류</li> <li>java.io.IOException: Unable to establish loopback connection 오류</li> </ul> <br /> 상기와 같이 오류의 원인이 두 가지로 나온다면 적용해서 해결될 가능성이 높다. (단, 실제 다른 이유 떄문일 수 있기 때문에 오류 메시지를 면밀하게 검토해봐야 한다)<br /> <br /> <blockquote> Written by Morris (MSFL)</blockquote> </div>

발생 환경

현재 프로젝트에서 Dropwizard를 적용하고 있는데, Mesos와 연계할 부분이 생겨서 Mesos Client를 구성하고 Ning을 사용해서 비동기 Http 클라이언트를 구성하였다. 그런데 디버그 모드일 때는 상관이 없지만 (아마도 처리가 되는 시간적인 부분이 있는 듯 하다) 실행에서 java.io.IOException: Unable to establish loopback connection 오류가 발생하는 것을 확인하였다.

오류 메시지

4047 ERROR 2015-02-26 14:01:13 [main] com.ning.http.client.AsyncHttpClient[loadDefaultProvider:561] -Unable to instantiate provider com.ning.http.client.providers.netty.NettyAsyncHttpProvider. Trying other providers.
4053 ERROR 2015-02-26 14:01:13 [main] com.ning.http.client.AsyncHttpClient[loadDefaultProvider:564] -org.jboss.netty.channel.ChannelException: Failed to create a selector.
org.jboss.netty.channel.ChannelException: Failed to create a selector.
at org.jboss.netty.channel.socket.nio.AbstractNioSelector.openSelector(AbstractNioSelector.java:343) ~[netty-3.9.2.Final.jar:na]
at org.jboss.netty.channel.socket.nio.AbstractNioSelector.(AbstractNioSelector.java:100) ~[netty-3.9.2.Final.jar:na]
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.(AbstractNioWorker.java:52) ~[netty-3.9.2.Final.jar:na]
at org.jboss.netty.channel.socket.nio.NioWorker.(NioWorker.java:45) ~[netty-3.9.2.Final.jar:na]
at org.jboss.netty.channel.socket.nio.NioWorkerPool.createWorker(NioWorkerPool.java:45) ~[netty-3.9.2.Final.jar:na]
at org.jboss.netty.channel.socket.nio.NioWorkerPool.createWorker(NioWorkerPool.java:28) ~[netty-3.9.2.Final.jar:na]
at org.jboss.netty.channel.socket.nio.AbstractNioWorkerPool.newWorker(AbstractNioWorkerPool.java:143) ~[netty-3.9.2.Final.jar:na]
at org.jboss.netty.channel.socket.nio.AbstractNioWorkerPool.init(AbstractNioWorkerPool.java:81) ~[netty-3.9.2.Final.jar:na]
at org.jboss.netty.channel.socket.nio.NioWorkerPool.(NioWorkerPool.java:39) ~[netty-3.9.2.Final.jar:na]
at org.jboss.netty.channel.socket.nio.NioWorkerPool.(NioWorkerPool.java:33) ~[netty-3.9.2.Final.jar:na]
at org.jboss.netty.channel.socket.nio.NioClientSocketChannelFactory.(NioClientSocketChannelFactory.java:151) ~[netty-3.9.2.Final.jar:na]
at org.jboss.netty.channel.socket.nio.NioClientSocketChannelFactory.(NioClientSocketChannelFactory.java:133) ~[netty-3.9.2.Final.jar:na]
at com.ning.http.client.providers.netty.NettyAsyncHttpProvider.(NettyAsyncHttpProvider.java:261) ~[async-http-client-1.8.12.jar:na]
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:1.7.0_67]
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) ~[na:1.7.0_67]
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.7.0_67]
at java.lang.reflect.Constructor.newInstance(Constructor.java:526) ~[na:1.7.0_67]
at com.ning.http.client.AsyncHttpClient.loadDefaultProvider(AsyncHttpClient.java:554) [async-http-client-1.8.12.jar:na]
at com.ning.http.client.AsyncHttpClient.(AsyncHttpClient.java:187) [async-http-client-1.8.12.jar:na]
at com.msfl.framework.web.NingAsyncHttpClient.(NingAsyncHttpClient.java:71) [classes/:na]
at com.msfl.framework.web.NingHttpClient.(NingHttpClient.java:48) [classes/:na]
at com.msfl.platform.mesos.client.McpMesosClientModule.configure(McpMesosClientModule.java:67) [MesosClient-0.0.1-SNAPSHOT.jar:na]
at com.google.inject.AbstractModule.configure(AbstractModule.java:62) [guice-4.0-beta5.jar:na]
at com.google.inject.spi.Elements$RecordingBinder.install(Elements.java:253) [guice-4.0-beta5.jar:na] at com.msfl.platform.mcp.service.McpServiceModule.configure(McpServiceModule.java:81) [classes/:na] at com.msfl.platform.mcp.service.McpServiceModule.configure(McpServiceModule.java:1) [classes/:na] at com.msfl.platform.mcp.guice.ConfigurationAwareModule.configure(ConfigurationAwareModule.java:60) [classes/:na] at com.google.inject.spi.Elements$RecordingBinder.install(Elements.java:253) [guice-4.0-beta5.jar:na]
at com.google.inject.spi.Elements.getElements(Elements.java:108) [guice-4.0-beta5.jar:na]
at com.google.inject.internal.InjectorShell$Builder.build(InjectorShell.java:135) [guice-4.0-beta5.jar:na] at com.google.inject.internal.InternalInjectorCreator.build(InternalInjectorCreator.java:104) [guice-4.0-beta5.jar:na] at com.google.inject.Guice.createInjector(Guice.java:96) [guice-4.0-beta5.jar:na] at com.msfl.platform.mcp.guice.GuiceBundle.run(GuiceBundle.java:137) [classes/:na] at com.msfl.platform.mcp.guice.GuiceBundle.run(GuiceBundle.java:1) [classes/:na] at io.dropwizard.setup.Bootstrap.run(Bootstrap.java:176) [dropwizard-core-0.7.1.jar:0.7.1] at io.dropwizard.cli.EnvironmentCommand.run(EnvironmentCommand.java:41) [dropwizard-core-0.7.1.jar:0.7.1] at io.dropwizard.cli.ConfiguredCommand.run(ConfiguredCommand.java:76) [dropwizard-core-0.7.1.jar:0.7.1] at io.dropwizard.cli.Cli.run(Cli.java:70) [dropwizard-core-0.7.1.jar:0.7.1] at io.dropwizard.Application.run(Application.java:72) [dropwizard-core-0.7.1.jar:0.7.1] at com.msfl.platform.mcp.service.McpService.main(McpService.java:182) [classes/:na] <p>Caused by: java.io.IOException: Unable to establish loopback connection<br> at sun.nio.ch.PipeImpl$Initializer.run(PipeImpl.java:125) ~[na:1.7.0_67]
at sun.nio.ch.PipeImpl$Initializer.run(PipeImpl.java:69) ~[na:1.7.0_67]<br> at java.security.AccessController.doPrivileged(Native Method) ~[na:1.7.0_67]<br> at sun.nio.ch.PipeImpl.(PipeImpl.java:141) ~[na:1.7.0_67]<br> at sun.nio.ch.SelectorProviderImpl.openPipe(SelectorProviderImpl.java:50) ~[na:1.7.0_67]<br> at java.nio.channels.Pipe.open(Pipe.java:150) ~[na:1.7.0_67]<br> at sun.nio.ch.WindowsSelectorImpl.(WindowsSelectorImpl.java:127) ~[na:1.7.0_67]<br> at sun.nio.ch.WindowsSelectorProvider.openSelector(WindowsSelectorProvider.java:44) ~[na:1.7.0_67]<br> at java.nio.channels.Selector.open(Selector.java:227) ~[na:1.7.0_67]<br> at org.jboss.netty.channel.socket.nio.SelectorUtil.open(SelectorUtil.java:63) ~[netty-3.9.2.Final.jar:na]<br> at org.jboss.netty.channel.socket.nio.AbstractNioSelector.openSelector(AbstractNioSelector.java:341) ~[netty-3.9.2.Final.jar:na]<br> … 39 common frames omitted</p> <p>Caused by: java.net.ConnectException: Connection refused: connect<br> at sun.nio.ch.Net.connect0(Native Method) ~[na:1.7.0_67]<br> at sun.nio.ch.Net.connect(Net.java:465) ~[na:1.7.0_67]<br> at sun.nio.ch.Net.connect(Net.java:457) ~[na:1.7.0_67]<br> at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:670) ~[na:1.7.0_67]<br> at java.nio.channels.SocketChannel.open(SocketChannel.java:184) ~[na:1.7.0_67]<br> at sun.nio.ch.PipeImpl$Initializer.run(PipeImpl.java:97) ~[na:1.7.0_67]
… 49 common frames omitted

원인 유추

문제는 모듈 초기화 시점 (Google Guice 사용)에 AsyncHttpClient 를 생성하는 시점과 실제 생성된 객체를 사용하는 시점이 다르다는 점이고, 오류는 초기화 시점에 발생한다. 물론 그 이후에 실제 사용할 때는 별다른 문제가 없다. (이런 증상 때문에 시간적인 문제라고 유추하고 있다. ㅠㅠ)

해결 방법

정확한 해결방법이라고 볼 수는 없지만 JVM이 시작할 때 IP version prefs를 처리할 때 IPv6를 사용하기 때문인 것으로 보인다. 즉 Loopback

연결을 처리하면서 IPv6를 먼저 처리하고 실패 후에 IPv4를 시도하는 것으로 보인다는 것이다. 따라서 이런 상황에서는 IPv4를 사용하도록 JVM 옵션을 설정하면 된다.

-Djava.net.perferIPv4Stack=true

위의 옵션을 주고 실행을 하면 위에서 발생했던 오류는 해결이 된다. 위에서 언급한 발생 상황뿐만 아니라 아래와 같이 유사한 오류 메시지들이 발생하는 경우라면 적용해 보는 것이 좋다.

• java.net.ConnectionException: Connection refused: connect 오류
• java.io.IOException: Unable to establish loopback connection 오류

상기와 같이 오류의 원인이 두 가지로 나온다면 적용해서 해결될 가능성이 높다. (단, 실제 다른 이유 떄문일 수 있기 때문에 오류 메시지를 면밀하게 검토해봐야 한다)

Written by Morris (MSFL)