You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@felix.apache.org by "Pierre De Rop (JIRA)" <ji...@apache.org> on 2012/09/11 23:34:07 UTC

[jira] [Created] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Pierre De Rop created FELIX-3661:
------------------------------------

             Summary: 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


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

[jira] [Closed] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "Pierre De Rop (JIRA)" <ji...@apache.org>.
     [ https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Pierre De Rop closed FELIX-3661.
--------------------------------

    Resolution: Invalid

I'm closing this issue because the problem actually comes from some circular dependencies in our product, so there is no reason to keep this issue open.

I have not yet found them, but I will ask to Arjun to add a feature in its felix service diagnostic webconsole plugin for automatic detection and display of circular dependencies; this might help me to go ahead.
                
> 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, 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

[jira] [Commented] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "Pierre De Rop (JIRA)" <ji...@apache.org>.
    [ https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13455670#comment-13455670 ] 

Pierre De Rop commented on FELIX-3661:
--------------------------------------

(the msg.log file to analyze if the one from 14/Sep/12 09:32)
                
> 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, 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

[jira] [Reopened] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "Pierre De Rop (JIRA)" <ji...@apache.org>.
     [ https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Pierre De Rop reopened FELIX-3661:
----------------------------------


Even after having refactored my "agent" component in order to avoid circular dependencies, the expected service (CompositeFactory) is not yet bound to my "agent" component.

In my refactoring, I managed to not register anymore the services that might lead to cycles.
 
For now I reopen the issue and will continue to investigate.
 
It's actually difficult for now to make a diagnostic because I have many services which are not mine, and for now, it seems that  when some cycles are detected, there are no warnings logged by SCR (or they are logged in other conditions ?) So maybe I have missed some other possible cycles ?

Could something be done in order to help tracking such cyclic dependencies ? for example some logs I could add in SCR ?

thanks.


                
> 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

[jira] [Commented] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "David Jencks (JIRA)" <ji...@apache.org>.
    [ https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13454125#comment-13454125 ] 

David Jencks commented on FELIX-3661:
-------------------------------------

Still not seeing exactly how this is happening.... does the activate method in your agent class call out to anything?  Is there any chance it is blocking on something?
                
> 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: 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

[jira] [Commented] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "David Jencks (JIRA)" <ji...@apache.org>.
    [ https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13453540#comment-13453540 ] 

David Jencks commented on FELIX-3661:
-------------------------------------

I see something about what is going on.... I think one thread has created the object and activated it but not yet set it as the instance object, but the state is no longer "unsatisfied".  So the other  thread can't find the object to bind to.

I'm not sure how to fix this yet.... but I just started thinking :-)
                
> 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: 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

[jira] [Updated] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "Pierre De Rop (JIRA)" <ji...@apache.org>.
     [ https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Pierre De Rop updated FELIX-3661:
---------------------------------

    Attachment: msg.log

attached the log file, with ds.loglevel=debug.
                
> 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
>         Attachments: 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

[jira] [Updated] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "Pierre De Rop (JIRA)" <ji...@apache.org>.
     [ https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Pierre De Rop updated FELIX-3661:
---------------------------------

    Attachment: msg.log
    
> 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, 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

[jira] [Commented] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "David Jencks (JIRA)" <ji...@apache.org>.
    [ https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13454708#comment-13454708 ] 

David Jencks commented on FELIX-3661:
-------------------------------------

Well, we agree on how the components and services are related :-).  Since A registers B from it's activate method, this is approximately equivalent to just A and C, with C having a reference to A (instead of B).  This is a circular dependency that is not expected to work with DS.  Just because you added some code to register some of the services doesn't make it any less circular :-)  The spec can't enumerate all possible circular dependency situations, it just says that in general at best you will get all the components created and some of the references set up, but you shouldn't expect all the references to get set up.

I'm fairly sure this is one of the situations that used to work when we were not spec compliant about registering immediate components before creating the implementation object, which is why you code worked with the old DS.

Your code might work if you registered B in a different thread. (but returned immediately from the activate method.  If you wait for the other thread you'll get a deadlock).  Then the other thread wouldn't be able to get a read lock until the write lock is released after the component instance is set for A.  This is roughly what I propose in FELIX-3557

                
> 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

[jira] [Commented] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "Pierre De Rop (JIRA)" <ji...@apache.org>.
    [ https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13454693#comment-13454693 ] 

Pierre De Rop commented on FELIX-3661:
--------------------------------------

No, as far as I know, I don't have such circular dependency.
However, I will take time to extensively verify your assumption. I will let you know.

But in the meantime, I have made a quick test which seems to reproduce the usecase I was talking about in my previous post:

I made this:

@Component
public class A
{
    @Reference(type='*') /* optional, cardinality=0..N, dynamic */
    void bindC(C c)
    {
        System.out.println("A.bindC");
    }

    @Activate
    void start(BundleContext ctx)
    {
        System.out.println("A.start: registering B");
        ctx.registerService(B.class.getName(), new B(), null);
    }
}

public class B
{
}

@Component(provide={C.class}) // delayed component ...
public class C
{
    @Reference
    void bindB(B b) {
        System.out.println("C.bindB");
    }
    
    @Activate
    void start() {
        System.out.println("C.start");
    }
}

Here, we have: 

- A depends on C (optional/dynamic)
- C depends on B, and provides itself, (delayed component)
- A registers B from its activate and this should enable C (C is a delayed component, but since A has a Ref(dynamic,optional,cardinality=0..N) on C, then C should be activated.


I don't think we have a circular dependency here, because C does not depend on A.

But with this test, C is never activated, and A is thus never bound to C, and I see the log:

DEBUG: test.scr (11): [test.scr.A] Dependency Manager: Adding Service test.scr.C/36
DEBUG: test.scr (11): [test.scr.A] DependencyManager : component not yet created, assuming bind method call succeeded


Now, what is interesting is that if I change the definition of C to be immediate, then everything is working file:

@Component(immediate=true, provide={C.class})
public class C
{
    @Reference
    void bindB(B b) {
        System.out.println("C.bindB");
    }
    
    @Activate
    void start() {
        System.out.println("C.start");
    }
}

-> A is created (and registers B from its activate)
-> C is created
-> A is injected with B

But I think that it should also work with C being a delayed component, because A defines an optional dependency on C ...
Am I making sense ?

                
> 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

[jira] [Updated] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "Pierre De Rop (JIRA)" <ji...@apache.org>.
     [ https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Pierre De Rop updated FELIX-3661:
---------------------------------

    Attachment: msg2.log

attached the second log file msg2.log
                
> 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

[jira] [Commented] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "Pierre De Rop (JIRA)" <ji...@apache.org>.
    [ 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

[jira] [Commented] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "Pierre De Rop (JIRA)" <ji...@apache.org>.
    [ https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13454726#comment-13454726 ] 

Pierre De Rop commented on FELIX-3661:
--------------------------------------

Ok, I understand. I will try to locate all those indirect circular dependencies in our code and will try to refactor.

I'm closing this issue.

Thanks for your help.
                
> 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

[jira] [Commented] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "David Jencks (JIRA)" <ji...@apache.org>.
    [ https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13454493#comment-13454493 ] 

David Jencks commented on FELIX-3661:
-------------------------------------

I would like to verify something you said in the last comment, as it would explain what is happening.  I believe you have a circular dependency that is not expected to be satisfied by DS.  This might be one of the cases that used to work because we didn't follow the spec and created immediate components before registering them as services.

I think the situation is equivalent to having two components A and B with B having a mandatory reference to A and A having an optional reference to B. (you have a few more components in the loop, and apparently something that is in code rather than just a component).  In this case DS can create both A and B but can't set up the optional reference.  See the circular reference tests....

I came up with a way around this that sets up the missine reference asynchronously later.... I'm not sure if it still works with current code.  See FELIX-3557

Anyway this is something that IMO cannot be fixed in DS without some extension like I propose in 3557.
                
> 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

[jira] [Commented] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "David Jencks (JIRA)" <ji...@apache.org>.
    [ https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13455008#comment-13455008 ] 

David Jencks commented on FELIX-3661:
-------------------------------------

I haven't thought of a way to detect and log cyclic dependencies.  Although maybe something like the idea in 3557 would work, I haven't thought about it very hard.  Can you modify your test case to show the problem you are still seeing?

IIRC when I was looking at this there was a lot of churn going on when the cycle couldn't be completed.  It does seem like we should be able to detect it.
                
> 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

[jira] [Commented] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "Pierre De Rop (JIRA)" <ji...@apache.org>.
    [ https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13454695#comment-13454695 ] 

Pierre De Rop commented on FELIX-3661:
--------------------------------------

oops, there was an error in the end of my previous message:

-> A is created (and registers B from its activate)
-> C is created
-> A is injected with C (and not with B)



                
> 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

[jira] [Closed] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "Pierre De Rop (JIRA)" <ji...@apache.org>.
     [ https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Pierre De Rop closed FELIX-3661.
--------------------------------

    Resolution: Fixed
    
> 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

[jira] [Assigned] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "David Jencks (JIRA)" <ji...@apache.org>.
     [ https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

David Jencks reassigned FELIX-3661:
-----------------------------------

    Assignee: David Jencks
    
> 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: 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

[jira] [Commented] (FELIX-3661) Scr sometimes does not invoke Reference bind method

Posted by "Pierre De Rop (JIRA)" <ji...@apache.org>.
    [ https://issues.apache.org/jira/browse/FELIX-3661?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13455669#comment-13455669 ] 

Pierre De Rop commented on FELIX-3661:
--------------------------------------

Actually it's not a testcase, but a big application I am trying to start, and I don't have knowledge about every dependencies, that's why it's difficult for now to find out the cycles.
I would appreciate if you could take a look again at the msg.log I will attach after this message, because if I can find out the remaining cycles (I guess there are still some), then I will be able to
proceed with the validation of FELIX-3645 "could not obtain lock in 5000 ms" issue (I'm actually stuck about these cycles ...).

Regarding the logs, I think that in the future, it might be very helpful to plan to add some warnings in SCR (and the specification also recommends to log an error when some cycles are detected).

Now, in the log, the remaining problem is at 2012-09-14 10:13:54,344: here, the "agent" component is expected to be injected with the MuxHandler service, but we then see the log: 

2012-09-14 10:13:54,344 ProxyAppReporter-FastCacheListener DEBUG osgi  - [agent] Dependency Manager: Adding Service com.nextenso.mux.MuxHandler/597
2012-09-14 10:13:54,344 ProxyAppReporter-FastCacheListener DEBUG osgi  - [agent] DependencyManager : component not yet created, assuming bind method call succeeded

This MuxHandler service is provided by the ["sipagent"] component. So, I suspect that there is a cycle inside the "sipagent" component.

thanks again.

                
> 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, 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