Баг в ESP-IDF: MDNS, Wireshark и при чём тут единороги

Всем привет. Я занимаюсь коммерческой разработкой в IoT, в основном мы используем модули от Espressif — ESP8266 и ESP32.

В рамках «догфудинга» мы иногда берём свои продукты домой и используем в повседневной жизни. И вот, однажды, от одного из сотрудников поступила жалоба: после установки новой тестовой прошивки на устройстве, его домашняя сеть сначала начала жестоко глючить и зависать, а потом ситуация нормализовалась, но наш девайс более не был виден ни в локальной сети, ни в облаке.

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

Разведка

Для начала, я решил собрать максимальное количество данных про ситуацию в её терминальной стадии. Не перезагружая устройство, я запустил Wireshark в режиме Monitor Mode, настроив фильтрацию на MAC-адрес устройства. Выяснилось, что девайс уверен, что его сеть в порядке — он упорно слал роутеру какие-то данные, однако роутер ему ничего не отвечал. Хм, подозрительно.

В админке роутера девайс тоже был виден как подключенный. Но почему же нету обратной связи? На этот вопрос я получил ответ, когда решил подключить к этому же роутеру ещё одно устройство (точнее, один из своих devkit-ов), и убрал фильтрацию в Wireshark. Оказывается, у роутера поменялся MAC-адрес! Хм, подозрительно. Поменялся он ровно на один последний бит, при этом вся остальная техника эту подмену осознала, а вот наше устройство — нет, и упорно отсылало данные на старый мак-адрес, который, конечно же, никто уже не слушал.

Ладно, пришло время узнать больше. Перезагружаем роутер. Теоретически, это же должно вернуть его MAC в «обычное» состояние? И действительно, MAC вернулся. Но зависший девайс уже был «в коме», и упорно не хотел ничего делать. Ничего нового мы от него уже не узнаем, так что перезагружаем и его. А заодно, дабы собрать больше данных, пропишем в Wireshark пароль от роутера, чтобы он расшифровал весь трафик.

Коллапс

Тут произошло что-то странное. Сначала девайс, как положено, вернулся в сеть. А дальше началось… Количество сообщений в окне Wireshark начало расти с невероятной скоростью. Впрочем, через несколько минут всё остановилось — роутер снова решил проявить свою альтернативную, отличающуюся на один бит, сущность. Ладно, у нас есть дамп, давайте посмотрим, что это было.

And the winner is… 99% захваченных пакетов были про MDNS. Мы действительно используем его, чтобы телефоны могли найти наши девайсы в локальной сети, и работать с ними даже в условиях отсутствия облака (что иногда случается по разным причинам, начиная с «забыли заплатить за интернет», и заканчивая сбоями у Amazon). Но почему так много? Интервал между сообщениями — десятки миллисекунд, и соотношение «входящих/исходящих» (по отношению к девайсу) примерно одинаковое. Что ж, пора раскуривать.

Последовательность пакетов была следующая:

1. Девайс регистрируется в multicast-группе MDNS, чтобы иметь возможность получать запросы на обнаружение.

2. Девайс отправляет collision-query-пакет с запросом ANY на полный адрес своего «сервиса», чтобы узнать, есть ли в сети кто-то, кому он может «помешать».

3. Роутер перенаправляет collision-query-пакет всем устройствам multicast-группы, включая сам девайс.

4. Девайс отправляет advertise-пакет с PTR, SRV, TXT и A/AAAA записями multicast-группе MDNS, сообщая, что он появился в сети.

5. Роутер перенаправляет advertise-пакет всем устройствам multicast-группы, включая сам девайс.

6. 2-5 пункты начинают повторяться с большой скоростью.

Сразу становится понятно, почему проблема не проявлялась на нашем тестовом окружении в офисе — наши роутеры не перенаправляют multicast самому отправителю. Но почему мы не видели этого поведения на старой прошивке? И действительно, откатив девайс до старой версии, я стабилизировал ситуацию. Начинаем бить в бубен.

Делаем diff. Видим, что немного поменялся код внутренней логики, не влияющий на сетевую часть. Что ж, это можно отмести почти сразу. Ещё поменялся номер версии… Ну да, с 0.9 на 0.10. Не может же это влиять? Или… Ладно, пока оставим эту мысль. Ищем, где отправляются пакеты из MDNS.

Debugger? printf!

