Application not saving logs to specific appender

Question

I'm trying to save some logs from Apache James to specific appender.

Apache James by default uses Apache Commons Logging with added Logback. Logback.xml configuration looks like:

    <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
            <resetJUL>true</resetJUL>
    </contextListener>

    <!--  Appenders for console and logs -->

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
            <encoder>
                    <pattern>%d{HH:mm:ss.SSS} %highlight([%-5level]) %thread %logger{15}:%line - %msg%n%rEx</pattern>
                    <immediateFlush>false</immediateFlush>
            </encoder>
    </appender>

    <appender name="JAMES" class="ch.qos.logback.core.rolling.RollingFileAppender">
            <file>./logs/james.log</file>
            <encoder>
                    <pattern>%d{HH:mm:ss.SSS} [%-5level] %thread %logger{15}:%line - %msg%n%rEx</pattern>
                    <immediateFlush>false</immediateFlush>
            </encoder>

            <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">       
               <fileNamePattern>./logs/james.%d{yyyy-MM-dd}.log</fileNamePattern>
               <maxHistory>30</maxHistory>
            </rollingPolicy>
    </appender>

<appender name="JAMES-SERVER" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>./logs/james-server.log</file>
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} [%-5level] %thread %logger{15}:%line - %msg%n%rEx</pattern>
        <immediateFlush>false</immediateFlush>
    </encoder>

    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>./logs/james-server.log.%d{yyyy-MM-dd}</fileNamePattern>
        <maxHistory>30</maxHistory>
    </rollingPolicy>
</appender>

    <logger name="org.domain.mypackage" level="DEBUG">
        <appender-ref ref="JAMES-SERVER" />
    </logger>

    <root level="INFO">
            <appender-ref ref="CONSOLE" />
            <appender-ref ref="JAMES"/>
    </root>

Apache James starting as

java -classpath "james-server-jpa-guice.jar:james-server-jpa-guice.lib/*:james-server-jpa-guice.lib" -javaagent:james-server-jpa-guice.lib/openjpa-3.0.0.jar -Dlogback.configurationFile=./conf/logback.xml -Dworking.directory=. org.apache.james.JPAJamesServerMain >> ./logs/james.log

All logs fine to james.log but specific package above org.domain.mypackage is not logged to james-server.log but appears to be in james.log

Any thoughts on that?

@LuisMuñoz I have added `additivity` to the related line and it makes that logs from that package are not getting logged in the `james.log` but still are not in the `james-server.log`. Thoughts? — JackTheKnife, May 15 '19 at 14:05
Permissions on that file? May be its already an empty one and belongs to root or other user, remove it. Also, I don't think you need to add ` >> ./logs/james.log` to the command since you already have a file appender assigned to `root` log level. You may have duplicated messages. — LMC, May 15 '19 at 14:13
@LuisMuñoz I have replaced `james.log` to `james-server.log` in the JAMES appender and it writes to that file so no permission issues. Then I have removed `>> ./logs/james.log` but after that will not log James core code logs - just mailet logs. My goal is to separate James core code as james.log and maliets code logs as james-server.log. — JackTheKnife, May 15 '19 at 14:40

LMC · Accepted Answer · 2019-05-15T19:26:57.417

Your setup might need 2 fixes, remove immediateFlush tags at least for testing and add JAMES-APPENDERto root logger. immediateFlush=false should be set when heavy logging activity is expected, for testing purposes, set it to true.

  <root level="DEBUG">
    <appender-ref ref="CONSOLE" />
    <appender-ref ref="JAMES" />
    <appender-ref ref="JAMES-SERVER" />
  </root>

Logback setup can be conveniently tested using logback-examples package as follows:

export LOGBACK_CP="/home/luis.munoz/.m2/repository/org/slf4j/slf4j-api/1.6.1/slf4j-api-1.6.1.jar:/home/luis.munoz/.m2/repository/ch/qos/logback/logback-core/1.1.3/logback-core-1.1.3.jar:logback-examples-1.1.3.jar:/home/luis.munoz/.m2/repository/ch/qos/logback/logback-classic/1.1.3/logback-classic-1.1.3.jar"

