Loggin is not being configured by ConfigAdmin or not reading org.ops4j.pax.logging.log4j2.config.file

Description

Hi, Apache Felix is saving configuration for PaxLogging, however it is not reading the configuration (my guess) and Pax keeps forward all messages to console in debug mode.

My Trace
Updated org.ops4j.pax.logging.log4j2.config.file to /Users/davi/Development/git/siteview/io.infolayer.siteview.framework/root/conf/log.xml

Part of my code used to configure Pax

ServiceReference<ConfigurationAdmin> reference = bundleContext.getServiceReference(ConfigurationAdmin.class);
ConfigurationAdmin configurationAdmin = bundleContext.getService(reference);

if (configurationAdmin != null) {
Configuration config = configurationAdmin.getConfiguration(PaxLoggingConstants.LOGGING_CONFIGURATION_PID);

if (config == null) {
System.out.println("DEBUG1 NULL");
}else {
if (config.getProperties() != null) {
System.out.println("DEBUG1 " + config.getProperties().size());
}else {
System.out.println("DEBUG1 NULL properties");
}
}

File cf = new File(rootDirectory, "log.xml");

Dictionary<String, Object> map = new Hashtable<String, Object>();
map.put(PaxLoggingConstants.PID_CFG_LOG4J2_CONFIG_FILE, cf.getCanonicalPath());
config.update(map);
log.info("Updated {} to {}", PaxLoggingConstants.PID_CFG_LOG4J2_CONFIG_FILE, cf.getCanonicalPath());
}else {
System.out.println("DEBUG1 NULL config admin");
}

List of ConfigAdmin files

.//org
.//org/ops4j
.//org/ops4j/pax
.//org/ops4j/pax/logging.config
.//org_apache_felix_cm_impl_DynamicBindings.config

logging.config content

cat .//org/ops4j/pax/logging.config
:org.apache.felix.configadmin.revision:=L"7"
org.ops4j.pax.logging.log4j2.config.file="/Users/davi/Development/git/siteview/io.infolayer.siteview.framework/root/conf/log.xml"
service.pid="org.ops4j.pax.logging"

log.xml file is exactly as suggested

<Configuration id="builtin.rolling">
<Appenders>
<Console name="console">
<PatternLayout pattern="%logger/%class [%level] %message%n" />
</Console>
<RollingFile name="file" append="true">
<fileName>logs/servicexpto.log</fileName>
<filePattern>logs/servicexpto.log.%d{yyyy-MM}</filePattern>
<PatternLayout pattern="%logger/%class [%level] %mdc %message%n" />
<Policies>
<TimeBasedTriggeringPolicy />
</Policies>
</RollingFile>
</Appenders>

<Loggers>
<Logger name="my.logger" level="info" additivity="false">
<AppenderRef ref="file" />
</Logger>
<Root level="info">
<AppenderRef ref="console" />
</Root>
</Loggers>
</Configuration>

VM args (just for trying)

I've also tried to get rid of console DEBUG level by setting VM args -Dorg.ops4j.pax.logging.DefaultServiceLog.level=INFO, and got not result either.

Load bundle

