Java – SLF4J + Logback does not log in WildFly

I run web application in WildFly 8 and for some reason it does not log. I use SLF4J with LOGBACK. The log file is created on deploy but it is empty. I do not see my log statements in wildfly logs either.

The class contains:

package com.blah.oops;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

static final Logger log = LoggerFactory.getLogger(EndpointImpl.class);

log.debug("request called");

War contains:

• WEB-INF\lib\slf4j-api-1.7.5.jar
• WEB-INF\lib\logback-classic-1.1.1.jar
• WEB-INF\lib\logback-core-1.1.1.jar
• WEB-INF\classes\logback.xml

Configuration file logback.xml contains:

<configuration scan="true" scanPeriod="10 seconds">
    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>${LOG_PATH}/backend-main.log</file>
        <encoder>
            <pattern>%date %level [%thread] %logger{10} %msg%n</pattern>
        </encoder>
    </appender>

    <!-- PROFILER configuration -->
    <turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
        <Marker>PROFILER</Marker>
        <OnMatch>ACCEPT</OnMatch>
        <!--  <OnMatch>DENY</OnMatch> -->
    </turboFilter>

    <logger name="org.eclipse.jetty.util.log" level="info"/>
    <logger name="com.blah" level="debug"/>
    <logger name="org.apache.cxf" level="warn"/>

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

console.log contains logback initialization:

.[0m.[0m10:19:52,716 INFO  [stdout] (MSC service thread 1-2) 10:19:52,489 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
.[0m.[0m10:19:52,717 INFO  [stdout] (MSC service thread 1-2) 10:19:52,489 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
.[0m.[0m10:19:52,717 INFO  [stdout] (MSC service thread 1-2) 10:19:52,490 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [vfs:/content/backend.war/WEB-INF/classes/logback.xml]
.[0m.[0m10:19:52,717 INFO  [stdout] (MSC service thread 1-2) 10:19:52,501 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@666dc663 - URL [vfs:/content/backend.war/WEB-INF/classes/logback.xml] is not of type file
.[0m.[0m10:19:52,717 INFO  [stdout] (MSC service thread 1-2) 10:19:52,524 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
.[0m.[0m10:19:52,717 INFO  [stdout] (MSC service thread 1-2) 10:19:52,529 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeFilter scanning period to 10 seconds
.[0m.[0m10:19:52,718 INFO  [stdout] (MSC service thread 1-2) 10:19:52,529 |-INFO in ReconfigureOnChangeFilter{invocationCounter=0} - Will scan for changes in [[]] every 10 seconds.
.[0m.[0m10:19:52,718 INFO  [stdout] (MSC service thread 1-2) 10:19:52,529 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Adding ReconfigureOnChangeFilter as a turbo filter
.[0m.[0m10:19:52,718 INFO  [stdout] (MSC service thread 1-2) 10:19:52,532 |-ERROR in ch.qos.logback.core.joran.action.PropertyAction - Could not find resource [acquirer.properties].
.[0m.[0m10:19:52,718 INFO  [stdout] (MSC service thread 1-2) 10:19:52,532 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
.[0m.[0m10:19:52,718 INFO  [stdout] (MSC service thread 1-2) 10:19:52,535 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [jettyConsole]
.[0m.[0m10:19:52,718 INFO  [stdout] (MSC service thread 1-2) 10:19:52,572 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.FileAppender]
.[0m.[0m10:19:52,719 INFO  [stdout] (MSC service thread 1-2) 10:19:52,573 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE]
.[0m.[0m10:19:52,719 INFO  [stdout] (MSC service thread 1-2) 10:19:52,575 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
.[0m.[0m10:19:52,719 INFO  [stdout] (MSC service thread 1-2) 10:19:52,576 |-INFO in ch.qos.logback.core.FileAppender[FILE] - File property is set to [/var/log/blah/backend-main.log]
.[0m.[0m10:19:52,719 INFO  [stdout] (MSC service thread 1-2) 10:19:52,591 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.eclipse.jetty.util.log] to INFO
.[0m.[0m10:19:52,719 INFO  [stdout] (MSC service thread 1-2) 10:19:52,592 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.blah] to DEBUG
.[0m.[0m10:19:52,719 INFO  [stdout] (MSC service thread 1-2) 10:19:52,592 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.cxf] to WARN
.[0m.[0m10:19:52,720 INFO  [stdout] (MSC service thread 1-2) 10:19:52,592 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
.[0m.[0m10:19:52,720 INFO  [stdout] (MSC service thread 1-2) 10:19:52,713 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[ROOT]
.[0m.[0m10:19:52,720 INFO  [stdout] (MSC service thread 1-2) 10:19:52,713 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
.[0m.[0m10:19:52,720 INFO  [stdout] (MSC service thread 1-2) 10:19:52,714 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@30fbc21e - Registering current configuration as safe fallback point

It seems to me that LOGBACK is successfully configured. But log messages are lost. Any idea what is going there? It makes me no sense.