[jboss-jira] [JBoss JIRA] (AS7-5967) RemoteNamingTestCase intermittently fails on IBM JDK due to org.jboss.remoting3.NotOpenException: Endpoint is not open
Ivo Studensky (JIRA)
jira-events at lists.jboss.org
Wed Nov 21 15:42:21 EST 2012
[ https://issues.jboss.org/browse/AS7-5967?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12736205#comment-12736205 ]
Ivo Studensky commented on AS7-5967:
------------------------------------
IBM JDK seems to be too fast. The culprit of this issue is that IBM JDK sometimes finalizes the InitialContext created by getRemoteContext() method before the lookup() method finishes. See the following log snippet. The RemoteContext is finalized by J9VMInternals.runFinalize and then lookup() method fails.
{noformat}
16:21:13,521 TRACE [org.jboss.remoting.resource] (Finalizer thread) my own stack trace from AbstractHandleableCloseable#closeAsync at ENTRY:
16:21:13,524 TRACE [org.jboss.remoting.resource] (Finalizer thread) org.jboss.remoting3.spi.AbstractHandleableCloseable.closeAsync(AbstractHandleableCloseable.java:350)
16:21:13,529 TRACE [org.jboss.remoting.resource] (Finalizer thread) org.jboss.remoting3.EndpointImpl.closeAction(EndpointImpl.java:208)
16:21:13,535 TRACE [org.jboss.remoting.resource] (Finalizer thread) org.jboss.remoting3.spi.AbstractHandleableCloseable.closeAsync(AbstractHandleableCloseable.java:369)
16:21:13,539 TRACE [org.jboss.remoting.resource] (Finalizer thread) org.jboss.naming.remote.client.EndpointCache.release(EndpointCache.java:58)
16:21:13,543 TRACE [org.jboss.remoting.resource] (Finalizer thread) org.jboss.naming.remote.client.EndpointCache$EndpointWrapper.closeAsync(EndpointCache.java:189)
16:21:13,545 TRACE [org.jboss.remoting.resource] (Finalizer thread) org.jboss.naming.remote.client.InitialContextFactory$1.close(InitialContextFactory.java:228)
16:21:13,555 TRACE [org.jboss.remoting.resource] (Finalizer thread) org.jboss.naming.remote.client.RemoteContext.finalize(RemoteContext.java:199)
16:21:13,558 TRACE [org.jboss.remoting.resource] (Finalizer thread) java.lang.J9VMInternals.runFinalize(J9VMInternals.java:455)
16:21:13,562 TRACE [org.jboss.remoting.resource] (Finalizer thread) Closing Remoting remote connection provider 50f78597 for endpoint "config-based-naming-client-endpoint" <e6872e7> asynchronously
16:21:13,570 TRACE [org.jboss.remoting.endpoint] (Finalizer thread) Phase 1 shutdown count 00000001 of endpoint "config-based-naming-client-endpoint" <e6872e7> (closed a cancelled connection)
16:21:13,571 TRACE [org.xnio.nio.selector] (Remoting "config-based-naming-client-endpoint" read-1) Beginning select on sun.nio.ch.EPollSelectorImpl at 3e388ef1
16:21:13,574 TRACE [org.xnio.nio.selector] (Remoting "config-based-naming-client-endpoint" read-1) Selected on sun.nio.ch.EPollSelectorImpl at 3e388ef1
16:21:13,576 TRACE [org.xnio.nio.selector] (Remoting "config-based-naming-client-endpoint" read-1) Beginning select on sun.nio.ch.EPollSelectorImpl at 3e388ef1
16:21:13,575 DEBUG [org.jboss.naming.remote.client.HaRemoteNamingStore] (main) Failed to connect to server remote://127.0.0.1:4447: java.lang.RuntimeException: Operation failed with status CANCELLED
at org.jboss.naming.remote.protocol.IoFutureHelper.get(IoFutureHelper.java:89)
at org.jboss.naming.remote.client.HaRemoteNamingStore.failOverSequence(HaRemoteNamingStore.java:180)
at org.jboss.naming.remote.client.HaRemoteNamingStore.namingStore(HaRemoteNamingStore.java:131)
at org.jboss.naming.remote.client.HaRemoteNamingStore.namingOperation(HaRemoteNamingStore.java:112)
at org.jboss.naming.remote.client.HaRemoteNamingStore.lookup(HaRemoteNamingStore.java:223)
at org.jboss.naming.remote.client.RemoteContext.lookup(RemoteContext.java:79)
at org.jboss.naming.remote.client.RemoteContext.lookup(RemoteContext.java:83)
at javax.naming.InitialContext.lookup(InitialContext.java:422)
at org.jboss.as.test.integration.naming.remote.simple.RemoteNamingTestCase.testRemoteLookup(RemoteNamingTestCase.java:77)
{noformat}
The current test method which does not work on IBM JDK is as follows:
{code}
@Test public void testRemoteLookup() throws Exception {
assertEquals("TestValue", getRemoteContext().lookup("test"));
}
{code}
And this is a slightly modified test method which works on IBM JDK nicely (it holds an explicit reference to the InitialContext):
{code}
@Test public void testRemoteLookup() throws Exception {
Context context = null;
try {
context = getRemoteContext();
assertEquals("TestValue", context.lookup("test"));
} finally {
if (context != null)
context.close();
}
}
{code}
Note that the issue disappears when running with any Byteman's script, i.e. it is not possible to debug it with Byteman. That's the reason why I had to modify the remoting sources to print out a stack trace on closeAsync method entry.
> RemoteNamingTestCase intermittently fails on IBM JDK due to org.jboss.remoting3.NotOpenException: Endpoint is not open
> ----------------------------------------------------------------------------------------------------------------------
>
> Key: AS7-5967
> URL: https://issues.jboss.org/browse/AS7-5967
> Project: Application Server 7
> Issue Type: Feature Request
> Components: Test Suite
> Affects Versions: 7.1.3.Final (EAP)
> Environment: IBM JDK 6
> IBM JDK 7
> Reporter: Ivo Studensky
> Assignee: Ivo Studensky
>
> RemoteNamingTestCase intermittently fails when running on IBM JDK. According to logs the remoting channel had been closed before the endpoint tried to connect to it. Unfortunately, when I was trying to debug this issue the tests always nicely passed.
> test.log snippet:
> {noformat}
> 13:16:31,115 DEBUG [org.xnio.nio] (Remoting "config-based-naming-client-endpoint" read-1) Started channel thread 'Remoting "config-based-naming-client-endpoint" read-1', selector sun.nio.ch.EPollSelectorImpl at 345642e1
> 13:16:31,115 DEBUG [org.xnio.nio] (Remoting "config-based-naming-client-endpoint" write-1) Started channel thread 'Remoting "config-based-naming-client-endpoint" write-1', selector sun.nio.ch.EPollSelectorImpl at 1dc68cf2
> 13:16:31,121 DEBUG [org.jboss.naming.remote.client.InitialContextFactory] (main) jboss.naming.client.connect.options. has the following options {org.xnio.Options.SASL_POLICY_NOPLAINTEXT=>false}
> 13:16:31,191 ERROR [org.jboss.naming.remote.protocol.v1.RemoteNamingStoreV1] (Remoting "config-based-naming-client-endpoint" task-1) Channel end notification received, closing channel Channel ID d1f17196 (outbound) of Remoting connection fd3dcedc to /127.0.0.1:4447
> 13:16:31,204 DEBUG [org.jboss.naming.remote.client.HaRemoteNamingStore] (main) Failed to connect to server remote://127.0.0.1:4447: org.jboss.remoting3.NotOpenException: Endpoint is not open
> at org.jboss.remoting3.EndpointImpl.resourceUntick(EndpointImpl.java:182)
> at org.jboss.remoting3.EndpointImpl.doConnect(EndpointImpl.java:261)
> at org.jboss.remoting3.EndpointImpl.doConnect(EndpointImpl.java:251)
> at org.jboss.remoting3.EndpointImpl.connect(EndpointImpl.java:349)
> at org.jboss.remoting3.EndpointImpl.connect(EndpointImpl.java:333)
> at org.jboss.naming.remote.client.EndpointCache$EndpointWrapper.connect(EndpointCache.java:105)
> at org.jboss.naming.remote.client.HaRemoteNamingStore.failOverSequence(HaRemoteNamingStore.java:179)
> at org.jboss.naming.remote.client.HaRemoteNamingStore.namingOperation(HaRemoteNamingStore.java:117)
> at org.jboss.naming.remote.client.HaRemoteNamingStore.lookup(HaRemoteNamingStore.java:223)
> at org.jboss.naming.remote.client.RemoteContext.lookup(RemoteContext.java:79)
> at org.jboss.naming.remote.client.RemoteContext.lookup(RemoteContext.java:83)
> at javax.naming.InitialContext.lookup(InitialContext.java:422)
> at org.jboss.as.test.integration.naming.remote.simple.RemoteNamingTestCase.testRemoteLookup(RemoteNamingTestCase.java:74)
> {noformat}
> server.log snippet:
> {noformat}
> 13:16:31,025 INFO [org.jboss.as.server] (management-handler-thread - 3) JBAS018559: Deployed "test.jar"
> 13:16:31,163 DEBUG [org.jboss.naming.remote.server.RemoteNamingService] (Remoting "thinkpax" task-3) Channel Opened - Channel ID 51f17196 (inbound) of Remoting connection b9da2788 to /127.0.0.1:46866
> 13:16:31,176 DEBUG [org.jboss.naming.remote.server.RemoteNamingService] (Remoting "thinkpax" task-4) Chosen version 0x01
> 13:16:31,189 DEBUG [org.jboss.naming.remote.server.RemoteNamingService] (Remoting "thinkpax" read-1) Channel Channel ID 51f17196 (inbound) of Remoting connection b9da2788 to /127.0.0.1:46866 closed.
> 13:16:31,193 INFO [org.jboss.as.naming] (Remoting "thinkpax" task-1) JBAS011806: Channel end notification received, closing channel Channel ID 51f17196 (inbound) of Remoting connection b9da2788 to null
> {noformat}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
More information about the jboss-jira
mailing list