Периодические перезапуски ve-01

[san]

У пользователя после обновления с r35 на r40 плата VE-01 стала перезапускаться каждые 40 минут, после отката обратно на r35 проблема исчезла.

Я записал конфиг пользователя в свой блок c и у меня похожий дефект повторяется, но плата перезапускается каждые 15 мин.
Прилагаю:

• конфиг.
• лог VE-01 r41(slot 11). В логе пойманы два момента перезапуска
• лог SW-01.

[san]

удалил из лога VE-01 последний перезапуск, не относящийся к делу

[alx]

В конфиге странный режим IPv6:

<ip6config>-1</ip6config>

тогда как допустимыми являются значения 0, 1 и 2...

Интересно, прекратятся ли перезагрузки, если установить здесь значение 2???

[alx]

Всем перезагрузкам предшествует появление загадочного сообщения

net eth0: smi_eth_part smi_alloc failed

после которого следует несколько серий сообщений

net eth0: scheduling TX queue timer

Есть предположение, что это может быть как-то связано с тем, что хост 192.168.0.1 у нас отсутствует и не отвечает на запросы ARP. Поэтому есть предложение провести еще один эксперимент: заменить адрес шлюза 192.168.0.1 на 192.168.0.13 и посмотреть, прекратятся ли перезапуски (или, как вариант, они могут начать происходить реже)...

[alx]

Как показал анализ кода ядра, сообщение net eth0: smi_eth_part smi_alloc failed выводится ядром, если оно хотело передать пакет в MSP (через очередь в разделяемой памяти), но не смогло выделить для этого дескриптор, так как пул дескрипторов пуст. Дескрипторы, в свою очередь, берутся из пула при помещении пакета в очередь, а освобождаться, очевидно, должны уже в MSP при получении пакета из очереди.

Видимо, пакеты в очередь помещались чаще, чем MSP их из очереди забирал и обрабатывал, что привело к исчерпанию пула дескрипторов. Почему это произошло, непонятно: либо CSP почему-то начал передавать очень много пакетов (чему я не вижу причин), и MSP в них "захлебнулся", либо MSP по неизвестным причинам перестал (или сильно замедлил темп) получения и обработки пакетов из очереди...

Далее, при невозможности поместить пакет в очередь драйвер останавливает передачу пакетов (вызывая netif_stop_queue()) и запускает таймер на 10 мс. По истечении таймера снова проверяется, стали ли ресурсы доступны. Если да, передача возобновляется, если нет - таймер запускается еще на 10 мс, и все повторяется. Судя по наличию множества сообщений scheduling TX queue timer и отсутствию сообщений waking TX queue, возобновление передачи пакетов не наступает никогда. Косвенно это является (как мне кажется) свидетельством того, что MSP просто прекратил брать пакеты из очереди, в результате чего очередь переполнилась, и передача пакетов полностью остановилась.

[alx]

Replying to alx:

Есть предположение, что это может быть как-то связано с тем, что хост 192.168.0.1 у нас отсутствует и не отвечает на запросы ARP.

Подумав, я решил, что это маловероятно, так как у клиента шлюз с адресом 192.168.0.1, очевидно, существует и на запросы отвечает, тем не менее, проблема есть...

[alx]

Еще информация: прошивка MSP между ревизиями прошивки 35 и 41 не менялась (последний раз менялась в ревизии прошивки 29).

[alx]

Replying to san:
после отката обратно на r35 проблема исчезла.

Хорошо бы сузить диапазон. В идеале установить конкретную ревизию, начиная с которой проблема возникла.

[san]

Установил <ip6config>2</ip6config> - дефект повторяется

так как у клиента шлюз с адресом 192.168.0.1, очевидно, существует

я не уверен что это так, эксперимент проведу

[alx]

Replying to san:

так как у клиента шлюз с адресом 192.168.0.1, очевидно, существует

я не уверен что это так

??? Думаешь, клиент сконфигурировал 23 полупостоянных потока RTP, 22 из которых неработоспособны в принципе? И так аппаратура работала пол-года до обновления прошивки? Теоретически это допустить, конечно, можно, но непонятно, зачем кто-о мог такое сделать...

[san]

ага, согласен))

очевидно, существует

[alx]

Оказывается, очередь не всегда "затыкается" сразу и навсегда:

