Remote method call fails after 30 minutes

[th.janssen]

Hi,

we are working with JBoss AS 7.1.1 and run into the following problem during remote calls:

Our client creates an InitialContext during startup and caches it. Everything works fine as long as the user keeps using the client application. But if the client is not used for at least 30 minutes, the connection seems to be broken and the next remote method call will not return. I see the bean reference in the debugger, so the lookup seems to work. Some time after the client tried to call the method on the SLSB, JBoss writes this message to the log:

01:59:34,863 ERROR [org.jboss.remoting.remote.connection] (Remoting "testserver" read-1) JBREM000200: Remote connection failed: java.io.IOException: Eine vorhandene Verbindung wurde vom Remotehost geschlossen

Everything works fine, if I create a new InitialContext for each server request.

Any ideas how to solve this issue?

Is it wrong to keep a reference on the InitialContext? In the past it was done because it took some time to create the InitialContext, but it seems to be ok now.

edit:

We use this code to setup the connection and to create the InitialContext:

// define the JBoss client properties
        final Properties clientProperties = new Properties();
        clientProperties.put("remote.connectionprovider.create.options.org.xnio.Options.SSL_ENABLED", "false");
        clientProperties.put("remote.connections", "default");

        clientProperties.put("remote.connection.default.host", this.hostName);
        clientProperties.put("remote.connection.default.port", Integer.toString(this.portNumber));

        clientProperties.put("remote.connection.default.username", userName);
        if (password != null) {
            clientProperties.put("remote.connection.default.password", password);
        }

        clientProperties.put("remote.connection.default.connect.options.org.xnio.Options.SASL_DISALLOWED_MECHANISMS",
                "JBOSS-LOCAL-USER");
        clientProperties.put("remote.connection.default.connect.options.org.xnio.Options.SASL_POLICY_NOPLAINTEXT",
                "false");

        // create client configuration
        final EJBClientConfiguration clientConfiguration = new PropertiesBasedEJBClientConfiguration(clientProperties);

        // create a context selector
        final ContextSelector<EJBClientContext> contextSelector = new ConfigBasedEJBClientContextSelector(
                clientConfiguration);

        // set the selector for use
        EJBClientContext.setSelector(contextSelector);

        try {
            final Hashtable<Object, Object> contextProperties = new Hashtable<>();
            ejbURLContextFactory.class.getName();
            contextProperties.put(Context.URL_PKG_PREFIXES, "org.jboss.ejb.client.naming");
            this.initialContext = new InitialContext(contextProperties);
        } catch (final NamingException ex) {
            throw new RuntimeException(ex);
        }

Thanks a lot!

Thorben

Add code for connection setup and InitialContext creation

[wdfink]

Hi Thorben,

do you see any messages in the log if you set 'org.jboss.ejb' to TRACE at the client and ... mmmh org.jboss.remote (remoting) and org.xnio to TRACE at server side?

I suppose you leave the test without load for 30mins, right?

[th.janssen]

Wolf-Dieter Fink schrieb:

I suppose you leave the test without load for 30mins, right?

Yes, there is no load on the client and therefore there are no requests send to JBoss. There are no additional clients in my test environment, so there is also no server load during the 30mins.

Wolf-Dieter Fink schrieb:

do you see any messages in the log if you set 'org.jboss.ejb' to TRACE at the client

Sorry, I cannot provide a client log at the moment

Wolf-Dieter Fink schrieb:

do you see any messages in the log if you set [...] org.jboss.remote (remoting) and org.xnio to TRACE at server side?

This is writte to the server log:

