[sguilhen]

After rebasing my branch to fix the compilation error seen by David, I've run into a snagging issue: half of the time the AS starts fine, half of the time I get the following error:

16:40:20,613 ERROR [org.jboss.msc.service.fail] (MSC service thread 1-7) MSC00001: Failed to start service jboss.iiop.naming-service: org.jboss.msc.service.StartException in service jboss.iiop.naming-service: Failed to start service
    at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1696) [jboss-msc-1.0.0.Beta8.jar:1.0.0.Beta8]
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [:1.6.0_24]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [:1.6.0_24]
    at java.lang.Thread.run(Thread.java:662) [:1.6.0_24]
Caused by: java.lang.ExceptionInInitializerError
    at org.jacorb.orb.Delegate.getReference(Unknown Source)
    at org.jacorb.orb.ORB.getReference(Unknown Source)
    at org.jacorb.poa.POA.getReference(Unknown Source)
    at org.jacorb.poa.POA.create_reference_with_id(Unknown Source)
    at org.jboss.as.iiop.service.CorbaNamingService.start(CorbaNamingService.java:77)
    at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1675) [jboss-msc-1.0.0.Beta8.jar:1.0.0.Beta8]
    ... 3 more
Caused by: org.omg.CORBA.INITIALIZE: Cannot instantiate com.sun.corba.se.impl.javax.rmi.CORBA.StubDelegateImpl
    at javax.rmi.CORBA.Stub.createDelegateIfSpecified(Stub.java:221) [:1.6.0_24]
    at javax.rmi.CORBA.Stub.<clinit>(Stub.java:61) [:1.6.0_24]
    ... 9 more
Caused by: java.lang.ClassNotFoundException: com.sun.corba.se.impl.javax.rmi.CORBA.StubDelegateImpl from [Module "org.jboss.as.standalone:main" from local module loader @48d19bc8 (roots: /home/sguilhen/Workspace/workspace-jboss/jboss-as/build/target/jboss-7.0.0.Beta4-SNAPSHOT/modules)] (no security manager: RMI class loader disabled)
    at sun.rmi.server.LoaderHandler.loadClass(LoaderHandler.java:375) [:1.6.0_24]
    at sun.rmi.server.LoaderHandler.loadClass(LoaderHandler.java:165) [:1.6.0_24]
    at java.rmi.server.RMIClassLoader$2.loadClass(RMIClassLoader.java:620) [:1.6.0_24]
    at java.rmi.server.RMIClassLoader.loadClass(RMIClassLoader.java:202) [:1.6.0_24]
    at java.rmi.server.RMIClassLoader.loadClass(RMIClassLoader.java:135) [:1.6.0_24]
    at javax.rmi.CORBA.Stub.loadDelegateClass(Stub.java:242) [:1.6.0_24]
    at javax.rmi.CORBA.Stub.createDelegateIfSpecified(Stub.java:219) [:1.6.0_24]
    ... 10 more

When it fails, the javax.rmi.CORBA.Stub is coming from the JDK instead of the javax.rmi.api module. Also, we can see that the org.jboss.as.standalone module is attempting to load the delegate, even though this code run from within the org.jboss.as.iiop module.

As I said before, this is not consistent, sometimes I get the error, sometimes the server starts correctly. This wasn't happening before today's rebase, so I'm guessing something changed in the modules project. Any ideas?

[sguilhen]

I've enabled the TRACE debug level for org.jboss.modules and here's what I've found out so far:

- When the startup succeeds, the javax.rmi.CORBA.Stub is loaded and defined from the javax.rmi.api module. Then the server attempts to load the com.sun.corba.se.impl.javax.rmi.CORBA.StubDelegateImpl class from the same module. It shows that this class can't be loaded from this module but the server goes on and starts correctly. No other entries involving this class are found:

