[
https://issues.apache.org/jira/browse/AVRO-848?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Holger Hoffstätte updated AVRO-848:
-----------------------------------
Component/s: java
Description:
Duringt testing for AVRO-842 I noticed that exceptions seem to be handled
differently between the different transeiver 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 ;)
was:
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 ;)
> Duplicate/confusing exception logging in NettyTransceiver
> ---------------------------------------------------------
>
> Key: AVRO-848
> URL: https://issues.apache.org/jira/browse/AVRO-848
> Project: Avro
> Issue Type: Improvement
> Components: java
> 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 transeiver 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
