Duplicate/confusing exception logging in NettyTransceiver
---------------------------------------------------------
Key: AVRO-848
URL: https://issues.apache.org/jira/browse/AVRO-848
Project: Avro
Issue Type: Improvement
Affects Versions: 1.5.1
Reporter: Holger Hoffstätte
Duringt testing for AVRO-842 I noticed that exceptions seem to be handled
differently between the different server types. To duplicate run my CrashTest
example from AVRO-842 against the SaslSocketServer with the root logger set to
INFO and the log.error() in the catch block disabled, and you'll see:
[07-01 10:58:22] INFO org.apache.avro.ipc.SocketServer: starting /0.0.0.0
[07-01 10:58:22] INFO h2o.avro.bugs.CrashTest$MyServiceImpl: doSomething()
[07-01 10:58:22] INFO org.apache.avro.ipc.SocketServer: stopping /0.0.0.0
[07-01 10:58:22] INFO org.apache.avro.ipc.SaslSocketTransceiver: closing to
0.0.0.0/0.0.0.0:16221
There are no spurious exceptions bubbling up, as it should be: propagated or
handled exceptions should never be logged as anything but DEBUG, and
preferrably not at all.
However with the NettyTransceiver against the NettyServer and the root log
level set to WARN (to silence INFO messages from Netty) we see the following:
java.net.ConnectException: Connection refused: no further information
at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
at
sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:567)
at
org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.connect(NioClientSocketPipelineSink.java:384)
at
org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.processSelectedKeys(NioClientSocketPipelineSink.java:354)
at
org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.run(NioClientSocketPipelineSink.java:276)
at
org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
at
org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:44)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
[07-01 11:01:53] WARN org.apache.avro.ipc.NettyTransceiver: Unexpected
exception from downstream.
java.net.ConnectException: Connection refused: no further information
at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
~[na:1.6.0_26]
at
sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:567)
~[na:1.6.0_26]
at
org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.connect(NioClientSocketPipelineSink.java:384)
~[netty-3.2.4.Final.jar:na]
at
org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.processSelectedKeys(NioClientSocketPipelineSink.java:354)
~[netty-3.2.4.Final.jar:na]
at
org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.run(NioClientSocketPipelineSink.java:276)
~[netty-3.2.4.Final.jar:na]
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
[na:1.6.0_26]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
[na:1.6.0_26]
at java.lang.Thread.run(Thread.java:662) [na:1.6.0_26]
Two things to note here:
- the first stack trace is not loggged but seems to be a System.err dump, maybe
because the exception was uncaught (ending up being handled by the thread
group?) or there is a printStackTrace() somewhere; I could not immediately find
the cause when I had a quick look.
- the second exception is logged by NettyTransceiver and I'd argue that it
should not be, since:
a) the SaslSocketServer does not do it
b) WARN is misleading since the exception has been caught and will be propagated
c) the exception might be handled properly upstream with no reason to alert the
logfile authorities ;)
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