18:30:17,470 TRACE [org.jboss.modules] (MSC service thread 1-14) Finding class javax.rmi.CORBA.Stub from Module "org.jacorb:main" from local module loader @6b86768e (roots: /home/sguilhen/Workspace/workspace-jboss/jboss-as/build/target/jboss-7.0.0.Beta4-SNAPSHOT/modules)
18:30:17,470 TRACE [org.jboss.modules] (MSC service thread 1-14) Finding local class javax.rmi.CORBA.Stub from Module "javax.rmi.api:main" from local module loader @6b86768e (roots: /home/sguilhen/Workspace/workspace-jboss/jboss-as/build/target/jboss-7.0.0.Beta4-SNAPSHOT/modules)
18:30:17,470 TRACE [org.jboss.modules] (MSC service thread 1-14) Loading class javax.rmi.CORBA.Stub locally from Module "javax.rmi.api:main" from local module loader @6b86768e (roots: /home/sguilhen/Workspace/workspace-jboss/jboss-as/build/target/jboss-7.0.0.Beta4-SNAPSHOT/modules)
18:30:17,471 TRACE [org.jboss.modules] (MSC service thread 1-14) Attempting to define class javax.rmi.CORBA.Stub in Module "javax.rmi.api:main" from local module loader @6b86768e (roots: /home/sguilhen/Workspace/workspace-jboss/jboss-as/build/target/jboss-7.0.0.Beta4-SNAPSHOT/modules)
...
18:30:17,472 TRACE [org.jboss.modules] (MSC service thread 1-14) Defined class javax.rmi.CORBA.Stub in Module "javax.rmi.api:main" from local module loader @6b86768e (roots: /home/sguilhen/Workspace/workspace-jboss/jboss-as/build/target/jboss-7.0.0.Beta4-SNAPSHOT/modules)
...
18:30:17,485 TRACE [org.jboss.modules] (MSC service thread 1-14) Finding class com.sun.corba.se.impl.javax.rmi.CORBA.StubDelegateImpl from Module "javax.rmi.api:main" from local module loader @6b86768e (roots: /home/sguilhen/Workspace/workspace-jboss/jboss-as/build/target/jboss-7.0.0.Beta4-SNAPSHOT/modules)
18:30:17,485 TRACE [org.jboss.modules] (MSC service thread 1-14) Class com.sun.corba.se.impl.javax.rmi.CORBA.StubDelegateImpl not found from Module "javax.rmi.api:main" from local module loader @6b86768e (roots: /home/sguilhen/Workspace/workspace-jboss/jboss-as/build/target/jboss-7.0.0.Beta4-SNAPSHOT/modules)

- When the startup fails, javax.rmi.CORBA.Stub is loaded just like shown before, but when the server attempts to load the StubDelegateImpl, two modules are involved: javax.rmi.api and org.jboss.as.standalone. After that, the logs show that org.jboss.as.standalone attempts to load javax.rmi.CORBA.Stub, which ultimately loads the JDK version of the class we see in the exception.

18:25:04,039 TRACE [org.jboss.modules] (MSC service thread 1-1) Finding class com.sun.corba.se.impl.javax.rmi.CORBA.StubDelegateImpl from Module "javax.rmi.api:main" from local module loader @6b86768e (roots: /home/sguilhen/Workspace/workspace-jboss/jboss-as/build/target/jboss-7.0.0.Beta4-SNAPSHOT/modules)
18:25:04,039 TRACE [org.jboss.modules] (MSC service thread 1-1) Class com.sun.corba.se.impl.javax.rmi.CORBA.StubDelegateImpl not found from Module "javax.rmi.api:main" from local module loader @6b86768e (roots: /home/sguilhen/Workspace/workspace-jboss/jboss-as/build/target/jboss-7.0.0.Beta4-SNAPSHOT/modules)
18:25:04,040 TRACE [org.jboss.modules] (MSC service thread 1-1) Finding class com.sun.corba.se.impl.javax.rmi.CORBA.StubDelegateImpl from Module "org.jboss.as.standalone:main" from local module loader @6b86768e (roots: /home/sguilhen/Workspace/workspace-jboss/jboss-as/build/target/jboss-7.0.0.Beta4-SNAPSHOT/modules)
18:25:04,040 TRACE [org.jboss.modules] (MSC service thread 1-1) Class com.sun.corba.se.impl.javax.rmi.CORBA.StubDelegateImpl not found from Module "org.jboss.as.standalone:main" from local module loader @6b86768e (roots: /home/sguilhen/Workspace/workspace-jboss/jboss-as/build/target/jboss-7.0.0.Beta4-SNAPSHOT/modules)
...
18:25:04,043 TRACE [org.jboss.modules] (MSC service thread 1-1) Finding class javax.rmi.CORBA.Stub from Module "org.jboss.as.standalone:main" from local module loader @6b86768e (roots: /home/sguilhen/Workspace/workspace-jboss/jboss-as/build/target/jboss-7.0.0.Beta4-SNAPSHOT/modules)
18:25:04,043 TRACE [org.jboss.modules] (MSC service thread 1-1) Class javax.rmi.CORBA.Stub not found from Module "org.jboss.as.standalone:main" from local module loader @6b86768e (roots: /home/sguilhen/Workspace/workspace-jboss/jboss-as/build/target/jboss-7.0.0.Beta4-SNAPSHOT/modules)

