I just updated the trunk, and ran a mvn test, and indeed, found an lllegal
state exception:
(notice the "should not be called" trace):
.....
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.B] Activating
component
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.B] No change in
target property for dependency c
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.B] State
transition : Unsatisfied -> Registered
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.B] registering
services
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.A] Dependency
Manager: Adding Service
org.apache.felix.scr.integration.components.concurrency.B/6623
log level: 1 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1: FrameworkEvent
ERROR
java.lang.IllegalStateException: Should not be called
at
org.apache.felix.scr.impl.manager.ComponentFactoryImpl.invokeBindMethod(ComponentFactoryImpl.java:285)
at
org.apache.felix.scr.impl.manager.DependencyManager.serviceAdded(DependencyManager.java:355)
at
org.apache.felix.scr.impl.manager.DependencyManager.serviceChanged(DependencyManager.java:163)
at
org.apache.felix.framework.util.EventDispatcher.invokeServiceListenerCallback(EventDispatcher.java:932)
at
org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:793)
at
org.apache.felix.framework.util.EventDispatcher.fireServiceEvent(EventDispatcher.java:543)
at
org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:4260)
at org.apache.felix.framework.Felix.registerService(Felix.java:3275)
at
org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:346)
at
org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:721)
at
org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:704)
at
org.apache.felix.scr.impl.manager.AbstractComponentManager.registerComponentService(AbstractComponentManager.java:749)
at
org.apache.felix.scr.impl.manager.AbstractComponentManager$Unsatisfied.activate(AbstractComponentManager.java:1522)
at
org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:614)
at
org.apache.felix.scr.impl.manager.DependencyManager.serviceAdded(DependencyManager.java:286)
at
org.apache.felix.scr.impl.manager.DependencyManager.serviceChanged(DependencyManager.java:163)
at
org.apache.felix.framework.util.EventDispatcher.invokeServiceListenerCallback(EventDispatcher.java:932)
at
org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:793)
at
org.apache.felix.framework.util.EventDispatcher.fireServiceEvent(EventDispatcher.java:543)
at
org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:4260)
at org.apache.felix.framework.Felix.registerService(Felix.java:3275)
at
org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:346)
at
org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:721)
at
org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:704)
at
org.apache.felix.scr.impl.manager.AbstractComponentManager.registerComponentService(AbstractComponentManager.java:749)
at
org.apache.felix.scr.impl.manager.AbstractComponentManager$Unsatisfied.activate(AbstractComponentManager.java:1522)
at
org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:614)
at
org.apache.felix.scr.impl.manager.ComponentFactoryImpl.newInstance(ComponentFactoryImpl.java:109)
at
org.apache.felix.scr.integration.components.concurrency.CFactory.run(CFactory.java:46)
at java.lang.Thread.run(Thread.java:662)
log level: 3 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1: ServiceEvent
REGISTERED
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.B] Dependency
Manager: Service c activation on other thread bound service reference
[org.apache.felix.scr.integration.components.concurrency.C]
log level: 3 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1: ServiceEvent
REGISTERED
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] This thread
collected dependencies
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] activate won
collecting dependencies, proceed to creating object.
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] State
transition : Registered -> FactoryInstance
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] getting
activate: activate
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Locating method
activate in class org.apache.felix.scr.integration.components.concurrency.C
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
org.apache.felix.scr.integration.components.concurrency.C.activate([interface
org.osgi.service.component.ComponentContext]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
org.apache.felix.scr.integration.components.concurrency.C.activate([interface
org.osgi.framework.BundleContext]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
org.apache.felix.scr.integration.components.concurrency.C.activate([interface
java.util.Map]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
org.apache.felix.scr.integration.components.concurrency.C.activate() not
found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Locating method
activate in class java.lang.Object
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
java.lang.Object.activate([interface
org.osgi.service.component.ComponentContext]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
java.lang.Object.activate([interface org.osgi.framework.BundleContext]) not
found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
java.lang.Object.activate([interface java.util.Map]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
java.lang.Object.activate() not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] activate method
[activate] not found, ignoring
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Unregistering
the services
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.B] Dependency
Manager: Removing Service
org.apache.felix.scr.integration.components.concurrency.C/6622
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.B] Dependency
Manager: Deactivating component due to mandatory dependency on
c/org.apache.felix.scr.integration.components.concurrency.C not satisfied
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.B] Deactivating
component
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.B] Unregistering
the services
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.A] Dependency
Manager: Removing Service
org.apache.felix.scr.integration.components.concurrency.B/6623
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.A] Dependency
Manager: Ignoring removed Service for b : Service 6,623 not bound
log level: 3 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1: ServiceEvent
UNREGISTERING
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.B] State
transition : Registered -> Unsatisfied
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.B] Component
deactivated
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.B] Dependency
Manager: Ignoring removed Service for c : Service 6,622 not bound
log level: 3 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1: ServiceEvent
UNREGISTERING
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] getting
deactivate: deactivate
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Locating method
deactivate in class
org.apache.felix.scr.integration.components.concurrency.C
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
org.apache.felix.scr.integration.components.concurrency.C.deactivate([interface
org.osgi.service.component.ComponentContext]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
org.apache.felix.scr.integration.components.concurrency.C.deactivate([interface
org.osgi.framework.BundleContext]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
org.apache.felix.scr.integration.components.concurrency.C.deactivate([interface
java.util.Map]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
org.apache.felix.scr.integration.components.concurrency.C.deactivate([int])
not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
org.apache.felix.scr.integration.components.concurrency.C.deactivate([class
java.lang.Integer]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
org.apache.felix.scr.integration.components.concurrency.C.deactivate() not
found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Locating method
deactivate in class java.lang.Object
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
java.lang.Object.deactivate([interface
org.osgi.service.component.ComponentContext]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
java.lang.Object.deactivate([interface org.osgi.framework.BundleContext])
not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
java.lang.Object.deactivate([interface java.util.Map]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
java.lang.Object.deactivate([int]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
java.lang.Object.deactivate([class java.lang.Integer]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Declared Method
java.lang.Object.deactivate() not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] deactivate
method [deactivate] not found, ignoring
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Component
org.apache.felix.scr.integration.components.concurrency.C created: DS=1,
implementation=org.apache.felix.scr.integration.components.concurrency.C,
immediate=false, default-enabled=true, factory=CFactory,
configuration-policy=optional, activate=activate, deactivate=deactivate,
modified=null
configuration-pid=org.apache.felix.scr.integration.components.concurrency.C
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Component
org.apache.felix.scr.integration.components.concurrency.C Services:
servicefactory=false,
services=[org.apache.felix.scr.integration.components.concurrency.C]
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Component
org.apache.felix.scr.integration.components.concurrency.C Properties: {}
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Creating new
instance from component factory
org.apache.felix.scr.integration.components.concurrency.C with
configuration null
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] State
transition : Disabled -> Unsatisfied
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Component
enabled
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Activating
component
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] State
transition : Unsatisfied -> Registered
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] registering
services
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
BundleComponentActivator : Bundle [20] will destroy 5 instances
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.A] Unregistering
the services
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory]
Dependency Manager: Removing Service
org.osgi.service.component.ComponentFactory/14
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory]
Dependency Manager: Deactivating component due to mandatory dependency on
aFactory/org.osgi.service.component.ComponentFactory not satisfied
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory]
Deactivating component
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory] getting
deactivate: deactivate
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory] Locating
method deactivate in class
org.apache.felix.scr.integration.components.concurrency.AFactory
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory] Declared
Method
org.apache.felix.scr.integration.components.concurrency.AFactory.deactivate([interface
org.osgi.service.component.ComponentContext]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory] Declared
Method
org.apache.felix.scr.integration.components.concurrency.AFactory.deactivate([interface
org.osgi.framework.BundleContext]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory] Declared
Method
org.apache.felix.scr.integration.components.concurrency.AFactory.deactivate([interface
java.util.Map]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory] Declared
Method
org.apache.felix.scr.integration.components.concurrency.AFactory.deactivate([int])
not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory] Declared
Method
org.apache.felix.scr.integration.components.concurrency.AFactory.deactivate([class
java.lang.Integer]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory] Found
deactivate method: void
org.apache.felix.scr.integration.components.concurrency.AFactory.deactivate()
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory] invoking
deactivate: deactivate
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory] State
transition : Active -> Unsatisfied
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory]
Component deactivated
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory]
Dependency Manager: Ignoring removed Service for aFactory : Service 14 not
bound
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory]
Dependency Manager: Removing Service
org.osgi.service.component.ComponentFactory/14
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory]
Dependency Manager: Not counting Service for cFactory : Service 14 does not
match target filter (component.factory=CFactory)
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory]
Dependency Manager: Ignoring removed Service for cFactory : Service 14 not
bound
log level: 3 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1: ServiceEvent
UNREGISTERING
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Unregistering
the services
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory]
Dependency Manager: Removing Service
org.osgi.service.component.ComponentFactory/15
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory]
Dependency Manager: Not counting Service for aFactory : Service 15 does not
match target filter (component.factory=AFactory)
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory]
Dependency Manager: Deactivating component due to mandatory dependency on
aFactory/org.osgi.service.component.ComponentFactory not satisfied
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory] Current
state: Unsatisfied, Event: deactivate (reason: 2)
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.AFactory]
Dependency Manager: Ignoring removed Service for aFactory : Service 15 not
bound
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory]
Dependency Manager: Removing Service
org.osgi.service.component.ComponentFactory/15
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory]
Dependency Manager: Deactivating component due to mandatory dependency on
cFactory/org.osgi.service.component.ComponentFactory not satisfied
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory]
Deactivating component
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory] getting
deactivate: deactivate
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory] Locating
method deactivate in class
org.apache.felix.scr.integration.components.concurrency.CFactory
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory] Declared
Method
org.apache.felix.scr.integration.components.concurrency.CFactory.deactivate([interface
org.osgi.service.component.ComponentContext]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory] Declared
Method
org.apache.felix.scr.integration.components.concurrency.CFactory.deactivate([interface
org.osgi.framework.BundleContext]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory] Declared
Method
org.apache.felix.scr.integration.components.concurrency.CFactory.deactivate([interface
java.util.Map]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory] Declared
Method
org.apache.felix.scr.integration.components.concurrency.CFactory.deactivate([int])
not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory] Declared
Method
org.apache.felix.scr.integration.components.concurrency.CFactory.deactivate([class
java.lang.Integer]) not found
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory] Found
deactivate method: void
org.apache.felix.scr.integration.components.concurrency.CFactory.deactivate()
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory] invoking
deactivate: deactivate
log level: 3 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1: ServiceEvent
REGISTERED
log level: 1 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Locking
activity before IllegalMonitorStateException:
obtainReadLock from: ComponentFactoryImpl.newInstance.1 readLocks: 0
writeLocks: 0 thread: Thread[Thread-5,5,main] time: 1347005735361
releaseReadLock from: register.service.1 readLocks: 1 writeLocks: 0
thread: Thread[Thread-5,5,main] time: 1347005735362
obtainReadLock from: register.service.1 readLocks: 0 writeLocks: 0
thread: Thread[Thread-5,5,main] time: 1347005735365
releaseReadLock from: ComponentFactoryImpl.newInstance.1 readLocks: 0
writeLocks: 0 thread: Thread[Thread-5,5,main] time: 1347005735365
log level: 1 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.C] Thread dump
ThreadId: 24 : name: Thread-5 State: RUNNABLE
LockInfo: null LockOwnerId: -1 LockOwnerName: null
sun.management.ThreadImpl.dumpThreads0(Native Method)
sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:433)
org.apache.felix.scr.impl.manager.AbstractComponentManager.dumpThreads(AbstractComponentManager.java:278)
org.apache.felix.scr.impl.manager.AbstractComponentManager.releaseReadLock(AbstractComponentManager.java:222)
org.apache.felix.scr.impl.manager.ComponentFactoryImpl.newInstance(ComponentFactoryImpl.java:123)
org.apache.felix.scr.integration.components.concurrency.CFactory.run(CFactory.java:46)
java.lang.Thread.run(Thread.java:662)
ThreadId: 20 : name: Thread-1 State: WAITING
LockInfo: java.util.ArrayList@11258b2 LockOwnerId: -1 LockOwnerName: null
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:485)
org.apache.felix.log.LogListenerThread.run(LogListenerThread.java:139)
ThreadId: 19 : name: Executor: 1 State: WAITING
LockInfo:
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@17d2d70LockOwnerId:
-1 LockOwnerName: null
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:156)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987)
java.util.concurrent.DelayQueue.take(DelayQueue.java:160)
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:609)
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:602)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:947)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
java.lang.Thread.run(Thread.java:662)
ThreadId: 18 : name: Configuration Updater State: WAITING
LockInfo: java.util.LinkedList@1325573 LockOwnerId: -1 LockOwnerName: null
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:485)
org.apache.felix.cm.impl.UpdateThread.run(UpdateThread.java:67)
ThreadId: 17 : name: SCR Component Actor State: WAITING
LockInfo: java.util.LinkedList@1882c1a LockOwnerId: -1 LockOwnerName: null
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:485)
org.apache.felix.scr.impl.ComponentActorThread.run(ComponentActorThread.java:76)
java.lang.Thread.run(Thread.java:662)
ThreadId: 16 : name: DestroyJavaVM State: RUNNABLE
LockInfo: null LockOwnerId: -1 LockOwnerName: null
ThreadId: 15 : name: FelixStartLevel State: WAITING
LockInfo: java.util.ArrayList@1079724 LockOwnerId: -1 LockOwnerName: null
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:485)
org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:272)
java.lang.Thread.run(Thread.java:662)
ThreadId: 14 : name: FelixDispatchQueue State: WAITING
LockInfo: java.util.ArrayList@153c017 LockOwnerId: -1 LockOwnerName: null
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:485)
org.apache.felix.framework.util.EventDispatcher.run(EventDispatcher.java:1063)
org.apache.felix.framework.util.EventDispatcher.access$000(EventDispatcher.java:54)
org.apache.felix.framework.util.EventDispatcher$1.run(EventDispatcher.java:101)
java.lang.Thread.run(Thread.java:662)
ThreadId: 13 : name: RMI TCP Connection(1)-139.54.130.12 State: WAITING
LockInfo: java.lang.Thread@1ddcb LockOwnerId: -1 LockOwnerName: null
java.lang.Object.wait(Native Method)
java.lang.Thread.join(Thread.java:1186)
java.lang.Thread.join(Thread.java:1239)
org.apache.felix.scr.integration.components.concurrency.CFactory.deactivate(CFactory.java:37)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
org.apache.felix.scr.impl.helper.BaseMethod.invokeMethod(BaseMethod.java:230)
org.apache.felix.scr.impl.helper.BaseMethod.access$500(BaseMethod.java:37)
org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:607)
org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:488)
org.apache.felix.scr.impl.helper.ActivateMethod.invoke(ActivateMethod.java:149)
org.apache.felix.scr.impl.manager.ImmediateComponentManager.disposeImplementationObject(ImmediateComponentManager.java:283)
org.apache.felix.scr.impl.manager.ImmediateComponentManager.deleteComponent(ImmediateComponentManager.java:154)
org.apache.felix.scr.impl.manager.AbstractComponentManager$State.doDeactivate(AbstractComponentManager.java:1364)
org.apache.felix.scr.impl.manager.AbstractComponentManager$Satisfied.deactivate(AbstractComponentManager.java:1622)
org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:619)
org.apache.felix.scr.impl.manager.DependencyManager.serviceRemoved(DependencyManager.java:404)
org.apache.felix.scr.impl.manager.DependencyManager.serviceChanged(DependencyManager.java:246)
org.apache.felix.framework.util.EventDispatcher.invokeServiceListenerCallback(EventDispatcher.java:932)
org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:793)
org.apache.felix.framework.util.EventDispatcher.fireServiceEvent(EventDispatcher.java:543)
org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:4260)
org.apache.felix.framework.Felix.access$000(Felix.java:74)
org.apache.felix.framework.Felix$1.serviceChanged(Felix.java:390)
org.apache.felix.framework.ServiceRegistry.unregisterService(ServiceRegistry.java:148)
org.apache.felix.framework.ServiceRegistrationImpl.unregister(ServiceRegistrationImpl.java:127)
org.apache.felix.scr.impl.manager.AbstractComponentManager.unregisterComponentService(AbstractComponentManager.java:759)
org.apache.felix.scr.impl.manager.AbstractComponentManager$State.doDeactivate(AbstractComponentManager.java:1360)
org.apache.felix.scr.impl.manager.AbstractComponentManager$Satisfied.dispose(AbstractComponentManager.java:1636)
org.apache.felix.scr.impl.manager.AbstractComponentManager.disposeInternal(AbstractComponentManager.java:638)
org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:460)
org.apache.felix.scr.impl.manager.ComponentFactoryImpl.disposeComponents(ComponentFactoryImpl.java:392)
org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:307)
org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:316)
org.apache.felix.scr.impl.Activator.bundleChanged(Activator.java:183)
org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:868)
org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:789)
org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:514)
org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4244)
org.apache.felix.framework.Felix.stopBundle(Felix.java:2351)
org.apache.felix.framework.Felix.uninstallBundle(Felix.java:2463)
org.apache.felix.framework.BundleImpl.uninstall(BundleImpl.java:1012)
org.apache.felix.scr.integration.ComponentTestBase.tearDown(ComponentTestBase.java:187)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:37)
org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263)
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:69)
org.ops4j.pax.exam.invoker.junit.internal.ContainerTestRunner.runChild(ContainerTestRunner.java:70)
org.ops4j.pax.exam.invoker.junit.internal.ContainerTestRunner.runChild(ContainerTestRunner.java:37)
org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
org.junit.runners.ParentRunner.run(ParentRunner.java:292)
org.junit.runner.JUnitCore.run(JUnitCore.java:157)
org.junit.runner.JUnitCore.run(JUnitCore.java:136)
org.ops4j.pax.exam.invoker.junit.internal.JUnitProbeInvoker.invokeViaJUnit(JUnitProbeInvoker.java:124)
org.ops4j.pax.exam.invoker.junit.internal.JUnitProbeInvoker.findAndInvoke(JUnitProbeInvoker.java:94)
org.ops4j.pax.exam.invoker.junit.internal.JUnitProbeInvoker.call(JUnitProbeInvoker.java:77)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
org.ops4j.pax.swissbox.framework.RemoteFrameworkImpl.callService(RemoteFrameworkImpl.java:186)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:303)
sun.rmi.transport.Transport$1.run(Transport.java:159)
java.security.AccessController.doPrivileged(Native Method)
sun.rmi.transport.Transport.serviceCall(Transport.java:155)
sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535)
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790)
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649)
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
java.lang.Thread.run(Thread.java:662)
ThreadId: 12 : name: RMI Scheduler(0) State: TIMED_WAITING
LockInfo:
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@883f8fLockOwnerId:
-1 LockOwnerName: null
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:196)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2025)
java.util.concurrent.DelayQueue.take(DelayQueue.java:164)
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:609)
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:602)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:947)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
java.lang.Thread.run(Thread.java:662)
ThreadId: 11 : name: GC Daemon State: TIMED_WAITING
LockInfo: sun.misc.GC$LatencyLock@104c58e LockOwnerId: -1 LockOwnerName:
null
java.lang.Object.wait(Native Method)
sun.misc.GC$Daemon.run(GC.java:100)
ThreadId: 10 : name: RMI Reaper State: WAITING
LockInfo: java.lang.ref.ReferenceQueue$Lock@462799 LockOwnerId: -1
LockOwnerName: null
java.lang.Object.wait(Native Method)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
sun.rmi.transport.ObjectTable$Reaper.run(ObjectTable.java:333)
java.lang.Thread.run(Thread.java:662)
ThreadId: 9 : name: RMI TCP Accept-0 State: RUNNABLE
LockInfo: null LockOwnerId: -1 LockOwnerName: null
java.net.PlainSocketImpl.socketAccept(Native Method)
java.net.PlainSocketImpl.accept(PlainSocketImpl.java:408)
java.net.ServerSocket.implAccept(ServerSocket.java:462)
java.net.ServerSocket.accept(ServerSocket.java:430)
sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:369)
sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:341)
java.lang.Thread.run(Thread.java:662)
ThreadId: 4 : name: Signal Dispatcher State: RUNNABLE
LockInfo: null LockOwnerId: -1 LockOwnerName: null
ThreadId: 3 : name: Finalizer State: WAITING
LockInfo: java.lang.ref.ReferenceQueue$Lock@1ae9ef9 LockOwnerId: -1
LockOwnerName: null
java.lang.Object.wait(Native Method)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
ThreadId: 2 : name: Reference Handler State: WAITING
LockInfo: java.lang.ref.Reference$Lock@147164d LockOwnerId: -1
LockOwnerName: null
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:485)
java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory] State
transition : Active -> Unsatisfied
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory]
Component deactivated
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
[org.apache.felix.scr.integration.components.concurrency.CFactory]
Dependency Manager: Ignoring removed Service for cFactory : Service 15 not
bound
log level: 3 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1: ServiceEvent
UNREGISTERING
log level: 4 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1:
BundleComponentActivator : Bundle [20] STOPPED
log level: 3 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1: ServiceEvent
UNREGISTERING
log level: 3 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1: BundleEvent
STOPPED
log level: 3 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1: BundleEvent
UNRESOLVED
log level: 3 D=Fri Sep 07 10:15:35 CEST 2012, T=Thread-1: BundleEvent
UNINSTALLED
at my maven finished with an out of memory exception:
[org.ops4j.exec.DefaultJavaRunner] : Shutdown in progress...
[org.ops4j.exec.DefaultJavaRunner] : Unwrapping stream I/O.
[org.ops4j.exec.DefaultJavaRunner] : Platform has been shutdown.
Exception in thread "ThreadedStreamConsumer" java.lang.OutOfMemoryError:
Java heap space
at java.util.Arrays.copyOf(Arrays.java:2882)
at
java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:100)
at
java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:390)
at java.lang.StringBuilder.append(StringBuilder.java:119)
at
org.apache.maven.plugin.surefire.report.TestSetRunListener.getAsString(TestSetRunListener.java:211)
at
org.apache.maven.plugin.surefire.report.TestSetRunListener.testFailed(TestSetRunListener.java:168)
at
org.apache.maven.plugin.surefire.booterclient.output.ForkClient.consumeLine(ForkClient.java:109)
at
org.apache.maven.plugin.surefire.booterclient.output.ThreadedStreamConsumer$Pumper.run(ThreadedStreamConsumer.java:67)
at java.lang.Thread.run(Thread.java:662)
On Fri, Sep 7, 2012 at 9:30 AM, David Jencks <[email protected]> wrote:
> I fixed the problems I was working on....
>
>
> I saw one case in your concurrency test of an IllegalMonitorStateException
> and added some code that I hope will log the cause. Since then, of course
> :-), I haven't seen the problem recur.
>
> I'm running tests here with our project with the patch to FELIX-3659....
> will know more in the morning.
>
> thanks!
> david jencks
>
