Logs not being captured by SIO2 LogAdapter

[NeilAgg]

I am using the LogAdapter from the SIO2 project to allow me to use Log4j2 for all my application logging.
It seems Lemur’s logs are not being captured by it.

Here is a test code:

package jme3;

import com.jme3.app.SimpleApplication;
import com.simsilica.lemur.GuiGlobals;
import com.simsilica.util.LogAdapter;

public class LemurTest extends SimpleApplication {
  @Override
  public void simpleInitApp() {
    LogAdapter.initialize();
    GuiGlobals.initialize(this);
  }
  
  public static void main(String[] args) {
    new LemurTest().start();
  }
}

Here is my log4j2.properties:

status = warn
appenders = console

# Create a console appender
appender.console.type = Console
appender.console.name = LogToConsole
appender.console.layout.type = PatternLayout
appender.console.layout.pattern = %level: %msg%n

# Set the simsilica logging level
logger.simsilica.name = com.simsilica
logger.simsilica.level = warn
logger.simsilica.additivity = false
logger.simsilica.appenderRef.console.ref = LogToConsole

# Set the root logging level
rootLogger.level = info
rootLogger.appenderRef.stdout.ref = LogToConsole

From the output of the program, I can see the LogAdapter is being called to manage the com.simsilica package, but the Lemur logs are still being printed at the info level even though I set the log adapter to warn level:

Setting root JUL log level to:FINE
logger config:root
Setting JUL Log: level to:INFO
logger config:com.simsilica
Setting JUL Log:com.simsilica level to:WARNING
12:51:16.398 [jME3 Main] INFO com.simsilica.lemur.GuiGlobals - Initializing GuiGlobals with:com.simsilica.lemur.GuiGlobals@15c326c
12:51:16.426 [jME3 Main] INFO com.simsilica.lemur.GuiGlobals - Lemur build date:20220405

This is not a big deal, just figured I would record it here in case the developers want to address it sometime in the future.

[pspeed]

The LogAdapter is for adapting Java’s standard logging (JUL) to log4j config. Lemur is already using slf4j and therefore already picks up log4j2 settings. LogAdapter is not needed except to control JME logs.

As to the other, it’s a log4j2 config issue and not really Lemur’s fault. It’s just log.info() and you need to get the right log4j magic to right to turn that off. Trust me that it’s possible…

It’s been a million years since I used the .properties style config so I can’t help much with log4j support in this case.

[NeilAgg]

@pspeed

Lemur […] already picks up log4j2 settings

That is good, thank you for clearing that up.

@pspeed

It’s been a million years since I used the .properties style config so I can’t help much with log4j support in this case.

What style of log4j2 config are you using? Maybe I need to change my system over to that.

[pspeed]

I switched to the XML form a long time ago.

I don’t know that I have a particularly good example handy but this is the one I’m using for my blocked tool right now:
log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn" name="MyApp" packages="">
  <Appenders>
    <RollingFile name="RollingFile" fileName="block-ed.log" ignoreExceptions="false"                
                 filePattern="logs/$${date:yyyy-MM}/block-ed-%d{MM-dd-yyyy}-%i.log.gz">
      <PatternLayout>
        <Pattern>%d{ABSOLUTE} %t %-5p [%c{1}] %m%n</Pattern>        
      </PatternLayout>
      <OnStartupTriggeringPolicy />
    </RollingFile>
    
    <Console name="STDOUT" target="SYSTEM_OUT" ignoreExceptions="false">
      <PatternLayout pattern="%d{ABSOLUTE} %-5p [%c{1}] %m%n"/>
    </Console>
  </Appenders>
  
  <Loggers>

    <Logger name="com.simsilica.lemur.style" level="INFO"/>
 
    <Root level="INFO">
      <AppenderRef ref="RollingFile"/>
      <AppenderRef ref="STDOUT"/>
    </Root>
  </Loggers>
</Configuration>

[NeilAgg]

I tried this log4j2.xml file:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn">
  <Appenders>
    <Console name="stdout" target="SYSTEM_OUT" ignoreExceptions="false">
      <PatternLayout pattern="%m %n"/>
    </Console>
  </Appenders>
  
  <Loggers>
    <Logger name="com._3dmathpuzzles" level="trace" additivity="false">
      <AppenderRef ref="stdout"/>
    </Logger>
    <Logger name="com.simsilica" level="warn" additivity="false">
      <AppenderRef ref="stdout"/>
    </Logger>
    <Root level="warn">
      <AppenderRef ref="stdout"/>
    </Root>
  </Loggers>
</Configuration>

But I am still getting the output from Lemur.
Any ideas?

[asser_fahrenholz]

@NeilAgg

<Root level="warn">
      <AppenderRef ref="stdout"/>
    </Root>

Your root level is warn, so you wont get info message unless you have specific loggers that are info-level. Try with pspeeds XML and change the package names to yours.

I had issues as well recently, so I went back to basics to some extent. You can see mine here: https://github.com/assofohdz/Subspace-Infinity/blob/infinity/infinity/src/main/resources/log4j2.xml

[pspeed]

@asser_fahrenholz

so you wont get info message

He’s trying to suppress the info messages and is seeing them anyway.

At a glance, I cannot see why his config is allowing INFO through at all. Might even be worth checking to make sure that log4j2.xml is really being used and maybe that there isn’t another one hanging around in some jar somewhere.

[NeilAgg]

@pspeed

make sure that log4j2.xml is really being used

