I'm using Log4J 2 alongside TestNG and Java 7 with IntelliJ as the IDE for a web automation project.
I'm trying to redirect the standard error output of all uncaught Exceptions to a Log4J 2 log file with level ERROR.
I've created a subclass of an UncaughtExceptionHandler called Log4J2UncaughtExceptionHandler that is meant to log the uncaught exceptions to an output log file:
public class Log4JUncaughtExceptionHandler implements Thread.UncaughtExceptionHandler {
@Override
public void uncaughtException(Thread t, Throwable e) {
logger.error(e);
}
}
Then in the code, I have set the default UncaughtExceptionHandler to this newly created handler instance:
Thread.setDefaultUncaughtExceptionHandler(log4JUncaughtExceptionHandler);
...and then I have verified that the UncaughtExceptionHandler has been changed:
// Prints "2016-10-31 15:15:19,623 INFO [Test worker] plugins.Log4JUtils (Log4JUtils.java:89) - test.java.utils.Log4JUncaughtExceptionHandler@118414c5"
Log4JUtils.logInfo(Thread.getDefaultUncaughtExceptionHandler().toString());
...but then I raise an uncaught exception:
String s = null;
s.charAt(0);
...and although the NullPointerException gets logged to the console for IntelliJ, it does not show up in the error file I've directed the error to.
Moreover, when I place a debug point in the above uncaughtException() method, the debugger does NOT stop there.
I am not sure why something like this is occurring. Are there some exceptions that are simply not tracked by UncaughtExceptionHandlers?
Stack trace
Here is the stack trace. I should note as well that the above consists of tests using Selenium and Firefox with a Gradle build. I've interjected the NullPointerException statements at the beginning of one of the test cases.
3:14:59 PM: Executing external task 'DEBUG_qa1TestFirefox'...
:compileJava UP-TO-DATE
:processResources UP-TO-DATE
:classes UP-TO-DATE
:compileTestJava UP-TO-DATE
:processTestResources UP-TO-DATE
:testClasses UP-TO-DATE
Connected to the target VM, address: '127.0.0.1:56873', transport: 'socket'
:DEBUG_qa1TestFirefox
Default Suite STANDARD_OUT
2016-10-31 15:15:08,044 INFO [Test worker] plugins.Log4JUtils (Log4JUtils.java:89) -
-----------------------------------------------------------------------------
------------ The test is starting now at 2016-10-31-15-15-08-031 ------------
-----------------------------------------------------------------------------
15:15:08.044 [Test worker] INFO test.java.utils.plugins.Log4JUtils -
-----------------------------------------------------------------------------
------------ The test is starting now at 2016-10-31-15-15-08-031 ------------
-----------------------------------------------------------------------------
Default Suite > Firefox STANDARD_OUT
2016-10-31 15:15:08,084 INFO [Test worker] plugins.Log4JUtils (Log4JUtils.java:89) -
-------------------------------------------------
------------ Testing case #[6.0]: [] ------------
-------------------------------------------------
15:15:08.084 [Test worker] INFO test.java.utils.plugins.Log4JUtils -
-------------------------------------------------
------------ Testing case #[6.0]: [] ------------
-------------------------------------------------
2016-10-31 15:15:16,862 INFO [Test worker] plugins.Log4JUtils (Log4JUtils.java:89) - Browser opened in FIREFOX
15:15:16.862 [Test worker] INFO test.java.utils.plugins.Log4JUtils - Browser opened in FIREFOX
Default Suite > Firefox > test.java.<censored> STANDARD_OUT
2016-10-31 15:15:19,623 INFO [Test worker] plugins.Log4JUtils (Log4JUtils.java:89) - test.java.utils.Log4JUncaughtExceptionHandler@118414c5
15:15:19.623 [Test worker] INFO test.java.utils.plugins.Log4JUtils - test.java.utils.Log4JUncaughtExceptionHandler@118414c5
Default Suite > Firefox > test.java.<censored> FAILED
java.lang.NullPointerException at <censored>.java:543
Disconnected from the target VM, address: '127.0.0.1:56873', transport: 'socket'
1 test completed, 1 failed
There were failing tests. See the report at: file:///C:/Users/<censored>/build/reports/2016-10-31-03_15_04_628/Firefox/index.html
BUILD SUCCESSFUL
Total time: 29.899 secs
3:15:29 PM: External task execution finished 'DEBUG_qa1TestFirefox'.
TestNG method
The TestNG method where the NullPointerException is being called:
@Test(groups = {group1, group2})
@TestMethodLabel(testNumber = 6, text = "")
public final void testMethod1() {
// DEBUG PURPOSES ONLY: Force a NullPointerException to be thrown.
Log4JUtils.logInfo(Thread.getDefaultUncaughtExceptionHandler().toString());
String s = null;
s.charAt(0);
// <main test case code here>
}
Full code for handler
package <censored>;
import <censored>;
/**
* A handler for uncaught exceptions.
*/
public class Log4JUncaughtExceptionHandler implements Thread.UncaughtExceptionHandler {
/**
* Run any code necessary to handle the uncaught exception (e).
*
* Any exception thrown by this method will be ignored by the
* Java Virtual Machine.
*
* @param t the thread from which the Exception has been declared.
* @param e the exception to raise.
*/
@Override
public void uncaughtException(Thread t, Throwable e) {
Log4JUtils.OUTPUT_LOGGER.error(e.getStackTrace());
}
}
Log4J2 configs (2 different files for stderr and stdout)
<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
<Appenders>
<File name="STDOUT_FILE" fileName="${sys:logFilePath}" append="false">
<PatternLayout pattern="%d %t %-5p %c{2} - %m%n"/>
<Filters>
<ThresholdFilter level="error" onMatch="DENY" onMismatch="NEUTRAL"/>
<ThresholdFilter level="fatal" onMatch="DENY" onMismatch="NEUTRAL"/>
</Filters>
</File>
<File name="STDERR_FILE" fileName="${sys:errFilePath}" append="false">
<PatternLayout pattern="%d %t %-5p %c{2} - %m%n"/>
</File>
<Console name="STDOUT" target="SYSTEM_OUT">
<Filters>
<ThresholdFilter level="error" onMatch="DENY" onMismatch="NEUTRAL"/>
<ThresholdFilter level="fatal" onMatch="DENY" onMismatch="NEUTRAL"/>
</Filters>
<PatternLayout pattern="%d %-5p [%t] %C{2} (%F:%L) - %m%n"/>
</Console>
<Console name="STDERR" target="SYSTEM_ERR">
<PatternLayout pattern="%d %-5p [%t] %C{2} (%F:%L) - %m%n"/>
</Console>
</Appenders>
<Loggers>
<Logger name="test.java.utils.plugins.Log4JUtils" level="TRACE">
<AppenderRef ref="STDERR" level="ERROR"/>
<AppenderRef ref="STDOUT" level="INFO"/>
<AppenderRef ref="STDOUT" level="WARN"/>
<AppenderRef ref="STDERR" level="DEBUG"/>
<AppenderRef ref="STDERR" level="FATAL"/>
<AppenderRef ref="STDOUT" level="TRACE"/>
<AppenderRef ref="STDERR_FILE" level="ERROR"/>
<AppenderRef ref="STDOUT_FILE" level="INFO"/>
<AppenderRef ref="STDOUT_FILE" level="WARN"/>
<AppenderRef ref="STDERR_FILE" level="DEBUG"/>
<AppenderRef ref="STDERR_FILE" level="FATAL"/>
<AppenderRef ref="STDOUT_FILE" level="TRACE"/>
</Logger>
</Loggers>
</Configuration>
The logger being called
The logger being called is in a class called Log4JUtils. Also, the actual logger being called is substituted in for the dummy name of the logger (see Log4JUncaughtExceptionHandler.java)
public class Log4JUtils {
/**
* The LOGGER for this class instance that writes output to log files.
*/
private static final Logger OUTPUT_LOGGER = LogManager.getLogger(Log4JUtils.class.getName());
}
