Netty causing all log4j logging to duplicate

Thu Jul 1 12:46:53 EDT 2010

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.
-- 
View this message in context: http://netty-forums-and-mailing-lists.685743.n2.nabble.com/Netty-causing-all-log4j-logging-to-duplicate-tp5244186p5244186.html
Sent from the Netty User Group mailing list archive at Nabble.com.