chore: Log when service fails to instantiate

[hypr2771]

Context

Had the following issue during my switch from Jackson 2 to 3:

• my Felix container was upgraded in version 3
• my bundles were still using version 2
• they instantiated some modules
• which were provided by the container
• these modules did not have any namespace change
• so classes were still existing
• but these classes were not usable by Jackson 2

It was really not straightforward to debug due to the lack of logging on the org.apache.felix.scr.impl.manager.SingleComponentManager#getService(Bundle, ServiceRegistration<S>) method, and particularly since it caches the result.

View an example stack trace

ERROR : bundle my-plugin:2.1.0 (6)[my.plugin.path.MyPluginService(0)] : Failed to create service from bundle
java.lang.VerifyError: Bad type on operand stack
Exception Details:
  Location:
    my/plugin/path.MyPluginService.<clinit>()V @68: invokevirtual
  Reason:
    Type 'io/vavr/jackson/datatype/VavrModule' (current frame, stack[1]) is not assignable to 'com/fasterxml/jackson/databind/Module'
  Current Frame:
    bci: @68
    flags: { }
    locals: { }
    stack: { 'com/fasterxml/jackson/databind/ObjectMapper', 'io/vavr/jackson/datatype/VavrModule' }
  Bytecode:
    0000000: bb01 c959 b702 a4b2 02aa 04b6 02ae b202
    0000010: b403 b602 b7b2 02ba 03b6 02ae b202 beb6
    0000020: 02c2 b202 c8b6 02cc bb02 ce59 b702 cfb6
    0000030: 02d3 bb00 6959 bb00 6759 b702 d404 b602
    0000040: d8b7 02db b602 d3b3 01b5 b1            

	at java.base/java.lang.Class.getDeclaredConstructors0(Native Method)
	at java.base/java.lang.Class.privateGetDeclaredConstructors(Class.java:2985)
	at java.base/java.lang.Class.getConstructors(Class.java:2025)
	at org.apache.felix.scr.impl.inject.internal.ComponentConstructorImpl.<init>(ComponentConstructorImpl.java:98)
	at org.apache.felix.scr.impl.inject.internal.ComponentMethodsImpl.initComponentMethods(ComponentMethodsImpl.java:110)
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.initDependencyManagers(AbstractComponentManager.java:1029)
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.collectDependencies(AbstractComponentManager.java:1057)
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:955)

Goal

The goal of this PR is simply to add a log to let user know when a failure occurs and why, so that he can be aware something wrong occurred and can know the reason behind the linkage issue.

[stbischof]

please look the ci jobs

[hypr2771]

please look the ci jobs

Done, sorry for the silly mistake.
I did applied the same behavior as if the getServiceInternal did fail and returned false: return null.
I wonder whether I should also add a this.setFailureReason(error); before returning.

[tjwatson]

Can you provide the complete stacktrace of the error?

My concern with the change is that it no longer is re-throwing the error. What I expect to happen here is that the service factory SCR registers with the framework should throw this exception out and the OSGi framework implementation should capture the exception and fire a Framework error event. Then the log service should be logging the framework error event exception for you to observe.

But now exception is caught and logged (that is fine), but then the exception is swallowed and not handled by the framework.

[hypr2771]

My concern with the change is that it no longer is re-throwing the error. What I expect to happen here is that the service factory SCR registers with the framework should throw this exception out and the OSGi framework implementation should capture the exception and fire a Framework error event. Then the log service should be logging the framework error event exception for you to observe.

You are right, it might break the propagation. We could just rethrow the exception if required. Reading each method to the exception, I noticed the fireFrameworkEvent(FrameworkEvent.ERROR, bundle, ex) part; should I instead just listen for the framework event and avoid the logging at the method level?

Anyway, as requested, here is the full stack trace:

View the full exception stack trace

