Введение

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

Завязка

Большинство наших маршрутизаторов имеют на борту LTE-модем. Некоторые — сразу два. Тут был как раз такой случай. Новые маршрутизаторы у нас появляются довольно часто, так что технология отработана: раз, проверили что всё включается, два, адаптировали device tree, три, отдаём тестировщикам для поиска всякого интересного.

Развитие

И они, конечно, нашли: не работают два модема одновременно. Как так? У меня же работали! Оказывается, если два quectel, тогда не работают. В каком бы порядке не включали, первый стартует нормально, а второй в EDL-режиме. Причём, поскольку EDL-режим стартует намного быстрее (меньше секунды, против 10 сек), то выглядит так, что второй стартует первым. Проблема повторяется с разными моделями от этого производителя. Как-будто, второй модем подключается к usb, осматривается, видит первый и говорит: "На этой шине уже есть модем quectel. Не положено иметь два модема quectel на одной шине." Выглядит примерно так:

[   40.828935] usb 3-1: new high-speed USB device number 2 using xhci-hcd
[   41.084049] qcserial 3-1:1.0: Qualcomm USB modem converter detected
[   41.084719] usb 3-1: Qualcomm USB modem converter now attached to ttyUSB0
[   42.388984] usb 1-1: new high-speed USB device number 2 using xhci-hcd
[   43.462712] option 1-1:1.0: GSM modem (1-port) converter detected
[   43.463214] usb 1-1: GSM modem (1-port) converter now attached to ttyUSB1
[   43.464313] option 1-1:1.1: GSM modem (1-port) converter detected
[   43.464875] usb 1-1: GSM modem (1-port) converter now attached to ttyUSB2
[   43.466322] option 1-1:1.2: GSM modem (1-port) converter detected
[   43.466983] usb 1-1: GSM modem (1-port) converter now attached to ttyUSB3
[   43.468368] option 1-1:1.3: GSM modem (1-port) converter detected
[   43.469121] usb 1-1: GSM modem (1-port) converter now attached to ttyUSB4
[   43.590363] qmi_wwan 1-1:1.4: cdc-wdm0: USB WDM device
[   43.592423] qmi_wwan 1-1:1.4 wwan0: register 'qmi_wwan' at usb-xhci-hcd.2.auto-1, WWAN/QMI device, f6:0c:68:0e:11:4d

Пробуем другую модель маршрутизатора. Параллельно, коллега запускает пару на PC. Если на PC тоже не заработает, то вопрос уже к quectel. На другом маршрутизаторе проблемы нет. Видимо, дело не в самих модемах. Либо не хватает энергии, либо дело в разводке usb или портов. На проблемном маршрутизаторе модемы подключены прямо к корневым хабам, а на другом — между корневым хабом и каждым из модемов есть ещё по одному хабу. Пока коллега проверяет два модема подключенные непосредственно к одному хабу на PC, я прозвоню электричество.

Модемы вставлены в разъёмы mpci-e. Замечательный разъём. Всем хорош, только питание на контактах №№ 2, 24 и 52. А все чётные контакты находятся на нижней стороне разъёма и спрятаны под модемом, когда он подключен. Надо искать где-то в другом месте. Должны быть какие-то резисторы или конденсаторы через которые проходит эта линия питания. Обращаемся к схеме разводки платы. Тем временем коллега сообщил, что на PC проблема не проявляется. Питание так же оказалось в норме (3,3 В на обоих разъёмах). Видимо проблема в софте.

Попробуем отключить всю программную обработку в пространстве пользователя. Ибо, всё больше и больше складывается впечатление, что это аппаратная проблема. Отключение программной обработки не решило проблему. Посмотрим включение питания и если не поможет, будем "нырять" в ядро. Стандартно, модемы включаются сразу один за другим. Добавим задержку в 10 секунд. Тоже не помогает. В логах ядра есть какое-то сообщение типа alloc_contig_range [x, y] RFNs busy. Сообщение как-будто указывает на проблемы с выделением последовательного участка памяти, что может быть источником проблемы. Может быть не хватает памяти на дескрипторы. Причём перед вторым модемом его намного больше. Может быть проблема как-то связана с выделяемой памятью

