CODEWITHSUNDEEP
spring-bootlog4j2
Vinny Gray
Vinny Gray

Reputation: 547

Log4J2 not working on Spring Boot on many levels

I am trying to use log4j2 in a Spring Boot application, but it is going wrong on several levels.

This is a very simple Hello World application, just trying to get things working before I try it in production code. It is just a simple Initializr-generated Spring Boot application, with no added dependencies.

Problem #1 is that I am getting the following warnings, so I tried adding exclusions, but so far nothing is working

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/C:/Users/vgray/.m2/repository/ch/qos/logback/logback-classic/1.2.3/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/C:/Users/vgray/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.13.3/log4j-slf4j-impl-2.13.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]

Here is the pom:

<?xml version="1.0" encoding="UTF-8"?>
<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>
    <parent>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <version>2.4.2</version>
        <relativePath/> <!-- lookup parent from repository -->
    </parent>
    <groupId>com.sample</groupId>
    <artifactId>log4j2</artifactId>
    <version>0.0.1-SNAPSHOT</version>
    <name>log4j2</name>
    <description>Demo project for Spring Boot</description>
    <properties>
        <java.version>11</java.version>
        <log4j2.version>2.13.3</log4j2.version>
    </properties>
    <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter</artifactId>
            <exclusions>
                <exclusion>
                    <groupId>org.springframework.boot</groupId>
                    <artifactId>spring-boot-starter-logging</artifactId>
                </exclusion>
            </exclusions>
        </dependency>

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-log4j2</artifactId>
        </dependency>
    </dependencies>

    <build>
        <plugins>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
            </plugin>
        </plugins>
    </build>

</project>

Problem #2 (I assume related) is that I have log4j2.xml in my src/main/resources dir, but it seems to be ignored.

Here is the log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn">
    <Properties>
        <Property name="basePath">E:\dev\log4j2\\logs</Property>
    </Properties>

    <Appenders>
        <RollingFile name="fileLogger" fileName="${basePath}/app-info.log" filePattern="${basePath}/app-info-%d{yyyy-MM-dd}.log">
            <PatternLayout>
                <pattern>[%-5level] %d{MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n</pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true" />
            </Policies>
        </RollingFile>

        <Console name="console" target="SYSTEM_OUT">
            <PatternLayout   pattern="[%-5level] %d{MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n" />
        </Console>
    </Appenders>
    <Loggers>
        <Logger name="Log4j2Application" level="debug" additivity="true">
            <appender-ref ref="fileLogger" level="debug" />
        </Logger>
        <Root level="debug" additivity="false">
            <appender-ref ref="console" />
        </Root>
    </Loggers>
</Configuration>

I am assuming it is ignored, because the pattern is supposed to be MM-dd..., but the log messages are logging differently.

Here is my entire Spring Boot program:

package com.vgray.sample.log4j2;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;

@SpringBootApplication
public class Log4j2Application {

    private static final Logger logger = LogManager.getLogger("Log4j2Application");

    public static void main(String[] args) {
        logger.trace("A TRACE Message");
        logger.debug("A DEBUG Message");
        logger.info("An INFO Message");
        logger.warn("A WARN Message");
        logger.error("An ERROR Message");
        logger.error("Error Message Logged !!!", new NullPointerException("NullError"));
        SpringApplication.run(Log4j2Application.class, args);
    }

}

Here is my entire log

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/C:/Users/vgray/.m2/repository/ch/qos/logback/logback-classic/1.2.3/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/C:/Users/vgray/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.13.3/log4j-slf4j-impl-2.13.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder]
21:20:18.355 [main] DEBUG Log4j2Application - A DEBUG Message
21:20:18.358 [main] INFO Log4j2Application - An INFO Message
21:20:18.358 [main] WARN Log4j2Application - A WARN Message
21:20:18.358 [main] ERROR Log4j2Application - An ERROR Message
21:20:18.361 [main] ERROR Log4j2Application - Error Message Logged !!!
java.lang.NullPointerException: NullError
    at com.vgray.sample.log4j2.Log4j2Application.main(Log4j2Application.java:19)
21:20:18.531 [restartedMain] DEBUG Log4j2Application - A DEBUG Message
21:20:18.532 [restartedMain] INFO Log4j2Application - An INFO Message
21:20:18.532 [restartedMain] WARN Log4j2Application - A WARN Message
21:20:18.532 [restartedMain] ERROR Log4j2Application - An ERROR Message
21:20:18.532 [restartedMain] ERROR Log4j2Application - Error Message Logged !!!
java.lang.NullPointerException: NullError
    at com.vgray.sample.log4j2.Log4j2Application.main(Log4j2Application.java:19)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:49)

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v2.4.2)

