Logback RollingFileAppender FileNotFoundException

Naveen picture Naveen · Oct 21, 2018 · Viewed 11.2k times · Source

I am using logback in my spring-boot project. When we deploy the app in PROD environment, deployment is failed with below exceptions. Before PROD, we deployed the app in lower environments, we did not see any issues. Can someone please throw some light?

In logback.xml we have specified the log path as "/app/tomcatprofile/micro001/logs/sc-erp-security-permissions-check.log" but from logs below, logpath is set as "/app/tomcatprofile/micro001/logs".

Also attached our logback xml.

15:54:22,305 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Active log file name: /app/tomcatprofile/micro001/logs
15:54:22,305 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - File property is set to [/app/tomcatprofile/micro001/logs]
15:54:22,305 |-ERROR in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - openFile(/app/tomcatprofile/micro001/logs,true) call failed. java.io.FileNotFoundException: /app/tomcatprofile/micro001/logs (Is a directory)
    at java.io.FileNotFoundException: /app/tomcatprofile/micro001/logs (Is a directory)
    at  at java.io.FileOutputStream.open0(Native Method)
    at  at java.io.FileOutputStream.open(FileOutputStream.java:270)
    at  at java.io.FileOutputStream.<init>(FileOutputStream.java:213)
    at  at ch.qos.logback.core.recovery.ResilientFileOutputStream.<init>(ResilientFileOutputStream.java:26)
    at  at ch.qos.logback.core.FileAppender.openFile(FileAppender.java:204)
    at  at ch.qos.logback.core.FileAppender.start(FileAppender.java:127)
    at  at ch.qos.logback.core.rolling.RollingFileAppender.start(RollingFileAppender.java:100)
    at  at ch.qos.logback.core.joran.action.AppenderAction.end(AppenderAction.java:90)
    at  at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:309)
    at  at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:193)
    at  at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:179)
    at  at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:62)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:165)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:152)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:110)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:53)
    at  at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:75)
    at  at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:150)
    at  at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:84)
    at  at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)
    at  at org.slf4j.LoggerFactory.bind(LoggerFactory.java:150)
    at  at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:124)
    at  at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:412)
    at  at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:357)
    at  at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:155)
    at  at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:132)
    at  at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:273)
    at  at org.springframework.boot.web.support.SpringBootServletInitializer.onStartup(SpringBootServletInitializer.java:86)
    at  at org.springframework.web.SpringServletContainerInitializer.onStartup(SpringServletContainerInitializer.java:169)
    at  at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5151)
    at  at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
    at  at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:725)
    at  at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:701)
    at  at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:717)
    at  at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:917)
    at  at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1701)
    at  at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at  at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at  at java.lang.Thread.run(Thread.java:745)

Logback.xml file

<?xml version="1.0" encoding="UTF-8"?>

<configuration>

    <property name="FILE_PATH" value="${catalina.base}/logs/sc-erp-security-permissions-check.log" />

    <appender name="consoleAppender" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <Pattern>%d [%t] %-5p %c - %X{TransactionId} - %m%n</Pattern>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>TRACE</level>
        </filter>
    </appender>

    <appender name="mainAppender"
              class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${FILE_PATH}</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${FILE_PATH}.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <append>true</append>
        <encoder>
            <Pattern>%d [%t] %-5p %c - %X{TransactionId} - %m%n</Pattern>
        </encoder>
    </appender>

    <logger name="com.adp.smartconnect" additivity="false">
        <level value="DEBUG" />
        <appender-ref ref="mainAppender" />
        <appender-ref ref="consoleAppender" />
    </logger>

    <include resource="org/springframework/boot/logging/logback/base.xml"/>

    <logger name="org.springframework.web" level="INFO"/>
    <logger name="org.springframework.boot" level="WARN"/>
    <logger name="org.springframework.jmx" level="WARN"/>
    <logger name="com.adp.smartconnect.commons" level="WARN" />
    <logger name="springfox" level="WARN"/>

    <logger name="org.springframework.ws.client.MessageTracing.sent" level="INFO"/>
    <logger name="org.springframework.ws.client.MessageTracing.received" level="INFO"/>
    <logger name="org.springframework.ws.server.MessageTracing" level="INFO"/>

    <root>
        <level value="INFO" />
        <appender-ref ref="mainAppender" />
        <appender-ref ref="consoleAppender" />
    </root>
</configuration>

Answer

Naveen picture Naveen · Oct 23, 2018

Our logback configuration uses spring-boot logback implementation internally, after I removed below line from logback.xml, issue is resolved.

<include resource="org/springframework/boot/logging/logback/base.xml"/>

Note: Our spring-boot version is 1.5.10

Puzzled questions:

  1. We still don't know why it is stripping "sc-erp-security-permissions-check.log" from complete log file path.
  2. With base.xml, deployment was successful in dev, qa and stage but failing only in 2 of 4 nodes in PROD.

I am still doing my research to find out exact root cause, will update this answer if I find something.

Thanks to @Andreas for his prompt responses.