PingTimerTask in JBoss AS 5.0.1.GA EAP

[kevin.lohmann]

Hi there,

since we switched to JBoss 5.0.1.GA EAP (from 5.1.0.GA), plenty of times we see warnings in server.log like this:

2010-08-31 16:34:37,211 WARN [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] (Timer-4) Unable to send ping: shutting down PingTimerTask
java.net.SocketException: Connection reset by peer: socket write error
 at java.net.SocketOutputStream.socketWrite0(Native Method)
 at java.net.SocketOutputStream.socketWrite(Unknown Source)
 at java.net.SocketOutputStream.write(Unknown Source)
 at org.jboss.remoting.transport.bisocket.BisocketClientInvoker$PingTimerTask.run(BisocketClientInvoker.java:723)
 at java.util.TimerThread.mainLoop(Unknown Source)
 at java.util.TimerThread.run(Unknown Source)

Or:

2010-08-31 22:18:38,519 WARN  [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] (Timer-4) Unable to send ping: shutting down PingTimerTask
java.net.SocketException: Socket closed
    at java.net.SocketOutputStream.socketWrite(Unknown Source)
    at java.net.SocketOutputStream.write(Unknown Source)
    at org.jboss.remoting.transport.bisocket.BisocketClientInvoker$PingTimerTask.run(BisocketClientInvoker.java:723)
    at java.util.TimerThread.mainLoop(Unknown Source)
    at java.util.TimerThread.run(Unknown Source)

Or:

2010-08-31 15:06:24,248 WARN  [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] (Timer-4) Unable to send ping: shutting down PingTimerTask
java.net.SocketException: Software caused connection abort: socket write error
    at java.net.SocketOutputStream.socketWrite0(Native Method)
    at java.net.SocketOutputStream.socketWrite(Unknown Source)
    at java.net.SocketOutputStream.write(Unknown Source)
    at org.jboss.remoting.transport.bisocket.BisocketClientInvoker$PingTimerTask.run(BisocketClientInvoker.java:723)
    at java.util.TimerThread.mainLoop(Unknown Source)
    at java.util.TimerThread.run(Unknown Source)

Or:

2010-08-31 18:38:11,886 WARN  [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] (Timer-4) Unable to send ping: shutting down PingTimerTask
java.lang.NullPointerException
    at org.jboss.remoting.transport.bisocket.BisocketClientInvoker$PingTimerTask.run(BisocketClientInvoker.java:723)
    at java.util.TimerThread.mainLoop(Unknown Source)
    at java.util.TimerThread.run(Unknown Source)

I can imagine what the PingTimerTask should do. But I'd like to hear from the experts what they say about it.

How can we handle these warnings?

Sometimes our clients receive warnings like this:

WARNING org.jboss.remoting.transport.bisocket.BisocketServerInvoker$ControlMonitorTimerTask@1f175da: detected failure on control connection Thread[control: Socket[addr=XXX/yyyy,port=7063,localport=4328],3,main] (a2sc3v-fo68je-gdiugvr5-1-gdjopipw-llpl: requesting new control connection (org.jboss.remoting.transport.bisocket.BisocketServerInvoker)

which we consider to be a part of the warnings the server logs. Can that be? Or is it another phenomenon?

I can't find any informations about these questions. The ones I see are out of date (three years ago)...

Anyone who can help me?

Thanks in advance,

Kevin

[kevin.lohmann]

Hi there again,

I've created a simple standalone-client-scenario to reproduce the above warnings:

public class TestScenario {

    // ############### CONFIG #################
    private final static String sJMS_CONNECTION_FACTORY_NAME = "ClusteredConnectionFactory";
    private final static int sCONCURRENT_CALLS = 25;
    private final static long sSLEEP_TIME = sCONCURRENT_CALLS * 100;
    // ########################################
    
    private final static CountDownLatch sCDL = new CountDownLatch(sCONCURRENT_CALLS);
    private final static SimpleDateFormat sDATE_FORMATER = new SimpleDateFormat("HH:mm:ss.SSS ");
    
    public static void main(String[] args) {

        for (int i = 0; i < sCONCURRENT_CALLS; i++) {
            final int lIteration = i;
            Thread lThread = new Thread(new Runnable() {
                @Override
                public void run() {
                    try {
                        doIteration();
                    } catch (Throwable t) {
                        t.printStackTrace();
                    }
                }
            }, "Thread-no." + lIteration);
            lThread.setDaemon(true);
            lThread.start();
        }

        try {
            Thread.sleep(sSLEEP_TIME);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

        log("...ready!");
        
    }

    /**
     * @throws NamingException 
     */
    private static void doIteration() throws NamingException {

        log("...lookup JMSConnectionFactory...");
        ConnectionFactory lConnectionFactory = lookUpJMSConnectionFactory();

        sCDL.countDown();
        
        Connection lConnection;
        try {
            log("...create JMSConnection...");
            lConnection = lConnectionFactory.createConnection();
            log("...close JMSConnection...");
            lConnection.close();
        } catch (JMSException e) {
            e.printStackTrace();
        }

        log("...ready!");

    }

    /**
     * @return
     * @throws NamingException 
     */
    private static ConnectionFactory lookUpJMSConnectionFactory() throws NamingException {
        Context lContext = new InitialContext();
        return (ConnectionFactory) lContext.lookup(sJMS_CONNECTION_FACTORY_NAME);

    }

    private static void log(String pLog) {
        System.out.println(sDATE_FORMATER.format(new Date()) + Thread.currentThread().getName() + pLog);
    }
    
}

This will create ${sCONCURRENT_CALLS} daemon threads. Each thread gets a jms connectionfactory, creates a connection and closes the connection. The main thread will sleep ${sSLEEP_TIME} milli seconds before terminating.

With the above config, I receive everytime the following ConcurrentModificationException within the client:

Exception in thread "Thread-1" java.util.ConcurrentModificationException
    at java.util.WeakHashMap$HashIterator.nextEntry(WeakHashMap.java:762)
    at java.util.WeakHashMap$KeyIterator.next(WeakHashMap.java:795)
    at org.jboss.jms.client.delegate.ClientClusteredConnectionFactoryDelegate$FinalizerShutdownHook.run(ClientClusteredConnectionFactoryDelegate.java:462)

In server.log the following can be seen:

2010-09-02 11:57:05,510 WARN  [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] (Timer-4) Unable to send ping: shutting down PingTimerTask
java.net.SocketException: Connection reset by peer: socket write error
    at java.net.SocketOutputStream.socketWrite0(Native Method)
    at java.net.SocketOutputStream.socketWrite(Unknown Source)
    at java.net.SocketOutputStream.write(Unknown Source)
    at org.jboss.remoting.transport.bisocket.BisocketClientInvoker$PingTimerTask.run(BisocketClientInvoker.java:723)
    at java.util.TimerThread.mainLoop(Unknown Source)
    at java.util.TimerThread.run(Unknown Source)

And:

2010-09-02 11:56:59,401 ERROR [org.jboss.remoting.transport.socket.ServerThread] (WorkerThread#40[10.3.4.124:4488]) WorkerThread#40[10.3.4.124:4488] failed
java.io.IOException: Connection reset by peer: socket write error
    at java.net.SocketOutputStream.socketWrite0(Native Method)
    at java.net.SocketOutputStream.socketWrite(Unknown Source)
    at java.net.SocketOutputStream.write(Unknown Source)
    at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
    at java.io.BufferedOutputStream.flush(Unknown Source)
    at java.io.DataOutputStream.flush(Unknown Source)
    at org.jboss.jms.wireformat.NullResponse.write(NullResponse.java:53)
    at org.jboss.jms.wireformat.JMSWireFormat.write(JMSWireFormat.java:237)
    at org.jboss.remoting.transport.socket.ServerThread.versionedWrite(ServerThread.java:1051)
    at org.jboss.remoting.transport.socket.ServerThread.completeInvocation(ServerThread.java:807)
    at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:721)
    at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:575)
    at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:234)