2021-02-28 21:20:19.087  INFO 69604 --- [  restartedMain] c.v.sample.log4j2.Log4j2Application      : Starting Log4j2Application using Java 11.0.3 on DESKTOP-AM6DIPA with PID 69604 (E:\dev\log4j2\target\classes started by vgray in e:\dev\log4j2)
2021-02-28 21:20:19.089  INFO 69604 --- [  restartedMain] c.v.sample.log4j2.Log4j2Application      : No active profile set, falling back to default profiles: default
2021-02-28 21:20:19.174  INFO 69604 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : Devtools property defaults active! Set 'spring.devtools.add-properties' to 'false' to disable
2021-02-28 21:20:19.174  INFO 69604 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : For additional web related logging consider setting the 'logging.level.web' property to 'DEBUG'
2021-02-28 21:20:20.352  INFO 69604 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2021-02-28 21:20:20.364  INFO 69604 --- [  restartedMain] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2021-02-28 21:20:20.364  INFO 69604 --- [  restartedMain] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.41]
2021-02-28 21:20:20.451  INFO 69604 --- [  restartedMain] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2021-02-28 21:20:20.451  INFO 69604 --- [  restartedMain] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1275 ms
2021-02-28 21:20:20.657  INFO 69604 --- [  restartedMain] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2021-02-28 21:20:20.829  INFO 69604 --- [  restartedMain] o.s.b.d.a.OptionalLiveReloadServer       : LiveReload server is running on port 35729
2021-02-28 21:20:20.862  INFO 69604 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2021-02-28 21:20:20.876  INFO 69604 --- [  restartedMain] c.v.sample.log4j2.Log4j2Application      : Started Log4j2Application in 2.33 seconds (JVM running for 3.718)

Upvotes: 2

Views: 4124

Answers (2)

xerx593
xerx593

Reputation: 13261

Sorry, cannot reproduce/works like a charm:

https://github.com/xerx593/soq66415875

  • Uses configuration from src/main/resources/log4j2.xml.
  • Prints DEBUG log messages to:
    • console as to
    • ${working_dir}/app-info.log (according to configuration) and exits.

Tiny(iest) changes to original Post:

  • removed (redundant) <log4j2.version/> from pom.xml (2.13.3 - same version as managed by spring-boot-starter:2.4.2)
  • relative addressing of the log file.

Output:

[DEBUG] 03-01 05:20:38.923 [main] Log4j2Application - A DEBUG Message
[INFO ] 03-01 05:20:38.938 [main] Log4j2Application - An INFO Message
[WARN ] 03-01 05:20:38.938 [main] Log4j2Application - A WARN Message
[ERROR] 03-01 05:20:38.938 [main] Log4j2Application - An ERROR Message
[ERROR] 03-01 05:20:38.938 [main] Log4j2Application - Error Message Logged !!!
java.lang.NullPointerException: NullError
    at com.example.demo.Log4j2Application.main(Log4j2Application.java:18) [classes/:?]

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v2.4.2)

[INFO ] 03-01 05:20:39.839 [main] Log4j2Application - Starting Log4j2Application using Java 11.0.10 on rihanna with PID 9892 (D:\DEV\projects\soq66415875\target\classes started by xerx in D:\DEV\projects\soq66415875)
[DEBUG] 03-01 05:20:39.839 [main] Log4j2Application - Running with Spring Boot v2.4.2, Spring v5.3.3
[INFO ] 03-01 05:20:39.839 [main] Log4j2Application - No active profile set, falling back to default profiles: default
[DEBUG] 03-01 05:20:39.839 [main] SpringApplication - Loading source class com.example.demo.Log4j2Application
...

.... tons of debug messages, and finally:

    ...
    org.springframework.boot.autoconfigure.info.ProjectInfoAutoConfiguration



[INFO ] 03-01 05:20:40.889 [main] Log4j2Application - Started Log4j2Application in 1.744 seconds (JVM running for 3.669)
[DEBUG] 03-01 05:20:40.904 [SpringContextShutdownHook] AnnotationConfigApplicationContext - Closing org.springframework.context.annotation.AnnotationConfigApplicationContext@54ec8cc9, started on Mon Mar 01 05:20:39 CET 2021
[DEBUG] 03-01 05:20:40.904 [SpringContextShutdownHook] AnnotationMBeanExporter - Unregistering JMX-exposed beans on shutdown

;) (or it is one/both of the tiny changes, or other "side effects")

Upvotes: 1

Ananthapadmanabhan
Ananthapadmanabhan

Reputation: 6206

I think both your problems arouse because you were not excluding the logging dependency from the spring-boot-starter-parent which you were including as the parent dependency. You need to exclude it from starter parent like:

   <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <exclusions>
            <exclusion>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-starter-logging</artifactId>
            </exclusion>
        </exclusions>
    </dependency>

Your pom.xml was excluding it from spring-boot-starter instead.

Upvotes: 2

Related Questions