On demand resolution

[thomas.diesler]

I created a test for DynamicImport-Package to check whether https://jira.jboss.org/jira/browse/JBCL-131 is actually working at the OSGi layer.

I still get a CNFE. Here is the trace

2010-03-26 11:24:06,939 INFO  [org.jboss.osgi.framework.plugins.internal.FrameworkEventsPluginImpl] Bundle INSTALLED: Bundle{osgi.cmpn-4.2.0.200908310645}
2010-03-26 11:24:06,939 DEBUG [org.jboss.osgi.framework.bundle.OSGiBundleManager] Added: Bundle{osgi.cmpn-4.2.0.200908310645}
2010-03-26 11:24:06,940 DEBUG [org.jboss.classloading.spi.dependency.Domain] org.jboss.classloading.spi.dependency.Domain@191e4c{OSGiClassLoaderDomain} add module OSGiModule osgi.cmpn:4.2.0.200908310645
2010-03-26 11:24:06,940 TRACE [org.jboss.classloading.spi.dependency.ClassLoadingSpace] OSGiModule osgi.cmpn:4.2.0.200908310645 joining org.jboss.classloading.spi.dependency.ClassLoadingSpace@1984a9d
2010-03-26 11:24:06,943 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] OSGiBundleClassLoader@17ebe66{dynamic-log-service-0.0.0} loadClass org.osgi.service.log.LogService resolve=false
2010-03-26 11:24:06,944 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] OSGiBundleClassLoader@17ebe66{dynamic-log-service-0.0.0} aquireLockFairly Thread[main,5,main]
2010-03-26 11:24:06,945 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] OSGiBundleClassLoader@17ebe66{dynamic-log-service-0.0.0} aquiredLock Thread[main,5,main] holding=1
2010-03-26 11:24:06,947 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] OSGiBundleClassLoader@17ebe66{dynamic-log-service-0.0.0} load from domain org.osgi.service.log.LogService domain=OSGiClassLoaderDomain@2bfdff{OSGiClassLoaderDomain}
2010-03-26 11:24:06,947 TRACE [org.jboss.classloader.spi.base.BaseClassLoaderDomain] OSGiClassLoaderDomain@2bfdff{OSGiClassLoaderDomain} findLoader org/osgi/service/log/LogService.class classLoader=OSGiBundleClassLoader@17ebe66{dynamic-log-service-0.0.0} allExports=false findInParent=true
2010-03-26 11:24:06,948 TRACE [org.jboss.classloader.spi.ClassLoaderDomain] OSGiClassLoaderDomain@2bfdff{OSGiClassLoaderDomain} org/osgi/service/log/LogService.class does NOT match parent beforeFilter=[java], OSGI_CORE, [org.osgi.framework, org.osgi.framework.hooks, org.osgi.framework.hooks.service, org.osgi.framework.launch, org.osgi.service.condpermadmin, org.osgi.service.packageadmin, org.osgi.service.permissionadmin, org.osgi.service.startlevel, org.osgi.service.url, javax.imageio, javax.imageio.stream, javax.management, javax.management.loading, javax.management.modelmbean, javax.management.monitor, javax.management.openmbean, javax.management.relation, javax.management.remote, javax.management.remote.rmi, javax.management.timer, javax.naming, javax.naming.event, javax.naming.spi, javax.net, javax.net.ssl, javax.xml.datatype, javax.xml.namespace, javax.xml.parsers, javax.xml.transform, javax.xml.transform.dom, javax.xml.transform.sax, javax.xml.transform.stream, javax.xml.validation, org.apache.log4j, org.jboss.beans.metadata.plugins.builder, org.jboss.beans.metadata.plugins, org.jboss.beans.metadata.spi.builder, org.jboss.beans.metadata.spi, org.jboss.dependency.spi, org.jboss.kernel.spi.dependency, org.jboss.logging, org.jboss.osgi.deployment.deployer, org.jboss.osgi.deployment.interceptor, org.jboss.osgi.spi.capability, org.jboss.osgi.spi.framework, org.jboss.osgi.spi.service, org.jboss.osgi.spi.util, org.jboss.osgi.spi, org.jboss.osgi.testing, org.w3c.dom, org.w3c.dom.bootstrap, org.w3c.dom.events, org.w3c.dom.ls, org.w3c.dom.ranges, org.w3c.dom.traversal, org.w3c.dom.views, org.xml.sax, org.xml.sax.ext, org.xml.sax.helpers]
2010-03-26 11:24:06,948 TRACE [org.jboss.classloader.spi.base.BaseClassLoaderDomain] OSGiClassLoaderDomain@2bfdff{OSGiClassLoaderDomain} not loading org/osgi/service/log/LogService.class from all exports
2010-03-26 11:24:06,948 TRACE [org.jboss.classloader.spi.base.BaseClassLoaderDomain] OSGiClassLoaderDomain@2bfdff{OSGiClassLoaderDomain} trying to load org/osgi/service/log/LogService.class from import LazyFilteredDelegateLoader@12dd76{factory=org.jboss.classloading.spi.dependency.policy.DynamicClassLoaderPolicyFactory@8990e4} for OSGiBundleClassLoader@17ebe66{dynamic-log-service-0.0.0}
2010-03-26 11:24:06,948 TRACE [org.jboss.classloader.spi.filter.FilteredDelegateLoader] LazyFilteredDelegateLoader@12dd76{factory=org.jboss.classloading.spi.dependency.policy.DynamicClassLoaderPolicyFactory@8990e4} org/osgi/service/log/LogService.class matches resource filter=<EVERYTHING>
2010-03-26 11:24:06,948 TRACE [org.jboss.classloading.spi.dependency.ClassLoadingSpace] OSGiModule dynamic-log-service:0.0.0 resolving org.jboss.classloading.spi.dependency.ClassLoadingSpace@d306dd
2010-03-26 11:24:06,948 TRACE [org.jboss.classloader.spi.base.BaseDelegateLoader] Factory did not create a delegate: org.jboss.classloading.spi.dependency.policy.DynamicClassLoaderPolicyFactory@8990e4
2010-03-26 11:24:06,949 WARN  [org.jboss.classloader.spi.base.BaseDelegateLoader] Not getting resource org/osgi/service/log/LogService.class from policy that has no classLoader: LazyFilteredDelegateLoader@12dd76{factory=org.jboss.classloading.spi.dependency.policy.DynamicClassLoaderPolicyFactory@8990e4 filter=<EVERYTHING>}
2010-03-26 11:24:06,949 TRACE [org.jboss.classloader.spi.base.BaseClassLoaderDomain] OSGiClassLoaderDomain@2bfdff{OSGiClassLoaderDomain} trying to load org/osgi/service/log/LogService.class from requesting OSGiBundleClassLoader@17ebe66{dynamic-log-service-0.0.0}
2010-03-26 11:24:06,949 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] OSGiBundleClassLoader@17ebe66{dynamic-log-service-0.0.0} get resource locally org/osgi/service/log/LogService.class
2010-03-26 11:24:06,950 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] OSGiBundleClassLoader@17ebe66{dynamic-log-service-0.0.0} resource not found locally org/osgi/service/log/LogService.class
2010-03-26 11:24:06,950 TRACE [org.jboss.classloader.spi.ClassLoaderDomain] OSGiClassLoaderDomain@2bfdff{OSGiClassLoaderDomain} org/osgi/service/log/LogService.class does NOT match parent afterFilter=<NOTHING>
2010-03-26 11:24:06,952 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] OSGiBundleClassLoader@17ebe66{dynamic-log-service-0.0.0} unlock Thread[main,5,main] holding=1
2010-03-26 11:24:06,952 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] OSGiBundleClassLoader@17ebe66{dynamic-log-service-0.0.0} class not found org.osgi.service.log.LogService

