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

    А поймал ли единорог этот баг?

    К сожалению, data flow PVS-Studio не нашёл этой проблемы с linked-list. Но будем справедливы - я тоже обратил внимание на эту ошибку не с первого раза (и даже не с третьей вычитки кода). Андрей говорит, что подобную диагностику добавить можно - а значит, одна из следующих версий может начать ловить такие гейзенбаги.

    Ads
    AdBlock has stolen the banner, but banners are not teeth — they will be back

    More

    Comments 2

      +2
      и при чём тут единороги
      А мы проверяли Wireshark в 2015 и 2019 годах, тем самым оставив «радужный» след :D
        +1
        Интересный кейс, спасибо!
        Главное — хорошо что сообщили о баге китайцам, может починят наконец-то.

        из-за бага в коде (который, если верить git blame, лежит там уже очень много лет)
        Вот она, ценность чистого бэклога и отсутствия технического долга!
        Уже в который раз убеждаемся, что прежде чем пилить новые фичи, надо сначала вылизать старые.

        Only users with full accounts can post comments. Log in, please.