Mailing-List: contact dev-help@aries.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@aries.apache.org
Date: Fri, 29 Aug 2014 07:33:53 +0000 (UTC)
From: "Michael Hirsch (JIRA)" <jira@apache.org>
To: dev@aries.apache.org
Message-ID: <JIRA.12737743.1409297620596.629.1409297633233@arcas>
In-Reply-To: <JIRA.12737743.1409297620596@arcas>
References: <JIRA.12737743.1409297620596@arcas>
Subject: [jira] [Created] (ARIES-1240) TimeoutException when using
 Blueprint-Service-Proxy within ServiceTracker
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit

Michael Hirsch created ARIES-1240:
-------------------------------------

             Summary: TimeoutException when using Blueprint-Service-Proxy within ServiceTracker
                 Key: ARIES-1240
                 URL: https://issues.apache.org/jira/browse/ARIES-1240
             Project: Aries
          Issue Type: Bug
          Components: Blueprint
    Affects Versions: blueprint-core-1.2.0
         Environment: Felix OSGi container
blueprint-core
blueprint-contexts for providing and consuming OSGi services
plain OSGi ServiceTracker
            Reporter: Michael Hirsch


*Environment Setup*
In a large/complex OSGi environment we are using blueprint for providing and consuming OSGi services in combination with plain OSGi to register services and consume using ServiceTracker.

*Failure Description*
It occurs that when an underlying OSGi service will be unregister and register again (e.g. by configuration updates) blueprint unregisters and re-register all depending services which is correct but it will causing that when re-register OSGi blueprint the services in the blueprint context get also registered which might be an ServiceTracker is tracking these services.

In case the ServiceTracker using an Blueprint-Service-Proxy within the _addingService()_ method which has been re-registered in the registration chain the Blueprint-Service is running into a TimeoutException caused that ServiceListenerEvents are synchronous delivered and the ServiceTracker is running in the same thread as the blueprints ReferenceRecipe will be notified about the re-registration.

This issue only occurs with the blueprint-core version *1.2.0* which is related to the bug fix change ARIES-896 where the ServiceListener events has been handled in a blueprint executor.
{quote}
Aries-896: Undo threading changes to AbstractServiceReferenceRecipe.serviceChanged() since they can result in unbind-methods being driven with invalid service references.
{quote} 
Without this change this error does not occur.

*Reproduce / Verification*
I attached a complete thread dump showing the the blueprint proxy is waiting for the ServiceReference

Thread Dump, the whole thread dump is attached.
{code}
"Gogo shell" daemon prio=6 tid=0x000000000e4eb800 nid=0x2a88 in Object.wait() [0x00000000117db000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000007d6018608> (a java.lang.Object)
	at org.apache.aries.blueprint.container.ReferenceRecipe.getService(ReferenceRecipe.java:206)
	- locked <0x00000007d6018608> (a java.lang.Object)
	at org.apache.aries.blueprint.container.ReferenceRecipe.access$000(ReferenceRecipe.java:55)
	at org.apache.aries.blueprint.container.ReferenceRecipe$ServiceDispatcher.call(ReferenceRecipe.java:294)
	at org.apache.aries.proxy.impl.ProxyHandler$1.invoke(ProxyHandler.java:54)
	at org.apache.aries.proxy.impl.ProxyHandler.invoke(ProxyHandler.java:119)
	at com.sun.proxy.$Proxy1.doSomething(Unknown Source)
	at org.bugtesting.provider.impl.MyServiceImpl.callManagedServiceProvider(MyServiceImpl.java:18)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.apache.aries.proxy.impl.ProxyHandler$1.invoke(ProxyHandler.java:54)
	at org.apache.aries.proxy.impl.ProxyHandler.invoke(ProxyHandler.java:119)
	at com.sun.proxy.$Proxy0.callManagedServiceProvider(Unknown Source)
	at org.bugtesting.servicetracker.MyConsumerServiceTracker.addingService(MyConsumerServiceTracker.java:50)
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:932)
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:864)
	at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256)
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229)
	at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:894)
	at org.apache.felix.framework.util.EventDispatcher.invokeServiceListenerCallback(EventDispatcher.java:943)
	at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:794)
	at org.apache.felix.framework.util.EventDispatcher.fireServiceEvent(EventDispatcher.java:544)
	at org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:4425)
	at org.apache.felix.framework.Felix.registerService(Felix.java:3429)
	at org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:346)
	at org.apache.aries.blueprint.container.BlueprintContainerImpl.registerService(BlueprintContainerImpl.java:552)
	at org.apache.aries.blueprint.container.ServiceRecipe.register(ServiceRecipe.java:191)
	at org.apache.aries.blueprint.container.BlueprintContainerImpl.notifySatisfaction(BlueprintContainerImpl.java:837)
	- locked <0x00000007d5fc17e8> (a org.apache.aries.blueprint.container.ServiceRecipe)
	at org.apache.aries.blueprint.container.AbstractServiceReferenceRecipe.setSatisfied(AbstractServiceReferenceRecipe.java:424)
	at org.apache.aries.blueprint.container.AbstractServiceReferenceRecipe.serviceAdded(AbstractServiceReferenceRecipe.java:366)
	at org.apache.aries.blueprint.container.AbstractServiceReferenceRecipe.serviceChanged(AbstractServiceReferenceRecipe.java:346)
	at org.apache.felix.framework.util.EventDispatcher.invokeServiceListenerCallback(EventDispatcher.java:943)
	at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:794)
	at org.apache.felix.framework.util.EventDispatcher.fireServiceEvent(EventDispatcher.java:544)
	at org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:4425)
	at org.apache.felix.framework.Felix.registerService(Felix.java:3429)
	at org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:346)
	at org.apache.aries.blueprint.container.BlueprintContainerImpl.registerService(BlueprintContainerImpl.java:552)
	at org.apache.aries.blueprint.container.ServiceRecipe.register(ServiceRecipe.java:191)
	at org.apache.aries.blueprint.container.BlueprintContainerImpl.notifySatisfaction(BlueprintContainerImpl.java:837)
	- locked <0x00000007d6018a88> (a org.apache.aries.blueprint.container.ServiceRecipe)
{code}

Futheremore there is an test application (OSGi container) where this bug can be reproduced within the test application there is also an how to text file how to re-produce the bug.
{quote}
#1 Start Container of the TestApplication with bin/start.bat

#2 You'll see log information that the ServiceTracker-AddingService has been called
   and using the Blueprint-Proxy (MyService) and everything is ok


#3 Use the command 'breakit' (without quotes) to re-register the underlying managed-service (MyManagedService). 
   After 10seconds (blueprint-reference-timeout, but sometimes the defined timeout does not work 
   and you need to wait 5minutes - default timeout) you see that the MyService is running into a timeout


#4 verify the bug with diffrent blueprint-core versions by replacing the "org.apache.aries.blueprint.core-1.2.0.jar" bundle 
   with another one. Before 1.2.0 version the TimeoutException will not occure
{quote}


--
This message was sent by Atlassian JIRA
(v6.2#6252)