g! lb
START LEVEL 1
ID|State |Level|Name
0|Active | 0|System Bundle (6.0.2)|6.0.2
1|Active | 1|org.objectweb.asm (7.1.0)|7.1.0
2|Active | 1|org.objectweb.asm.commons (7.1.0)|7.1.0
3|Active | 1|org.objectweb.asm.tree (7.1.0)|7.1.0
4|Active | 1|Apache Commons IO (2.6.0)|2.6.0
5|Active | 1|geronimo-jta_1.1_spec (1.1.1)|1.1.1
6|Active | 1|Gson (2.8.5)|2.8.5
7|Active | 1|jansi (1.17.1)|1.17.1
8|Active | 1|javax.annotation API (1.3.2)|1.3.2
9|Active | 1|javax.mail bundle from Glassfish (1.4.1.v201005082020)|1.4.1.v201005082020
10|Active | 1|WebSocket server API (1.0.0)|1.0.0
11|Active | 1|Jetty :: Servlet Annotations (9.4.18.v20190429)|9.4.18.v20190429
12|Active | 1|Jetty :: Asynchronous HTTP Client (9.4.18.v20190429)|9.4.18.v20190429
13|Active | 1|Jetty :: Deployers (9.4.18.v20190429)|9.4.18.v20190429
14|Active | 1|Jetty :: Http Utility (9.4.18.v20190429)|9.4.18.v20190429
15|Active | 1|Jetty :: IO Utility (9.4.18.v20190429)|9.4.18.v20190429
16|Active | 1|Jetty :: JNDI Naming (9.4.18.v20190429)|9.4.18.v20190429
17|Active | 1|Jetty :: OSGi :: Boot (9.4.18.v20190429)|9.4.18.v20190429
18|Active | 1|Jetty Servlet API and Schemas for OSGi (4.0.1)|4.0.1
19|Active | 1|Jetty :: Plus (9.4.18.v20190429)|9.4.18.v20190429
20|Active | 1|Jetty :: Security (9.4.18.v20190429)|9.4.18.v20190429
21|Active | 1|Jetty :: Server Core (9.4.18.v20190429)|9.4.18.v20190429
22|Active | 1|Jetty :: Servlet Handling (9.4.18.v20190429)|9.4.18.v20190429
23|Active | 1|Jetty :: Utilities (9.4.18.v20190429)|9.4.18.v20190429
24|Active | 1|Jetty :: Webapp Application Support (9.4.18.v20190429)|9.4.18.v20190429
25|Active | 1|Jetty :: XML utilities (9.4.18.v20190429)|9.4.18.v20190429
26|Active | 1|JLine Bundle (3.7.0)|3.7.0
27|Active | 1|mongo-java-driver (3.7.1)|3.7.1
28|Active | 1|Apache Aries SPI Fly Dynamic Weaving Bundle (1.2.1)|1.2.1
29|Active | 1|Apache Felix Bundle Repository (2.0.10)|2.0.10
30|Active | 1|Apache Felix Configuration Admin Service (1.9.12)|1.9.12
31|Active | 1|Apache Felix EventAdmin (1.5.0)|1.5.0
32|Active | 1|Apache Felix File Install (3.6.4)|3.6.4
33|Active | 1|Apache Felix Gogo Command (1.0.2)|1.0.2
34|Active | 1|Apache Felix Gogo JLine Shell (1.1.0)|1.1.0
35|Active | 1|Apache Felix Gogo Runtime (1.1.0)|1.1.0
36|Active | 1|Apache Felix Log Service (1.2.0)|1.2.0
37|Active | 1|Apache Felix Declarative Services (2.1.16)|2.1.16
38|Active | 1|org.osgi:org.osgi.util.function (1.1.0.201802012106)|1.1.0.201802012106
39|Active | 1|org.osgi:org.osgi.util.promise (1.1.1.201810101357)|1.1.1.201810101357
40|Active | 1|OPS4J Pax Logging - API (1.11.2)|1.11.2
41|Active | 1|OPS4J Pax Logging - Log4Jv2 implementation (1.11.2)|1.11.2
42|Active | 1|Java Servlet API (3.1.0)|3.1.0
43|Active | 1|Jetty :: Websocket :: API (9.4.18.v20190429)|9.4.18.v20190429
44|Active | 1|Jetty :: Websocket :: Client (9.4.18.v20190429)|9.4.18.v20190429
45|Active | 1|Jetty :: Websocket :: Common (9.4.18.v20190429)|9.4.18.v20190429
46|Active | 1|Jetty :: Websocket :: Server (9.4.18.v20190429)|9.4.18.v20190429
47|Active | 1|Jetty :: Websocket :: Servlet Interface (9.4.18.v20190429)|9.4.18.v20190429
48|Active | 1|Siteview :: Plugins :: Microsoft Active Directory (1.0.0)|1.0.0
49|Active | 1|Siteview :: Plugins :: Sample (1.0.1)|1.0.1
50|Active | 1|Siteview :: Configuration Manager (1.0.0)|1.0.0
51|Active | 1|Siteview :: Plugins (1.0.1)|1.0.1
52|Active | 1|Siteview :: Plugins :: NMAP Network Scanner (1.0.0)|1.0.0
53|Active | 1|Siteview :: Plugins :: Database Oracle (1.0.0)|1.0.0
54|Active | 1|Siteview :: Plugins :: Vmware API SDK (1.0.0)|1.0.0
55|Active | 1|Siteview :: Mesh (1.0.0)|1.0.0
56|Active | 1|Siteview :: API Library (1.0.0)|1.0.0
57|Active | 1|Siteview :: Identity Manager (1.0.1)|1.0.1
58|Active | 1|Siteview :: Plugins :: Microsoft Office365 (1.0.0)|1.0.0
59|Active | 1|Siteview :: Server Shell Commands (1.0.0)|1.0.0
60|Active | 1|Siteview :: Repository Plugin (1.0.1)|1.0.1
61|Active | 1|Siteview :: Web API Services (1.0.0)|1.0.0
g!