07:47:33,835 TRACE [org.xnio.channels.framed] (Remoting "testserver" read-1) Did not read a length
07:47:33,836 TRACE [org.xnio.nio.selector] (Remoting "testserver" read-1) Beginning select on sun.nio.ch.WindowsSelectorImpl@5a424a96
08:52:01,337 TRACE [org.xnio.nio.selector] (Remoting "testserver" read-1) Selected on sun.nio.ch.WindowsSelectorImpl@5a424a96
08:52:01,338 TRACE [org.xnio.nio.selector] (Remoting "testserver" read-1) Selected key sun.nio.ch.SelectionKeyImpl@1ba62063 for java.nio.channels.SocketChannel[connected local=testserver/192.168.11.62:4447 remote=/192.168.10.146:51059]
08:52:01,338 TRACE [org.xnio.listener] (Remoting "testserver" read-1) Invoking listener Read listener for org.xnio.channels.FramedMessageChannel around TCP socket channel (NIO) <2599e956> on channel TCP socket channel (NIO) <2599e956>
08:52:01,339 TRACE [org.xnio.listener] (Remoting "testserver" read-1) Invoking listener org.jboss.remoting3.remote.RemoteReadListener@4abf8d4e on channel org.xnio.channels.FramedMessageChannel around TCP socket channel (NIO) <2599e956>
08:52:01,339 TRACE [org.xnio.channels.framed] (Remoting "testserver" read-1) Copying message from java.nio.HeapByteBuffer[pos=4 lim=158 cap=8196] into java.nio.HeapByteBuffer[pos=0 lim=8192 cap=8192]
08:52:01,341 TRACE [org.xnio.channels.framed] (Remoting "testserver" read-1) Did not read a length
08:52:01,343 TRACE [org.xnio.nio.selector] (Remoting "testserver" read-1) Beginning select on sun.nio.ch.WindowsSelectorImpl@5a424a96
08:52:01,343 TRACE [org.xnio.channels.framed] (Remoting "testserver" task-2) Accepting java.nio.HeapByteBuffer[pos=0 lim=11 cap=8192] into java.nio.HeapByteBuffer[pos=0 lim=8196 cap=8196]
08:52:01,343 TRACE [org.xnio.channels.framed] (Remoting "testserver" task-2) Accepted a message into java.nio.HeapByteBuffer[pos=15 lim=8196 cap=8196]
08:52:01,344 TRACE [org.xnio.channels.framed] (Remoting "testserver" task-2) Fully flushed org.xnio.channels.FramedMessageChannel around TCP socket channel (NIO) <2599e956>
08:52:01,359 TRACE [org.xnio.safe-close] (Remoting "testserver" task-2) Closing resource org.jboss.remoting3.remote.InboundMessage$3@6dfb9261
08:52:01,402 INFO  [stdout] (EJB default - 4) Hibernate: select [...]

