Log4j2: Logs not sent to Console where as logs to file works fine

Question

I am a newbie to log4j. My log4j configuration is not writing logs to Console where as the logs to File is working fine. I am not able to troubleshoot this issue inspite of refering earlier posts. I have two appenders - one for Console and the other for File. I intend to write ERROR and FATAL to file hence using level=ERROR. I intend to write all logs to console hence using level=TRACE for Console. My code contains just one package named 'parallel', has one class named ClassA with one method that logs all types of logs.

If I specify both Console and File appenders within Root tag then my expectations are met. If I move the File appender outside Root and mention it under Logger tag then only File appender works where as Console appender does not work. Is it mandatory that all appenders be placed under Root tag?

package parallel;
public class ClassA {
private final   Logger log = LogManager.getLogger(ClassA.class);
@Test 
public void testLogs() {
    log.info("info");
    log.debug("debug");
    log.warn("warn");
    log.error("error");
    log.fatal("fatal");
    log.trace("trace");
}

}

<Configuration status="INFO">
<Properties>
   <Property name="basePath" value="./logs" />
</Properties>
<Appenders>
  <Console name="console" target="SYSTEM_OUT">
    <PatternLayout>
     <Pattern>
     [%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n
     </Pattern>
    </PatternLayout>
  </Console>
  <File name="fileLogger" fileName="${basePath}/error.log">
    <PatternLayout>
    <Pattern>
     [%-5level] %d{yyyy-MM-dd HH:mm:ss} [%t] %c{1} - %msg%n
    </Pattern>
    </PatternLayout>
  </File>
</Appenders>
<Loggers>
   <Root name="parallel">
     <AppenderRef ref="console" level="trace" />
   </Root>
   <Logger name="parallel" level="warn" additivity="false">
      <AppenderRef ref="fileLogger" />
   </Logger>
</Loggers>

Answer 1

As I understand it, your goal is to accomplish these items:

I intend to write ERROR and FATAL to file hence using level=ERROR. I intend to write all logs to console hence using level=TRACE for Console.

Please read the entire answer before making a final choice regarding what you will implement in your code.

You could do this by configuring your loggers as follows:

<Loggers>
    <Root>
        <AppenderRef ref="console"/>
    </Root>
    <Logger name="parallel" level="ALL" additivity="true">
        <AppenderRef ref="fileLogger" level="ERROR"/>
    </Logger>
</Loggers>

Log events will be accepted by each logger based on logger name and the level of the event. If you call log.error(...) for example an ERROR level event is generated. If log was obtained through LogManager.getLogger(ClassA.class) then log4j will search its configuration for a logger called "parallel.ClassA". If it does not find such a logger it will go up the hierarchy to a less specific logger - "parallel". If this logger does not exist it will go to the root logger.

Once the logger is identified log4j must determine if the event is accecpted by that logger. This is based on the level setting for the logger. Since the "parallel" logger is set to a level of ALL it will accept events of any level.

After the logger accepts an event, its appenders must also accept the event. The level associated with file appender of the "parallel" logger is ERROR so this appender will only accept events that are ERROR and FATAL level.

Since additivity is true for "parallel" logger whenever it accepts an event it will pass that event to the appenders of all of its parent loggers as well (unless one of them breaks the chain by specifying additivity false - see log4j2 architecture page for details). So any events accepted by "parallel" will go to the console appender associated with root logger.

There is a problem with this approach in that if a log event reached the root logger with a level of ERROR or FATAL it would not be written to your log file. The logs would "leak" to the console. This can happen if you accidentally write some bad code or if you accidentally forget to update your configuration file after adding some new code.

Here's some sample code to illustrate the problem:

package parallel;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class ClassA {
    private static final Logger log = LogManager.getLogger(ClassA.class);

    public static void main(String[] args) {
        log.info("info");
        log.debug("debug");
        log.warn("warn");
        log.error("error");
        log.fatal("fatal");
        log.trace("trace");

        // See the mistake here? 
        // The wrong logger name was used in the code, 
        // now the error event goes to the root logger!
        final Logger log2 = LogManager.getLogger("foo");
        log2.error("Woops an error!");
    }
}

The console output for the above using the configuration from the beginning of the answer is:

[INFO ] 2019-05-05 12:48:31.410 [main] ClassA - info
[DEBUG] 2019-05-05 12:48:31.411 [main] ClassA - debug
[WARN ] 2019-05-05 12:48:31.411 [main] ClassA - warn
[ERROR] 2019-05-05 12:48:31.411 [main] ClassA - error
[FATAL] 2019-05-05 12:48:31.412 [main] ClassA - fatal
[TRACE] 2019-05-05 12:48:31.412 [main] ClassA - trace
[ERROR] 2019-05-05 12:48:31.413 [main] foo - Woops an error!

The error log file only shows:

[ERROR] 2019-05-05 12:48:31 [main] ClassA - error
[FATAL] 2019-05-05 12:48:31 [main] ClassA - fatal

The simplest fix is to just move all of your appenders to the root logger as shown below:

<Loggers>
    <Root level="ALL">
        <AppenderRef ref="console"/>
        <AppenderRef ref="fileLogger" level="ERROR"/>
    </Root>
</Loggers>

Now all events are accepted by root logger and console appender but only ERROR and FATAL events are accepted by the file appender. Now even with incorrect code the log events will go to the right place.

Console ouput:

[INFO ] 2019-05-05 12:59:32.419 [main] ClassA - info
[DEBUG] 2019-05-05 12:59:32.421 [main] ClassA - debug
[WARN ] 2019-05-05 12:59:32.421 [main] ClassA - warn
[ERROR] 2019-05-05 12:59:32.421 [main] ClassA - error
[FATAL] 2019-05-05 12:59:32.421 [main] ClassA - fatal
[TRACE] 2019-05-05 12:59:32.421 [main] ClassA - trace
[ERROR] 2019-05-05 12:59:32.422 [main] foo - Woops an error!

Error log file:

[ERROR] 2019-05-05 12:59:32 [main] ClassA - error
[FATAL] 2019-05-05 12:59:32 [main] ClassA - fatal
[ERROR] 2019-05-05 12:59:32 [main] foo - Woops an error!

Other Possibly Helpful Links:

https://stackoverflow.com/a/51567436/3284624

I hope this helps you!

Answer 2

Partially solved..... I added Additivity="true" in the Logger tag and this made the logs print in both Console and File. However the log level of ERROR was being applied to both Console and File. My actual requirement is Console to have TRACE and File to have ERROR level. I am not able to understand the concept of Additivity from log4j2 official doc. Anyone who could explain this concept would be of great help.