java -cp "$LOGBACK_CP" chapters.appenders.ConfigurationTester ~/tmp/logback.xml

The following messages will be written to console and any configured files

12:37:45.336 [DEBUG] main c.a.ConfigurationTester:50 - **Hello test 123
12:37:45.338 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 0
12:37:45.439 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 1
12:37:45.540 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 2
12:37:45.640 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 3
12:37:45.742 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 4
12:37:45.843 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 5
12:37:45.943 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 6
12:37:46.044 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 7
12:37:46.145 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 8
12:37:46.246 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 9
12:37:46.355 [ERROR] main c.a.s.s.Bar:32 - error-level request
java.lang.Exception: test exception
        at chapters.appenders.sub.sample.Bar.subMethodToCreateRequest(Bar.java:32) [logback-examples-1.1.3.jar:na]
        at chapters.appenders.sub.sample.Bar.createLoggingRequest(Bar.java:27) [logback-examples-1.1.3.jar:na]
        at chapters.appenders.ConfigurationTester.main(ConfigurationTester.java:58) [logback-examples-1.1.3.jar:na]

On console, several log records useful for debugging a configuration are written

...
12:37:45,333 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CONSOLE] to Logger[ROOT]
12:37:45,333 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [JAMES] to Logger[ROOT]
12:37:45,333 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [JAMES-SERVER] to Logger[ROOT]
 ...

Also, this example package allows to "play" with the configuration and check the result. For example:

  <logger name="chapters.appenders.ConfigurationTester" level="DEBUG" additivity="false">
    <appender-ref ref="JAMES" />
  </logger>

  <logger name="chapters.appenders.sub.sample" level="DEBUG" additivity="false">
    <appender-ref ref="JAMES-SERVER" />
  </logger>

  <root level="DEBUG">
    <appender-ref ref="CONSOLE" />
  </root>

Will log this to james.log

16:04:44.487 [DEBUG] main c.a.ConfigurationTester:50 - **Hello test 123
16:04:44.490 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 0
16:04:44.590 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 1
16:04:44.691 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 2
16:04:44.792 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 3
16:04:44.892 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 4
16:04:44.993 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 5
16:04:45.093 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 6
16:04:45.194 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 7
16:04:45.295 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 8
16:04:45.395 [DEBUG] main c.a.ConfigurationTester:54 - logging statement 9

And this to james-server.log

16:04:45.502 [ERROR] main c.a.s.s.Bar:32 - error-level request
java.lang.Exception: test exception
    at chapters.appenders.sub.sample.Bar.subMethodToCreateRequest(Bar.java:32) [logback-examples-1.1.3.jar:na]
    at chapters.appenders.sub.sample.Bar.createLoggingRequest(Bar.java:27) [logback-examples-1.1.3.jar:na]
    at chapters.appenders.ConfigurationTester.main(ConfigurationTester.java:58) [logback-examples-1.1.3.jar:na]

I'm getting an error message for that test: `[ERROR] main c.a.s.s.Bar:32 - error-level request java.lang.Exception: test exception` — JackTheKnife, May 15 '19 at 17:29
lol I though it was an error too, but it's part of the [logging test](https://logback.qos.ch/xref/chapters/appenders/sub/sample/Bar.html). — LMC, May 15 '19 at 17:50
Interesting. Anyway - when I will move JAMES-SERVER appender to the ROOT logger it will log to the `james-server.log` and `james.log` the same, but when moved back to log based on package name is not. I think it must be something related to Apache Common Logging as for Tomcat code when I will use SLF4J it works fine with logger name. — JackTheKnife, May 15 '19 at 18:13
Did you add `additivity="false"` to the logger tag? Also, remove `>> ./logs/james.log` from the command. — LMC, May 15 '19 at 18:18
Finally I have got it to work. It looks like I need to keep `>> ./logs/james.log` and keep `immediateFlush` as `true` for JAMES-SERVER — JackTheKnife, May 15 '19 at 19:33

Application not saving logs to specific appender

1 Answers1