Как я провел прошлую пятницу

Расскажу как я провел прошлую пятницу. Провел я её пытаясь понять, почему простой как доска тест-кейс не работает.

Тест-кейс запускает код в среде, которая симулирует полетное окружение: среду выполнения, показания датчиков и т.д. Далее выполняется простой сценарий - тест-кейс получает телеметрию и выполняет действия/проверки по наступлению определенных событий. Например, тест-кейс может запустить ракету, выключить четвертый двигатель, когда высота превысит сотню метров, а затем проверить, что код корректно обработал нештатную ситуацию.

Такие тест-кейсы, естественно, не пишутся с нуля. Кейс набирается из уже готовых, давно написанных блоков. Что может быть очень простым делом (если есть готовый шаблон), или не очень простым (когда такой шаблон нужно создать самому). В этот раз случился как раз второй вариант. Когда все компоненты теста правильно соединены остается только написать код, который ждет наступления интересных событий и реагирует на них нужным образом.

К пятнице я добрался до момента, когда сценарий тест-кейса уже написан, но еще не работает. Сценарий вылетал по таймауту ожидая наступления одного из событий. При этом телеметрия четко показывала, что событие наступило и у теста был вагон времени, чтобы это заметить. Интересно, что точно такой же код, отслеживающий другую телеметрию работал как часы. Хм.

Посмотрел логи библиотеки, которая собственно отслеживает наступление событий. Сравнил работающий и неработающий случаи. Никакой разницы, за исключением того, что первый срабатывает, а второй - нет.

Посоветовался с коллегой. Тот пожал плечами и посоветовал вывалится в питоновскую консоль - тогда код тест-кейса можно будет подергать интерактивно и посмотреть что может быть не так. Попробовал. Подергал. Ничего особенного не надергал за исключением того, что интересующая меня телеметрия была помечена как “старая”. Ага!

Еще через пару часов ковыряния нашлась причина “старой” телеметрии. Как оказалось я нахомутал при сборке кейса и это повлияло на передачу телеметрии. Починил. Запустил - кейс по-прежнему вылетает по таймауту. Хм.

К этому моменту у меня закончились креативные идеи и я полез копаться в коде библиотеки обработки событий. Из этого описания может показаться, что это приличная библиотека. Но вы знаете, это как раз тот случай, когда первое впечатление обманчиво.

Как я уже упоминал выше, библиотека написана на питоне. Я ничего не имею ввиду против питона, за исключением одного незначительного нюанса - в “хорошо написанном” коде на питоне концов не найти. Вот и в этом случае имеем клиента с отложенной инициализацией, который запускает отдельный сервер и разговаривает с ним по доморощенному RPC. Сервер получает телеметрию и пытается сопоставить её с активными событиями из списка. Все это счастье изрядно приправлено декораторами, функциями обратного вызова и прочими питонскими плюшками. В теории они позволяют писать красивый, понятный и компактный код, но на практике они помогают запутать код так, что черт ногу сломит.

Помедитировав немного, я нашел место где собственно регистрируются события. Отладочные сообщения в логах очень помогли в поисках. Достаточно было поискать в коде текст сообщений о регистрации и удалении событий. После чего, я просто добавил отладочного вывода вокруг, чтобы понять, что именно происходит.

Первые несколько запусков ситуацию прояснили не сильно. По-прежнему одно событие уверенно ловилось, а другое - нет. Через несколько итераций, я добрался до следующего самородка:

# This does work! Actual parsing happens here.
data = packet.data

Значит так, следите за руками. Есть функция которая парсит пакет с данными. Мы заворачиваем её в @property, чтобы она выглядела как данные. Затем мы пишем комментарий в вызывающем коде “не верь глазам своим”. Профит? Ни один вопрос “нахрена?” не был задан при написании этого кода…

Впрочем, я отвлекаюсь. Отладочная печать показала, что в неработающем случае выполнение дальше строчки, показанной выше, не идет. Завернув её в try-except я получил ответ, который искал целый день - да, при парсинге пакета бросалось исключение; и да, исключение игнорировалось примерно вот так:

    ...
except ValueError:
    # This error is handled elsewhere.
    pass

Прямо классика. “Я выстрелю себе в ногу, а чтобы было не больно, - я сначала отрублю её топором”. Исключение, кстати, бросалось по делу. В пакет пробралась шальная запятая, которая, правда, игнорировалась всеми другими средствами для просмотра телеметрии.