Когда дворецкий — жертва
Сегодня мы отойдём от классического клише второсортных детективов и расскажем вам о случае из нашей практики, когда дворецкий сам выступил в роли жертвы, а поиски настоящего преступника привели нас к неожиданному результату. Но не стоит пугаться. Речь, конечно же, пойдет не о настоящих людях, а о программах. И о том, что нам не страшно признавать собственные ошибки: мы то знаем, что от них не застрахован ни один коллектив разработчиков.
Введение
Вначале — немного теории. Мы разрабатываем PVS-Studio — статический анализатор кода для C, C++ и C#. Для внутреннего тестирования нашего продукта мы используем разнообразные инструменты и приёмы: Unit и UI-тесты Visual Studio, совместный обзор кода, специализированные приложения-тестеры. Остановлюсь более подробно на последнем пункте.
При разработке новых диагностических правил, а также при изменении внутренних механизмов анализатора, всегда необходимо понимать, как именно произведенные изменения отразились на качестве анализа. Для решения данной задачи мы выполняем тестовые прогоны анализатора на некотором наборе больших открытых проектов. Для С/C++ кода используется около 150 проектов, для C# — 52. Тестер для анализа C/C++ проектов в Windows называется SelfTester. Далее речь пойдет именно про этот инструмент. Также существует специализированная система для Linux, но сейчас она останется за кадром.
Вся работа производится на сборочном сервере с Windows 10. В качестве сборочной системы мы используем Jenkins, который настроен на регулярный ночной запуск, в том числе, и тестеров. Запуск самого Jenkins производится из cmd-файла командой:
java -jar jenkins.war >
%JENKINS_PROJECTS%\Logs\%YYYY%.%MM%.%DD%_%HH%.%MI%.log 2>&1
Переменная JENKINS_PROJECTS задает местоположение папки проектов Jenkins на локальном диске. Переменные YYYY, MM, DD, HH и MI содержат, соответственно, дату и время на момент выполнения. Таким образом, после запуска Jenkins вывод его консоли будет перенаправлен в файл с именем вида:
2017.11.08_17.58.log
Cmd-файл стартует при помощи планировщика задач Windows. Запуск Jenkins как службы Windows для нас оказался неприменим, так как в этом случае возникали проблемы в работе UI-тестов Visual Studio: у службы нет рабочего стола. Таким образом, цепочка запусков выглядит так:
Windows Task Manager -> cmd.exe -> java.exe
Итак, ознакомившись с краткой вводной, перейдем к вопросу о том, что же пошло не так.
Проблема
Около полугода назад мы стали замечать, что время от времени Jenkins закрывается во время ночных сборок. В результате его приходилось запускать вручную, проверять логи и перезапускать некоторые задачи. Проблема воспроизводилась достаточно регулярно. Расследование было решено начать с более пристального изучения поведения Jenkins, ведь это именно он выполняет всю «грязную работу» и первым попадает под подозрение. Да-да, тот самый дворецкий.
Jenkins
В первую очередь была проверена конфигурация и настройки задач Jenkins. Проверка не выявила ничего серьезного. Тем более, если бы была допущена ошибка, например, в очередности, приоритете или времени запуска задач, то проблема, вероятно, проявлялась бы иначе. Да и маловероятно, чтобы Jenkins падал вследствие ошибок конфигурации.
В качестве временной меры задача планировщика Windows была перенастроена на периодический запуск Jenkins каждые 30 минут. Для защиты от повторного запуска выполнялась проверка наличия уже запущенного процесса.
Следующий шаг — изучение логов консоли Jenkins. Как вы, наверное, помните, у нас они сохраняются в папку %JENKINS_PROJECTS%\Logs, а имена файлов содержат метку времени создания (фактически — времени перезапуска Jenkins). Через какое-то время мы изучили содержимое этой папки и, как и ожидалось, обнаружили там довольно большое число файлов. Это свидетельствовало о том, что Jenkins продолжает перезапускаться. При этом сами логи консоли Jenkins не содержали ничего криминального. А проблема приобрела несколько иной характер: часть ночных тестов перестала выполняться. Они просто не стартовали. А те, что стартовали, зачастую завершались с ошибками.
Все это говорило в пользу того, что сам Jenkins, вероятно, не виноват. Кто-то извне препятствует его работе, «убивая» процесс java.exe.
Windows
В качестве следующего подозреваемого была выбрана Windows. Ну действительно, кому как не операционной системе нести ответственность за незапланированное завершение процессов. Возможно, система перезагружается после установки обновлений, либо по какой-то причине закрывает только процесс java.exe. Такое возможно, когда кто-то препятствует рестарту и он не производится, но система уже успела убить часть процессов. Так или иначе, но проведенный анализ логов Windows не дал результатов. Да, иногда система действительно перезагружалась, но все происходило в штатном режиме. Да и время и место «преступления» не совпадали.
Примерно в то же время, когда мы проводили наше расследование, случилось еще одно происшествие, которому сразу не было придано большого значения. В одну из ночей наш сборочный сервер «упал» вследствие возникновения BSOD. Автоматическая перезагрузка не случилась, поэтому утром мы могли лицезреть весьма безрадостную картину.
Для анализа дампа памяти был использован Windows Debugger (WinDbg). Утилита нашлась по пути «C:\Program Files (x86)\Windows Kits\10\Debuggers\x64\windbg.exe». Дамп находился по стандартному пути «C:\Windows\MEMORY.DMP». После анализа дампа в WinDbg была обнаружена причина и виновник BSOD:
CRITICAL_PROCESS_DIED (ef)
CRITICAL_PROCESS: svchost.exe
....
FAILURE_BUCKET_ID:
0xEF_svchost.exe_BUGCHECK_CRITICAL_PROCESS_TERMINATED_BY_
SelfTester.exe_6771c7c0
Как вы понимаете, принудительное закрытие экземпляров процессов svchost.exe обычно приводит к BSOD. Можете проверить.
Да, наш безукоризненный инструмент SelfTester привел к краху Windows. Но так как это было первое подобное происшествие за всю многолетнюю историю существования тестера, а последние правки в его код вносились очень давно, было решено считать, что «нам показалось».
Тем временем, расследование шло своим чередом. Для выяснения виновника завершения процесса java.exe была использована штатная Windows-утилита для настройки ключей реестра «Global Flags». В числе прочего она позволяет задать режим мониторинга завершения указанного процесса с записью события в системный лог:
В случае принудительного завершения процесса сторонним процессом, Application лог Windows должен содержать событие с Event ID = 3001 от источника Process Exit Monitor.
Как часто бывает в подобных случаях, стоило расставить ловушки, как добыча тут же попряталась. Следующие пару недель сервер работал идеально, задачи успешно отрабатывали, а лог Windows не содержал искомых событий.
Наконец, в одно прекрасное утро проблема повторилась, а в системном логе появилась следующая запись:
The process 'C:\Program Files\java\jre1.8.0_102\bin\java.exe' was terminated by the process 'D:\SelfTester\SelfTester.exe' with termination code 0. The creation time for the exiting process was 0×01d3541edc4f867b.
Снова SelfTester. Получается, именно по его вине завершался процесс java.exe, который его и порождал. Невероятное коварство.
SelfTester
Найти виновника — только половина дела. Теперь следует понять, что именно происходит и как это можно исправить. Для этого разберемся в механизмах работы тестера.
Для анализа каждого проекта С++ тестер запускает процесс анализатора (PVS-Studio_cmd.exe) с параметрами. По завершению анализа тестер не ждёт непосредственно завершения процесса, а реагирует на событие о том, что отчет о проверке (plog) создан, после чего, «на всякий случай», завершает процесс анализатора и его дочерние процессы. Вероятно, именно в этот момент происходит что-то непредвиденное.
На самом деле, этот алгоритм работы является наследием прошлого и сейчас в нем уже нет такой необходимости. Ранее же для анализа запускался devenv.exe c параметрами. Проверку осуществлял плагин PVS-Studio для Visual Studio. В ходе этого порождалось множество дочерних процессов, которые и надо было завершать.
Чтобы понять, что именно происходит, потребовалось добавить логирование механизма завершения процессов. После изучения логов удалось выяснить следующее. Дочерние для PVS-Studio_cmd.exe процессы в тестере ищутся следующим запросом WMI:
SELECT * FROM Win32_Process WHERE ParentProcessId={0}
Проблема в том, что на момент выполнения данного запроса процесса может уже не быть. Он честно отработал и завершился, но тестер этого не знает. Иногда возникает ситуация, когда ID процесса совпадает (был заново использован) с процессом, который изначально породил cmd.exe, на которой висит java.exe (процесс Task Scheduler). При этом Windows помнит ID родительских процессов, даже если они уже завершились. Так мы получаем этот cmd.exe и завершаем его, а также и его дочерние процессы (рекурсивно).
Решение
Проблема была решена добавлением в код тестера двух условий, при которых нельзя завершать дочерние процессы:
- Родительский процесс уже завершился.
- Родительский процесс не завершился, но он стартовал позже, чем его предполагаемые дочерние. В этом случае он мог заново использовать ID уже завершившегося процесса.
Заключение
Итак, расследование завершено. Все подозрения с невиновных сняты, а виновные найдены и строго наказаны (исправлены).
В заключение хочу отметить, что описанная ситуация — это, на мой взгляд, хороший пример того, как даже небольшая оплошность может привести к трудно воспроизводимой ошибке.
Мы не стесняемся признать свои ошибки и, думаю, читателям было интересно познакомиться с одной из них.
Безбажного кода и успешных сборок!
