Netty causing all log4j logging to duplicate

Wed Jul 7 03:47:31 EDT 2010

Jason,

I guess you are logging the exception in both
ChannelFuture.operationComplete() and
SimpleChannelHandler.exceptionCaught() for a connection attempt.  You
can safely omit the one in operationComplete().

Please let me know if I guessed it wrong.

HTH,
Trustin

On 07/02/2010 01:46 AM, jasons2645 wrote:
> 
> I can reproduce this issue consistently.  If I have a connection attempt
> failure, all logging across all loggers get duplicated (as shown below). 
> I've looked at what Netty is doing and don't see anything overt causing
> this.  I am not doing anything special wrt logging (e.g. I am not setting a
> custom InternalLoggerFactory), although I have tried doing this and have not
> managed to get different results.  
> 
> Any thoughts?
> 
> 
> INFO 2010-07-01 10:35:49,235 C:pillardata.util T:main | A custom log4j
> configuration was not specified.  Therefore, installed the default
> configuration: com/pillardata/client/gui/config/log/log4j.properties
> INFO 2010-07-01 10:35:49,235 C:client.gui T:main | Running with development
> tools enabled.
> INFO 2010-07-01 10:35:49,235 C:client.gui T:main | Using locale: en US 
> INFO 2010-07-01 10:35:49,250 C:client.gui T:main | JVM will use a maximum of
> 4 processor(s) and 989 mB RAM.
> INFO 2010-07-01 10:35:49,297 C:support.ClassPathXmlApplicationContext T:main
> | Refreshing
> org.springframework.context.support.ClassPathXmlApplicationContext at 165a3c2:
> display name
> [org.springframework.context.support.ClassPathXmlApplicationContext at 165a3c2];
> startup date [Thu Jul 01 10:35:49 MDT 2010]; root of context hierarchy
> INFO 2010-07-01 10:35:49,360 C:xml.XmlBeanDefinitionReader T:main | Loading
> XML bean definitions from class path resource
> [com/pillardata/client/gui/config/spring/adminapp.spring]
> INFO 2010-07-01 10:35:49,547 C:support.ClassPathXmlApplicationContext T:main
> | Bean factory for application context
> [org.springframework.context.support.ClassPathXmlApplicationContext at 165a3c2]:
> org.springframework.beans.factory.support.DefaultListableBeanFactory at 1ee148b
> INFO 2010-07-01 10:35:49,579 C:support.DefaultListableBeanFactory T:main |
> Pre-instantiating singletons in
> org.springframework.beans.factory.support.DefaultListableBeanFactory at 1ee148b:
> defining beans
> [SessionsManager,HelpManager,AsmGuiConfigService,configForHelpTargetsConfigKeys,configForNasConfigKeys,configForSanConfigKeys,configForSoftwareConfigKeys,configForGroupsConfigKeys,configForAlertConfigKeys,configForPerformanceConfigKeys,configForHardwareConfigKeys,configForJobScheduleConfigKeys];
> root of factory hierarchy
> INFO 2010-07-01 10:35:50,188 C:client.gui T:main | Gui was built July 1,
> 2010 07:36 MDT from p:\j\mainline\ant\guiframework.
> INFO 2010-07-01 10:35:50,188 C:pillardata.util T:main | DeadlockDetector
> started and will check for deadlock every 10000ms.
> INFO 2010-07-01 10:35:50,188 C:pillardata.util T:main | CpuHogDetector
> started and will check for cpu hogs every 5000ms.
> INFO 2010-07-01 10:35:51,329 C:util.net T:main | ClientNetworkControllerImpl
> attempting to connect to localhost/127.0.0.1:26008.
> INFO 2010-07-01 10:35:51,360 C:client.gui T:GUI-3 |
> SasmNavTreeNodeConfigLoader has started loading nav tree node configs.
> INFO 2010-07-01 10:35:51,438 C:client.gui T:AWT-EventQueue-0 |
> OpenWindowWorker displayed
> javax.swing.JFrame[frame0,740,501,624x383,layout=java.awt.BorderLayout,title=AxiomONE
> Storage Services
> Manager,resizable,normal,defaultCloseOperation=DISPOSE_ON_CLOSE,rootPane=javax.swing.JRootPane[,4,26,616x353,layout=javax.swing.JRootPane$RootLayout,alignmentX=0.0,alignmentY=0.0,border=,flags=16777673,maximumSize=,minimumSize=,preferredSize=],rootPaneCheckingEnabled=true].
> INFO 2010-07-01 10:35:52,438 C:util.net T:NettyClientBoss-1[New I/O client
> boss #1] | Handling closed channel [id: 0x01042fcc] in NetworkIoHandler.
> INFO 2010-07-01 10:35:52,438 C:util.net T:NettyClientBoss-1[New I/O client
> boss #1] | NetworkIoHandler ignoring closed event for [id: 0x01042fcc] since
> this channel is unknown.
> ERROR 2010-07-01 10:35:52,438 C:util.net T:NettyClientBoss-1[New I/O client
> boss #1] | In NetworkIoHandler, exception occurred for [id: 0x01042fcc].
> java.net.ConnectException: Connection refused: no further information
> 	at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
> 	at sun.nio.ch.SocketChannelImpl.finishConnect(Unknown Source)
> 	at
> org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.connect(NioClientSocketPipelineSink.java:374)
> 	at
> org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.processSelectedKeys(NioClientSocketPipelineSink.java:344)
> 	at
> org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.run(NioClientSocketPipelineSink.java:266)
> 	at
> org.jboss.netty.util.internal.IoWorkerRunnable.run(IoWorkerRunnable.java:46)
> 	at
> com.pillardata.util.workpool.RunnableAdaptor.run(RunnableAdaptor.java:54)
> 	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
> 	at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source)
> 	at java.util.concurrent.FutureTask.run(Unknown Source)
> 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
> 	at java.lang.Thread.run(Unknown Source)
> 	at
> com.pillardata.util.workpool.ResettableThread.run(ResettableThread.java:81)
> 3203 [NettyClientBoss-1[New I/O client boss #1]] ERROR
> com.pillardata.util.net  - In NetworkIoHandler, exception occurred for [id:
> 0x01042fcc].
> java.net.ConnectException: Connection refused: no further information
> 	at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
> 	at sun.nio.ch.SocketChannelImpl.finishConnect(Unknown Source)
> 	at
> org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.connect(NioClientSocketPipelineSink.java:374)
> 	at
> org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.processSelectedKeys(NioClientSocketPipelineSink.java:344)
> 	at
> org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.run(NioClientSocketPipelineSink.java:266)
> 	at
> org.jboss.netty.util.internal.IoWorkerRunnable.run(IoWorkerRunnable.java:46)
> 	at
> com.pillardata.util.workpool.RunnableAdaptor.run(RunnableAdaptor.java:54)
> 	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
> 	at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source)
> 	at java.util.concurrent.FutureTask.run(Unknown Source)
> 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
> 	at java.lang.Thread.run(Unknown Source)
> 	at
> com.pillardata.util.workpool.ResettableThread.run(ResettableThread.java:81)
> INFO 2010-07-01 10:35:52,829 C:client.gui T:GUI-3 |
> SasmNavTreeNodeConfigLoader finished loading nav tree node configs in 1
> second(s).
> 3594 [GUI-3] INFO com.pillardata.client.gui  - SasmNavTreeNodeConfigLoader
> finished loading nav tree node configs in 1 second(s).
> INFO 2010-07-01 10:35:52,829 C:client.gui T:GUI-3 | Unable to determine
> ActionType for ACTION_ALWAYS_ALLOWED.
> 3594 [GUI-3] INFO com.pillardata.client.gui  - Unable to determine
> ActionType for ACTION_ALWAYS_ALLOWED.
> INFO 2010-07-01 10:36:22,188 C:client.gui T:AWT-EventQueue-0 | Sasm
> terminating the application.
> 32953 [AWT-EventQueue-0] INFO com.pillardata.client.gui  - Sasm terminating
> the application.

-- 
what we call human nature in actuality is human habit
http://gleamynode.net/

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 293 bytes
Desc: OpenPGP digital signature
Url : http://lists.jboss.org/pipermail/netty-users/attachments/20100707/5a4cf4eb/attachment.bin 