Perhaps these are of special interest

[org.jboss.classloader.spi.base.BaseDelegateLoader] Factory did not create a delegate: org.jboss.classloading.spi.dependency.policy.DynamicClassLoaderPolicyFactory@8990e4
[org.jboss.classloader.spi.base.BaseDelegateLoader] Not getting resource org/osgi/service/log/LogService.class from policy that has no classLoader: LazyFilteredDelegateLoader@12dd76{factory=org.jboss.classloading.spi.dependency.policy.DynamicClassLoaderPolicyFactory@8990e4 filter=<EVERYTHING>}

Looking at the documentation I can't see waht I have missed. Just joking, there is of course no documentation on how this is suposed to work. I reopend the issue.

[thomas.diesler]

On the PackageRequirement I set

         // DynamicImport-Package
         if (isDynamic == true)
            setDynamic(true);

What else is there to do? Do we need to add special delegates to the policy?

[alesj]

I created a test for DynamicImport-Package to check whether https://jira.jboss.org/jira/browse/JBCL-131 is actually working at the OSGi layer.

I fail to see how dynamic import and JBCL-131 are related?

JBCL-131 is an impl of OSGi' lazy bundle activation -- e.g. only invoke BundleActivator if some class from that bundle needs to be loaded.

[adrian.brock]

Ales Justin wrote:

