4

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>
Ali Behzadian Nejad
  • 8,804
  • 8
  • 56
  • 106
Naveen
  • 907
  • 2
  • 15
  • 25
  • @Andreas if you look at our logback.xml file, we set File name as /app/tomcatprofile/micro001/logs/sc-erp-security-permissions-check.log. See below configuration. – Naveen Oct 21 '18 at 02:05
  • @Andreas in btw, this is not causing an issue in lower environments. – Naveen Oct 21 '18 at 02:06
  • Does the folder `/app/tomcatprofile/micro001/logs` exist, and is the user running Tomcat authorized to write to that folder? – Andreas Oct 21 '18 at 02:08
  • @Andreas yes that path exists and there are other apps which are writing logs to the same directory. – Naveen Oct 21 '18 at 02:09
  • That wasn't my question. Is the **user running Tomcat** authorized? Doesn't matter what other programs are doing, because they very likely are running as a different user than Tomcat is, given that standard setups of Tomcat on Linux machines run Tomcat using a dedicated `tomcat` user and group. – Andreas Oct 21 '18 at 02:12
  • @Andreas user which we use to deploy is a super user and it has read/write permissions. – Naveen Oct 21 '18 at 02:24
  • Ok, just to confirm terminology: "[Deploy](https://en.wikipedia.org/wiki/Software_deployment)" is the act of *installing* the code, e.g. with Tomcat that word is used for installing a new war file. Even if you were logged in as a superuser when you installed Tomcat itself, doesn't mean that the background Tomcat service process is running as that superuser. If you run `ps -Af`, what user name does it show for the process running Tomcat? On my CentOS, it says user `tomcat`, even though I only ever log in as `root`. – Andreas Oct 21 '18 at 02:34
  • @Andreas when I ran that command, user I see is 'wasadmin' which is our super user. In btw I really appreciate the time you are putting for my question. – Naveen Oct 21 '18 at 02:40

2 Answers2

3

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.

Hearen
  • 7,420
  • 4
  • 53
  • 63
Naveen
  • 907
  • 2
  • 15
  • 25
  • 2
    Did you got chance find the exact root cause ? I m facing the same issue. Its working fine on lower environments but failing on Prod – Vishal Kharde Mar 30 '20 at 09:48
0

In my case, the problem is caused by the running user does not have permission to create the folder containing the log file, which I set it to /var/log/webcast

What resolve my issue is to give permission to the running user in my .service file :

[Unit]
Description=myapp
After=syslog.target
  
[Service]
User=webcast
ExecStart=/bin/bash /opt/webcast/run.sh
SuccessExitStatus=143
Restart=always
RestartSec=5
StartLimitInterval=1

[Install]
WantedBy=multi-user.target

sudo usermod -aG adm **webcast**
Ali Behzadian Nejad
  • 8,804
  • 8
  • 56
  • 106
RAY
  • 2,201
  • 2
  • 19
  • 18