Jan  1 00:50:30 comcerto daemon.warn sip_ua[363]: comcerto.cpp:7188: 192.168.0.1: host is down
Jan  1 00:50:30 comcerto daemon.warn sip_ua[363]: comcerto.cpp:7188: 192.168.0.1: host is down
Jan  1 00:50:30 comcerto daemon.warn sip_ua[363]: comcerto.cpp:7188: 192.168.0.1: host is down
Jan  1 00:50:32 comcerto user.warn kernel: net eth0: scheduling TX queue timer
Jan  1 00:50:32 comcerto user.warn kernel: net eth0: waking TX queue
Jan  1 00:50:32 comcerto user.warn kernel: net eth0: scheduling TX queue timer
Jan  1 00:50:32 comcerto user.warn kernel: net eth0: waking TX queue
Jan  1 00:50:33 comcerto daemon.warn sip_ua[363]: comcerto.cpp:7188: 192.168.0.1: host is down
Jan  1 00:50:33 comcerto daemon.warn sip_ua[363]: comcerto.cpp:7188: 192.168.0.1: host is down
Jan  1 00:50:33 comcerto daemon.warn sip_ua[363]: comcerto.cpp:7188: 192.168.0.1: host is down
Jan  1 00:50:33 comcerto daemon.warn sip_ua[363]: comcerto.cpp:7188: 192.168.0.1: host is down
Jan  1 00:50:33 comcerto user.warn kernel: net eth0: scheduling TX queue timer
Jan  1 00:50:33 comcerto user.warn kernel: net eth0: waking TX queue
Jan  1 00:50:39 comcerto user.err kernel: net eth0: smi_eth_part smi_alloc failed
Jan  1 00:50:39 comcerto user.warn kernel: net eth0: scheduling TX queue timer
Jan  1 00:50:39 comcerto user.warn kernel: net eth0: scheduling TX queue timer
Jan  1 00:50:39 comcerto user.warn kernel: net eth0: scheduling TX queue timer
Jan  1 00:50:39 comcerto user.warn kernel: net eth0: scheduling TX queue timer
Jan  1 00:50:42 comcerto daemon.warn sip_ua[363]: comcerto.cpp:7188: 192.168.0.1: host is down
Jan  1 00:50:42 comcerto daemon.warn sip_ua[363]: comcerto.cpp:7188: 192.168.0.21: host is down
Jan  1 00:50:42 comcerto daemon.warn sip_ua[363]: comcerto.cpp:7188: 192.168.0.1: host is down

Она может возобновить работу (то есть MSP взял пакет и освободил, как минимум, один дескриптор), а потом снова исчерпать пул дескрипторов...

[alx]

Предполагаю, что перезагрузка возникает из-за того, что от MSP перестают приходить сообщения HeartBeat (в норме они приходят каждую секунду). Если эти сообщения не приходят, CSP просто не сбрасывает watchdog timer, после чего происходит reset без каких-либо сообщений в логе.

[alx]

Установлено, перезагрузки происходят в r1332. В r1331 их третий час нет. Думаю, можно считать, что и не будет.

Отличие в том, что в r1332 починили передачу СУВ: там выполняется setSignalingMode(20), чего не было в r1331.

[alx]

Основываясь на известных фактах и результатах эксперимента выдвигаю следующую гипотезу:

MSP приводит в удивление и замешательство установка режима сигнализации 20 (что означает прозрачную передачу СУВ через RTP по RFC2833) до того как каналу назначены параметры ethernet и IP и установлен RTP event payload type. Предполагаю, что в результате этого MSP начинает глючить и через какое-то время окончательно сходит с ума, что приводит к перезагрузке платы.

Для устранения бага предлагается вызывать setSignalingMode(20) только после старта потока RTP (внутри startRTP()), когда все сетевые настройки уже гарантированно выполнены. Кроме этого, отключать передачу СУВ перед остановкой потока RTP (вызывая setSignalingMode(0) внутри stopRTP()).

Две тестовые платы с таким алгоритмом установлены в блоки, между ними организовано 23 потока RTP. Наблюдаем за результатом...

[alx]

Результат наблюдения - платы не перезагружались.

Предлагаю передать тестовый sip_ua пользователю для теста.

[alx]

In 1407/sip_ua:

Изменена логика настройки полупостоянных потоков RTP: теперь
setSignalingMode(20) вызывается только после старта потока RTP,
а перед остановкой вызывается setSignalingMode(0). Как показала
проверка, это устранило перезагрузки, вызывавшиеся прекращением
приема сообщений MSP от CSP. Closes #264.