08:52:01,420 TRACE [org.xnio.channels.framed] (EJB default - 4) Accepting java.nio.HeapByteBuffer[pos=0 lim=1639 cap=8192] into java.nio.HeapByteBuffer[pos=0 lim=8196 cap=8196]
08:52:01,420 TRACE [org.xnio.channels.framed] (EJB default - 4) Accepted a message into java.nio.HeapByteBuffer[pos=1643 lim=8196 cap=8196]
08:52:01,421 TRACE [org.xnio.channels.framed] (EJB default - 4) Fully flushed org.xnio.channels.FramedMessageChannel around TCP socket channel (NIO) <2599e956>
08:52:01,421 TRACE [org.xnio.channels.framed] (EJB default - 4) Fully flushed org.xnio.channels.FramedMessageChannel around TCP socket channel (NIO) <2599e956>
08:52:01,421 TRACE [org.xnio.channels.framed] (EJB default - 4) Accepting java.nio.HeapByteBuffer[pos=0 lim=8 cap=8192] into java.nio.HeapByteBuffer[pos=0 lim=8196 cap=8196]
08:52:01,422 TRACE [org.xnio.channels.framed] (EJB default - 4) Accepted a message into java.nio.HeapByteBuffer[pos=12 lim=8196 cap=8196]
08:52:01,422 TRACE [org.xnio.channels.framed] (EJB default - 4) Fully flushed org.xnio.channels.FramedMessageChannel around TCP socket channel (NIO) <2599e956>
08:52:01,422 TRACE [org.xnio.channels.framed] (EJB default - 4) Fully flushed org.xnio.channels.FramedMessageChannel around TCP socket channel (NIO) <2599e956>
08:52:22,852 TRACE [org.xnio.nio.selector] (Remoting "testserver" read-1) Selected on sun.nio.ch.WindowsSelectorImpl@5a424a96
08:52:22,852 TRACE [org.xnio.nio.selector] (Remoting "testserver" read-1) Selected key sun.nio.ch.SelectionKeyImpl@1ba62063 for java.nio.channels.SocketChannel[connected local=testserver/192.168.11.62:4447 remote=/192.168.10.146:51059]
08:52:22,852 TRACE [org.xnio.listener] (Remoting "testserver" read-1) Invoking listener Read listener for org.xnio.channels.FramedMessageChannel around TCP socket channel (NIO) <2599e956> on channel TCP socket channel (NIO) <2599e956>
08:52:22,853 TRACE [org.xnio.listener] (Remoting "testserver" read-1) Invoking listener org.jboss.remoting3.remote.RemoteReadListener@4abf8d4e on channel org.xnio.channels.FramedMessageChannel around TCP socket channel (NIO) <2599e956>
08:52:22,854 ERROR [org.jboss.remoting.remote.connection] (Remoting "testserver" read-1) JBREM000200: Remote connection failed: java.io.IOException: Eine vorhandene Verbindung wurde vom Remotehost geschlossen
08:52:22,854 TRACE [org.xnio.safe-close] (Remoting "testserver" read-1) Closing resource org.xnio.channels.FramedMessageChannel around TCP socket channel (NIO) <2599e956>
08:52:22,854 TRACE [org.xnio.channels.framed] (Remoting "testserver" read-1) Fully flushed org.xnio.channels.FramedMessageChannel around TCP socket channel (NIO) <2599e956>
08:52:22,855 TRACE [org.xnio.nio.tcp.channel] (Remoting "testserver" read-1) Closing TCP socket channel (NIO) <2599e956>
08:52:22,855 TRACE [org.xnio.nio] (Remoting "testserver" read-1) Cancelling key sun.nio.ch.SelectionKeyImpl@1ba62063 of java.nio.channels.SocketChannel[closed] (same thread)
08:52:22,855 TRACE [org.xnio.nio.selector] (Remoting "testserver" write-1) Selected on sun.nio.ch.WindowsSelectorImpl@235b7c7f
08:52:22,855 TRACE [org.xnio.nio] (Remoting "testserver" read-1) Cancelling key sun.nio.ch.SelectionKeyImpl@379851c3 of java.nio.channels.SocketChannel[closed] (other thread)
08:52:22,856 TRACE [org.xnio.nio.selector] (Remoting "testserver" write-1) Beginning select on sun.nio.ch.WindowsSelectorImpl@235b7c7f (with timeout)
08:52:22,856 TRACE [org.xnio.listener] (Remoting "testserver" read-1) Invoking listener Close listener for org.xnio.channels.FramedMessageChannel around TCP socket channel (NIO) <2599e956> on channel TCP socket channel (NIO) <2599e956>
08:52:22,856 TRACE [org.xnio.nio.selector] (Remoting "testserver" write-1) Selected on sun.nio.ch.WindowsSelectorImpl@235b7c7f
08:52:22,856 TRACE [org.xnio.safe-close] (Remoting "testserver" read-1) Closing resource org.xnio.channels.FramedMessageChannel around TCP socket channel (NIO) <2599e956>
08:52:22,857 TRACE [org.xnio.nio.selector] (Remoting "testserver" write-1) Beginning select on sun.nio.ch.WindowsSelectorImpl@235b7c7f (with timeout)
08:52:22,857 TRACE [org.xnio.safe-close] (Remoting "testserver" read-1) Closing resource TCP socket channel (NIO) <2599e956>
08:52:22,857 TRACE [org.xnio.listener] (Remoting "testserver" read-1) Invoking listener org.jboss.remoting3.remote.RemoteReadListener$1@4f2dd7fe on channel org.xnio.channels.FramedMessageChannel around TCP socket channel (NIO) <2599e956>
08:52:22,858 TRACE [org.xnio.nio.selector] (Remoting "testserver" read-1) Beginning select on sun.nio.ch.WindowsSelectorImpl@5a424a96
08:52:22,858 TRACE [org.xnio.safe-close] (Remoting "testserver" task-3) Closing resource org.xnio.channels.FramedMessageChannel around TCP socket channel (NIO) <2599e956>

[jaikiran]

Try adding this to the EJB3 subsystem in standalone*.xml:

<subsystem xmlns="urn:jboss:domain:ejb3 ....>
...
    <remote connector-ref="remoting-connector" thread-pool-name="default">
        <channel-creation-options>
            <option name="KEEP_ALIVE" value="true" type="xnio"/>
        </channel-creation-options>
    </remote>

[th.janssen]

Message: JBAS014789: Unexpected element '{urn:jboss:domain:ejb3:1.2}channel-creation-options' encountered

Do I need to update to AS 7.1.2? Currently using 7.1.1.

[jaikiran]

Yes, I had forgotten that we introduced this post 7.1.1.

[th.janssen]

I build 7.1.2 and it seems that I run into https://issues.jboss.org/browse/AS7-4824 now.

Is there a tag for 7.1.3? If not, is the release already scheduled?