I assume, these warnings and errors occur because the clients brake away. Can anyone confirm this?

Thanks,

Kevin

[kevin.lohmann]

Two weeks later and nobody can add tow cents?

[ron_sigal]

Hi Kevin,

You have uncovered a bug in BisocketClientInvoker$PingTimerTask  which allows a write after the task should have shut down, and I've  created JIRA issue JBREM-1247 "BisocketClientInvoker$PingTimerTask   NPE"  to resolve it.  However, I consider it a minor problem, since  it occurs when a connection is shutting down anyway.

JBossMessaging  has, throughout most of its history, turned off the bisocket transport  ping facility by setting

 <attribute name="pingFrequency" isParam="true">214748364</attribute>

in  their remoting-bisocket-service.xml file.  In fact, that's the value I  see in JBossMessaging version 1.4.1.GA, which ships with EAP 5.0.1, so I  don't understand why there would be any pinging going on.  Did you  change that parameter?

Anyway, I wouldn't worry about  it.

As for the ConcurrentModificationException, you  should post the issue on the JBossMessaging users forum.

-Ron

[kevin.lohmann]

Hi Ron,

thanks for your reply!

Ron Sigal schrieb:

You have uncovered a bug [..] and I've  created JIRA issue JBREM-1247 [..].

Thanks for that.

JBossMessaging  has, throughout most of its history, turned off the bisocket transport  ping facility by setting

 <attribute name="pingFrequency" isParam="true">214748364</attribute>

in  their remoting-bisocket-service.xml file.  In fact, that's the value I  see in JBossMessaging version 1.4.1.GA, which ships with EAP 5.0.1, so I  don't understand why there would be any pinging going on.  Did you  change that parameter?

No. That parameter is default commented by

<!-- the following parameters are useful when there is a firewall between client and server. Uncomment them if so.-->

So the default value is 5000, isn't it!?

Anyway, I wouldn't worry about  it.

Thats what I'd liked to hear and what I supposed it to be, for me, it's just a warning to ignore! :-)

As for the ConcurrentModificationException, you  should post the issue on the JBossMessaging users forum.

I can give it a try, but unfortunately I guess, the willingness to help is not great (compare http://community.jboss.org/thread/156294). I'm glad that you took responsibility for this one!

Again, many thanks Ron!

Kevin

[ron_sigal]

Hi Kevin,

Re: "No. That parameter is default commented by

<!-- the following parameters are useful when  there is a firewall between client and server. Uncomment them if  so.-->

So the default value is 5000, isn't it!?"

Ah, that is due to an oversight, partly my own fault, which has been or will be corrected, in which the comment was added but the original uncommented values were eliminated.  The default values are usually too small, leading to spurious failures, so they should either be increased to a reasonable value, or, essentially, set to infinity, which is what JBossMessaging has generally done.  For example,

   <attribute name="pingFrequency" isParam="true">214748364</attribute>

Re: "Anyway, I wouldn't worry about  it."

Yeah, that's one of my favorite answers, too.  

Re: "I can give it a try, but unfortunately I guess, the willingness to help  is not great"

You have to understand that JBossMessaging has been superceded by HornetQ, a much better implementation, and the resources for working on JBossMessaging are limited.

-Ron