ERROR : bundle my-plugin:2.1.0 (6)[my.plugin.path.MyPluginService(0)] : Failed to create service from bundle
java.lang.VerifyError: Bad type on operand stack
Exception Details:
  Location:
    my/plugin/path.MyPluginService.<clinit>()V @68: invokevirtual
  Reason:
    Type 'io/vavr/jackson/datatype/VavrModule' (current frame, stack[1]) is not assignable to 'com/fasterxml/jackson/databind/Module'
  Current Frame:
    bci: @68
    flags: { }
    locals: { }
    stack: { 'com/fasterxml/jackson/databind/ObjectMapper', 'io/vavr/jackson/datatype/VavrModule' }
  Bytecode:
    0000000: bb01 c959 b702 a4b2 02aa 04b6 02ae b202
    0000010: b403 b602 b7b2 02ba 03b6 02ae b202 beb6
    0000020: 02c2 b202 c8b6 02cc bb02 ce59 b702 cfb6
    0000030: 02d3 bb00 6959 bb00 6759 b702 d404 b602
    0000040: d8b7 02db b602 d3b3 01b5 b1              

	at java.base/java.lang.Class.getDeclaredConstructors0(Native Method)
	at java.base/java.lang.Class.privateGetDeclaredConstructors(Class.java:2985)
	at java.base/java.lang.Class.getConstructors(Class.java:2025)
	at org.apache.felix.scr.impl.inject.internal.ComponentConstructorImpl.<init>(ComponentConstructorImpl.java:98)
	at org.apache.felix.scr.impl.inject.internal.ComponentMethodsImpl.initComponentMethods(ComponentMethodsImpl.java:110)
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.initDependencyManagers(AbstractComponentManager.java:1029)
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.collectDependencies(AbstractComponentManager.java:1057)
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:955)
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:920)
	at org.apache.felix.framework.ServiceRegistrationImpl.getFactoryUnchecked(ServiceRegistrationImpl.java:349)
	at org.apache.felix.framework.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:249)
	at org.apache.felix.framework.ServiceRegistry.getService(ServiceRegistry.java:362)
	at org.apache.felix.framework.Felix.getService(Felix.java:3984)
	at org.apache.felix.framework.BundleContextImpl.getService(BundleContextImpl.java:450)
	at my.container.listeners.SolutionBundleListener.updateService(SolutionBundleListener.java:77)
	at my.container.listeners.SolutionBundleListener.lambda$registerPlugin$1(SolutionBundleListener.java:58)
	at io.vavr.control.Try.run(Try.java:134)
	at my.container.listeners.SolutionBundleListener.lambda$registerPlugin$0(SolutionBundleListener.java:58)
	at io.vavr.Value.forEach(Value.java:258)
	at my.container.listeners.SolutionBundleListener.registerPlugin(SolutionBundleListener.java:58)
	at my.container.listeners.SolutionBundleListener.lambda$bundleChanged$0(SolutionBundleListener.java:51)
	at io.vavr.control.Option.peek(Option.java:457)
	at my.container.listeners.SolutionBundleListener.bundleChanged(SolutionBundleListener.java:51)
	at org.apache.felix.framework.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:915)
	at org.apache.felix.framework.EventDispatcher.fireEventImmediately(EventDispatcher.java:834)
	at org.apache.felix.framework.EventDispatcher.run(EventDispatcher.java:1147)
	at org.apache.felix.framework.EventDispatcher.access$000(EventDispatcher.java:54)
	at org.apache.felix.framework.EventDispatcher$1.run(EventDispatcher.java:102)
	at java.base/java.lang.Thread.run(Thread.java:1474)

I think we loose the trace here:

  <S> S getService(Bundle bundle, ServiceReference<S> ref, boolean isServiceObjetcs)
    {
        try
        {
            return m_registry.getService(bundle, ref, isServiceObjetcs);
        }
        catch (ServiceException ex)
        {
            fireFrameworkEvent(FrameworkEvent.ERROR, bundle, ex);
        }

        return null;
    }

[tjwatson]

I'm not familiar with the felix framework implementation, but if I follow correctly the implementation wrapped the causing exception in a ServiceException and that should have been caught by the catch block you posted and then the fireFrameworkEvent method should have fired an ERROR event.

If you have a log service bundle installed that should have mapped the framework event ERROR to a log entry as described at: https://docs.osgi.org/specification/osgi.core/8.0.0/service.log.html#d0e54935 and you should have been able to observe the error from the log service. That would be roughly equivalent to the ERROR log being proposed in this PR I think.

[tjwatson]

should I instead just listen for the framework event and avoid the logging at the method level?

I didn't answer your question. My point is that I don't believe we need to change anything in SCR to handle this error. Instead, we should continue to let it be thrown and handled by the framework as a framework event ERROR.