[FELIX-5867] reference field of type Logger for service LoggerFactory is always null

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: scr-2.1.2
• Component/s: Declarative Services (SCR)
• Assignee: Raymond Augé
• Reporter: Raymond Augé
• Created: 12/Jun/18 18:43
• Updated: 06/Aug/18 15:06
• Resolved: 13/Jun/18 01:36

Description

When trying the following snippet as defined in the r7 spec:

import org.osgi.service.component.annotations.Activate;
import org.osgi.service.component.annotations.Component;
import org.osgi.service.component.annotations.Reference;
import org.osgi.service.log.Logger;
import org.osgi.service.log.LoggerFactory;

@Component
public class WithLogger {

    @Reference(service = LoggerFactory.class)
    private Logger logger;

    @Activate
    void activate() {
        logger.info(l -> l.info("TESTING"));
    }

}

the logger field is always null with no obvious errors in the logs.

There's an obvious error due to the NPE in the activate method, but not why the reference field is null.

The SCR logs as follows:

[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37) BundleComponentActivator : Bundle active
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)BundleComponentActivator : Descriptor locations OSGI-INF/org.apache.aries.cdi.test.components.WithLogger.xml
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37) BundleComponentActivator : ComponentHolder created.
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)BundleComponentActivator : May enable component holder org.apache.aries.cdi.test.components.WithLogger
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)BundleComponentActivator :Enabling component holder org.apache.aries.cdi.test.components.WithLogger
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Querying state disabled
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Querying state disabled
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Component can not be activated since it is in state disabled
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Querying state disabled
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37) Updating target filters
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)No change in target property for dependency logger: currently registered: false
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37) No existing service listener to unregister for dependency logger
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Setting target property for dependency logger to null
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)New service tracker for logger, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.log.LoggerFactory), eventFilter null, initialReferenceFilter (objectClass=org.osgi.service.log.LoggerFactory)
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)dm logger tracker reset (closed)
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)classNameFilter: (objectClass=org.osgi.service.log.LoggerFactory) event filter: null
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)dm logger tracking 1 SingleStatic added \{org.osgi.service.log.LogService, org.osgi.service.log.LoggerFactory, org.eclipse.equinox.log.ExtendedLogService}=\{service.id=2, service.bundleid=0, service.scope=bundle} (enter)
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)dm logger tracking 1 SingleStatic active: false trackerOpened: false optional: false
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)dm logger tracking 1 SingleStatic added \{org.osgi.service.log.LogService, org.osgi.service.log.LoggerFactory, org.eclipse.equinox.log.ExtendedLogService}=\{service.id=2, service.bundleid=0, service.scope=bundle} (exit)
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)dm logger tracker opened
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)registering service listener for dependency logger
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Changed state from disabled to unsatisfiedReference
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37) Component enabled
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37) ActivateInternal
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Querying state unsatisfiedReference
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Querying state unsatisfiedReference
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Activating component from state unsatisfiedReference
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Querying state unsatisfiedReference
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Querying state unsatisfiedReference
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Changed state from unsatisfiedReference to satisfied
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Checking constructor public org.apache.aries.cdi.test.components.WithLogger()
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Found constructor with 0 arguments : public org.apache.aries.cdi.test.components.WithLogger()
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)getting field: logger
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Locating field logger in class org.apache.aries.cdi.test.components.WithLogger
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Found field: private org.osgi.service.log.Logger org.apache.aries.cdi.test.components.WithLogger.logger
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37) This thread collected dependencies
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37) getService (single component manager) dependencies collected.
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Querying state satisfied
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Querying state satisfied
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)For dependency logger, optional: false; to bind: [[RefPair: ref: [\{org.osgi.service.log.LogService, org.osgi.service.log.LoggerFactory, org.eclipse.equinox.log.ExtendedLogService}=\{service.id=2, service.bundleid=0, service.scope=bundle}] service: [null]]]
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)getting activate: activate
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Found activate method: void org.apache.aries.cdi.test.components.WithLogger.activate()
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)invoking activate: activate: parameters []
[main] ERROR o.a.a.cdi.test.components.WithLogger:67 - bundle cdi-itests.services-one:0.0.2.201806121839 (37)[org.apache.aries.cdi.test.components.WithLogger(0)] : The activate method has thrown an exception
java.lang.NullPointerException: null
    at org.apache.aries.cdi.test.components.WithLogger.activate(WithLogger.java:17)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.apache.felix.scr.impl.inject.methods.BaseMethod.invokeMethod(BaseMethod.java:228)
    at org.apache.felix.scr.impl.inject.methods.BaseMethod.access$1(BaseMethod.java:218)
    at org.apache.felix.scr.impl.inject.methods.BaseMethod$Resolved.invoke(BaseMethod.java:664)
    at org.apache.felix.scr.impl.inject.methods.BaseMethod.invoke(BaseMethod.java:510)
    at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:317)
    at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:307)
    at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:334)
    at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:114)
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:947)
    at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:919)
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:750)
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:661)
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:427)
    at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:665)
    at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:339)
    at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:381)
    at org.apache.felix.scr.impl.Activator.access$2(Activator.java:312)
    at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:263)
    at org.apache.felix.scr.impl.AbstractExtender.createExtension(AbstractExtender.java:196)
    at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:169)
    at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:1)
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:488)
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:1)
    at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232)
    at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:450)
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:908)
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
    at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:230)
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:137)
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:129)
    at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:191)
    at org.eclipse.osgi.container.Module.publishEvent(Module.java:476)
    at org.eclipse.osgi.container.Module.start(Module.java:467)
    at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:428)
    at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:447)
    at org.apache.aries.cdi.test.cases.AbstractTestCase.installBundle(AbstractTestCase.java:143)
    at org.apache.aries.cdi.test.cases.AbstractTestCase.installBundle(AbstractTestCase.java:136)
    at org.apache.aries.cdi.test.cases.AbstractTestCase.beforeClass(AbstractTestCase.java:69)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
    at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:24)
    at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
    at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
    at junit.framework.TestSuite.runTest(TestSuite.java:252)
    at junit.framework.TestSuite.run(TestSuite.java:247)
    at aQute.junit.Activator.test(Activator.java:351)
    at aQute.junit.Activator.run(Activator.java:187)
    at aQute.launcher.Launcher.lambda$serviceChanged$0(Launcher.java:1345)
    at aQute.launcher.Launcher.run(Launcher.java:347)
    at aQute.launcher.Launcher.main(Launcher.java:147)
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)DependencyManager: logger close component unbinding from org.apache.felix.scr.impl.manager.ComponentContextImpl@46b695ec at tracking count 1 refpairs: [[RefPair: ref: [\{org.osgi.service.log.LogService, org.osgi.service.log.LoggerFactory, org.eclipse.equinox.log.ExtendedLogService}=\{service.id=2, service.bundleid=0, service.scope=bundle}] service: [null]]]
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37) Failed creating the component instance; see log for reason
[main] DEBUG LogService.cdi-itests.services-one:? - bundle cdi-itests.services-one:0.0.2.201806121839 (37)Changed state from satisfied to failed

Issue Links

• links to: GitHub Pull Request #141