Log4J 2: Неперехваченные исключения: не регистрируются в файле

Я использую Log4J 2 вместе с TestNG и Java 7 с IntelliJ в качестве IDE для проекта веб-автоматизации.

Я пытаюсь перенаправить стандартный вывод ошибок всех необработанных исключений в файл журнала Log4J 2 с уровнем ERROR.

Я создал подкласс UncaughtExceptionHandler под названием Log4J2UncaughtExceptionHandler, предназначенный для записи неперехваченных исключений в выходной файл журнала:

public class Log4JUncaughtExceptionHandler implements Thread.UncaughtExceptionHandler {
    @Override
    public void uncaughtException(Thread t, Throwable e) {
        logger.error(e);
    }
}

Затем в коде я установил значение по умолчанию UncaughtExceptionHandler для этого вновь созданного экземпляра обработчика:

Thread.setDefaultUncaughtExceptionHandler(log4JUncaughtExceptionHandler);

... и затем я убедился, что UncaughtExceptionHandler был изменен:

// 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());

... но затем я вызываю неперехваченное исключение:

String s = null;
s.charAt(0);

... и хотя NullPointerException регистрируется в консоли для IntelliJ, он не отображается в файле ошибок, на который я направил ошибку.

Более того, когда я помещаю точку отладки в вышеприведенный метод uncaughtException(), отладчик НЕ останавливается на достигнутом.

Я не уверен, почему что-то подобное происходит. Есть ли какие-то исключения, которые просто не отслеживаются UncaughtExceptionHandlers?

Трассировки стека

Вот трассировка стека. Я также должен отметить, что приведенное выше состоит из тестов с использованием Selenium и Firefox со сборкой Gradle. Я вставил операторы NullPointerException в начале одного из тестовых случаев.

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
@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>
}
04_628/Firefox/index.html BUILD SUCCESSFUL Total time: 29.899 secs 3:15:29 PM: External task execution finished 'DEBUG_qa1TestFirefox'.

Метод TestNG

Метод TestNG, в котором вызывается NullPointerException:

@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>
}

Полный код обработчика

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 (2 разных файла для stderr и 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>

Регистратор вызывается

Вызываемый регистратор находится в классе с именем Log4JUtils. Кроме того, фактически вызываемый регистратор заменяется фиктивным именем регистратора (см. 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());

}

person Richard Chen    schedule 31.10.2016    source источник
comment
Не могли бы вы также добавить сюда журналы трассировки стека, пожалуйста. Для NPE, как показано в консоли.   -  person Naman    schedule 31.10.2016
comment
Привет, nullpointer, добавил трассировку стека.   -  person Richard Chen    schedule 31.10.2016
comment
test.java.utils.Log4JUncaughtExceptionHandler@118414c5 означает, что обработчик достигнут. Почему он не регистрируется в файле, зависит от конфигураций, используемых для log4j.   -  person Naman    schedule 31.10.2016
comment
Также предложил бы поделиться полными реализациями классов для обработчиков, вставкой нулевого указателя и конфигурациями log4j.   -  person Naman    schedule 31.10.2016
comment
Я также убедился, что stdout и stderr также направляются как на консоль IntelliJ, И в файл журнала/ошибки.   -  person Richard Chen    schedule 01.11.2016
comment
В классе обработчика отсутствует объявление для logger.   -  person Naman    schedule 01.11.2016
comment
nullpointer, регистратор переменной был просто именем-заполнителем для настоящего регистратора; Я заменил его.   -  person Richard Chen    schedule 01.11.2016
comment
Всем будущим посетителям: я также искал способ регистрировать все неперехваченные исключения (хотя мой проект не использует те же фреймворки, кроме log4j2), прочитал первые несколько абзацев этого вопроса, был взволнован, а затем разочарован, когда я прочитал весь вопрос и увидел, что, похоже, это не сработает. Однако я обнаружил, что это действительно работает с моей настройкой. Так что могу только порекомендовать попробовать - может у вас сработает так же, как и у меня. Этот вопрос также может быть актуален: stackoverflow.com/questions/2344654   -  person TuringTux    schedule 10.06.2019