In this case, the org.jboss.as.standalone module attempts to load the class right after the javax.rmi.api module fails to do so and this messes up everything. I even found the following entry:

18:25:04,046 TRACE [org.jboss.modules] (MSC service thread 1-1) Finding class org.jboss.as.iiop.service.CorbaNamingService from Module "org.jboss.as.standalone:main" from local module loader @6b86768e (roots: /home/sguilhen/Workspace/workspace-jboss/jboss-as/build/target/jboss-7.0.0.Beta4-SNAPSHOT/modules)
18:25:04,046 TRACE [org.jboss.modules] (MSC service thread 1-1) Class org.jboss.as.iiop.service.CorbaNamingService not found from Module "org.jboss.as.standalone:main" from local module loader @6b86768e (roots: /home/sguilhen/Workspace/workspace-jboss/jboss-as/build/target/jboss-7.0.0.Beta4-SNAPSHOT/modules)

For some reason, org.jboss.as.standalone is attempting to load the CorbaNamingService class which should be visible to the org.jboss.as.iiop module only.

[jason.greene]

So the problem is indeed TCCL usage from the Stub fork, along with a reference to a com.sun class:

http://anonsvn.jboss.org/repos/jbossas/projects/specs/trunk/jboss-rmi-api_1.0_spec/src/main/java/javax/rmi/CORBA/Stub.java

The reason it works occasionally is that when TCCL is null Class.forName falls back to the JDK which can load the sun class. When it is not null it tries to load it from the leaked TCCL which according to your log is the server module which doesnt cotain the class.

So it seems like we just need to port that stub base clase.

[sguilhen]

Jason, I fixed that locally yesterday and I still get the random error. I'll double check I have used the fixed version.

[sguilhen]

Yeah, I've enable a logger for the Stub class and it shows your description when TCCL is used. However, I've changed the code locally to ClassLoader loader = Stub.class.getClassLoader(); and the logs always show

ModuleClassLoader for Module "javax.rmi.api:main"

but the random error still persists.

[jason.greene]

Stefan Guilhen wrote:

Yeah, I've enable a logger for the Stub class and it shows your description when TCCL is used. However, I've changed the code locally to ClassLoader loader = Stub.class.getClassLoader(); and the logs always show

ModuleClassLoader for Module "javax.rmi.api:main"

but the random error still persists.

Did you try providing an impl of com.sun.corba.se.impl.javax.rmi.CORBA.StubDelegateImpl, and removing all dynamic loading altogether, it shouldnt be needed?

That code in Stub falls back to RMIClassLoader, which also uses TCCL internally.

[sguilhen]

That may work, I'll try it.

[sguilhen]

After a couple of changes I got the code running:

1- I now do new com.sun.corba.se.impl.javax.rmi.CORBA.StubDelegateImpl(); instead of reflectively loading and instantiating the delegate. The reflective approach is only used if the javax.rmi.CORBA.Stub sysproperty is specified.

2- I had to introduce a com.sun.corba module that exposes the com.sun.corba.se.impl packages of the system module and make the javax.rmi.api module depend on it.

Do you see any problems with this approach?