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

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

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

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

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

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