[jaikiran]

Thorben Janssen wrote:

Is there a tag for 7.1.3?

https://github.com/jbossas/jboss-as/tree/7.1.3.Final

[wdfink]

Hi Thorben,

no there is no release 7.1.3.

If you use a git clone you might use the tag '7.1.3.Beta1' or switch to branch '7.1-next' which is the preparation for 7.1.3 final.

Wolf

Ooops looks like I missed a tag

Message was edited by: Wolf-Dieter Fink

[wdfink]

"git fetch --tag upstream master"

solve it if you follow the Hacking guide when cloning AS7

[th.janssen]

Hi Wolf and Jaikiran,

thanks a lot for your support and sorry for my late reply.

I setup an AS 7.1.3 with KEEP_ALIVE option but it still does not work

Its the same as before. The request does not return to the client, but I see in the server log that the request is processed by the AS. A few seconds later, I see the JBREM000200 error code in the AS log file.

Any ideas?

Thorben

edit:

It seems to work with AS 7.1.1 if I set the property remote.connection.default.connect.options.org.jboss.remoting3.RemotingOptions.HEARTBEAT_INTERVAL on the connection properties passed to PropertiesBasedEJBClientConfiguration.

Are there any drawbacks with this workaround?

[jaikiran]

Thorben Janssen wrote:

edit:

It seems to work with AS 7.1.1 if I set the property remote.connection.default.connect.options.org.jboss.remoting3.RemotingOptions.HEARTBEAT_INTERVAL on the connection properties passed to PropertiesBasedEJBClientConfiguration.

Are there any drawbacks with this workaround?

I just had a discussion about this with David and setting the HEARTBEAT_INTERVAL is the right way to do it.

[th.janssen]

Thanks Jaikiran!

Any suggestions to which value the interval should be set? Currently it's 10 min.

[kieselhorst]

Thanks for this helpful thread. IMHO the value depends on your firewall configuration, we are currently trying 5 mins.

For anybody else reading this: The interval has to be specified in milliseconds.

[spyndi]

Hi Dennis,

How does this Heartbeat property work from one Jboss server to another Jboss server context? In our case, we have the application UI deployed in one Jboss container and it looks up the EJBs in another JBoss container. We see the "JBREM000200: Remote connection failed: java.io.IOException:" exception in the JBoss application server where the UI is deployed when the EJBs in the other JBoss server are accessed the very first time after a long interval.

Also, when I'm trying to set the HEARTBEAT_INTERVAL property in JBoss 7.1.2, it is throwing the following exception during JBoss server startup (it looks like the property tag is not defined):

Caused by: javax.xml.stream.XMLStreamException: ParseError at [row,col]:[512,17]

Message: JBAS014789: Unexpected element '{urn:jboss:domain:remoting:1.1}properties' encountered

        at org.jboss.as.controller.parsing.ParseUtils.unexpectedElement(ParseUtils.java:85) [jboss-as-controller-7.1.2.Final.jar:7.1.2.Final]

        at org.jboss.as.remoting.RemotingSubsystem11Parser.parseOutboundConnections(RemotingSubsystem11Parser.java:420) [jboss-as-remoting-7.1.2.Final.jar:7.1.2.Final]

        at org.jboss.as.remoting.RemotingSubsystem11Parser.readElement(RemotingSubsystem11Parser.java:130) [jboss-as-remoting-7.1.2.Final.jar:7.1.2.Final]

This is the setup/property I have in my standalone.xml file:

    <subsystem xmlns="urn:jboss:domain:remoting:1.1">

            <connector name="remoting-connector" socket-binding="remoting"/>

            <outbound-connections>

                <remote-outbound-connection name="default" outbound-socket-binding-ref="default"/>

                <remote-outbound-connection name="com.test.api" outbound-socket-binding-ref="test"/>

                <properties>

                   <property name="SSL_ENABLED" value="false"/>

                   <property name="SASL_POLICY_NOANONYMOUS" value="false"/>

                   <property name="KEEP_ALIVE" value="true"/>

                   <property name="org.jboss.remoting3.RemotingOptions.HEARTBEAT_INTERVAL" value="1000"/>

                </properties>

            </outbound-connections>

        </subsystem>

Does the Heartbeat property work for you in JBoss 7.1.2? Could you please let me know the property definition? (ie, what file? how you have added the property?)

Do we have to add the Heartbeat property in the jboss-ejb-client.xml file?

Thank you in advance.

Sudhakar