История одного бага

Всё началось с баг репорта от одного из пользователей нашего фрэймворка JDI Light — NullPointerException при WebPage.open(), а точнее WindowsManager.getWindows()

Максимально странное падение до 30% тестов разом с одной ошибкой. Причём либо падает сразу много, либо — не падает вообще.

Мы в JDI очень трепетно относимся к баг репортам пользователей, особенно такого фантастического качества — с подробным описанием и вот этим всем.

К расследованию немедленно приступил один из наших самых квалифицированных контрибьюторов — Владимир Клонин (кстати — один из победителей прошлогоднего хакатона автоматизаторов в Санк-Петербурге).

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

Это ввергло нас в некоторое уныние т.к. диагностика ошибки — весьма скудная.

Расстановка же дополнительной диагностики — привела в удивительному результату!

Напомню как работает JDI Light — в случае, если драйвер на машине не найден, то он, используя webdrivermanager, развиваемый разработчиком Boni García, пытается его скачать:

            wdm.setup();             logger.info("Download driver: '" +  driverName + "' successfully");             driverDownloaded = true;             downloadedDriverInfo = format("%s:%s:%s", driverType, platform, version);             driverPath = wdm.getDownloadedDriverPath();

после чего запрашивает и получает директорию где он лежит.

Удивительное заключается в том, что несмотря на то, что команда сетап выполняется успешно и без ошибок — driverPath оказывается NULL !

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

Разумеется мы тут же зарепортали эту проблему. На что получили не менее удивительный ответ. Автор нам не поверил:

Более того — у него эта функциональность покрыта тестом (разумеется одним, и разумеется, гоняемым в один поток, ха!) — и тест проходит. Он попросил нас предоставить рабочий пример [который будучи запущенным на рандомной машине — гарантировано продемонстрирует проблему, а как вы хотели?]

Тут, конечно, мы немного загрустили.

На этом этапе к вопросу подключилась одна из наших активных колумбийских контрибьютеров, муза нашей разработки — Наташа

Наташа придумала простую, но не очевидную вещь — сделала pr который превращает однопоточный прогон того теста — многопоточным, что, к счастью, приводит к падению.

Результат этого — оказался и вовсе неожиданным.

Бони нам не поверил. Теперь уже окончательно.

Баг, мы, конечно, мы исправили, путём включения дополнительных проверок в наш фреймворк. Но исправив эти многочисленные падения — мы обнаружили другие, весьма редкие.

Но борьба с ними — это совсем другая история…