В sysfs оказалось, что количество буферов URB отличается (в /sys/bus/usb/devices/<device addr>/urbnum). Или это не количество буферов, а номер текущего? Гугл говорит: номер текущего. Ну что ж, посмотрим, что там с памятью.

alloc_contig_range вызывается (через цепочку) из dma_alloc_coherent. Найдём все вызовы dma_alloc в подсистеме usb (driver/usb) и поставим там отладочную печать. Нашёлся usb_alloc_dev в drivers/usb/core/usb.c. Все сообщения "alloc_contig_range" приходят именно оттуда. Там вызывается xhci_alloc_dev. Из которого вызывается xhci_alloc_virt_device. Внутри, правда, код выглядит вполне невинно, так что начинает складываться впечатление, что информационные сообщения из alloc_contig_range — это ложный след. Тем не менее, надо отработать эту версию до конца.

Интересно. Внутри на пол-дороги вызывается xhci_ring_alloc, который срабатывает дважды для сбойного случая и 14 раз для хорошего случая. Но тут он вызывается откуда-то из другого места. Другое место оказалось usb_hcd_alloc_bandwidth. Который проверяет достаточно ли пропускной способности шины для нового устройства. Но при этом ему передаются структуры текущих usb настроек и конфигураций. То есть похоже, он проверяет что можно включить запрашиваемые настройки. На это же намекает комментарий "check whether a new bandwidth setting exceeds the bus bandwidth". С другой стороны, странно, что функция для проверки чего-то выделяет память.

Оказалось, что для обоих модемов функция возвращает 0, что интерпретируется, как успех. Но выделяется разное количество памяти. Надо проверить, что там в этой структуре usb_host_config. А там "representation of a device's configuration", то есть описание настройки устройства (а не хоста, как некоторые могли бы подумать). По простому говоря, все дескрипторы собранные с устройства собраны в эту структуру.

В общем, вроде тут бага нет. Посмотрим, что хост получает от устройства на старте с помощью tcpdump. Добавим в ядро драйвер usbmon и пересоберём libpcap с поддержкой usb. Прослушаем, что происходит на шине во время подключения модемов. Включили, собрали, insmod usbmon.ko;tcpdump -D показывает заветные usbmon0, usbmon1 и так далее. Снимаем трассировку при добавлении первого и второго модемов и сравниваем в wireshark. Последовательность оказывается довольно простой: приходит прерывание, инициируется сброс порта, дальше хост читает дескрипторы. Проблемный модем (или корневой хаб) проявляет себя довольно рано: при начальном сбросе порта приходится делать его дважды и уже первые дескрипторы показывают, что этого было достаточно, чтобы устройство инициализировалось неправильно. После сброса порта (SET_FEATURE PORT_RESET) там читается статус и драйвер контроллера видимо не доволен статусом который он прочёл. Поэтому он делает ещё один сброс. Несколько повторных тестов показали, что двойной сброс связан с несовершенством тестовой методики: запихивание модема в порт рукой не всегда проходит гладко. А в остальном процедуры инициализации идентичны. В общем, и здесь тупик.

Катарсис

Значит, если разница уже в самых первых дескрипторах, то модем уже при старте знает, что он не должен запустится нормально. Получить он это знание может либо по радио, либо по проводу. Радио — скорее всего неправильный вариант. Попробуем провода. Беглое гугление показывает, что для того чтобы перевести чип qualcomm в EDL режим надо заземлить какую-нибудь ножку. Возможно при старте одного модема, паразитно заземляется какая-то ножка на втором или что-то типа того? Втыкаем в первый разъём модем и проверяем все ножки на втором разъёме при выключенном, потом при включенном модеме и вуаля! Во втором случае, ножки 3 и 5 показывают уровень 1,8 В. На схеме платы ножки обозначены как coex_1 и coex_2. Смотрим в доки модема: reserved. Что за ...?! Оказалось, старая версия. В новой написано COEX_UART_RX и COEX_UART_TX. И пометка "It is prohibited to be pulled up high before startup". То есть когда первый модем стартует, он подтягивает эти пины (как и положено UARTу), а второй видя такое непотребство впадает в панику и запускается в EDL-режиме.

Заключение

Выпаиваем резисторы и выпиваем шампанское. Эпопея длинной в 2 дня закончилась