I think it is being used. I updated my log4j2.xml to set the log for my test class to info:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn">
  <Appenders>
    <Console name="stdout" target="SYSTEM_OUT" ignoreExceptions="false">
      <PatternLayout pattern="%level: %msg%n"/>
    </Console>
  </Appenders>
  
  <Loggers>
    <Logger name="com.simsilica" level="warn" additivity="false"/>
    <Logger name="jme3" level="info" additivity="false">
      <AppenderRef ref="stdout"/>
    </Logger>
    <Root level="warn">
      <AppenderRef ref="stdout"/>
    </Root>
  </Loggers>
</Configuration>

And then I put some logs in my test code:

package jme3;

import org.apache.logging.log4j.LogManager;

import com.jme3.app.SimpleApplication;
import com.simsilica.lemur.GuiGlobals;
import com.simsilica.util.LogAdapter;

public class LemurTest extends SimpleApplication {
  @Override
  public void simpleInitApp() {
    LogAdapter.initialize();
    GuiGlobals.initialize(this);
    
    LogManager.getLogger(getClass()).debug("This is a debug output");
    LogManager.getLogger(getClass()).info("This is an info output");
    LogManager.getLogger(getClass()).warn("This is a warn output");
  }
  
  public static void main(String[] args) {
    new LemurTest().start();
  }
}

And I only get the logs I expect:

INFO: This is an info output
WARN: This is a warn output

The debug log is not printed.

[pspeed]

And if you remove your Logger config does your INFO go away?

What if you use slf4j instead of going through to the log4j back-end directly?

[NeilAgg]

@pspeed

And if you remove your Logger config does your INFO go away?

Yes

@pspeed

What if you use slf4j instead of going through to the log4j back-end directly?

My test code is currently in a larger project. I will move it to a project with itself and test it there. I will get back to you.

[NeilAgg]

This is interesting.

I set up a new project with this pom.xml file:

<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
  <modelVersion>4.0.0</modelVersion>
  <groupId>com._3dmathpuzzles</groupId>
  <artifactId>LemurTest</artifactId>
  <version>0.0.1</version>
  <properties>
    <jme3_group>org.jmonkeyengine</jme3_group>
    <jme3_ver>3.5.2-stable</jme3_ver>
  </properties>
	<dependencies>
		<dependency>
    	<groupId>com.simsilica</groupId>
    	<artifactId>lemur</artifactId>
    	<version>1.16.0</version>
		</dependency>
    <dependency>
      <groupId>${jme3_group}</groupId>
      <artifactId>jme3-core</artifactId>
      <version>${jme3_ver}</version>
    </dependency>  
    <dependency>
      <groupId>${jme3_group}</groupId>
      <artifactId>jme3-desktop</artifactId>
      <version>${jme3_ver}</version>
    </dependency>  
    <dependency>
      <groupId>${jme3_group}</groupId>
      <artifactId>jme3-lwjgl3</artifactId>
      <version>${jme3_ver}</version>
    </dependency>
    <dependency> 
  		<groupId>org.slf4j</groupId>
  		<artifactId>slf4j-api</artifactId>
  		<version>2.0.6</version>
		</dependency>
		<dependency>
  		<groupId>ch.qos.logback</groupId>
  		<artifactId>logback-core</artifactId>
  		<version>1.4.5</version>
		</dependency>
		<dependency>
  		<groupId>ch.qos.logback</groupId>
  		<artifactId>logback-classic</artifactId>
  		<version>1.4.5</version>
		</dependency>
	</dependencies>
</project>

This is my test code:

import com.jme3.app.SimpleApplication;
import com.simsilica.lemur.GuiGlobals;

public class LemurTest extends SimpleApplication {
  @Override
  public void simpleInitApp() {
    GuiGlobals.initialize(this);
  }
  
  public static void main(String[] args) {
    new LemurTest().start();
  }
}

And my logback.xml:

<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%level %logger{36} %msg%n</pattern>
    </encoder>
  </appender>

  <root level="warn">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

I do not get the INFO output lines from GuiGlobals.
If I change the root level to info, I get them again.

[NeilAgg]

After playing with this for a while, I was able to isolate it down to something in the Spring dependency in my larger project.

If I have this dependency:

    <dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-thymeleaf</artifactId>
		  <exclusions>
		    <exclusion>
		      <groupId>ch.qos.logback</groupId>
		      <artifactId>logback-classic</artifactId>
		    </exclusion>
		    <exclusion>
		      <groupId>org.apache.logging.log4j</groupId>
		      <artifactId>log4j-to-slf4j</artifactId>
		    </exclusion>
		    <exclusion>
		      <groupId>org.slf4j</groupId>
		      <artifactId>slf4j-api</artifactId>
		    </exclusion>
		    <exclusion>
		      <groupId>org.slf4j</groupId>
		      <artifactId>jul-to-slf4j</artifactId>
		    </exclusion>
		  </exclusions>
		</dependency>

The INFO logs from GuiGlobals do not print.

But, if I comment out the exclusion for logback:

    <dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-thymeleaf</artifactId>
		  <exclusions>
			  <!--
		    <exclusion>
		      <groupId>ch.qos.logback</groupId>
		      <artifactId>logback-classic</artifactId>
		    </exclusion>
		    -->
		    <exclusion>
		      <groupId>org.apache.logging.log4j</groupId>
		      <artifactId>log4j-to-slf4j</artifactId>
		    </exclusion>
		    <exclusion>
		      <groupId>org.slf4j</groupId>
		      <artifactId>slf4j-api</artifactId>
		    </exclusion>
		    <exclusion>
		      <groupId>org.slf4j</groupId>
		      <artifactId>jul-to-slf4j</artifactId>
		    </exclusion>
		  </exclusions>
		</dependency>

I get the INFO outputs from GuiGlobals.

[pspeed]

Which sounds to me like you were configuring log4j but the logs were coming from logback.

[NeilAgg]

Exactly, but I was under the impression that slf4j would warn about having multiple logging outputs, but it did not