Баг в 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, чтобы я мог попытаться проанализировать код самостоятельно. Забегая вперёд, скажу, что там есть, на что посмотреть... Но об этом - в следующей серии.