I created a test for DynamicImport-Package to check whether https://jira.jboss.org/jira/browse/JBCL-131 is actually working at the OSGi layer.

I fail to see how dynamic import and JBCL-131 are related?

JBCL-131 is an impl of OSGi' lazy bundle activation -- e.g. only invoke BundleActivator if some class from that bundle needs to be loaded.

Well actually JBCL-131 is about lazy resolve, not lazy start.

It's not working because it hasn't been enabled.

I've committed the following patch which makes it work using Ales's DeploymentMetaData

(I've not done anything with lazy start).

I don't know if that is the correct place for it?

Another question is whether you always want to enable lazy resolve for OSGi, even if the user specifies something else?

P.S. There's no point re-opening issues in closed releases. You need to raise new issues.

/core/src/main/java/org/jboss/osgi/framework/deployers
$ svn diff
Index: AbstractClassLoadingDeployer.java
===================================================================
--- AbstractClassLoadingDeployer.java    (revision 103238)
+++ AbstractClassLoadingDeployer.java    (working copy)
@@ -29,6 +29,7 @@
import org.jboss.classloading.spi.metadata.CapabilitiesMetaData;
import org.jboss.classloading.spi.metadata.ClassLoadingMetaData;
import org.jboss.classloading.spi.metadata.RequirementsMetaData;
+import org.jboss.deployers.plugins.classloading.DeploymentMetaData;
import org.jboss.deployers.spi.DeploymentException;
import org.jboss.deployers.spi.deployer.DeploymentStages;
import org.jboss.deployers.spi.deployer.helpers.AbstractSimpleRealDeployer;
@@ -61,7 +62,10 @@
    {
       super(OSGiMetaData.class);
       addInput(AbstractBundleState.class);
-      setOutput(ClassLoadingMetaData.class);
+      addInput(ClassLoadingMetaData.class);
+      addInput(DeploymentMetaData.class);
+      addOutput(ClassLoadingMetaData.class);
+      addOutput(DeploymentMetaData.class);
       setStage(DeploymentStages.POST_PARSE);
       setTopLevelOnly(true);
    }
@@ -79,6 +83,13 @@
    @Override
    public void deploy(DeploymentUnit unit, OSGiMetaData osgiMetaData) throws DeploymentException
    {
+      if (unit.isAttachmentPresent(DeploymentMetaData.class) == false)
+      {
+         DeploymentMetaData deploymentMetaData = new DeploymentMetaData();
+         deploymentMetaData.setLazyResolve(true);
+         unit.addAttachment(DeploymentMetaData.class, deploymentMetaData);
+      }
+     
       if (unit.isAttachmentPresent(ClassLoadingMetaData.class))
          return;

[adrian.brock]

Adrian Brock wrote:

I've committed the following patch which makes it work using Ales's DeploymentMetaData
<snip/>
+import org.jboss.deployers.plugins.classloading.DeploymentMetaData;

P.S.2 Shouldn't this metadata be in the spi?

[alesj]

Adrian Brock wrote:

Adrian Brock wrote:

I've committed the following patch which makes it work using Ales's DeploymentMetaData
<snip/>
+import org.jboss.deployers.plugins.classloading.DeploymentMetaData;

P.S.2 Shouldn't this metadata be in the spi?

I guess for this one it's not too late to be moved there -- as it's been only introduced in 2.2.0.AlphaX?

(dunno why I put it there in the first place, might be same stupid reason as DepenenciesMD)

What about DependenciesMetaData -- which is also in impl/plugins?

Since this one has been around longer. :-(

[alesj]

I guess for this one it's not too late to be moved there -- as it's been only introduced in 2.2.0.AlphaX?

https://jira.jboss.org/jira/browse/JBDEPLOY-255

[thomas.diesler]

This change causes regression in bundle lifecycle handling. I added test coverage for this in the framework's BundleLifecycleTestCase

The issue is that a bundle may automatically progress to state RESOLVED after it gets installed . The expected behaviour is that a bundle stays in state INSTALLED until the first class load triggers a state change to RESOLVED. It is important that bundles do not get resolved one-by-one as they get installed because this may lead to undesired wirings. i.e. the resolver might no be able to correctly wire a set of bundles together

Consider, bundle B imports a package from bundle X. B gets installed. Starting B fails because of the the unresolved constraint. Later X gets installed and is expected to be in state INSTALLED. Currently, X progresses unexpectedly to state RESOLVED.

      Bundle bundleB = installBundle(assembleArchive("lifecycle-bundleB", "/bundles/lifecycle/bundleB", ActivatorB.class, ServiceB.class));
      assertBundleState(Bundle.INSTALLED, bundleB.getState());

      try
      {
         bundleB.start();
         fail("Unresolved constraint expected");
      }
      catch (BundleException ex)
      {
         // expected
      }

      Bundle bundleX = installBundle(assembleArchive("lifecycle-bundleX", "/bundles/lifecycle/bundleX", X.class));
      System.out.println("FIXME [JBDEPLOY-245] Unexpected dependee state changes");
      //assertBundleState(Bundle.INSTALLED, bundleX.getState());

I still need to look into the details of why this would happen.

[thomas.diesler]

What is the semantics of this?

DeploymentMetaData deploymentMetaData = new DeploymentMetaData();
deploymentMetaData.setLazyResolve(true);

Ales, could you please document this API?

Currently, every bundle deployment is set to "lazy resolve".

Could you please document the effect of this and why it should be correct.

[adrian.brock]

Thomas Diesler wrote:

This change causes regression in bundle lifecycle handling. I added test coverage for this in the framework's BundleLifecycleTestCase

<snip/>

I still need to look into the details of why this would happen.

It's happening because B's deployment unit has required-stage of "CLASSLOADER" (RESOLVED in OSGi) after the start() failed.

i.e. it wants to resolve it.

So when you install bundleX, it also says, hey B is not in the correct state and I can resolve it now,

but only by moving X to ClassLoader as well.

That is what lazy resolve is all about. It automatically resolves other classloaders that it needs if they are not resolved.

If B went back to required-stage "DESCRIBE" (INSTALLED in OSGi) after the start() failed then your test would work as expected.

I worked this out by adding the following to the test after the b.start() failure:

         OSGiBundleState bs = (OSGiBundleState) getBundleManager().getBundleState(bundleB);
         System.out.println(bundleB.getSymbolicName() + " state=" + ConstantsHelper.bundleState(bundleB.getState()) + " required=" + bs.getDeploymentUnit().getRequiredStage());

Which produces:

lifecycle-bundleB state=INSTALLED required=ClassLoader

So you can see the bundle state is inconsistent with the deployment unit state.

[thomas.diesler]

ok - thanks for the quick reply.

[adrian.brock]

This patch resolves the issue. It was only resetting the state if DeployerClient.change() threw a DeploymentException,

while in this case, there's no exception it is just incomplete.

core/src/main/java/org/jboss/osgi/framework/packageadmin
$ svn diff
Index: PackageAdminImpl.java
===================================================================
--- PackageAdminImpl.java    (revision 103305)
+++ PackageAdminImpl.java    (working copy)
@@ -347,6 +347,18 @@
       {
          log.error("Error resolving bundles: " + resolvableBundles, ex);
          allResolved = false;
+        
+         // Reset the required state for bundles that didn't get resolved
+         for (OSGiBundleState bundleState : resolvableBundles)
+         {
+            if (bundleState.getState() == Bundle.INSTALLED)
+            {
+               DeploymentUnit unit = bundleState.getDeploymentUnit();
+               unit.setRequiredStage(DeploymentStages.DESCRIBE);
+               ControllerContext ctx = unit.getAttachment(ControllerContext.class);
+               ctx.setRequiredState(ControllerState.newState(DeploymentStages.DESCRIBE.getName()));
+            }
+         }
       }
      
       return allResolved;

[alesj]

+               ctx.setRequiredState(ControllerState.newState(DeploymentStages.DESCRIBE.getName()));

This should be ControllerState.getInstance instead of ::newState, althought impl details will show it's the same result at the end. :-)

[adrian.brock]

To pass one of the other tests you added, I had to change the OSGi classloader shutdown policy to GC.

I thought you'd done that a while ago, but apparantly not (at least I couldn't find it?)

Index: AbstractClassLoadingDeployer.java
===================================================================
--- AbstractClassLoadingDeployer.java    (revision 103305)
+++ AbstractClassLoadingDeployer.java    (working copy)
@@ -26,6 +26,7 @@
import java.util.List;

import org.jboss.classloader.spi.ClassLoaderDomain;
+import org.jboss.classloader.spi.ShutdownPolicy;
import org.jboss.classloading.spi.metadata.CapabilitiesMetaData;
import org.jboss.classloading.spi.metadata.ClassLoadingMetaData;
import org.jboss.classloading.spi.metadata.RequirementsMetaData;
@@ -100,6 +101,7 @@
       OSGiBundleManager bundleManager = bundleState.getBundleManager();

       OSGiClassLoadingMetaData classLoadingMetaData = new OSGiClassLoadingMetaData();
       classLoadingMetaData.setName(bundleState.getSymbolicName());
       classLoadingMetaData.setVersion(bundleState.getVersion());
       classLoadingMetaData.setDomain(domain != null ? domain.getName() : null);

+      classLoadingMetaData.setShutdownPolicy(ShutdownPolicy.GARBAGE_COLLECTION);

In case you missed it:

http://community.jboss.org/thread/147089

http://community.jboss.org/thread/148829

[thomas.diesler]

I changed the reset logic such that it resets to the state that it was before the resolve attept.

Instead of always reset to "DESCRIBE".

      // Advance the bundles to stage CLASSLOADER and check at the end
      if (advanceBundlesToClassloader(resolvableBundles) == false)
      {
         resetBundleDeploymentStates(resolvableBundles);
         allResolved = false;
      }

private void resetBundleDeploymentStates(List<OSGiBundleState> resolvableBundles) 
   {
      for (OSGiBundleState bundleState: resolvableBundles)
      {
         DeploymentUnit unit = bundleState.getDeploymentUnit();
         StateTuple stateTuple = unit.removeAttachment(StateTuple.class);
         if (stateTuple != null)
         {
            stateTuple.reset(unit);
         }
      }
   }

The DeploymentMetaData is not available in 6.0.0.M2, so I had to refactor that out into a separate deployer that does a noop in M2.

With the recent change we also get spurious WARN messages

22:54:34,034 WARN  [BaseDelegateLoader] Not getting package org.osgi.service.log from policy that has no classLoader: LazyFilteredDelegateLoader@191eb90{factory=org.jboss.classloading.spi.dependency.policy.DynamicClassLoaderPolicyFactory@1004a1a filter=<EVERYTHING>}
22:54:34,040 WARN  [BaseDelegateLoader] Not getting package org.osgi.service.log from policy that has no classLoader: LazyFilteredDelegateLoader@191eb90{factory=org.jboss.classloading.spi.dependency.policy.DynamicClassLoaderPolicyFactory@1004a1a filter=<EVERYTHING>}
22:54:34,065 INFO  [FrameworkEventsPluginImpl] Service REGISTERED: Service{id=8,classes=[org.osgi.service.log.LogService]}
22:54:34,069 INFO  [FrameworkEventsPluginImpl] Service REGISTERED: Service{id=9,classes=[org.osgi.service.log.LogReaderService]}
22:54:34,075 WARN  [BaseDelegateLoader] Not getting package org.osgi.util.tracker from policy that has no classLoader: LazyFilteredDelegateLoader@191eb90{factory=org.jboss.classloading.spi.dependency.policy.DynamicClassLoaderPolicyFactory@1004a1a filter=<EVERYTHING>}
22:54:34,076 WARN  [BaseDelegateLoader] Not getting package org.osgi.util.tracker from policy that has no classLoader: LazyFilteredDelegateLoader@191eb90{factory=org.jboss.classloading.spi.dependency.policy.DynamicClassLoaderPolicyFactory@1004a1a filter=<EVERYTHING>}
22:54:34,076 WARN  [BaseDelegateLoader] Not getting resource org/osgi/util/tracker/ServiceTrackerCustomizer.class from policy that has no classLoader: LazyFilteredDelegateLoader@191eb90{factory=org.jboss.classloading.spi.dependency.policy.DynamicClassLoaderPolicyFactory@1004a1a filter=<EVERYTHING>}
22:54:34,111 WARN  [BaseDelegateLoader] Not getting resource org/osgi/util/tracker/ServiceTracker$AllTracked.class from policy that has no classLoader: LazyFilteredDelegateLoader@191eb90{factory=org.jboss.classloading.spi.dependency.policy.DynamicClassLoaderPolicyFactory@1004a1a filter=<EVERYTHING>}
22:54:34,112 WARN  [BaseDelegateLoader] Not getting resource org/osgi/util/tracker/ServiceTracker$Tracked.class from policy that has no classLoader: LazyFilteredDelegateLoader@191eb90{factory=org.jboss.classloading.spi.dependency.policy.DynamicClassLoaderPolicyFactory@1004a1a filter=<EVERYTHING>}
22:54:34,114 WARN  [BaseDelegateLoader] Not getting resource org/osgi/util/tracker/AbstractTracked.class from policy that has no classLoader: LazyFilteredDelegateLoader@191eb90{factory=org.jboss.classloading.spi.dependency.policy.DynamicClassLoaderPolicyFactory@1004a1a filter=<EVERYTHING>}

which is because the DynamicClassLoaderPolicyFactory does not create a policy. Not sure how this is suposed to work.