Environment

MacOS 10.14 java 1.8.0_211

Activity

Show:
Grzegorz Grzybek
October 2, 2019, 1:53 PM

Hmm, I have strange feeling that you could try:

instead of what you currently have:

it'll work. Please try

this 2nd argument is bundle location. And if you don't specify it, the PID will be owned by the calling bundle, which means that pax-logging-log4j2 won't have access to this PID.

Davi Baldin Tavares
October 2, 2019, 2:19 PM

Wow, perfect shot. Now my bundle is configuring Pax now.

org.ops4j.pax.logging.pax-logging-log4j2 [org.ops4j.pax.logging.spi.support.EventAdminConfigurationNotifier] INFO : Sending Event Admin nofification (configuration successful) to org/ops4j/pax/logging/Configuration
org.ops4j.pax.logging.pax-logging-api [log4j2] INFO : Log4J2 configured using file '/Users/davi/Development/git/siteview/io.infolayer.siteview.framework/root/conf/log.xml'. Ignored FQCN: org.apache.logging.log4j.spi.AbstractLogger
org.ops4j.pax.logging.spi.support.EventAdminConfigurationNotifier/org.ops4j.pax.logging.spi.support.EventAdminConfigurationNotifier [INFO] Sending Event Admin nofification (configuration successful) to org/ops4j/pax/logging/Configuration

By now I got half the DEBUG messages I don’t want to, because Pax was running for a while “unconfigured” - before my bundle’s start() lifecycle.

 

And finally, how to make Pax read it’s configuration kept by ConfigAdmin at Pax bundle’s start() next time without need to configure it again? - Should I got to the fragment bundle approach?

Regards,

Davi

 

Grzegorz Grzybek
October 2, 2019, 3:03 PM

I use pax-logging through Karaf and it has this in etc/system.properties:

So in Karaf, indeed - until configadmin updates pax-logging with proper PID config, there's no logging.

You can check https://ops4j1.jira.com/wiki/spaces/paxlogging/pages/499580944/Using+Pax+Logging+API+without+backend documentation - there's org.ops4j.pax.logging.useFileLogFallback option with which you can redirect those early logs into file. Many new pax-logging integration tests do that.

Davi Baldin Tavares
October 2, 2019, 4:19 PM

Felix has the same feature (or should work similar to). I got a clear picture how to configure Pax. I’ll dig a little bit more on Felix because I cannot switch to Karaf right now. Thank you Grzegorz for pointing me the mistake. As soon as found a solution I’ll share here.

 

Jean-Baptiste Onofre
November 2, 2019, 6:27 AM

Please reopen this Jira if needed with details about your finding about Felix.

Assignee

Unassigned

Reporter

Davi Baldin Tavares

Fix versions

None

Labels

None

Components

Affects versions

Priority

Minor
Configure