Как поступил бы на моём месте любой профессиональный разработчик? Правильно: начал обмазывать логами все места отправки пакетов в файле mdns.c. Поиск быстро привёл меня к функции _mdns_create_probe_packet. Поискав по файлу места, из которых она вызывается (и пройдя по стеку вызовов немного дальше), я остановился на строчке #2917 в функции mdns_parse_packet. В логах это место действительно появлялось очень часто. Подозрение пало на вызов _mdns_check_txt_collision. Тут начала вырисовываться картина происходящего: девайс, получая свой же advertise, находил в нём TXT-запись, и сравнивал его со своим TXT. Но ведь он сам его отправил! Ладно, смотрим код самой функции. Я даже приведу его тут по частям, с описанием происходящего.

size_t data_len = 1; if (len == 1 && service->txt) {   return -1;//we win } else if (len > 1 && !service->txt) {   return 1;//they win } else if (len == 1 && !service->txt) {   return 0;//same }

Тут мы создаём переменную data_len, а так же проверяем наличие TXT-записи в нашем service. Вроде бы всё нормально — тут мы проходим дальше.

mdns_txt_linked_item_t * txt = service->txt; while (txt) {   data_len += 2 + strlen(service->txt->key) + strlen(service->txt->value);   txt = txt->next; }  if (len > data_len) {   return 1;//they win } else if (len < data_len) {   return -1;//we win }

Тут мы высчитываем длину буфера, в который должен влезть наш TXT из сервиса, а заодно сравниваем эту длину с тем, что мы получили из эфира.

uint8_t ours[len]; uint16_t index = 0; char * tmp;  txt = service->txt; while (txt) {   tmp = (char *)malloc(2 + strlen(txt->key) + strlen(txt->value));   if (tmp) {     sprintf(tmp, "%s=%s", txt->key, txt->value);     _mdns_append_string(ours, &index, tmp);     free(tmp);   } else {     HOOK_MALLOC_FAILED;     // continue   }   txt = txt->next; }  int ret = memcmp(ours, data, len); if (ret > 0) {   return -1;//we win } else if (ret < 0) {   return 1;//they win } return 0;//same

Ну и тут мы кодируем наш TXT в буфер, размер которого уже просчитали (и проверили), и сравниваем его содержимое с полученным.

Уже нашли ошибку? Я тоже заметил её не сразу, поэтому решил пройтись по коду построчно. Опять же, помог мне с этим printf.

Когда я «упал» на проверке длины, я немного удивился. Но как? Ведь «правильная» длина (которую 10мс назад отправил сам девайс) точно совпадает с «входящей»! Давайте ещё раз взглянем на её подсчёт.

mdns_txt_linked_item_t * txt = service->txt; while (txt) {   data_len += 2 + strlen(service->txt->key) + strlen(service->txt->value);   txt = txt->next; }

Окей, тут явно виден проход по linked-list. Мы берём очередной элемент, берём длину его key и value… Стоп. Его или service->txt? Так, понятно…

Выходит, из-за бага в коде (который, если верить git blame, лежит там уже очень много лет), мы всегда берём длину от первого элемента. Но как это работало всё это время? А вот так: нам повезло. Всё это время TXT-записи, которые мы добавляли, по сумме длин чётко совпадали с длиной первого, умноженного на N. Получается, стоило нам добавить новый элемент, поменять порядок элементов, или изменить длину любого из них — и всё, баг начинал проявляться. Но при чём тут номер версии? Ах да, мы же передаём его в MDNS… Паззл сошёлся.

И что дальше?

Соответствующий issue в ESP-IDF я отправил, в своих рабочих копиях мы это место исправили, и наши девайсы прекратили сводить с ума бедные роутеры.

Но тут встал правильный вопрос: а сколько ещё таких багов может быть в SDK? Проект большой, кода много (а часть ещё и стороннего — в виде submodule). Наверняка есть что-то интересное, странное, ужасное…? То, что не вылезает у нас на тестировании, но может создать нам проблем в случайный момент времени.

Так при чём тут единороги?

С этой мыслью я написал @Andrey2008 вспоминая про PVS-Studio. Он любезно согласился попробовать посмотреть на этот проект, а также поделился триальной версией ключа для PVS-Studio, чтобы я мог попытаться проанализировать код самостоятельно. Забегая вперёд, скажу, что там есть, на что посмотреть… Но об этом — в следующей серии.