2 Replies Latest reply on Feb 13, 2015 3:41 PM by shawkins

Netty error on closing Teiid connection

pranavk Feb 13, 2015 12:33 AM

Hi,

I'm getting a netty error when, after performing operations, I proceed to close the Teiid connection. I see that a point was raised on this in an earlier discussion on this forum, but it didn't point to any solution. Could someone please point me to why this could be occurring/to a solution for the same. Below is the error stack:

Thanks,

Pranav

INFO \| jvm 1	\| 2015/02/09 11:47:35 \| WARN [TRANSPORT] TEIID40113 Unhandled exception, aborting operation
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| java.io.IOException: An existing connection was forcibly closed by the remote host
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.SocketDispatcher.$$YJP$$write0(Native Method) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.SocketDispatcher.write0(SocketDispatcher.java) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:51) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.IOUtil.write(IOUtil.java:51) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:487) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.SocketSendBufferPool$UnpooledSendBuffer.transferTo(SocketSendBufferPool.java:203) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.AbstractNioWorker.write0(AbstractNioWorker.java:202) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.AbstractNioWorker.writeFromUserCode(AbstractNioWorker.java:147) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.handleAcceptedSocket(NioServerSocketPipelineSink.java:99) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.eventSunk(NioServerSocketPipelineSink.java:36) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.handler.stream.ChunkedWriteHandler.flush(ChunkedWriteHandler.java:280) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleDownstream(ChunkedWriteHandler.java:121) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.Channels.write(Channels.java:725) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.teiid.transport.ObjectEncoder.handleDownstream(ObjectEncoder.java:140) ~[teiid-runtime-8.9.0.Final.jar:8.9.0.Final]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.Channels.write(Channels.java:704) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.Channels.write(Channels.java:671) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.AbstractChannel.write(AbstractChannel.java:248) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.teiid.transport.SSLAwareChannelHandler$ObjectChannelImpl.write(SSLAwareChannelHandler.java:93) ~[teiid-runtime-8.9.0.Final.jar:8.9.0.Final]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.teiid.transport.SocketClientInstance.exceptionOccurred(SocketClientInstance.java:117) ~[teiid-runtime-8.9.0.Final.jar:8.9.0.Final]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.teiid.transport.SSLAwareChannelHandler.exceptionCaught(SSLAwareChannelHandler.java:200) ~[teiid-runtime-8.9.0.Final.jar:8.9.0.Final]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleUpstream(ChunkedWriteHandler.java:142) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.handler.codec.frame.FrameDecoder.exceptionCaught(FrameDecoder.java:377) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.Channels.fireExceptionCaught(Channels.java:525) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:74) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:109) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:328) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:90) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| WARN [TRANSPORT] TEIID40113 Unhandled exception, aborting operation
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| java.io.IOException: An existing connection was forcibly closed by the remote host
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.SocketDispatcher.$$YJP$$read0(Native Method) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.SocketDispatcher.read0(SocketDispatcher.java) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:43) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.IOUtil.read(IOUtil.java:192) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:379) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:64) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:109) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:328) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:90) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]

1. Re: Netty error on closing Teiid connection

shawkins Feb 13, 2015 7:57 AM (in response to pranavk)

Most versions of Netty don't give a good way to distinguish an exception related to a normal client disconnection from other exceptions. Even if the socket is effectively closed/unwritable it will notify listeners yet report isClosed=false. This means that somewhat expected exceptions are logged at a higher level than they should be. Things like this were made better by [TEIID-3152] result set close after session close reported as an error - JBoss Issue Tracker in 8.9 - which looks for specific close exceptions "Connection reset by peer" and "Broken Pipe". A specific check may be needed for "An existing connection was forcibly closed by the remote host" as well.
Actions
2. Re: Netty error on closing Teiid connection

shawkins Feb 13, 2015 3:41 PM (in response to shawkins)

I went ahead and logged/worked this as [TEIID-3337] Netty exception related to close logged at warn level - JBoss Issue Tracker
Actions

Go to original post

INFO \| jvm 1	\| 2015/02/09 11:47:35 \| WARN [TRANSPORT] TEIID40113 Unhandled exception, aborting operation
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| java.io.IOException: An existing connection was forcibly closed by the remote host
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.SocketDispatcher.$$YJP$$write0(Native Method) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.SocketDispatcher.write0(SocketDispatcher.java) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:51) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.IOUtil.write(IOUtil.java:51) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:487) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.SocketSendBufferPool$UnpooledSendBuffer.transferTo(SocketSendBufferPool.java:203) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.AbstractNioWorker.write0(AbstractNioWorker.java:202) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.AbstractNioWorker.writeFromUserCode(AbstractNioWorker.java:147) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.handleAcceptedSocket(NioServerSocketPipelineSink.java:99) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.eventSunk(NioServerSocketPipelineSink.java:36) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.handler.stream.ChunkedWriteHandler.flush(ChunkedWriteHandler.java:280) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleDownstream(ChunkedWriteHandler.java:121) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.Channels.write(Channels.java:725) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.teiid.transport.ObjectEncoder.handleDownstream(ObjectEncoder.java:140) ~[teiid-runtime-8.9.0.Final.jar:8.9.0.Final]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.Channels.write(Channels.java:704) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.Channels.write(Channels.java:671) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.AbstractChannel.write(AbstractChannel.java:248) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.teiid.transport.SSLAwareChannelHandler$ObjectChannelImpl.write(SSLAwareChannelHandler.java:93) ~[teiid-runtime-8.9.0.Final.jar:8.9.0.Final]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.teiid.transport.SocketClientInstance.exceptionOccurred(SocketClientInstance.java:117) ~[teiid-runtime-8.9.0.Final.jar:8.9.0.Final]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.teiid.transport.SSLAwareChannelHandler.exceptionCaught(SSLAwareChannelHandler.java:200) ~[teiid-runtime-8.9.0.Final.jar:8.9.0.Final]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleUpstream(ChunkedWriteHandler.java:142) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.handler.codec.frame.FrameDecoder.exceptionCaught(FrameDecoder.java:377) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.Channels.fireExceptionCaught(Channels.java:525) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:74) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:109) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:328) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:90) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| WARN [TRANSPORT] TEIID40113 Unhandled exception, aborting operation
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| java.io.IOException: An existing connection was forcibly closed by the remote host
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.SocketDispatcher.$$YJP$$read0(Native Method) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.SocketDispatcher.read0(SocketDispatcher.java) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:43) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.IOUtil.read(IOUtil.java:192) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:379) ~[na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:64) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:109) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:328) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:90) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178) ~[netty-3.6.10.Final.jar:na]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
INFO \| jvm 1	\| 2015/02/09 11:47:35 \| at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]