Отлов спорадичных багов с помощью BTrace 👣

Один из забористых багов, с которым мне довелось "развлекаться" в преддверии отпуска, сочетал в себе много интересного:
— воспроизводился только на удалённом сервере в контуре партнёра;
— требовал одновременных действий минимум 2-х человек;
— не имёл чёткого набора шагов, а только некий паттерн;
— из-за этого требовал по несколько попыток, чтобы проявиться.

Как не трудно догадаться, там была замешана гонка потоков. Она сильно осложняла диагностику, и даже удалённое подключение отладчиком через SSH-туннель не давало результата — как только один или несколько потоков оказывались под отладкой, они переставали "шалить" и укладывались в положенные временные рамки. Словом, типичный гейзенбаг — существует только пока за ним никто не наблюдает 👻

Втыкать логирование в разные места кода и таким образом постепенно локализовывать проблему было можно, но уж очень долго и утомительно — нужно было бесконечно готовить патчи, выносить их на этот (довольно нагруженный) сервер и перезапускать его, ожидая полного прогрева. Я даже попробовал, но уже на второй итерации мне это разонравилось🤢

И тогда мне вспомнился BTrace — диагностический инструмент под зонтиком OpenJDK, позволяющий внедрять в байт-код работающего приложения различные инъекции (прямо на #Java) для доставания почти любых данных из полей и локальных переменных, в том числе аргументов методов. Из-за того, что такими инъекциями можно наломать дров, в BTrace придуман специальный DSL, сильно ограничивающий допустимые действия (например, нельзя вызывать почти никакие методы прикладного кода), но позволяющий безопасно "снюхивать" данные из многих точек приложения 👃

Основной фичей BTrace в этот раз для меня стало отслеживание зависимых вызовов — это когда для заданного метода агент реагирует не на любые вызовы, а только на те, которые произошли из тела другого (тоже заданного) метода. В тексте BTrace-скрипта выглядит это примерно так (сокращённо):

    @OnMethod(clazz = "SpreadsheetSession"
            , method = "handleCellValue"      // метод-инициатор вызова
            , location = @Location(value = Kind.CALL
                , clazz = "SpreadsheetSession"
                , method = "calculateCellsDependentOnSingle"))    // целевой (проблемный) метод
    public static void handleCellValue(
           @TargetMethodOrField String method, 
           @ProbeMethodName String probeMethod,
           AnyType cellAbsRef, 
           boolean hasManualInput)  { 
        // ...
        String spreadsheet = str(Reflective.get("entity", cellAbsRef));    // извлечение данных через DSL
        // вывод извлеченных данных (тоже на DSL)
        println(method + " from " + probeMethod + ": " + spreadsheet + ":" + column + row + ", manualInput: " + hasManualInput);
    }

Это похоже на зависимые точки останова в отладчике, только никакого останова не происходит, а собранные данные выводятся в консоль, из которой запущен BTrace 🖥

Конечно, первое применение BTrace требует сильно больше времени, чем повтыкать System.out.println() или подцепиться отладчиком. Но зато потом, когда механизм освоен и отлажен, итерации диагностики вида "написал-применил-посмотрел-повторил" укорачиваются до нескольких минут и позволяют эффективно локализовывать даже такие упоротые изощрённые проблемы, как эта 🧶

Надеюсь, вам никогда не придётся отлаживать такие баги. Но если вдруг, имейте в виду, что BTrace может в этом пригодиться ✍️

—
P.S. Любопытно, что 10 лет назад, когда я не знал о BTrace (хотя он уже в каком-то виде существовал), я создал собственный инструмент jMint со схожей идеей: внедрять в работающее приложение кусочки кода на Java (дроплеты), чтобы менять его поведение с целью тестирования и/или отладки. Основное отличие jMint — в отсутствии "безопасного" DSL. Причина здесь не только в слабоумии и отваге автора, но и в стремлении дать возможность заглушать нежелательное поведение или временно менять интересующее. Поэтому применение инструмента было строго ограничено тестовым контуром. Несмотря на опасности и ограничения, он неплохо прижился в моей прошлой команде и какое-то время продолжал применяться после моего ухода. Подробнее о нём можно узнать здесь 📖
—