[jira] [Commented] (FELIX-6108) SCR activation log-messages cannot be disabled with R7 LogService

["Carsten Ziegeler (JIRA)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/FELIX-6108?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16833314#comment-16833314 ] 

Carsten Ziegeler commented on FELIX-6108:
-----------------------------------------

[~rotty3000] WDYT?

> SCR activation log-messages cannot be disabled with R7 LogService
> -----------------------------------------------------------------
>
>                 Key: FELIX-6108
>                 URL: https://issues.apache.org/jira/browse/FELIX-6108
>             Project: Felix
>          Issue Type: Bug
>          Components: Declarative Services (SCR)
>    Affects Versions: scr-2.1.16
>            Reporter: Tobias Gunkel
>            Priority: Major
>              Labels: log
>
> With R7 logging, it does not seem to be possible to deactivate the SCR activation log-messages if DEBUG mode is activated for a component.
> E.g. if you want to debug a component named "org.test.Main" you would set the log-level for this component to "DEBUG" in the logger config.
> As SCR also uses the logger "org.test.Main" for logging its activation messages (on DEBUG level) it also starts to verbosely log this information.
> This makes it hard to see the DEBUG messages of the component itself:
> {code:java}
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main] :  BundleComponentActivator : ComponentHolder created.
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main] : Dependency Manager created admininterface=org.osgi.service.cm.ConfigurationAdmin, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=admin, field-option=replace, collection-type=null, parameter=null
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main] : Dependency Manager created loggerFactoryinterface=org.osgi.service.log.LogService, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=loggerFactory, field-option=replace, collection-type=null, parameter=null
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main] : Component created: DS=DS13, implementation=org.test.Main, immediate=true, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[org.test.Main]
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main] : Component Services: scope=singleton, services=[org.test.Main]
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main] : Component Properties: {}
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main] : Querying state disabled
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main] : Querying state disabled
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main] : Component can not be activated since it is in state disabled
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main] : Querying state disabled
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] :  Updating target filters
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : No change in target property for dependency admin: currently registered: false
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] :  No existing service listener to unregister for dependency admin
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Setting target property for dependency admin to null
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : New service tracker for admin, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.cm.ConfigurationAdmin), eventFilter null, initialReferenceFilter (objectClass=org.osgi.service.cm.ConfigurationAdmin)
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : dm admin tracker reset (closed)
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : dm admin tracker opened
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : registering service listener for dependency admin
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : No change in target property for dependency loggerFactory: currently registered: false
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] :  No existing service listener to unregister for dependency loggerFactory
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Setting target property for dependency loggerFactory to null
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : New service tracker for loggerFactory, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.log.LogService), eventFilter null, initialReferenceFilter (objectClass=org.osgi.service.log.LogService)
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : dm loggerFactory tracker reset (closed)
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : dm loggerFactory tracking 1 SingleStatic added [org.osgi.service.log.LogService, org.osgi.service.log.LoggerFactory] (enter)
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : dm loggerFactory tracking 1 SingleStatic active: false trackerOpened: false optional: false
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : dm loggerFactory tracking 1 SingleStatic added [org.osgi.service.log.LogService, org.osgi.service.log.LoggerFactory] (exit)
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : dm loggerFactory tracker opened
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : registering service listener for dependency loggerFactory
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Changed state from disabled to unsatisfiedReference
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] :  Component enabled
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] :  ActivateInternal
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Querying state unsatisfiedReference
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Querying state unsatisfiedReference
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Activating component from state unsatisfiedReference
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Querying state unsatisfiedReference
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Querying state unsatisfiedReference
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Dependency not satisfied: admin
> 16:37:08.970 DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] :  Not all dependencies satisfied, cannot activate
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : dm admin tracking 2 SingleStatic added [org.osgi.service.cm.ConfigurationAdmin] (enter)
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] :  ActivateInternal
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Querying state unsatisfiedReference
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Querying state unsatisfiedReference
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Activating component from state unsatisfiedReference
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Querying state unsatisfiedReference
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Querying state unsatisfiedReference
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Changed state from unsatisfiedReference to satisfied
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : registration change queue [registered]
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Checking constructor public org.test.Main()
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Found constructor with 0 arguments : public org.test.Main()
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : getting field: admin
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Locating field admin in class org.test.Main
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : getReferenceClass: Looking for interface class org.osgi.service.cm.ConfigurationAdmin through loader of org.test.Main
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : getParameterClass: Found class org.osgi.service.cm.ConfigurationAdmin
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Found field: org.osgi.service.cm.ConfigurationAdmin org.test.Main.admin
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : getting field: loggerFactory
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Locating field loggerFactory in class org.test.Main
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : getReferenceClass: Looking for interface class org.osgi.service.log.LogService through loader of org.test.Main
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : getParameterClass: Found class org.osgi.service.log.LogService
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Found field: org.osgi.service.log.LogService org.test.Main.loggerFactory
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] :  This thread collected dependencies
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] :  getService (single component manager) dependencies collected.
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Querying state satisfied
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Querying state satisfied
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : For dependency admin, optional: false; to bind: [[RefPair: ref: [[org.osgi.service.cm.ConfigurationAdmin]] service: [org.apache.felix.cm.impl.ConfigurationAdminImpl@3349e9bb]]]
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : For dependency loggerFactory, optional: false; to bind: [[RefPair: ref: [[org.osgi.service.log.LogService, org.osgi.service.log.LoggerFactory]] service: [org.apache.felix.log.LogServiceImpl@409bf450]]]
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : getting activate: activate
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] :  Locating method activate in class org.test.Main
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Declared Method org.test.Main.activate([interface org.osgi.service.component.ComponentContext]) not found
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Found activate method: public void org.test.Main.activate()
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : invoking activate: activate: parameters []
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : invoked activate: activate
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] :  Set implementation object for component
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : Changed state from satisfied to active
> DEBUG org.test.Main - bundle org.test:0.0.0 (4)[org.test.Main(0)] : dm admin tracking 2 SingleStatic added [org.osgi.service.cm.ConfigurationAdmin] (exit)
> {code}
> This behavior was introduced with FELIX-5866. In the comments of the issue it is stated that the log level of SCR can now be configured by LoggerAdmin. But this is not the case (or I am missing something) because the Logger configuration used is the one of the component (here "org.test.Main") and not the one of SCR.
> With R6 logging it was possible to disable this as the SCR configuration was also checked.
> With R7 it is not (as R7LogServiceLogger.checkScrConfig() returns false).
> There is also no possibility to filter these messages out as they are logged on the component logger and not on an SCR logger.
> Maybe as a solution the SCR log-level should be checked too, i.e. loggerFactory.getLogger("org.apache.felix.scr").isLogEnabled(...).



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)