Logback+SLF4J does no log in JavaEE 7 application

Question

I'm building a simple app and now i'm facing the "logging nightmare" on javaee application. I've done days of searches, hundreds of change/test but there's no way to make it run. My app is made of a simple

  EAR
   +-- /lib
   |     +-- slf4j-api-1.7.25.jar
   |     +-- logback-classic-1.2.3.jar
   |     +-- logback-core-1.2.3.jar
   |
   +-- JAR (JPA/EJB/Producers/Interceptors)
   |    +--src/main/resources
   |        +-- logback.xml
   |        +-- logback-test.xml
   |
   +-- WAR

The libs are so loaded in the lib directory of the EAR file.
my pom.xml in the EJB project contains this dependencies:

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.25</version>
</dependency>
<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.2.3</version>
</dependency>

there is also the javaee-api-7.0 as provided. I'm putting log facility inside the EJB project so I can use the log producer in the webapp and inject the logger also inside the JSF controllers. The logback.xml is this:

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true">
    <property name="DEV_HOME" value="c:/Dev" />

    <appender name="FILE-AUDIT"
                  class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${DEV_HOME}/debug.log</file>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <Pattern>WE:%d{yyyy-MM-dd HH:mm:ss} - %msg%n</Pattern>
        </encoder>

        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- rollover daily -->
            <fileNamePattern>${DEV_HOME}/archived/debug.%d{yyyy-MM-dd}.%i.log
            </fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy
                class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
        </rollingPolicy>
    </appender>

    <logger name="it.univaq.we2018" level="DEBUG" additivity="false">
        <appender-ref ref="FILE-AUDIT" />
    </logger>

    <root level="ERROR">
        <appender-ref ref="FILE-AUDIT" />
    </root>
</configuration>

All my classes are under the it.univaq.we2018 package (.service, .controllers, ....). Here is the CDI producer (the System.out are there just for my purposes):

@Named
@Singleton
public class LoggerProducer {
    @Produces
    public Logger produceLogger(InjectionPoint ip) {
        System.out.println("-----> construct logging for: "+ip.getMember().getDeclaringClass());
        Logger log = LoggerFactory.getLogger(ip.getMember().getDeclaringClass());
        System.out.println("-----> LogFactory is: "+log+" for "+log.getName()); 
        return log;
    }
}

This is an EJB where it's used:

@Stateless
@LocalBean
public class SecurityService implements Serializable {
    @Inject
    Logger log;

    public boolean performSecurityCheck(String userName, String target) {        
        log.debug("Testing ["+target+"] for user ["+userName+"]...");
        return true;
    }
}

The package of the Logger and LoggerFactory is org.slf4j
Tried to move the logback.xml under every folder/package...nothing. The output is always the same:

INFORMAZIONI:   indexController.init() INFORMAZIONI:   ---- ENTER:
[it.univaq.we2018.tutor.controller.IndexController.doAction()]

INFORMAZIONI:   -----> construct logging for: class
it.univaq.we2018.tutor.service.SecurityService

INFORMAZIONI:   -----> LogFactory is: 
Logger[it.univaq.we2018.tutor.service.SecurityService]
for it.univaq.we2018.tutor.service.SecurityService

INFORMAZIONI:  10:38:34.423 [http-thread-pool::http-listener-1(4)] DEBUG
it.univaq.we2018.tutor.service.SecurityService - Testing
[it.univaq.we2018.tutor.controller.IndexController.doAction()] for
user [null]...

INFORMAZIONI:   indexController.doAction() INFORMAZIONI:  
BaseService.businessMethod() INFORMAZIONI:   ---- EXIT: 
[it.univaq.we2018.tutor.controller.IndexController.doAction()]

The log row #4 is the one that should go to the file but the file is never opened and the format of the log is not consistent with the configuration (should start with WE: prefix and have different pattern). I don't know how to fix this. I always thought that the logging of JavaEE application needed a complete redesign from the ground-up: the appserver should provide a "plugin" mechanism like the datasource that reduces all of this problem related to configuration, classloading, lib clashing and so on.

Running on NetBeans 8.2 maven javaee7 archetype project, Java 1.8_172 under Payara 5.182.

Answer 1

You have a resource visibility problem.

Jars in the EAR/lib directory cannot see classes or resources in EJB jars or WAR files. Your configuration currently appears to be in an EJB module. Therefore the log-back classes in the EAR/lib directory cannot see the configuration files.

If you must package your logging configuration then it will need to be in a jar that is in the EAR/lib directory for it to be found.

More information on visibility of resources and classes within an EAR file can be found in my answer to My ear is not able to find ejb module classes.

Personally, I prefer to externalise logging configuration. In the case of log-back you can specify a path to the config file using the -Dlogback.configurationFile=/path/to/config.xml environment variable.