Search code examples
eclipsetomcatlogbacklogback-classic

Tomcat logback console appender follows ROOT level only and not named appenders

I use Tomcat with Eclipse. I recently upgraded to Neon and also recreated my Tomcat server configuration in there. Since then, I have not been able to log my web application properly to the Eclipse console. Specifically, if I set an INFO level in my web application appenders, they will go successfully to a log file, but not the console.

Strangely, it is only if I change the ROOT level from WARN to INFO, then the console will show the INFO levels for my application. But of course that puts everything else at INFO also, making this not very useful.

I send all Tomcat logging through logback as well. For my launch configuration, I use in arguments:

-Dcatalina.base="C:\dev\eclipse\workspace\.metadata\.plugins\org.eclipse.wst.server.core\tmp0" -Dcatalina.home="C:\dev\apache-tomcat-7.0.52" -Dwtp.deploy="C:\dev\eclipse\workspace\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps" -Djava.endorsed.dirs="C:\dev\apache-tomcat-7.0.52\endorsed" -Djava.util.logging.manager="org.apache.juli.ClassLoaderLogManager" -Djava.util.logging.config.file="C:/dev/apache-tomcat-7.0.52/conf/logging.properties" -Ddeployment.security.SSLv2Hello=false -Ddeployment.security.SSLv3=false -Ddeployment.security.TLSv1=false -Ddeployment.security.TLSv1.1=true -Ddeployment.security.TLSv1.2=true -Dlogback.configurationFile="C:/dev/apache-tomcat-7.0.52/lib/logback.xml"

and in the classpath, I add tomcat-juli.jar and jul-to-slf4j-1.7.25.jar.

Here is my logback.xml:

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="10 seconds">
 <!-- always a good idea to have an OnConsoleStatusListener    -->
 <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />  

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level (%file:%line\) - %message%n</pattern>
        </encoder>
    </appender>

    <!-- Tomcat service output has been disabled so all stdout/stderr messages come here as well. -->
    <appender name="main" class="ch.qos.logback.core.rolling.RollingFileAppender">  -->
    <!--See also http://logback.qos.ch/manual/appenders.html#RollingFileAppender -->
        <File>C:/dev/apache-tomcat-7.0.52/logs/tomcat7.log</File>
        <Append>true</Append>
        <encoder>
            <Charset>UTF-8</Charset>
            <pattern>%5level [%thread] %date{ISO8601} %class{0}:%line %mdc{requestId} - %message %n%rootException</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <maxHistory>10</maxHistory>
            <FileNamePattern>C:/dev/apache-tomcat-7.0.52/logs/tomcat7.%d{yyyy-MM-dd}.log</FileNamePattern>
        </rollingPolicy>
    </appender>

  <!-- If desired, we can create a class logger with additivity false to put that in its own log file -->

  <!-- be quiet -->
  <logger name="org.apache.struts2.util.TokenHelper" level="ERROR" />
  <logger name="org.dbunit.dataset.AbstractTableMetaData" level="ERROR"/>
  <logger name="org.springframework.mock.web.MockServletContext" level="ERROR"/>
  <logger name="org.w3c.tidy" level="OFF"/>
  <logger name="com.opensymphony.xwork2.DefaultActionProxy" level="ERROR"/>

  <!-- having issues with logging -->
  <logger name="ch.qos" level="DEBUG" />

  <logger name="com.mycompany.web.product.Catalog" level="INFO" />

  <root level="WARN">
    <appender-ref ref="CONSOLE"/>
    <appender-ref ref="main"/>
   </root>

</configuration>

