Что .jar сторонний нам готовил…

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



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


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

    Комментарии 18

      +5
      возможно, что ошибка совсем не в вашем коде, а в сторонней библиотеке

      Э, ну мы как-то после полугода разборок, смены трех или четырех версий Java, дорылись силами поддержки Оракла и своими до бага в ядре линукс. Типа, Один из вариантов mutex плохо работал.
      • НЛО прилетело и опубликовало эту надпись здесь
        +4
        Не понял из текста.
        Почему нельзя было воспроизвести у себя и посмотреть?
          +7

          Потому что данный тип исключения с циклической ссылкой генерировался библиотекой Apache VFS в очень специфическом случае — когда upload файла фейлился на OutputStream.close(). В остальных случаях, когда соединение рвалось на OutputStream.write(), в т.ч. и на интеграционных тестах, все отрабатывало без проблем. В то время у клиента по ночам возникали проблемы с инфраструктурой, и данный баг время от времени редко, но вылезал.

            +1
            Так баг-то, по вашему, в Logback или в Apache VFS?

            (по моему – в Apache VFS, но хорошо было бы увидеть исправление в нём и защиту от таких багов в Logback)
              +2

              Если глобально, то в дизайне IO-стримов в Java. А конкретно этом случае виноват Logback. В Java нигде не говорится, что циклические ссылки невозможны или некорректны. Она не дает создать только прямую ссылку на само исключение через ex.addSuppressed(ex), а транзитивные возможны. К тому же остальные логгеры отрабатывают корректно.


              Apache VFS в случае, если рвалась сессия SFTP, кешировал это исключение и кидал его на все последующие вызовы write(), что впринципе корректно. Но поскольку в close() Apache VFS еще производил запись (типа установить атрибуты удаленного файла), то в случае ошибки блок try-with-resources добавлял к suppressed то же самое закешированное исключение, что вызывало цикличность. Как-то так.


              P.S. Вот Apache VFS реально плохо задизайнена. Там дофига подводных камней, один из которых — привязка ресурсов к ThreadLocal. То есть если вы открываете ресурс в одном треде, пишите или закрываете в другом, то у вас происходит утечка памяти, которая в нашем случае стабильно приводила к OutOfMemoryError.

                +4
                Страшные вещи вы рассказываете…
                Привязку ресурсов к треду я ещё могу понять (если это задокументировано), а вот кэширование и повторное использование exceptions за пределами моих представлений о добре и зле.
          +1

          Из подобных мистических историй но уровнем загадочности полегче припомнилось:
          Задача планировщика так же останавливалась в try-catch блоке, при этом проходя мимо всех catch и finally. Но здесь было проще догадаться: как оказалось, задача где-то у себя очень глубоко (где не ожидалось) открывала http соединение, и вечно ждало ответа, хотя физически соединение было прервано (даже от сети отключали, исключение не выпадало)


          Ещё более лёгкая на догадки проблема была связана с некорректной велосипедной реализацией пула в части синхронизации, ошибка похожая на ленивый синглтон в котором отсутствует блок синхронизации, в результате которой утекали зомби, оставшиеся без нужных ссылок (случайно заменены заместителями делающими их работу), ничего не делающие, но висящие в памяти и активно мешающие.

            +6

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

              +3

              Да можно подумать сторонние библиотеки пишут единороги с крыльями…
              Разбираясь в коде jdbc thin драйвере Oracle просто поражался степени лапшеватости и корявости его кода.
              jdbc драйвер кидал пустое(!) RuntimeException при возникновении проблем маппинга структур java на структуры Oracle.
              Всегда нужно быть готовым к подобным проблемам.

                0
                Давно делал workaround-ы для различных кривых оракловых инфраструктурных утилит. В том числе декомпилировал и встраивал свой код. Степень криворукости оракловых программистов поражает воображение. Иногда тратил слишком много времени на попытки докопаться и доработку просто отменяли.
                0
                Мы однажды столкнулись с тем, что Hibernate генерировал синтаксически некорректный SQL для Oracle (там как-то смешивались оракловый JOIN с плюсиком и классический JOIN, точно уже не помню). Несколько месяцев пришлось держать свой форк, пока наш патч в апстрим не приняли.
                  0

                  Хибернейт у меня до сих пор оставляет некий осадок от использования. И некорректный sql тоже был. Из недавнего — в тестах, когда тест запускается внутри одной единственной транзакции с Rollback аннотацией над тестовым методом при транзакционной вложенности в тестируемых сервисах хибернейт теряет дочерние сущности. Вроде как и баг хибернейта, но руки не дошли докопаться до истины

                    0

                    У меня тоже с хибернейтом не сложилось. Известны случаи, где он генерит семантически неправильный SQL, иногда делает странные сторонние вещи, когда его не просят, причем в зависимости от движка базы, до последнего времени криво поддерживал EntityGraph, и после перехода на ByteBuddy стал неимоверно долго стартовать. Поэтому я уже привык использовать EclipseLink.

                  +1

                  Ваша ошибка в неиспользовании блока finally.

                    0
                    А я не так давно собственноручно раскопал баг с 100% CPU при использовании Selector.select() в Android.
                    Но как оказалось, до меня уже раскопали.
                    www.saschahlusiak.de/2018/10/selector-select-returns-0-immediately

                    Печаль в том, что этот баг находится в sun.nio.ch.PollSelectorImpl Java 8, и Android его не особо спешить исправить…
                      +2
                      Данная баг фича все еще присутствует в последней версии библиотеки.

                      Лицензия свободная. Так, исправьте и сделайте PR, кто вам мешает?

                        +1
                        Что мешает?
                        Ну вот например: планировщик заданий «enterprise» (как они себя называют) уровня.
                        github.com/quartz-scheduler/quartz/issues
                        176 issues (225 закрыто)
                        38 висящих пулл-реквестов
                        28 contributor-ов
                        Последний релиз — год назад.
                        При активной эксплуатации нашёлся редкий баг, и вряд ли кто будет его чинить — у всех-то нормально работает.

                        В учебных заведениях нужно доносить мысль, что open-source — это не «бесплатно скачал и пользуйся», а никто ничего тебе не должен. И при выборе библиотеки нужно взвешивать затраты между поддерживаемым платным ПО и затратами на самостоятельное допиливание «бесплатного» ПО.

                        Чтобы потом не разочаровываться.

                      Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

                      Самое читаемое