Opened 3 years ago
Closed 3 years ago
#370 closed баг (готово)
Теряется связность с платой VE-02
| Reported by: | san | Owned by: | alx |
|---|---|---|---|
| Priority: | высокий | Milestone: | 1 очередь |
| Component: | VE-02 | Keywords: | |
| Cc: |
Description
Во время настройки и проверки очередной схемы связи я обнаружил, что платы VE-02 ведут себя странно: через некоторое время нормальной работы(ничего страшного и зверского я с ними не делал) с платами теряется связность по IP.
Изменение сетевых настроек платы через веб-интерфейс во время проявления бага не даёт эффекта.
Я провожу эксперимент в блоке 192.168.20.166
На данный момент баг проявился на платах VE-02 на местах 10, 12, 14, 16
Я могу подключить консольный COM любой одной платы в TCP, сейчас COM платы в слоте 16 доступен через TCP-сервер 192.168.1.240 порт 1001
Change History (35)
comment:1 by , 3 years ago
comment:2 by , 3 years ago
Replying to san:
через некоторое время нормальной работы с платами теряется связность по IP.
Связность чего?
follow-up: 6 comment:3 by , 3 years ago
Ну, например, для определённости, плата перестаёт отвечать на пинг её ipv4 WAN адреса.
comment:4 by , 3 years ago
Судя по счетчикам интерфейса платы в слоте 16 и порта коммутатора, плата "не видит" передаваемые ей пакеты.
За работу с сетевыми интерфейсами платы VE-01/VE-02 отвечает MSP. Судя по приходящим из MSP неизвестным индикациям FC=0x0132, MSP находится в каком-то странном состоянии (я подобное состояние условно называю "сошел с ума"). Предполагаю, что это как-то связано с ненормальным поведением платы. Так как код MSP нам не подконтролен, исправить этот баг мы вряд ли можем. Можно разве что попытаться его каким-то образом обнаруживать и обходить. Например при получении (одной или нескольких за определенный период времени) индикаций 0x0132 перезагружать плату.
И еще одна мысль. Платы VE-01/VE-02 производятся и используются давно, но до сих пор жалоб на подобную ситуацию не поступало. Даже в нашем офисе VE-01 работает месяцами без перезагрузок и подобных проблем. А сейчас вдруг сразу пять плат в одном блоке в течение суток пришли в такое состояние. Это наводит на мысль о том, что в этом блоке есть какой-то общий для всех плат фактор, послуживший триггером, заставившим платы перестать работать. Наверное имеет смысл попытаться выявить этот фактор.
Также замечу, что в платах не последние ревизии прошивок (25, в то время как последняя - 27), однако это вряд ли является существенным в данном случае.
follow-up: 7 comment:5 by , 3 years ago
Это наводит на мысль о том, что в этом блоке есть какой-то общий для всех плат фактор, послуживший триггером, заставившим платы перестать работать. Наверное имеет смысл попытаться выявить этот фактор.
Я этот баг обнаружил ранее в других нескольких блоках, каких-то специфических факторов я не могу отметить, просто включаю плату и создаю небольшой трафик через неё.
comment:6 by , 3 years ago
Replying to san:
Ну, например, для определённости, плата перестаёт отвечать на пинг её ipv4 WAN адреса.
Я вообще-то хотел узнать, между чем и чем теряется связность (связность может быть между, как минимум, двумя объектами). Но позже, посмотрев на ситуацию, я понял, что, очевидно, связность потерялась между VE-02 и всем. :)
comment:7 by , 3 years ago
Replying to san:
каких-то специфических факторов я не могу отметить, просто включаю плату и создаю небольшой трафик через неё.
Так делают все владельцы плат, но почему-то баг воспроизводится только у тебя. :) Я думаю, какой-то фактор все-таки должен иметь место, хоть сейчас и никто не может его отметить (и даже предположить). Поэтому и хотелось бы каким-то образом его выявить. Если мы выявим этот фактор, возможно, мы сможем предпринять какие-то меры по его устранению, и, таким образом, сможем бороться с причиной проблемы, а не с ее последствием, что всегда лучше (перезагрузка платы выглядит очень уж плохо).
follow-up: 10 comment:8 by , 3 years ago
Я подозреваю, что баг стал проявляться после одного из обновлений. Плат VE-02 для блок 3U не так много в природе и пользователи часто не торопятся обновляться, поэтому возможно пока никто не обнаружил проблемы.
Кстати оказалось, что я веду лог своего эксперимента :-)
Пинг от платы в 16 слоте начал прерываться около 13 часов по пермскому времени,
а начиная с 12.08.2021 13:33:04 - плата совсем перестала отвечать на пинг.
follow-up: 12 comment:9 by , 3 years ago
Отчёт по последней плате которую я сломал сегодня.
Плата в слоте 3:
(Время в GMT+5)
До 13.08.2021 10:23:16 - стабильно отвечала на пинг
Затем я создал трафик в пределах пары мегабит к устройству подключенному к LAN и обратно
13.08.2021 10:40:28 - зафиксировал отсутствие ответа на 5 пингов подряд(такие были настройки для записи происшествия в лог)
13.08.2021 12:18:26 - плата с этого времени больше не отвечает на пинг
comment:10 by , 3 years ago
Replying to san:
Я подозреваю, что баг стал проявляться после одного из обновлений. Плат VE-02 для блок 3U не так много в природе и пользователи часто не торопятся обновляться, поэтому возможно пока никто не обнаружил проблемы.
VE-02 и VE-01 с сетью работают одинаково (MSP "не знает", в какой плате он работает). У меня на рабочем месте платы с последними ревизиями прошивок. В нашей АТС VE-01 тоже с последней прошивкой (в веб-интерфейсе отображается старая ревизия, но на самом деле она новая, так как я обновил вручную).
Прошивка MSP последний раз была обновлена в феврале 2017 года. С этого времени было произведено 171 плата VE-01 и 111 плат VE-02. Маловероятно, что катастрофическая проблема, возникающая в течение суток после начала работы платы, не была обнаружена в течение четырех лет...
follow-up: 13 comment:11 by , 3 years ago
Моя гипотеза, что в относительно недавних обновления платы VE-02 для блока 3U мы каким то образом создали условия для воспроизведения бага MSP.
follow-up: 14 comment:12 by , 3 years ago
Replying to san:
Затем я создал трафик в пределах пары мегабит к устройству подключенному к LAN и обратно
Это уже может быть тем фактором, о котором я писал выше. В реальной жизни телефон оператора такой трафик создать вряд ли может, обычно видеопоток телефона не превышает 1 Мбит/с, а аудиопоток - 100 кбит/c. Что если попробовать воспроизвести проблему меньшим трафиком - например 512 кбит/с. Есть ли какое-то влияние скорости трафика на возникновение проблемы?
comment:13 by , 3 years ago
Replying to san:
Моя гипотеза, что в относительно недавних обновления платы VE-02 для блока 3U мы каким то образом создали условия для воспроизведения бага MSP.
Прошивку какой ревизии ты хотел бы проверить?
follow-up: 15 comment:14 by , 3 years ago
Replying to alx:
В реальной жизни телефон оператора такой трафик создать вряд ли может, обычно видеопоток телефона не превышает 1 Мбит/с, а аудиопоток - 100 кбит/c. Что если попробовать воспроизвести проблему меньшим трафиком - например 512 кбит/с.
Платы в слотах 10 и 12 я поломал просто передачей RTP потока(PCMA) - телефон подключенный к LAN установил соединение с окончанием PPS в голос передавался туда и обратно и через некоторое время плата перестала пинговаться.
Я думаю что воспроизведение бага имеет некоторую вероятность, а большее количество трафика повышает эту вероятность.
Прошивку какой ревизии ты хотел бы проверить?
После обеда постараюсь вспомнить с кокой версией я ранее работал без проблем.
comment:15 by , 3 years ago
Replying to san:
Платы в слотах 10 и 12 я поломал просто передачей RTP потока(PCMA) - телефон подключенный к LAN установил соединение с окончанием PPS в голос передавался туда и обратно и через некоторое время плата перестала пинговаться.
Это означает, что большой объем трафика не является необходимым - окончание PPS генерирует мизерный трафик - до 100 кбит/с, с видеопотоками не работает. Это - нормальное штатное использование платы...
follow-up: 18 comment:16 by , 3 years ago
Заметил, что в настройках плат отключен протокол IPv6. Воспроизводится ли проблема, если установить режим SLAAC (это значение по умолчанию)?
comment:17 by , 3 years ago
Появилась еще одна мысль. Было бы интересно сравнить содержимое регистров MAC в нормальном состоянии и в "ненормальном" состоянии. Возможно, в них будут видны какие-то различия. Несмотря на то, что контроллерами MAC управляет MSP, CSP мог бы время от времени читать и анализировать их регистры и таким образом определять, что с сетью случилось что-то ненормальное. А возможно (при изрядной доле везения), можно было бы и "починить" работу сети без ререзагрузки платы, например каким-нибудь программным сбросом и повторной конфигурацией MAC...
comment:18 by , 3 years ago
Replying to alx:
Воспроизводится ли проблема, если установить режим SLAAC (это значение по умолчанию)?
Воспроизводится
comment:19 by , 3 years ago
В пятницу перед обедом создал трафик платам VE-01 и VE-02 у себя в блоке (более 2 Мбит/с для каждой). Сегодня понедельник, связность ни с одной из плат не пропала, платы отвечают как положено... Еще раз убеждаюсь, что в исходном эксперименте действует еще какой-то фактор. На эту же мысль наводит эксперимент с прошивкой VE-02 ревизии 20, с которой ранее не было проблем, а теперь есть...
comment:20 by , 3 years ago
При пинге платы VE-02 через два интерфейса ордновременно проблему воспроизвести не удалось. Однако пинг внешнего устройства через плату VE-02 проблему воспроизвел. В чем разница этих двух экспериментов для платы VE-02, непонятно...
Вот что выводится в лог при начале проблемы:
Aug 16 11:48:33 comcerto daemon.err sip_ua[575]: comcerto.cpp:2623: MSP ALERT channelId=0xffff, Type=1, CPU=0, Action=0, Channel=65534 ts=0 Aug 16 11:48:33 comcerto daemon.info sip_ua[578]: regSyncAgent.cpp:536: registration database saved to /lib/sip_ua/regDataBase.xml Aug 16 11:48:34 comcerto daemon.warn sip_ua[575]: comcerto.cpp:2559: ---> channel 0xffff (ts 0): unknown indication: FC=0x0132 len=12 Aug 16 11:48:34 comcerto daemon.warn sip_ua[575]: comcerto.cpp:2565: ---> 360a 0603 0132 0000 0001 fffb Aug 16 11:48:34 comcerto daemon.err sip_ua[575]: comcerto.cpp:2623: MSP ALERT channelId=0xffff, Type=1, CPU=0, Action=0, Channel=65534 ts=0 Aug 16 11:48:34 comcerto daemon.info sip_ua[578]: regSyncAgent.cpp:536: registration database saved to /lib/sip_ua/regDataBase.xml Aug 16 11:48:35 comcerto daemon.warn sip_ua[575]: comcerto.cpp:2559: ---> channel 0xffff (ts 0): unknown indication: FC=0x0132 len=12 Aug 16 11:48:35 comcerto daemon.warn sip_ua[575]: comcerto.cpp:2565: ---> 390a 0603 0132 0000 0002 7ffb
follow-up: 22 comment:21 by , 3 years ago
При изменении режима линка интерфейса LAN с 100Base-TX на 10Base-T проблема воспроизводиться перестала.
comment:22 by , 3 years ago
Replying to alx:
При изменении режима линка интерфейса LAN с 100Base-TX на 10Base-T проблема воспроизводиться перестала.
Это утверждение было сделано поспешно - обнаружена ошибка в эксперименте. Эксперимент начат повторно.
comment:23 by , 3 years ago
Проблема воспроизвелась в режиме 10Base-T порта LAN. Симптомы те же: ALERT'ы типа 1 (что означает NO_MEMORY), после чего периодическая индикация 0x0132. После увеличения нагрузки появились сообщения от VED о получении испорченных данных (?):
Aug 17 09:55:24 comcerto daemon.err sip_ua[451]: comcerto.cpp:2623: MSP ALERT channelId=0xffff, Type=1, CPU=0, Action=0, Channel=65534 ts=0 Aug 17 09:55:25 comcerto daemon.warn sip_ua[451]: comcerto.cpp:2559: ---> channel 0xffff (ts 0): unknown indication: FC=0x0132 len=12 Aug 17 09:55:25 comcerto daemon.info sip_ua[455]: regSyncAgent.cpp:536: registration database saved to /lib/sip_ua/regDataBase.xml Aug 17 09:55:42 comcerto daemon.warn sip_ua[451]: comcerto.cpp:2559: ---> channel 0xffff (ts 0): unknown indication: FC=0x0132 len=12 Aug 17 09:55:43 comcerto daemon.warn sip_ua[451]: comcerto.cpp:2559: ---> channel 0xffff (ts 0): unknown indication: FC=0x0132 len=12 Aug 17 09:56:02 comcerto daemon.warn sip_ua[451]: comcerto.cpp:2559: ---> channel 0xffff (ts 0): unknown indication: FC=0x0132 len=12 Aug 17 09:56:02 comcerto daemon.err sip_ua[451]: comcerto.cpp:2623: MSP ALERT channelId=0xffff, Type=1, CPU=0, Action=0, Channel=65534 ts=0 Aug 17 09:56:02 comcerto daemon.info sip_ua[455]: regSyncAgent.cpp:536: registration database saved to /lib/sip_ua/regDataBase.xml Aug 17 09:56:02 comcerto daemon.err sip_ua[451]: comcerto.cpp:2623: MSP ALERT channelId=0xffff, Type=1, CPU=0, Action=0, Channel=65534 ts=0 Aug 17 09:56:03 comcerto daemon.warn sip_ua[451]: comcerto.cpp:2559: ---> channel 0xffff (ts 0): unknown indication: FC=0x0132 len=12 Aug 17 09:56:03 comcerto daemon.info sip_ua[455]: regSyncAgent.cpp:536: registration database saved to /lib/sip_ua/regDataBase.xml Aug 17 09:56:12 comcerto daemon.warn sip_ua[451]: comcerto.cpp:2559: ---> channel 0xffff (ts 0): unknown indication: FC=0x0132 len=12 Aug 17 09:56:13 comcerto daemon.warn sip_ua[451]: comcerto.cpp:2559: ---> channel 0xffff (ts 0): unknown indication: FC=0x0132 len=12 Aug 17 09:56:21 comcerto daemon.warn sip_ua[451]: comcerto.cpp:2559: ---> channel 0xffff (ts 0): unknown indication: FC=0x0132 len=12 ..... Aug 17 10:09:46 comcerto daemon.warn sip_ua[451]: comcerto.cpp:2559: ---> channel 0xffff (ts 0): unknown indication: FC=0x0132 len=12 Aug 17 10:09:47 comcerto user.err kernel: VED: invalid fdesc (phys: 00b1bf40) content: part: 0a0002bc, release: 0001, len: 000006a2, offs: 00000000, interface: 00000003 Aug 17 10:09:47 comcerto user.err kernel: VED: fdesc payload: 3534 3736 3938 3b3a 3d3c 3f3e 4140 4342 4544 4746 4948 4b4a 4d4c 4f4e 5150 5352 5554 5756 5958 5b5a 5d5c 5f5e 6160 6362 6564 6766 6968 6b6a 6d6c 6f6e Aug 17 10:09:53 comcerto daemon.warn sip_ua[451]: comcerto.cpp:2559: ---> channel 0xffff (ts 0): unknown indication: FC=0x0132 len=12 Aug 17 10:09:55 comcerto daemon.warn sip_ua[451]: comcerto.cpp:2559: ---> channel 0xffff (ts 0): unknown indication: FC=0x0132 len=12 Aug 17 10:09:55 comcerto user.err kernel: VED: invalid fdesc (phys: 00aa4900) content: part: 0a0002bc, release: 0001, len: 00000622, offs: 00000000, interface: 00000003 Aug 17 10:09:55 comcerto user.err kernel: VED: fdesc payload: 3534 3736 3938 3b3a 3d3c 3f3e 4140 4342 4544 4746 4948 4b4a 4d4c 4f4e 5150 5352 5554 5756 5958 5b5a 5d5c 5f5e 6160 6362 6564 6766 6968 6b6a 6d6c 6f6e Aug 17 10:10:02 comcerto daemon.warn sip_ua[451]: comcerto.cpp:2559: ---> channel 0xffff (ts 0): unknown indication: FC=0x0132 len=12 Aug 17 10:10:03 comcerto daemon.warn sip_ua[451]: comcerto.cpp:2559: ---> channel 0xffff (ts 0): unknown indication: FC=0x0132 len=12 Aug 17 10:10:03 comcerto user.err kernel: VED: invalid fdesc (phys: 00b13f00) content: part: 0a0002bc, release: 0001, len: 00000622, offs: 00000000, interface: 00000003 Aug 17 10:10:03 comcerto user.err kernel: VED: fdesc payload: 3534 3736 3938 3b3a 3d3c 3f3e 4140 4342 b7b6 b9b8 bbba bdbc b7b6 b9b8 bbba bdbc b7b6 b9b8 bbba bdbc b7b6 b9b8 bbba bdbc b7b6 b9b8 bbba bdbc b7b6 b9b8 Aug 17 10:10:11 comcerto daemon.warn sip_ua[451]: comcerto.cpp:2559: ---> channel 0xffff (ts 0): unknown indication: FC=0x0132 len=12
Судя по тому, что MSP жалуется на ошибку выделения памяти, проблема не связана напрямую с сетевыми интерфейсами, и "дергать" интерфейсы для ее устранения бесполезно. Возможно, имеет место какой-то баг MSP, связанный с приемом-передачей пакетов, приводящий к утечке или порче памяти.
В качестве решения проблемы предлагается выполнять перезагрузку платы при получении от MSP ALERT типа 1.
follow-up: 25 comment:24 by , 3 years ago
Проблема воспроизвелась в блоке MC04-VIP(ревизия ve-02: 1673) но в этой версии ПО плата перезагружается через некоторое время после получения ALERT.
В качестве решения проблемы предлагается выполнять перезагрузку платы при получении от MSP ALERT типа 1.
Видимо это единственный вариант, больше ничего не придумывается.
Алексей, сделай пожалуйста тестовую прошивку с перезагрузкой при ALERT типа 1 и положи в одну из плат VE-02 блока 192.168.20.176.
comment:25 by , 3 years ago
Replying to san:
Алексей, сделай пожалуйста тестовую прошивку с перезагрузкой при ALERT типа 1 и положи в одну из плат VE-02 блока 192.168.20.176.
VE-02 в слоте 10.
follow-up: 27 comment:26 by , 3 years ago
Хм.. кажется я таки сломал её. Она не получает адрес по DHCP, а при установке адреса вручную не пингуется.
Алексей посмотри пожалуйста на неё.
COM платы доступен через TCP-сервер 192.168.1.240 порт 1001
comment:27 by , 3 years ago
Replying to san:
Алексей посмотри пожалуйста на неё.
Посмотрел. Не вижу в логе сообщений об индикации FC=0x0132...
А был ALERT с типом 1?
follow-up: 29 comment:28 by , 3 years ago
Не знаю. А при установленной подробности лога должны мы там увидеть ALERT и FC= ?
comment:29 by , 3 years ago
Replying to san:
А при установленной подробности лога должны мы там увидеть ALERT и FC= ?
В лог вывестись должны. Ранее я заметил, что индикация 0x0132 появляется только при наличии сетевого трафика. Предполагаю, что после воспроизведения проблемы трафик был отключен, поэтому сообщения в лог об индикации 0x0132 прекратились. ALERT выдается однократно (хотя выше он вывелся трижды), поэтому чтобы его увидеть надо смотреть лог в момент воспроизведения проблемы.
comment:30 by , 3 years ago
Ещё раз воспроизвёл - после ALERT 12:16:53 плата перезапустилась, но связности нет.
Jan 1 00:00:11 syslogd started: BusyBox v1.18.5 Jan 1 00:00:11 kernel: klogd started: BusyBox v1.18.5 (2021-02-22 20:45:56 YEKT) Jan 1 00:00:11 kernel: Linux version 2.6.22.19-4.07.0-candidate1-c300evm (alx@voip) (gcc version 5.3.0 (GCC) ) #6 Thu Jun 4 10:56:43 YEKT 2020 Jan 1 00:00:11 kernel: CPU: ARMv6-compatible processor [4117b361] revision 1 (ARMv6TEJ), cr=00c5387f Jan 1 00:00:11 kernel: Machine: Comcerto 300 (x570) Jan 1 00:00:11 kernel: Memory policy: ECC disabled, Data cache writeback Jan 1 00:00:11 kernel: On node 0 totalpages: 28416 Jan 1 00:00:11 kernel: DMA zone: 222 pages used for memmap Jan 1 00:00:11 kernel: DMA zone: 0 pages reserved Jan 1 00:00:11 kernel: DMA zone: 28194 pages, LIFO batch:7 Jan 1 00:00:11 kernel: Normal zone: 0 pages used for memmap Jan 1 00:00:11 kernel: CPU0: D VIPT write-back cache Jan 1 00:00:12 sysinit: brctl: SIOCGIFBR: Package not installed Jan 1 00:00:13 sysinit: sh: bad number Jan 1 00:00:13 sysinit: sh: bad number Jan 1 00:00:13 sysinit: sh: bad number Jan 1 00:00:13 sysinit: sh: bad number Jan 1 00:00:13 sysinit: sh: bad number Jan 1 00:00:13 sysinit: sh: bad number Jan 1 00:00:13 sysinit: sh: bad number Jan 1 00:00:13 sysinit: sh: bad number Jan 1 00:00:14 dnsmasq[369]: started, version 2.75 cachesize 150 Jan 1 00:00:14 dnsmasq[369]: compile time options: no-IPv6 GNU-getopt no-DBus no-i18n no-IDN DHCP no-DHCPv6 no-Lua TFTP no-conntrack no-ipset no-auth no-DNSSEC loop-detect no-inotify Jan 1 00:00:14 dnsmasq[369]: using local addresses only for domain lan Jan 1 00:00:14 dnsmasq[369]: no servers found in /tmp/resolv.conf.auto, will retry Jan 1 00:00:14 dnsmasq[369]: read /etc/hosts - 1 addresses Jan 1 00:00:15 kernel: NET: Registered protocol family 27 Jan 1 00:00:15 dropbear[425]: Running in background Jan 1 00:00:18 sysinit: sh: bad number Jan 1 00:00:18 sysinit: sh: bad number Jan 1 00:00:18 sysinit: sh: bad number Jan 1 00:00:18 sysinit: sh: bad number Jan 1 00:00:18 sysinit: sh: bad number Jan 1 00:00:18 sysinit: sh: bad number Jan 1 00:00:18 sysinit: sh: bad number Jan 1 00:00:18 sysinit: sh: bad number Jan 1 00:00:18 sysinit: dnsmasq: failed to create listening socket for port 53: Address already in use Jan 1 00:00:18 dnsmasq[440]: failed to create listening socket for port 53: Address already in use Jan 1 00:00:18 dnsmasq[440]: FAILED to start up Jan 1 00:00:19 sysinit: starting SIP UA daemon: sip_ua...net.unix.max_dgram_qlen = 256 Jan 1 00:00:19 sysinit: done. Jan 1 00:00:19 sysinit: sysctl: error: 'net.ipv4.netfilter.ip_conntrack_checksum' is an unknown key Jan 1 00:00:19 sysinit: sysctl: error: 'net.ipv4.netfilter.ip_conntrack_max' is an unknown key Jan 1 00:00:19 sysinit: sysctl: error: 'net.ipv4.netfilter.ip_conntrack_tcp_timeout_established' is an unknown key Jan 1 00:00:19 sysinit: sysctl: error: 'net.ipv4.netfilter.ip_conntrack_udp_timeout' is an unknown key Jan 1 00:00:19 sysinit: sysctl: error: 'net.ipv4.netfilter.ip_conntrack_udp_timeout_stream' is an unknown key Jan 1 00:00:24 kernel: eth1: no IPv6 routers present Jan 1 00:00:28 sip_ua[455]: regSyncAgent.cpp:489: file timestamp is 1630412060 sec in the future Aug 31 12:14:50 sip_ua[476]: poller.cpp:2634: Configuring FPGA... Aug 31 12:14:51 sip_ua[476]: comcerto.cpp:2174: !!!!! function IP_ADDRESS_v6 (0x0310): error CNF_ERROR_IP_ADDRESS_BAD_IP_ADDRESS (0x0b03): Aug 31 12:14:51 sip_ua[476]: comcerto.cpp:2175: Invalid IP Address Aug 31 12:14:51 udhcpc[490]: udhcpc (v1.18.5) started Aug 31 12:14:51 sip_ua[476]: comcerto.cpp:5135: comcerto_set_ip6() failed (result=-2819) Aug 31 12:14:51 udhcpc[490]: Sending discover... Aug 31 12:14:52 sip_ua[476]: poller.cpp:3101: ntpclient exited with return code 1 Aug 31 12:14:52 udhcpc[490]: Sending select for 192.168.0.106... Aug 31 12:14:52 udhcpc[490]: Lease of 192.168.0.106 obtained, lease time 12928 Aug 31 12:14:52 sip_ua[451]: sip_ua.cpp:835: IP change 127.0.0.1 --> 192.168.0.106 detected Aug 31 12:16:14 sip_ua[451]: user_agent.cpp:3437: cannot build REGISTER message (rc=-5) Aug 31 12:16:14 sip_ua[451]: user_agent.cpp:3486: cannot build REGISTER message (rc=-3) Aug 31 12:16:14 sip_ua[451]: user_agent.cpp:3437: cannot build REGISTER message (rc=-5) Aug 31 12:16:14 sip_ua[476]: fs01.cpp:390: module 1 [FS01]: DC-DC calibration started... Aug 31 12:16:14 sip_ua[476]: fs01.cpp:427: module 1 [FS01]: SLIC calibration started... Aug 31 12:16:17 sip_ua[476]: fs01.cpp:541: module 1 [FS01]: SLIC calibration 2 started... Aug 31 12:16:20 kernel: eth2: no IPv6 routers present Aug 31 12:16:53 sip_ua[451]: comcerto.cpp:2616: MSP ALERT channelId=0xffff, Type=1, CPU=0, Action=0, Channel=65534 ts=0 Jan 1 00:00:11 syslogd started: BusyBox v1.18.5 Jan 1 00:00:11 kernel: klogd started: BusyBox v1.18.5 (2021-02-22 20:45:56 YEKT) Jan 1 00:00:11 kernel: Linux version 2.6.22.19-4.07.0-candidate1-c300evm (alx@voip) (gcc version 5.3.0 (GCC) ) #6 Thu Jun 4 10:56:43 YEKT 2020 Jan 1 00:00:11 kernel: CPU: ARMv6-compatible processor [4117b361] revision 1 (ARMv6TEJ), cr=00c5387f Jan 1 00:00:11 kernel: Machine: Comcerto 300 (x570) Jan 1 00:00:11 kernel: Memory policy: ECC disabled, Data cache writeback Jan 1 00:00:11 kernel: On node 0 totalpages: 28416 Jan 1 00:00:11 kernel: DMA zone: 222 pages used for memmap Jan 1 00:00:11 kernel: DMA zone: 0 pages reserved Jan 1 00:00:11 kernel: DMA zone: 28194 pages, LIFO batch:7 Jan 1 00:00:11 kernel: Normal zone: 0 pages used for memmap Jan 1 00:00:11 kernel: CPU0: D VIPT write-back cache Jan 1 00:00:13 sysinit: brctl: SIOCGIFBR: Package not installed Jan 1 00:00:13 init: starting pid 260, tty '/dev/ttyS0': '/bin/ash --login' Jan 1 00:00:13 sysinit: sh: bad number Jan 1 00:00:13 sysinit: sh: bad number Jan 1 00:00:13 sysinit: sh: bad number Jan 1 00:00:13 sysinit: sh: bad number Jan 1 00:00:13 sysinit: sh: bad number Jan 1 00:00:13 sysinit: sh: bad number Jan 1 00:00:13 sysinit: sh: bad number Jan 1 00:00:13 sysinit: sh: bad number Jan 1 00:00:14 dnsmasq[372]: started, version 2.75 cachesize 150 Jan 1 00:00:14 dnsmasq[372]: compile time options: no-IPv6 GNU-getopt no-DBus no-i18n no-IDN DHCP no-DHCPv6 no-Lua TFTP no-conntrack no-ipset no-auth no-DNSSEC loop-detect no-inotify Jan 1 00:00:14 dnsmasq[372]: using local addresses only for domain lan Jan 1 00:00:14 dnsmasq[372]: no servers found in /tmp/resolv.conf.auto, will retry Jan 1 00:00:14 dnsmasq[372]: read /etc/hosts - 1 addresses Jan 1 00:00:15 kernel: NET: Registered protocol family 27 Jan 1 00:00:15 dropbear[429]: Running in background Jan 1 00:00:18 sysinit: sh: bad number Jan 1 00:00:18 sysinit: sh: bad number Jan 1 00:00:18 sysinit: sh: bad number Jan 1 00:00:18 sysinit: sh: bad number Jan 1 00:00:18 sysinit: sh: bad number Jan 1 00:00:18 sysinit: sh: bad number Jan 1 00:00:18 sysinit: sh: bad number Jan 1 00:00:18 sysinit: sh: bad number Jan 1 00:00:18 sysinit: dnsmasq: failed to create listening socket for port 53: Address already in use Jan 1 00:00:18 dnsmasq[445]: failed to create listening socket for port 53: Address already in use Jan 1 00:00:18 dnsmasq[445]: FAILED to start up Jan 1 00:00:19 sysinit: starting SIP UA daemon: sip_ua...net.unix.max_dgram_qlen = 256 Jan 1 00:00:19 sysinit: done. Jan 1 00:00:19 sysinit: sysctl: error: 'net.ipv4.netfilter.ip_conntrack_checksum' is an unknown key Jan 1 00:00:19 sysinit: sysctl: error: 'net.ipv4.netfilter.ip_conntrack_max' is an unknown key Jan 1 00:00:19 sysinit: sysctl: error: 'net.ipv4.netfilter.ip_conntrack_tcp_timeout_established' is an unknown key Jan 1 00:00:19 sysinit: sysctl: error: 'net.ipv4.netfilter.ip_conntrack_udp_timeout' is an unknown key Jan 1 00:00:19 sysinit: sysctl: error: 'net.ipv4.netfilter.ip_conntrack_udp_timeout_stream' is an unknown key Jan 1 00:00:24 kernel: eth1: no IPv6 routers present Jan 1 00:00:28 sip_ua[460]: regSyncAgent.cpp:489: file timestamp is 1630412185 sec in the future Aug 31 12:16:55 sip_ua[481]: poller.cpp:2634: Configuring FPGA... Aug 31 12:16:56 sip_ua[481]: comcerto.cpp:2174: !!!!! function IP_ADDRESS_v6 (0x0310): error CNF_ERROR_IP_ADDRESS_BAD_IP_ADDRESS (0x0b03): Aug 31 12:16:56 sip_ua[481]: comcerto.cpp:2175: Invalid IP Address Aug 31 12:16:56 sip_ua[481]: comcerto.cpp:5135: comcerto_set_ip6() failed (result=-2819) Aug 31 12:16:56 sip_ua[481]: poller.cpp:3101: ntpclient exited with return code 1 Aug 31 12:16:58 sip_ua[456]: user_agent.cpp:3437: cannot build REGISTER message (rc=-5) Aug 31 12:16:58 sip_ua[456]: utils.cpp:244: kernel returned error -101 (Network is unreachable) Aug 31 12:16:58 sip_ua[456]: comcerto.cpp:7154: 192.168.0.5: failed Aug 31 12:16:58 sip_ua[456]: utils.cpp:244: kernel returned error -101 (Network is unreachable) Aug 31 12:16:58 sip_ua[456]: comcerto.cpp:7154: 192.168.0.5: failed Aug 31 12:16:58 sip_ua[456]: utils.cpp:244: kernel returned error -101 (Network is unreachable) Aug 31 12:16:58 sip_ua[456]: comcerto.cpp:7154: 192.168.0.5: failed Aug 31 12:16:58 sip_ua[481]: poller.cpp:3101: ntpclient exited with return code 1 Aug 31 12:18:18 sip_ua[481]: fs01.cpp:390: module 1 [FS01]: DC-DC calibration started... Aug 31 12:18:18 sip_ua[481]: fs01.cpp:427: module 1 [FS01]: SLIC calibration started... Aug 31 12:18:19 sip_ua[481]: poller.cpp:3101: ntpclient exited with return code 1 Aug 31 12:18:20 sip_ua[481]: poller.cpp:3101: ntpclient exited with return code 1 Aug 31 12:18:21 sip_ua[481]: fs01.cpp:541: module 1 [FS01]: SLIC calibration 2 started... Aug 31 12:18:21 sip_ua[481]: poller.cpp:3101: ntpclient exited with return code 1 Aug 31 12:18:23 sip_ua[481]: poller.cpp:3101: ntpclient exited with return code 1 Aug 31 12:18:24 sip_ua[481]: poller.cpp:3101: ntpclient exited with return code 1 Aug 31 12:18:25 sip_ua[481]: poller.cpp:3101: ntpclient exited with return code 1 Aug 31 12:18:26 kernel: eth2: no IPv6 routers present Aug 31 12:18:27 sip_ua[481]: poller.cpp:3101: ntpclient exited with return code 1 Aug 31 12:18:28 sip_ua[481]: poller.cpp:3101: ntpclient exited with return code 1 Aug 31 12:18:29 sip_ua[481]: poller.cpp:3101: ntpclient exited with return code 1 Aug 31 12:18:31 sip_ua[481]: poller.cpp:3101: ntpclient exited with return code 1 Aug 31 12:18:32 sip_ua[481]: poller.cpp:3101: ntpclient exited with return code 1 Aug 31 12:18:34 sip_ua[481]: poller.cpp:2986: error: NTP client process 665 is missing: kill() returned error 'No such process' Aug 31 12:18:34 sip_ua[481]: poller.cpp:3101: ntpclient exited with return code 1
comment:31 by , 3 years ago
| Resolution: | → готово |
|---|---|
| Status: | new → closed |
follow-up: 34 comment:33 by , 3 years ago
| Resolution: | готово |
|---|---|
| Status: | closed → reopened |
Т.к. появились новые данные тикет переоткрою
Выяснилось, что у пользователей блоков VIP c r1062 (v10_23_03_01_AS_11), uptime блоков составляет длительное время(173 дня, 55 дней), хотя к портам LAN подключены SIP телефоны и разговоры ведутся ежедневно. Т.е. баг у них не воспроизводится.
Я собрал стенд в котором VIP r1673 перезагружается в течении нескольких минут, проверил раз 5.
В тех-же условиях r1062 не разу не перезагрузился и работает нормально.
comment:34 by , 3 years ago
Replying to san:
Т.к. появились новые данные тикет переоткрою
Выяснилось, что у пользователей блоков VIP c r1062, uptime блоков составляет длительное время(173 дня, 55 дней), хотя к портам LAN подключены SIP телефоны и разговоры ведутся ежедневно. Т.е. баг у них не воспроизводится.
Насколько я понимаю, выше указаны ревизии пакета ve-02. Эта информация, как мне кажется, ни о чем не говорит, так как пакет ve-02 практически никак не участвует в приеме/передаче транзитных пакетов. Единственное, что делает sip_ua - это читает конфиг-файл и настраивает адреса сетевым интерфейсам. Транзитные пакеты не покидают ядро, и никак не взаимодействуют с userland-процессами. Процесс sip_ua можно вообще завершить, а пакеты будут продолжать ходить через плату.
Для того чтобы убедиться в этом, я хотел собрать sip_ua ревизии 1062 и провести эксперимент, но эта версия настолько старая, что я не смог ни правильно воспроизвести ее сборку, ни вытащить ее из другого блока (ругалась на отсутствие какого-то символа даже после копирования всех библиотек).
Как видно из комментариев выше, проблема наблюдается в MSP. Поэтому я провел другой эксперимент. Я взял блока, в котором воспроизводится проблема, и проверил его работу с другими имеющимися у меня версиями MSP firmware.
| firmware version | SPU version | Комментарий |
| v11_26_02_04_PSN_01 | C64V_7_10_3 | Из MSP приходит ALERT, перестает работать сеть |
| v10_23_03_01_AS_03 | C64V_7_7_6 | Сеть не работает сразу (нет линка на eth2) |
| v7_20 | C64V_7_4_3 | Сеть не работает сразу (нет линка на eth2) |
| v10_23_03_01_AS_11 | C64V_7_7_12 | Проблема не воспроизводится |
| v10_23_03_01_AS_12 | C64V_7_7_12 | Проблема не воспроизводится |
| v11_26_03_08_SS_04 | C64V_7_10_13 | Проблема не воспроизводится |
| v7_22_03_16_HW_49 | C64V_7_6_36 | Проблема не воспроизводится |
| v7_22_03_16_HW_50 | C64V_7_6_36 | Проблема не воспроизводится |
Обрати внимание, что в процессе экспериментов ни один файл в CSP не менялся. Менялась только MSP firmware. Мне кажется, результаты экспериментов достаточно ясно указывают на то, что проблема в MSP firmware. Из всех имеющихся версий firmware проблема воспроизводится только с одной.
Учитывая вышесказанное, мне не совсем понятна задача. Что мне сделать в рамках этого переоткрытого тикета?
comment:35 by , 3 years ago
| Resolution: | → готово |
|---|---|
| Status: | reopened → closed |
В репозиторий добавлен новый пакет ve-02-msp, содержащий файл firmware v11_26_03_08_SS_04. При прошивке VE-02 в блоке MC04-DSL-3U теперь используется он.
Кажется плата в слоте 3 тоже "сломалась", минут 10 назад я пропустил через неё чуть больше трафика, чем было - создал трафик в пределах 2Мбит/с в течении пары минут.
После этого пинг до платы стал "рваным" - она отвечает не всегда.