[
https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13454316#comment-13454316
]
Pierre De Rop commented on FELIX-3661:
--------------------------------------
I don't think so.
what I think is the following: the "agent" activate method is invoked. Then
some services are registrered. Then the "CompositeFactory" is registered (at
this point, we are within the "agent" activate method, in the same thread).
but since we have not returned from the "agent" activate method, the agent's
bindCompositeFactory method is not called and we see the log "component not yet
created, assuming bind method call succeeded".
Finally, the agent's activate method returns, and the agent is never bound with
the CompositeFactory service (the agent has a dynamic, multiple 0..N reference
on the CompositeFactory service).
I have attached a second logfile "msg2.log", but this time, I have added a log
with a stacktrace just when the "agent" activate method is invoked, and also a
stacktrace at the end of the "agent" activate method. And between the two
stacktraces, we see the "component not yet created, assuming bind method call
succeeded" log.
The first time the "agent" activate method is called is at 2012-09-12
21:51:33,025:
2012-09-12 21:51:33,025 ProxyAppReporter-FastCacheListener DEBUG osgi -
[agent] invoking activate: activate
2012-09-12 21:51:33,025 ProxyAppReporter-FastCacheListener WARN callout -
Agent component activating
java.lang.Exception: stacktrace
at com.nextenso.agent.Agent.activate(Agent.java:372)
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.apache.felix.scr.impl.helper.BaseMethod.invokeMethod(BaseMethod.java:234)
at
org.apache.felix.scr.impl.helper.BaseMethod.access$500(BaseMethod.java:37)
at
org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:611)
at
org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:492)
at
org.apache.felix.scr.impl.helper.ActivateMethod.invoke(ActivateMethod.java:149)
at
org.apache.felix.scr.impl.manager.ImmediateComponentManager.createImplementationObject(ImmediateComponentManager.java:232)
at
org.apache.felix.scr.impl.manager.ImmediateComponentManager.createComponent(ImmediateComponentManager.java:123)
at
org.apache.felix.scr.impl.manager.AbstractComponentManager$Unsatisfied.activate(AbstractComponentManager.java:1585)
at
org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:630)
at
org.apache.felix.scr.impl.manager.DependencyManager.serviceAdded(DependencyManager.java:257)
at
org.apache.felix.scr.impl.manager.DependencyManager.serviceChanged(DependencyManager.java:134)
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.framework.BundleContextImpl.registerService(BundleContextImpl.java:320)
at
com.alcatel.as.service.config.impl.fc.PropertiesManager.update(PropertiesManager.java:211)
at
com.alcatel.as.service.config.impl.fc.FastCacheConfig.proxyAppPropertiesUpdated(FastCacheConfig.java:323)
at
com.nextenso.mgmt.reporter.ProxyAppReporter$FastCacheListeningThread.run(ProxyAppReporter.java:99)
Then at 2012-09-12 21:51:33,281, the CompositeFactory service is being
registered in the same thread, but the bind method is not invoked:
2012-09-12 21:51:33,281 ProxyAppReporter-FastCacheListener INFO
osgi.event.service - Service registered by bundle
com.alcatel_lucent.as.service.composite.impl(1.1100.01)
{objectClass=[com.alcatel_lucent.as.service.composite.CompositeFactory],service.id=567}
2012-09-12 21:51:33,281 ProxyAppReporter-FastCacheListener DEBUG osgi -
[agent] Dependency Manager: Adding Service
com.alcatel_lucent.as.service.composite.CompositeFactory/567
2012-09-12 21:51:33,299 ProxyAppReporter-FastCacheListener DEBUG osgi -
[agent] DependencyManager : component not yet created, assuming bind method
call succeeded
Finally, the "agent" activate method terminates and is about to return, at
2012-09-12 21:51:33,326:
2012-09-12 21:51:33,326 ProxyAppReporter-FastCacheListener WARN callout -
Agent component active
java.lang.Exception: stacktrace
at com.nextenso.agent.Agent._activate(Agent.java:667)
at com.nextenso.agent.Agent.access$100(Agent.java:92)
at com.nextenso.agent.Agent$6.run(Agent.java:380)
at
com.alcatel.as.service.concurrent.SerialExecutor.execute(SerialExecutor.java:41)
at com.nextenso.agent.Agent.activate(Agent.java:375)
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.apache.felix.scr.impl.helper.BaseMethod.invokeMethod(BaseMethod.java:234)
at
org.apache.felix.scr.impl.helper.BaseMethod.access$500(BaseMethod.java:37)
at
org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:611)
at
org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:492)
at
org.apache.felix.scr.impl.helper.ActivateMethod.invoke(ActivateMethod.java:149)
at
org.apache.felix.scr.impl.manager.ImmediateComponentManager.createImplementationObject(ImmediateComponentManager.java:232)
at
org.apache.felix.scr.impl.manager.ImmediateComponentManager.createComponent(ImmediateComponentManager.java:123)
at
org.apache.felix.scr.impl.manager.AbstractComponentManager$Unsatisfied.activate(AbstractComponentManager.java:1585)
at
org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:630)
at
org.apache.felix.scr.impl.manager.DependencyManager.serviceAdded(DependencyManager.java:257)
at
org.apache.felix.scr.impl.manager.DependencyManager.serviceChanged(DependencyManager.java:134)
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.framework.BundleContextImpl.registerService(BundleContextImpl.java:320)
at
com.alcatel.as.service.config.impl.fc.PropertiesManager.update(PropertiesManager.java:211)
at
com.alcatel.as.service.config.impl.fc.FastCacheConfig.proxyAppPropertiesUpdated(FastCacheConfig.java:323)
at
com.nextenso.mgmt.reporter.ProxyAppReporter$FastCacheListeningThread.run(ProxyAppReporter.java:99)
So, I suspect that the problem comes from the fact that the agent activate
method registers some services which indirectly satisfy the
CompositeFactoryImpl bundle, which in turns registers the CompositeFactory
service, while the agent's activate method is being executed ... this is
probably the root cause of the problem.
WDYT ?
> Scr sometimes does not invoke Reference bind method
> ---------------------------------------------------
>
> Key: FELIX-3661
> URL: https://issues.apache.org/jira/browse/FELIX-3661
> Project: Felix
> Issue Type: Bug
> Components: Declarative Services (SCR)
> Reporter: Pierre De Rop
> Assignee: David Jencks
> Attachments: msg2.log, msg.log
>
>
> With scr from trunk: sometimes, a satisfied Reference bind method is not
> invoked.
> I'm not sure, but this might be related to the FELIX-3659 issue and/or when
> Reference types are org.osgi.service.ComponentFactory types.
> The use case is the following:
> - I have a DS component (name="agent"), which depends on the CompositeFactory
> service (ref is dynamic, optional, cardinality=0..N).
> - the "agent" component is started (at this point), the CompositeFactory is
> not yet available
> - next, the implementation bundle for the CompositeFactory service starts and
> registers the service, using bundleContext.registerService.
> - but the "agent" component is not invoked in its
> bindCompositeFactory(CompositeFactory) method.
> I have attached a logfile which illustrates the problem.
> 1) Line 8491: the '"agent" component is being created, and some bind method
> are successfully invoked, except the "bindCompositeFactory" method (but this
> is normal since the service is optional, and not yet available):
> 2012-09-11 23:09:21,147 ProxyAppReporter-FastCacheListener DEBUG osgi -
> [agent] For dependency loggerRepository, optional: false; to bind:
> {[org.apache.log4j.spi.LoggerRepository]=org.apache.felix.scr.impl.manager.AbstractComponentManager$RefPair@1b7a875}
> 2012-09-11 23:09:21,147 ProxyAppReporter-FastCacheListener DEBUG osgi -
> [agent] invoking bind: bindLoggerRepository
> 2012-09-11 23:09:21,147 ProxyAppReporter-FastCacheListener DEBUG osgi -
> [agent] For dependency compositeFactory, optional: true; to bind: {}
> (here the bind for loggerRepository is invoked, but not for compositeFactory
> ... normal behavior for now.
> 2) at line 8644, the CompositeFactory service is being registered, but we see
> the "component not yet created, assuming bind method call succeeded" log and
> the bindCompositeFactory method on the "agent" component is not invoked.
> However, another
> "com.alcatel_lucent.as.service.composite.impl.shell.FelixCompositeCommand" DS
> component is succesfully bound with the CompositeFactory, but this component
> depends on the CompositeService, using a ServiceReference type, instead of
> the actual CompositeFactory type, in the bind method signature ...
> 2012-09-11 23:09:21,222 ProxyAppReporter-FastCacheListener WARN
> com.alcatel_lucent.as.service.composite.impl.CompositeFactoryImpl -
> Registering CompositeFactory ...
> 2012-09-11 23:09:21,222 ProxyAppReporter-FastCacheListener DEBUG osgi -
> [agent] Dependency Manager: Adding Service
> com.alcatel_lucent.as.service.composite.CompositeFactory/565
> 2012-09-11 23:09:21,222 ProxyAppReporter-FastCacheListener DEBUG osgi -
> [agent] DependencyManager : component not yet created, assuming bind method
> call succeeded
> 2012-09-11 23:09:21,223 ProxyAppReporter-FastCacheListener DEBUG osgi -
> [com.alcatel_lucent.as.service.composite.impl.shell.GogoCompositeCommand]
> Dependency Manager: Adding Service
> com.alcatel_lucent.as.service.composite.CompositeFactory/565
> 2012-09-11 23:09:21,223 ProxyAppReporter-FastCacheListener DEBUG osgi -
> [com.alcatel_lucent.as.service.composite.impl.shell.GogoCompositeCommand]
> DependencyManager : component not yet created, assuming bind method call
> succeeded
> 2012-09-11 23:09:21,223 ProxyAppReporter-FastCacheListener DEBUG osgi -
> [com.alcatel_lucent.as.service.composite.impl.shell.FelixCompositeCommand]
> Dependency Manager: Adding Service
> com.alcatel_lucent.as.service.composite.CompositeFactory/565
> 2012-09-11 23:09:21,223 ProxyAppReporter-FastCacheListener DEBUG osgi -
> [com.alcatel_lucent.as.service.composite.impl.shell.FelixCompositeCommand]
> getting bind: bindCompositeFactory
> 2012-09-11 23:09:21,224 ProxyAppReporter-FastCacheListener DEBUG osgi -
> [com.alcatel_lucent.as.service.composite.impl.shell.FelixCompositeCommand]
> Locating method bindCompositeFactory in class
> com.alcatel_lucent.as.service.composite.impl.shell.FelixCompositeCommand
> 2012-09-11 23:09:21,224 ProxyAppReporter-FastCacheListener DEBUG osgi -
> [com.alcatel_lucent.as.service.composite.impl.shell.FelixCompositeCommand]
> doFindMethod: Looking for method
> com.alcatel_lucent.as.service.composite.impl.shell.FelixCompositeCommand.bindCompositeFactory
> 2012-09-11 23:09:21,224 ProxyAppReporter-FastCacheListener DEBUG osgi -
> [com.alcatel_lucent.as.service.composite.impl.shell.FelixCompositeCommand]
> doFindMethod: Found Method public void
> com.alcatel_lucent.as.service.composite.impl.shell.FelixCompositeCommand.bindCompositeFactory(org.osgi.framework.ServiceReference)
> 2012-09-11 23:09:21,224 ProxyAppReporter-FastCacheListener DEBUG osgi -
> [com.alcatel_lucent.as.service.composite.impl.shell.FelixCompositeCommand]
> Found bind method: public void
> com.alcatel_lucent.as.service.composite.impl.shell.FelixCompositeCommand.bindCompositeFactory(org.osgi.framework.ServiceReference)
> 2012-09-11 23:09:21,224 ProxyAppReporter-FastCacheListener DEBUG osgi -
> [com.alcatel_lucent.as.service.composite.impl.shell.FelixCompositeCommand]
> invoking bind: bindCompositeFactory
> 2012-09-11 23:09:21,224 ProxyAppReporter-FastCacheListener INFO
> osgi.event.service - Service registered by bundle
> com.alcatel_lucent.as.service.composite.impl(1.1100.01)
>
> {objectClass=[com.alcatel_lucent.as.service.composite.CompositeFactory],service.id=565}
> Hope that the log file will be enough to understand the issue ?
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
