Spring-boot: logback.xml processed 2 times with spring-boot

[Giambapisasale]

Hi all,
I've tested a very strange behaviour with spring-boot and logback. Seems that the file logback.xml is processed 2 times after application start, the first on initialization of class SpringApplication,

row 160: private final Log log = LogFactory.getLog(getClass());

the second time when the application runs and environment is prepared, class SpringApplication

row 285: runListener.environmentPrepared(environment);

this strange behaviour result on double creation of log file if a timestamp is associated.
This is my logback.xml:

<configuration>

    <timestamp key="byMilliSecond" datePattern="yyyyMMddHHmmssSS" />
    <property file="application.properties" />

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>LOG_${input_file}_${byMilliSecond}.log</file>
        <append>false</append>
        <encoder>
            <pattern>%-4relative [%thread] %-5level %logger{35} - %msg %n</pattern>
        </encoder>
    </appender>

    <!-- human readable log file-->
    <appender name="human_log_file" class="ch.qos.logback.core.FileAppender">
        <file>ERROR_${input_file}_${byMilliSecond}.log</file>
        <append>true</append>
        <encoder>
            <pattern>%-4relative [%thread] %-5level %logger{35} - %msg %n</pattern>
        </encoder>
    </appender>

    <!-- human readable logger -->
    <logger name="human_log" level="DEBUG" additivity="false">
        <appender-ref ref="human_log_file" />
    </logger>

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

while this is my application starting code:

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;

@SpringBootApplication
public class Application {

    public static void main(String[] args) throws Exception {
        SpringApplication.run(Application.class, args);
    }
}

[Giambapisasale]

for example if I set ${input_file} as testRH.csv the result is the sequent:

ERROR_testRH.csv_20150902162131287.log
ERROR_testRH.csv_20150902162142618.log
LOG_testRH.csv_20150902162131287.log
LOG_testRH.csv_20150902162142618.log

the log used is only the last created

[philwebb]

@Giambapisasale It sounds like you're hitting the issue described in #2558. There's a brief description of why in https://github.com/spring-projects/spring-boot/issues/2558#issuecomment-115447712.

Could you try the latest 1.3 milestone and rename your configuration to logback-spring.xml and let me know if that fixes it?