O que um .jar de terceiros estava preparando para nós ...

Vou lhe contar um incidente divertido que fez toda a nossa equipe suar muito e quase levou alguns a um colapso nervoso. O resultado desta pesquisa é uma ferramenta eficaz que qualquer desenvolvedor pode usar para colocar o resto da equipe nos nervos. O objetivo desta postagem é alertar sobre possíveis situações não triviais e estar preparado para elas.

Digressão lírica

, . open-source , - , , , . , . , . . , . , work-around, , .

:

• . , .
• . , , . , , , StackOverflow.
• , , .
• . , . : , “ ” .
• . , .

.

, . , , SFTP .

:

public class Task implements Runnable {
    static final Logger log = LoggerFactory.getLogger(Task.class);

    public void run() {
        log.info("Task started");
        try(var remoteFile = createRemoteFile(xxx)) {
            this.setState(STARTED);
            for (int page = 0;;page++) {
                var block = service.requestDataBlock(page);
                if (block == null) break;
                transformData(block);
                remoteFile.writeDataBlock(block);
            }
            this.setState(FINISHED);
            log.info("Task finished");
        } catch (Exception ex) {
            log.error("Task failed", ex);
            this.setState(ERROR);
        }
    }
}

, , state=STARTED . — - . "Task started", "Task finished" "Task failed".

1

, , . — - dead lock. , thread dump , . .

2

, thread dump, , — . - "Task started", "Task finished" "Task failed"! , , Throwable Error, Exception. catch(Exception) catch(Throwable) . — , thread dump- .

3

, . , , thread dump, , . - . , . !

4

— , — , . , - OutOfMemoryError, catch ( OutOfMemoryError). java -XX:+CrashOnOutOfMemoryError -XX:+HeapDumpOnOutOfMemoryError. java- OutOfMemory hs_err_pid, — memory dump . : OutOfMemory — ( ), , .

5

. : , ! - Thread.stop(), , - JDK. — , , - , . System.out.println(), try-catch . :

java.lang.StackOverflowError
    at java.lang.reflect.InvocationTargetException.<init>(InvocationTargetException.java:72)
    at sun.reflect.GeneratedMethodAccessor1.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at ch.qos.logback.classic.spi.ThrowableProxy.<init>(ThrowableProxy.java:66)
    at ch.qos.logback.classic.spi.ThrowableProxy.<init>(ThrowableProxy.java:72)
    at ch.qos.logback.classic.spi.ThrowableProxy.<init>(ThrowableProxy.java:72)
    at ch.qos.logback.classic.spi.ThrowableProxy.<init>(ThrowableProxy.java:72)
    at ch.qos.logback.classic.spi.ThrowableProxy.<init>(ThrowableProxy.java:72)
    at ch.qos.logback.classic.spi.ThrowableProxy.<init>(ThrowableProxy.java:72)
            ...

! , Logback. , , — Error, ! , :

log.error("Task failed", ex);

What a Terrible Failure (WTF?!)

- ? ThrowableProxy Logback , suppressed exceptions, :

suppressed = new ThrowableProxy[throwableSuppressed.length];
for (int i = 0; i < throwableSuppressed.length; i++) {
   this.suppressed[i] = new ThrowableProxy(throwableSuppressed[i]);
   this.suppressed[i].commonFrames = 
        ThrowableProxyUtil.findNumberOfCommonFrames(throwableSuppressed[i].getStackTrace(),
                   stackTraceElementProxyArray);
}

, suppressed exceptions . :

@Test
public void testLogback() throws Exception {
    Logger log = LoggerFactory.getLogger(TestLogback.class);
    //    java 
    // java.lang.IllegalArgumentException: Self-suppression not permitted
    //ex.addSuppressed(ex);
    //   
    Exception ex = new Exception("Test exception");
    Exception ex1 = new Exception("Test exception1");
    ex.addSuppressed(ex1);
    ex1.addSuppressed(ex);
    log.error("Exception", ex);
}

— StackOverflowError! Java, ( 19000 maven-) , , . Logback , SFTP — Apache VFS. IOException suppressed, IOException. .

Logback ? , 2014 :

https://jira.qos.ch/browse/LOGBACK-1027

2019:

https://jira.qos.ch/browse/LOGBACK-1454

.

, Java ? , ex.printStackTrace(), , CIRCULAR REFERENCE:

java.io.IOException: Test exception
    at org.example.test.TestLogback.lambda$testJavaOutput$1(TestLogback.java:43)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
    Suppressed: java.lang.Exception: Test exception1
        at org.example.test.TestLogback.lambda$testJavaOutput$1(TestLogback.java:44)
        ... 5 more
    [CIRCULAR REFERENCE:java.lang.Exception: Test exception]

java.util.logging.

Log4j , suppressed exception.

14:15:22.154 [main] ERROR org.example.test.TestLogback - Test
java.lang.Exception: Test exception
    at org.example.test.TestLogback.testLog4j(TestLogback.java:61) [test-classes/:?]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_251]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_251]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_251]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_251]
    Suppressed: java.lang.Exception: Test exception1
        at org.example.test.TestLogback.testLog4j(TestLogback.java:62) [test-classes/:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_251]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_251]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_251]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_251]
        Suppressed: java.lang.Exception: Test exception
            at org.example.test.TestLogback.testLog4j(TestLogback.java:61) [test-classes/:?]
            at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_251]
            at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_251]
            at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_251]
            at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_251]

Logback — . , :

• , , , . .
• , , .
• , .
• , .
• Não espere que seu tíquete seja corrigido rapidamente ou uma solicitação de pull seja aceita rapidamente - levará vários meses a vários anos antes que a correção seja publicada no repositório oficial.
• Se você estiver usando Logback, adapte a exceção removendo as referências circulares antes de registrá-la. Isso só pode ser feito nos manipuladores de nível superior em Thread e ExecutorService.