19.10.2020 16:33
Throwable 18 11400 Источник

Расскажу об одном занимательном инциденте, который заставил сильно попотеть всю нашу команду, а некоторых чуть было не довел до нервного срыва. Результатом исследований стало эффективное средство, при помощи которого любой разработчик может сильно потрепать нервы всей остальной команде. Смысл данного поста — предупредить о возможных нетривиальных ситуациях и быть к ним готовыми.



Лирическое отступление


На сегодняшний день процесс разработки любого софта немыслим без использования стороннего кода, который так или иначе интегрируются с вашим. Благодаря движению 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 — это прекрасная библиотека с большим набором возможностей. Все вышесказанное было скорей примером, чтобы подчеркнуть следующие банальные истины при использовании стороннего кода:


  • Если вы столкнулись с ошибкой или странным поведением программы, возможно, что ошибка совсем не в вашем коде, а в сторонней библиотеке. Это также надо учитывать при анализе.
  • Любой код, даже написанный матерыми разработчиками и использующийся в большом числе проектов, содержит ошибки и недочеты.
  • Ошибки в библиотеках могут приводить к побочным и неожиданным эффектам, которые выскакивают в самых разных местах и сложны для анализа.
  • В некоторых случаях корректное поведение кода попросту не определено, вопреки нашим ожиданиям и кажущейся логичности.
  • Не ждите, что быстро пофиксят ваш тикет или быстро примут pull-request — пройдет от нескольких месяцев до нескольких лет прежде, чем исправление опубликуют в официальном репозитории.
  • Если вы используете Logback, адаптируйте исключение, убирая циклические ссылки, прежде чем вывести его в лог. Это можно делать только в обработчиках самого верхнего уровня в Thread и ExecutorService.