[jboss-remoting-issues] [JBoss JIRA] Work started: (JBREM-826) JBoss Remoting logs at ERROR and WARN in many places

JBoss Remoting logs at ERROR and WARN in many places ---------------------------------------------------- Key: JBREM-826 URL: http://jira.jboss.com/jira/browse/JBREM-826 Project: JBoss Remoting Issue Type: Bug Security Level: Public(Everyone can see) Reporter: Tim Fox Assigned To: Ron Sigal Fix For: 2.4.0.CR1 (Pinto) In many places JBoss Remoting logs at ERROR or WARN which seem inappropriate. JBR is a toolkit and should not log errors it does not handle. There is a general principle of you shouldn't log unless you handle the error. If you just pass it up, don't log. This principle is adhered to in JBoss AS for example, and IMHO should be used throughout all JBoss projects. If every toolkit being used in the chain logged the same error then you end up with a complete mess in the logs every time an exception occurs. Failover in JBoss Messaging is a good example. In JBM we detect failure of the remoting connection via the connection listener, and transparently reconnect on a different node. In this case, from the users POV *no error* has occurred - the process should be completely seamless. However JBoss Remoting spews a load of exceptions to the logs at ERROR and WARN, for example: SERVER 1 STDOUT: @RMI TCP Connection(2)-127.0.0.1 08:27:29,571 INFO [RMITestServer] kill() invoked - first deregistering from the rmi registry SERVER 1 STDOUT: @RMI TCP Connection(2)-127.0.0.1 08:27:29,572 INFO [RMITestServer] unregistered messaging_rmi_server_1 from registry SERVER 1 STDOUT: @RMI TCP Connection(2)-127.0.0.1 08:27:29,573 INFO [RMITestServer] unregistered naming_rmi_server_1 from registry SERVER 1 STDOUT: @RMI TCP Connection(2)-127.0.0.1 08:27:29,573 INFO [RMITestServer] Killing VM!!!! @main 08:27:29,940 INFO [ServerManagement] Waiting for server to die SERVER 0 STDOUT: @Timer-4 08:27:30,084 ERROR [SocketClientInvoker] Got marshalling exception, exiting SERVER 0 STDOUT: java.net.SocketException: end of file SERVER 0 STDOUT: at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:577) SERVER 0 STDOUT: at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.transport(BisocketClientInvoker.java:413) SERVER 0 STDOUT: at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:122) SERVER 0 STDOUT: at org.jboss.remoting.ConnectionValidator.doCheckConnection(ConnectionValidator.java:133) SERVER 0 STDOUT: at org.jboss.remoting.ConnectionValidator.run(ConnectionValidator.java:308) SERVER 0 STDOUT: at java.util.TimerThread.mainLoop(Timer.java:512) SERVER 0 STDOUT: at java.util.TimerThread.run(Timer.java:462) @main 08:27:30,241 INFO [ServerManagement] server 1 killed and dead @Timer-3 08:27:30,275 ERROR [SocketClientInvoker] Got marshalling exception, exiting java.net.SocketException: end of file at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:577) at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.transport(BisocketClientInvoker.java:413) at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:122) at org.jboss.remoting.ConnectionValidator.doCheckConnection(ConnectionValidator.java:133) at org.jboss.remoting.ConnectionValidator.run(ConnectionValidator.java:308) at java.util.TimerThread.mainLoop(Timer.java:512) at java.util.TimerThread.run(Timer.java:462) @Thread-9 08:27:30,318 WARN [Client] unable to remove remote callback handler: Can not get connection to server. Problem establishing socket connection for InvokerLocator [bisocket://localhost:2840/?clientLeasePeriod=10000&clientMaxPoolSize=200&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&marshaller=org.jboss.jms.wireformat.JMSWireFormat&numberOfCallRetries=1&numberOfRetries=10&pingFrequency=214748364&pingWindowFactor=10&socket.check_connection=false&timeout=0&unmarshaller=org.jboss.jms.wireformat.JMSWireFormat] @Thread-9 08:27:30,338 WARN [LeasePinger] LeasePinger[SocketClientInvoker[53ab04, bisocket://localhost:2840](3j001-c12qds-f8e5pqu9-1-f8e5pqwg-3)] failed sending disconnect for client lease for client with session ID 3j001-c12qds-f8e5pqu9-1-f8e5pqua-2 @Thread-9 08:27:30,360 WARN [LeasePinger] LeasePinger[SocketClientInvoker[53ab04, bisocket://localhost:2840](3j001-c12qds-f8e5pqu9-1-f8e5pqwg-3)] failed to ping to server: Can not get connection to server. Problem establishing socket connection for InvokerLocator [bisocket://localhost:2840/?clientLeasePeriod=10000&clientMaxPoolSize=200&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&marshaller=org.jboss.jms.wireformat.JMSWireFormat&numberOfCallRetries=1&numberOfRetries=10&pingFrequency=214748364&pingWindowFactor=10&socket.check_connection=false&timeout=0&unmarshaller=org.jboss.jms.wireformat.JMSWireFormat] @Thread-10 08:27:30,532 WARN [Client] unable to remove remote callback handler: Can not get connection to server. Problem establishing socket connection for InvokerLocator [bisocket://localhost:2840/?clientLeasePeriod=10000&clientMaxPoolSize=200&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&marshaller=org.jboss.jms.wireformat.JMSWireFormat&numberOfCallRetries=1&numberOfRetries=10&pingFrequency=214748364&pingWindowFactor=10&socket.check_connection=false&timeout=0&unmarshaller=org.jboss.jms.wireformat.JMSWireFormat] @Thread-10 08:27:30,551 WARN [LeasePinger] LeasePinger[SocketClientInvoker[53ab04, bisocket://localhost:2840](3j001-c12qds-f8e5pqu9-1-f8e5pqwg-3)] failed sending disconnect for client lease for client with session ID 3j001-c12qds-f8e5pqu9-1-f8e5pss1-9 @Thread-10 08:27:30,570 WARN [LeasePinger] LeasePinger[SocketClientInvoker[53ab04, bisocket://localhost:2840](3j001-c12qds-f8e5pqu9-1-f8e5pqwg-3)] failed to ping to server: Can not get connection to server. Problem establishing socket connection for InvokerLocator [bisocket://localhost:2840/?clientLeasePeriod=10000&clientMaxPoolSize=200&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&marshaller=org.jboss.jms.wireformat.JMSWireFormat&numberOfCallRetries=1&numberOfRetries=10&pingFrequency=214748364&pingWindowFactor=10&socket.check_connection=false&timeout=0&unmarshaller=org.jboss.jms.wireformat.JMSWireFormat] @Thread-9 08:27:30,600 ERROR [BisocketServerInvoker] unable to get secondary locator org.jboss.remoting.CannotConnectException: Can not get connection to server. Problem establishing socket connection for InvokerLocator [bisocket://localhost:2840/?clientLeasePeriod=10000&clientMaxPoolSize=200&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&marshaller=org.jboss.jms.wireformat.JMSWireFormat&numberOfCallRetries=1&numberOfRetries=10&pingFrequency=214748364&pingWindowFactor=10&socket.check_connection=false&timeout=0&unmarshaller=org.jboss.jms.wireformat.JMSWireFormat] at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:532) at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.transport(BisocketClientInvoker.java:413) at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:122) at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.getSecondaryLocator(BisocketClientInvoker.java:538) at org.jboss.remoting.transport.bisocket.BisocketServerInvoker.createControlConnection(BisocketServerInvoker.java:228) at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.transport(BisocketClientInvoker.java:402) at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:122) at org.jboss.remoting.Client.invoke(Client.java:1634) at org.jboss.remoting.Client.addCallbackListener(Client.java:1703) at org.jboss.remoting.Client.addListener(Client.java:921) at org.jboss.jms.client.remoting.JMSRemotingConnection.addInvokerCallbackHandler(JMSRemotingConnection.java:237) at org.jboss.jms.client.remoting.JMSRemotingConnection.start(JMSRemotingConnection.java:312) at org.jboss.jms.client.delegate.ClientClusteredConnectionFactoryDelegate.establishCallback(ClientClusteredConnectionFactoryDelegate.java:99) at org.jboss.jms.client.remoting.ConnectionFactoryCallbackHandler$CallbackConnectionListener.handleConnectionException(ConnectionFactoryCallbackHandler.java:105) at org.jboss.remoting.ConnectionValidator$1.run(ConnectionValidator.java:452) Caused by: java.net.ConnectException: Connection refused at java.net.PlainSocketImpl.socketConnect(Native Method) at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333) at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195) at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182) at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366) at java.net.Socket.connect(Socket.java:519) at org.jboss.remoting.transport.socket.SocketClientInvoker.createSocket(SocketClientInvoker.java:187) at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.createSocket(BisocketClientInvoker.java:420) at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.getConnection(MicroSocketClientInvoker.java:815) at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:525) ... 14 more @Thread-9 08:27:30,620 WARN [Client] unable to remove remote callback handler: Can not get connection to server. Problem establishing socket connection for InvokerLocator [bisocket://localhost:2840/?clientLeasePeriod=10000&clientMaxPoolSize=200&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&marshaller=org.jboss.jms.wireformat.JMSWireFormat&numberOfCallRetries=1&numberOfRetries=10&pingFrequency=214748364&pingWindowFactor=10&socket.check_connection=false&timeout=0&unmarshaller=org.jboss.jms.wireformat.JMSWireFormat] @Thread-9 08:27:30,639 WARN [LeasePinger] LeasePinger[SocketClientInvoker[53ab04, bisocket://localhost:2840](3j001-c12qds-f8e5pqu9-1-f8e5pqwg-3)] failed sending disconnect for client lease for client with session ID 3j001-c12qds-f8e5pqu9-1-f8e5puat-k @Thread-10 08:27:30,760 ERROR [BisocketServerInvoker] unable to get secondary locator org.jboss.remoting.CannotConnectException: Can not get connection to server. Problem establishing socket connection for InvokerLocator [bisocket://localhost:2840/?clientLeasePeriod=10000&clientMaxPoolSize=200&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&marshaller=org.jboss.jms.wireformat.JMSWireFormat&numberOfCallRetries=1&numberOfRetries=10&pingFrequency=214748364&pingWindowFactor=10&socket.check_connection=false&timeout=0&unmarshaller=org.jboss.jms.wireformat.JMSWireFormat] at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:532) at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.transport(BisocketClientInvoker.java:413) at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:122) at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.getSecondaryLocator(BisocketClientInvoker.java:538) at org.jboss.remoting.transport.bisocket.BisocketServerInvoker.createControlConnection(BisocketServerInvoker.java:228) at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.transport(BisocketClientInvoker.java:402) at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:122) at org.jboss.remoting.Client.invoke(Client.java:1634) at org.jboss.remoting.Client.addCallbackListener(Client.java:1703) at org.jboss.remoting.Client.addListener(Client.java:921) at org.jboss.jms.client.remoting.JMSRemotingConnection.addInvokerCallbackHandler(JMSRemotingConnection.java:237) at org.jboss.jms.client.remoting.JMSRemotingConnection.start(JMSRemotingConnection.java:312) at org.jboss.jms.client.delegate.ClientClusteredConnectionFactoryDelegate.establishCallback(ClientClusteredConnectionFactoryDelegate.java:99) at org.jboss.jms.client.remoting.ConnectionFactoryCallbackHandler$CallbackConnectionListener.handleConnectionException(ConnectionFactoryCallbackHandler.java:105) at org.jboss.remoting.ConnectionValidator$1.run(ConnectionValidator.java:452) Caused by: java.net.ConnectException: Connection refused at java.net.PlainSocketImpl.socketConnect(Native Method) at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333) at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195) at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182) at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366) at java.net.Socket.connect(Socket.java:519) at org.jboss.remoting.transport.socket.SocketClientInvoker.createSocket(SocketClientInvoker.java:187) at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.createSocket(BisocketClientInvoker.java:420) at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.getConnection(MicroSocketClientInvoker.java:815) at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:525) ... 14 more @Thread-10 08:27:30,780 WARN [Client] unable to remove remote callback handler: Can not get connection to server. Problem establishing socket connection for InvokerLocator [bisocket://localhost:2840/?clientLeasePeriod=10000&clientMaxPoolSize=200&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&marshaller=org.jboss.jms.wireformat.JMSWireFormat&numberOfCallRetries=1&numberOfRetries=10&pingFrequency=214748364&pingWindowFactor=10&socket.check_connection=false&timeout=0&unmarshaller=org.jboss.jms.wireformat.JMSWireFormat] @Thread-10 08:27:30,807 WARN [LeasePinger] LeasePinger[SocketClientInvoker[53ab04, bisocket://localhost:2840](3j001-c12qds-f8e5pqu9-1-f8e5pqwg-3)] failed sending disconnect for client lease for client with session ID 3j001-c12qds-f8e5pqu9-1-f8e5pugn-p @Thread-13 08:27:31,491 INFO [FailoverCommandCenter] JBoss Messaging server failure detected - waiting for failover to complete... @Thread-13 08:27:31,793 ERROR [SocketClientInvoker] Got marshalling exception, exiting java.net.SocketException: Connection reset at java.net.SocketInputStream.read(SocketInputStream.java:168) at java.io.BufferedInputStream.fill(BufferedInputStream.java:218) at java.io.BufferedInputStream.read(BufferedInputStream.java:235) at java.io.FilterInputStream.read(FilterInputStream.java:66) at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.readVersion(MicroSocketClientInvoker.java:1000) at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:574) at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.transport(BisocketClientInvoker.java:413) at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:122) at org.jboss.remoting.LeasePinger.sendClientPing(LeasePinger.java:283) at org.jboss.remoting.LeasePinger.addClient(LeasePinger.java:117) at org.jboss.remoting.MicroRemoteClientInvoker.establishLease(MicroRemoteClientInvoker.java:358) at org.jboss.remoting.Client.setupClientLease(Client.java:1625) at org.jboss.remoting.Client.connect(Client.java:1525) at org.jboss.remoting.Client.connect(Client.java:462) at org.jboss.jms.client.remoting.JMSRemotingConnection$1.run(JMSRemotingConnection.java:295) at java.security.AccessController.doPrivileged(Native Method) at org.jboss.jms.client.remoting.JMSRemotingConnection.start(JMSRemotingConnection.java:291) at org.jboss.jms.client.delegate.ClientConnectionFactoryDelegate.org$jboss$jms$client$delegate$ClientConnectionFactoryDelegate$createConnectionDelegate$aop(ClientConnectionFactoryDelegate.java:154) at org.jboss.jms.client.delegate.ClientConnectionFactoryDelegate$createConnectionDelegate_N3019492359065420858.invokeNext(ClientConnectionFactoryDelegate$createConnectionDelegate_N3019492359065420858.java) at org.jboss.jms.client.container.StateCreationAspect.handleCreateConnectionDelegate(StateCreationAspect.java:83) at org.jboss.aop.advice.org.jboss.jms.client.container.StateCreationAspect0.invoke(StateCreationAspect0.java) at org.jboss.jms.client.delegate.ClientConnectionFactoryDelegate$createConnectionDelegate_N3019492359065420858.invokeNext(ClientConnectionFactoryDelegate$createConnectionDelegate_N3019492359065420858.java) at org.jboss.jms.client.delegate.ClientConnectionFactoryDelegate.createConnectionDelegate(ClientConnectionFactoryDelegate.java) at org.jboss.jms.client.container.ClusteringAspect.handleCreateConnectionDelegate(ClusteringAspect.java:134) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at org.jboss.aop.advice.PerInstanceAdvice.invoke(PerInstanceAdvice.java:121) at org.jboss.jms.client.delegate.ClientClusteredConnectionFactoryDelegate$createConnectionDelegate_N3019492359065420858.invokeNext(ClientClusteredConnectionFactoryDelegate$createConnectionDelegate_N3019492359065420858.java) at org.jboss.jms.client.delegate.ClientClusteredConnectionFactoryDelegate.createConnectionDelegate(ClientClusteredConnectionFactoryDelegate.java) at org.jboss.jms.client.FailoverCommandCenter.failureDetected(FailoverCommandCenter.java:129) at org.jboss.jms.client.container.ConnectionFailureListener.handleConnectionException(ConnectionFailureListener.java:62) at org.jboss.jms.client.remoting.ConsolidatedRemotingConnectionListener.handleConnectionException(ConsolidatedRemotingConnectionListener.java:81) at org.jboss.remoting.ConnectionValidator$1.run(ConnectionValidator.java:452) @Thread-13 08:27:31,801 WARN [LeasePinger] LeasePinger[SocketClientInvoker[682406, bisocket://localhost:2854](3j001-c12qds-f8e5pqu9-1-f8e5puj4-v)] failed to ping to server: Failed to communicate. Problem during marshalling/unmarshalling; nested exception is: java.net.SocketException: Connection reset @Thread-2 08:27:31,820 ERROR [SocketClientInvoker] Got marshalling exception, exiting java.net.SocketException: Connection reset at java.net.SocketInputStream.read(SocketInputStream.java:168) at java.io.BufferedInputStream.fill(BufferedInputStream.java:218) at java.io.BufferedInputStream.read(BufferedInputStream.java:235) at java.io.FilterInputStream.read(FilterInputStream.java:66) at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.readVersion(MicroSocketClientInvoker.java:1000) at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:574) at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.transport(BisocketClientInvoker.java:413) at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:122) at org.jboss.remoting.Client.invoke(Client.java:1634) at org.jboss.remoting.Client.invoke(Client.java:548) at org.jboss.jms.client.delegate.ClientClusteredConnectionFactoryDelegate.removeCallback(ClientClusteredConnectionFactoryDelegate.java:152) at org.jboss.jms.client.delegate.ClientClusteredConnectionFactoryDelegate.closeCallback(ClientClusteredConnectionFactoryDelegate.java:168) at org.jboss.jms.client.delegate.ClientClusteredConnectionFactoryDelegate.finalize(ClientClusteredConnectionFactoryDelegate.java:158) at org.jboss.jms.client.delegate.ClientClusteredConnectionFactoryDelegate$FinalizerShutdownHook.run(ClientClusteredConnectionFactoryDelegate.java:418) @Thread-2 08:27:31,839 WARN [Client] unable to remove remote callback handler: Can not get connection to server. Problem establishing socket connection for InvokerLocator [bisocket://localhost:2854/?clientLeasePeriod=10000&clientMaxPoolSize=200&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&marshaller=org.jboss.jms.wireformat.JMSWireFormat&numberOfCallRetries=1&numberOfRetries=10&pingFrequency=214748364&pingWindowFactor=10&socket.check_connection=fals This completely messes up the logs and the customer believes something has gone wrong, phones support and they waste a lot of time trying to work out what the problem is, when actually there is no problem and this is perfectly successful failover from one node to another, but to the customer they have a flawed experience. The customer says "Why was JBoss reporting errors when everything was ok?" If anything is to be logged in these cases it should be at DEBUG level at the highest, so it can be easily supressed in the standard log4j config. In the mean-time if you could provide a log4j config which supresses these messages for the specific classes so they don't appear even on ERROR level that would be much appreciated.