12:09 a.m.
[ http://jira.jboss.com/jira/browse/JBREM-826?page=all ]
Ron Sigal closed JBREM-826.
---------------------------
Resolution: Done
Wherever Remoting code throws an exception, it will log a message at no higher that DEBUG
level.
It should be possible safely to set log levels for Client, LeasePinger,
BisocketServerInvoker, and SocketClientInvoker to WARN or ERROR.
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.
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
5925
days inactive
5925
days old
jboss-remoting-issues@lists.jboss.org
0 comments
1 participants
participants (1)
-
Ron Sigal (JIRA)