And here is the output in the Eclipse console I get when I start Tomcat: 20:01:06,793 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [C:/dev/apache-tomcat-7.0.52/lib/logback.xml] at [file:/C:/dev/apache-tomcat-7.0.52/lib/logback.xml] 20:01:06,938 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set 20:01:06,974 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Will scan for changes in [file:/C:/dev/apache-tomcat-7.0.52/lib/logback.xml] 20:01:06,975 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeTask scanning period to 10 seconds 20:01:06,980 |-INFO in ch.qos.logback.core.joran.action.StatusListenerAction - Added status listener of type [ch.qos.logback.core.status.OnConsoleStatusListener] 20:01:07,017 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] 20:01:07,023 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CONSOLE] 20:01:07,032 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property 20:01:07,079 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender] 20:01:07,083 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [main] 20:01:07,086 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property 20:01:07,100 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@391359742 - No compression will be used 20:01:07,103 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@391359742 - Will use the pattern C:/dev/apache-tomcat-7.0.52/logs/tomcat7.%d{yyyy-MM-dd}.log for the active file 20:01:07,111 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'yyyy-MM-dd' from file name pattern 'C:/dev/apache-tomcat-7.0.52/logs/tomcat7.%d{yyyy-MM-dd}.log'. 20:01:07,111 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Roll-over at midnight. 20:01:07,119 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting initial period to Sun Jul 09 19:51:44 EDT 2017 20:01:07,124 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[main] - Active log file name: C:/dev/apache-tomcat-7.0.52/logs/tomcat7.log 20:01:07,124 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[main] - File property is set to [C:/dev/apache-tomcat-7.0.52/logs/tomcat7.log] 20:01:07,128 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.struts2.util.TokenHelper] to ERROR 20:01:07,128 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.dbunit.dataset.AbstractTableMetaData] to ERROR 20:01:07,128 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.springframework.mock.web.MockServletContext] to ERROR 20:01:07,128 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.w3c.tidy] to OFF 20:01:07,128 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.opensymphony.xwork2.DefaultActionProxy] to ERROR 20:01:07,129 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [ch.qos] to DEBUG 20:01:07,129 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.sentrylink.web.product.Catalog] to INFO 20:01:07,129 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to WARN 20:01:07,130 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CONSOLE] to Logger[ROOT] 20:01:07,131 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [main] to Logger[ROOT] 20:01:07,131 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration. 20:01:07,132 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@14acaea5 - Registering current configuration as safe fallback point 20:01:07.606 [main] WARN (SetPropertiesRule.java:218) - [SetPropertiesRule]{Server/Service/Engine/Host/Context} Setting property 'source' to 'org.eclipse.jst.jee.server:web' did not find a matching property. 20:01:10,298 |-INFO in ch.qos.logback.classic.servlet.LogbackServletContainerInitializer@55d16720 - Adding an instance of class ch.qos.logback.classic.servlet.LogbackServletContextListener to the current web-app 20:01:17,590 |-INFO in ch.qos.logback.classic.servlet.LogbackServletContainerInitializer@75b3fa82 - Adding an instance of class ch.qos.logback.classic.servlet.LogbackServletContextListener to the current web-app 20:01:24,547 |-INFO in ch.qos.logback.access.tomcat.LogbackValve[null] - filename property not set. Assuming [conf\logback-access.xml] 20:01:24,547 |-INFO in ch.qos.logback.access.tomcat.LogbackValve[null] - Could NOT configuration file [C:\dev\eclipse\workspace\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\conf\logback-access.xml] using property "catalina.base" 20:01:24,547 |-INFO in ch.qos.logback.access.tomcat.LogbackValve[null] - Found configuration file [C:\dev\apache-tomcat-7.0.52\conf\logback-access.xml] using property "catalina.home" 20:01:24,554 |-INFO in ch.qos.logback.access.joran.action.ConfigurationAction - debug attribute not set 20:01:24,554 |-INFO in ch.qos.logback.core.joran.action.StatusListenerAction - Added status listener of type [ch.qos.logback.core.status.OnConsoleStatusListener] 20:01:24,554 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender] 20:01:24,554 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE] 20:01:24,556 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@1990676241 - No compression will be used 20:01:24,556 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@1990676241 - Will use the pattern logs/data-access.%d{yyyy-MM-dd}.log for the active file 20:01:24,557 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'yyyy-MM-dd' from file name pattern 'logs/data-access.%d{yyyy-MM-dd}.log'. 20:01:24,557 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Roll-over at midnight. 20:01:24,558 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting initial period to Sat Jul 08 22:21:36 EDT 2017 20:01:24,558 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.access.PatternLayoutEncoder] for [encoder] property 20:01:24,572 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Active log file name: logs/data-access.log 20:01:24,572 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - File property is set to [logs/data-access.log] 20:01:24,573 |-INFO in ch.qos.logback.access.joran.action.ConfigurationAction - End of configuration. 20:01:24,573 |-INFO in ch.qos.logback.access.joran.JoranConfigurator@783a197d - Registering current configuration as safe fallback point 20:01:24,573 |-INFO in ch.qos.logback.access.tomcat.LogbackValve[null] - Done configuring

At this point I load a web page that triggers the Catalog class with INFO logging. It successfully logs in the tomcat7.log file listed above. But it does NOT appear in the console.

If I change the Catalog appender to WARN level the log file correctly leaves out the INFO messages. And as mentioned earler, if I leave the Catalog appender at INFO and change the ROOT appender to INFO, it will show up in the console along with everything else.

I have upgraded to the latest versions of logback and slf4j and it has not helped. Any help appreciated.

Solution

  • I was able to resolve this.

    I have a custom context.xml as part of my Eclipse Tomcat server configuration. It had the attribute, swallowOutput="true". This is good for a production machine (it suppresses stdout) but not for what I was trying to do here. After setting that false, things worked.

    Why it worked before in Luna, but not Neon, who knows.