PaxLogginApi bundle's BundleContext is no longer valid in PaxExam tests [PAXEXAM-175]

Bartosz Kowalewski created PAXEXAM-175

From time to time I observe the following error in Pax Exam based tests.

java.lang.ExceptionInInitializerError
    at blah.createCamelContext(AbstractOSGiFlowTest.java:81)
    at blah.AbstractOSGiFlowTest.setUp(AbstractOSGiFlowTest.java:100)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.ops4j.pax.exam.junit.extender.impl.internal.CallableTestMethodImpl.runBefores(CallableTestMethodImpl.java:172)
    at org.ops4j.pax.exam.junit.extender.impl.internal.CallableTestMethodImpl.injectContextAndInvoke(CallableTestMethodImpl.java:124)
    at org.ops4j.pax.exam.junit.extender.impl.internal.CallableTestMethodImpl.call(CallableTestMethodImpl.java:101)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.ops4j.pax.exam.rbc.internal.RemoteBundleContextImpl.remoteCall(RemoteBundleContextImpl.java:80)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:305)
    at sun.rmi.transport.Transport$1.run(Transport.java:159)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.Transport.serviceCall(Transport.java:155)
    at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:619)
Caused by: java.lang.IllegalStateException: BundleContext is no longer valid
    at org.eclipse.osgi.framework.internal.core.BundleContextImpl.checkValid(BundleContextImpl.java:1003)
    at org.eclipse.osgi.framework.internal.core.BundleContextImpl.getBundle(BundleContextImpl.java:151)
    at org.ops4j.pax.logging.OSGIPaxLoggingManager.getLogger(OSGIPaxLoggingManager.java:94)
    at org.apache.commons.logging.LogFactory.getInstance(LogFactory.java:269)
    at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:164)
    at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:146)
    at org.apache.camel.impl.DefaultCamelContext.&lt;clinit&gt;(DefaultCamelContext.java:106)
    ... 28 more

As I said it happens from time to time. I thought that it is because the Pax Logging bundle hasn't been started yet, while the client app already uses logging API. Nevertheless, I got 'IllegalStateException: BundleContext is no longer valid' and not NPE, so I'm puzzled.
I thought that adding a wait (wait for state) for Pax Logging bundles would solve this issue. This could (probably) be incorporated into the logProfile. I think that currently the only bundle for which the pax container waits before starting the test method is the system bundle. It does not wait for other bundles. However, as I wrote above, I'm worried that I'm getting IllegalStateException instead of NPE - I'm not sure if adding additional waits would help.

Oh, one more thing. Of course the brute force workaround that I used in PAXEXAM-174 also got rid of the 'IllegalStateException: BundleContext is no longer valid' error ]:->.

Affects: 1.2.0 Votes: 0, Watches: 1

Toni Menzel commented

yep. But i am not sure if waiting for all bundles to be started is not really always true:

fragments
bundles that i want in resolved or installed state only by purpose

So, first thing you should use is startlevels, to structure your own bundles as well as 3rd party bundles in a way, that things like logging work at the expected point in time.

Solutions:
What i could think of is to have an interceptor in config method that lets you determine if the container is ready or not.
Like:

options(
  waitCondition(
   new Condiition() {
   boolean active(Bundle[] bundles, Integer[] states) {
.. (.implement your condition here.)
}
}
)
)

the condition will run at there place where your "hack" is currently at, ant repeated until its either "true" or timed out.
This will be executed in the host jvm (the one your junit runs in), thats why you don't get a full BundleContext.
That would be the Exam 1.2.x solution i guess which does not change the as-is strategy.

For 2.0 i have a precondition hook in mind that also runs on the server.

wdyt?
Any ideas?

Toni Menzel commented

Well, or make it much simpler and have a "waitForAllBundlesInState(int state)" option ?
This will skip fragments and will be pretty simple to implement.
Maybe it catches the relevant 90% of cases.

Bartosz Kowalewski commented

Ok, so I agree that:

1) An interceptor similar to the one that you described might be useful. However, it would require a lot of work from the one that creates the test case. Lots of digging in symbolic names, versions, etc. I'm lazy, I don't want to be forced to write a lot of code :smile:. Still, it might be useful if some real hacking is really required.

2) The waitForAllBundlesInState(int state) is also nice and I guess it is really a good idea to implement it. Unfortunately our usecase does not fall into these 90% of cases :smile:. We are running tests against a set of bundles that mimic Fuse ESB 4 (SMX 4). Because of the fact that there are around 170 bundles in a standalone installation of Fuse ESB 4, we only let Pax Exam to suck a subset of these. As we are lazy, we use SMX4 features - we do not specify each and every bundle explicitly using mavenBundle().groupId(...)... These features are sometimes not self-sufficient. Inside our Pax Exam tests we have some bundles that cannot be resolved and will probably never be (unless guys from Apache/Progress do some clean-up and divide the features that we use into some smaller ones). In order to make it possible for them to be resolved we would need to add tens of other bundles.
------

I haven't analyzed Pax Exam source code, so I'm not sure if it this is doable, but I was thinking more of this approach:

logProfile().waitForState(int)
mavenBundle().groupId("blah").artifactId("blah").version("1.1.1").waitForState(int)
scanFeatures("blah","blah").waitForState(int)
provision(newBundle().add(...).set(...)..build(withBnd()).waitForState(int))

Is it doable?

Thanks,
Bartek

Toni Menzel commented

2)
yes but of cause requires exam to do the matching on its own.
It is a little bit harder than it might seem in first place because (at least when using 1.2.x or the paxrunner container in 2.0) those urls (mavenBundle and all that produce urls for a certain url handler) are processed by Pax Runner, actually Exam never sees them.
Matching the bundles by symbolicname however should work in most cases.
It just gets hard when profiles fall into place, as they are definitely not resolved upfront as its a core piece of pax runner.

So, yes, in the end it should look like that. How we can archive that, we'll see.
I am strongly target that for the 2.0 branch and do it there with possibly necessary infrastructure changes in place rather than "hacking" it together for 1.x line.

ops4j / org.ops4j.pax.exam2

PaxLogginApi bundle's BundleContext is no longer valid in PaxExam tests [PAXEXAM-175] #299