You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@avro.apache.org by "Holger Hoffstätte (JIRA)" <ji...@apache.org> on 2011/07/01 11:12:28 UTC
[jira] [Created] (AVRO-848) Duplicate/confusing exception logging
in NettyTransceiver
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
[jira] [Updated] (AVRO-848) Duplicate/confusing exception logging
in NettyTransceiver
Posted by "Holger Hoffstätte (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AVRO-848?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Holger Hoffstätte updated AVRO-848:
-----------------------------------
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 SaslSocketTransceiver 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 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 ;)
> 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 SaslSocketTransceiver 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
[jira] [Updated] (AVRO-848) Duplicate/confusing exception logging
in NettyTransceiver
Posted by "Holger Hoffstätte (JIRA)" <ji...@apache.org>.
[ 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
[jira] [Resolved] (AVRO-848) Duplicate/confusing exception logging
in NettyTransceiver
Posted by "Doug Cutting (Resolved) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AVRO-848?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Doug Cutting resolved AVRO-848.
-------------------------------
Resolution: Duplicate
> 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 SaslSocketTransceiver 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.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira