FXO, FO01 остаётся в состоянии Connected

[san]

Пользователь сообщает, что одно из окончаний FO01 на плате VE-02, после нескольких успешных вызовов переходит в странное состояние - в веб-интерфейсе отображается состояние “Connected” с пустыми полями Вызывающий и вызываемый. В это время окончание не принимает звонки из SIP.
Самое неприятное, что настройка Таймаута RTP не помогает вывести окончание из этого состояния. Кнопка «разъединить» также не возвращает окончание в состояние Idle.

[san]

Прикрепил конфиг блока и лог VE-02

[alx]

1110	Oct  8 10:20:44 sip_ua[462]: fxo.cpp:345: ---> ts=254, state=Connected: Call disconnected, ts=254, flags=0000, data=72
1111	Oct  8 10:20:44 sip_ua[462]: comcerto.cpp:6947: ts 254: stopping RTP stream
1112	Oct  8 10:20:44 sip_ua[462]: comcerto.cpp:6947: ts 254: stopping RTP stream
1113	Oct  8 10:20:52 sip_ua[488]: user_agent.cpp:2095: ---> transport 0: SIP event 22 (Call Context is released!): cid=70, did=0, tid=0, rid=0, sid=0, nid=0
1114	Oct  8 10:21:15 sip_ua[488]: user_agent.cpp:2095: ---> transport 0: SIP event 22 (Call Context is released!): cid=72, did=0, tid=0, rid=0, sid=0, nid=0
1115	Oct  8 10:21:23 syslogd exiting
1116	Oct 21 07:17:32 syslogd started: BusyBox v1.18.5
1117	Oct 21 07:17:33 sip_ua[454]: fxo.cpp:345: ---> ts=254, state=Connected: Statistics received, ts=254, flags=0000, data=0

К сожалению, сразу после получения и обработки канальным окончанием FO01 события Disconnect в 10:20:44 UTC 8 октября в 10:21:23 логгинг в файл был выключен, и вновь включен 21 октября в 07:17:32 UTC. В журнале видно, что на момент возобновления логгирования канальное окончание находится в состоянии Connected, однако из-за этого 13-дневного перерыва ведения журнала нельзя утверждать, что канальное окончание осталось в состоянии Connected после получения Disconnect, а не перешло в состояние Connected позже. Во всех остальных вызовах канальное окончание переходило из состояния Connected в состояние Idle при получении Disconnect.

Анализ кода показал, что при получении события Disconnect канальное окончание непременно переходит либо в состояние DropLine (если находилось в состоянии Calling с разомкнутым шлейфом, это не наш случай), либо в состояние Idle (во всех остальных случаях). Если так, то переход в состояние Connected, в котором канальное окончание "залипло", произошел как раз в тот период, когда логгирование в файл было отключено. Это подтверждается еще и тем фактом, что после получения Disconnect канальное окончание деактивировало медиапоток RTP ("stopping RTP stream"), однако после возобновления логгирования мы видим события "Statistics received", которые генерируются только при активном потоке RTP.

Событие Hangup, возникающее при нажатии кнопки "разъединить" в веб-интерфейсе, зафиксировано в представленном логе один раз в 10:12:21 UTC 8 октября:

589	Oct  8 10:12:21 sip_ua[462]: fxo.cpp:345: ---> ts=254, state=Connected: Hangup, ts=254, flags=0000, data=0
590	Oct  8 10:12:21 sip_ua[462]: comcerto.cpp:6947: ts 254: stopping RTP stream
591	Oct  8 10:12:21 sip_ua[462]: fxo.cpp:345: ---> ts=254, state=Idle: Call disconnected, ts=254, flags=0000, data=49

В логе видно, что после получения события Hangup канальное окончание перешло в состояние Idle (строка 591). Таким образом, не выполнение перехода канального окончания в состояние Idle при нажатии кнопки "разъединить" представленным логом не подтверждается.

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

Прошу повторно воспроизвести описанную в тикете проблему при включенном логгировании в файл и заново приложить к тикету полученный лог-файл.

[san]

Насколько я понял пользователя, лог он включил уже после того как обнаружил окончание в залипшем состоянии. Т.е. то что было в логе до Oct 21 вообще не относится к проблеме.
Я попросил пользователя зафиксировать в логе сам переход из "рабочего" состояния в "залипшее", жду ответа.

[san]

p.s. у пользователе плата VE-02 с ревизией ПО 29

[san]

Другой пользователь сообщает о похожей проблеме:

Платы FXO стали в случайном порядке подвисать канальные окончания. В канальном окончании пишется что окончание находится в статусе Connected, на стороне FXS же канальное окончание показывает, что все в порядке в статусе Idle, но когда абонент поднимает трубку, то слышит короткие гудки. Лечится это только разъединением статуса Connected на стороне FXO путём нажатия на трубку в канальном окончании. Проявляется случайным образом на разных SIP окончаниях, но именно со стороны блока где стоят платы FXO.
Версия прошивки VE у нас была установлена 65, обновили все блоки до 67 проблема осталась

Настройки Таймаут RTP и Session Expires, по словам пользователя не выводят окончание FXO из "зависшего" состояния.

[san]

Попросил пользователя записать лог

[alx]

Replying to san:

Платы FXO стали в случайном порядке подвисать канальные окончания.

Это я не совсем понял... У него есть какое-то свое оборудование (платы FXO), к которому подключены каналы нашей платы VE-02?

Лечится это только разъединением статуса Connected на стороне FXO путём нажатия на трубку в канальном окончании.

А вот здесь ситуации различаются - в первом случае нажатие "трубки" не помогало...

Версия прошивки VE у нас была установлена 65, обновили все блоки до 67 проблема осталась

??? Нет такой прошивки у платы VE-02, последняя прошивка имеет номер ревизии 29. Вероятно, у этого пользователя плата не VE-02, а VE-01...

[alx]

Replying to san:

Попросил пользователя записать лог

И файл конфигурации тоже было бы полезно получить.

[san]

А вот здесь ситуации различаются - в первом случае нажатие "трубки" не помогало...

Не уверен на счёт этого, про то что не помогает нажатие трубки пользователь сообщал когда ПО VE-02 у него была ревизии 28. А после обновления до ревизии 29 пользователь сообщил

Кнопка отбоя в интерфейсе заработала.

Кажется я забыл об этом упомянуть.

Вероятно, у этого пользователя плата не VE-02, а VE-01...

Так и есть

И файл конфигурации тоже было бы полезно получить.

Обещал прислать

[alx]

Replying to san:

про то что не помогает нажатие трубки пользователь сообщал когда ПО VE-02 у него была ревизии 28. А после обновления до ревизии 29 пользователь сообщил

Кнопка отбоя в интерфейсе заработала.

Это очень странно, потому что в прошивке ревизии 29 вроде бы ничего, что могло бы как-то повлиять на работу (точнее, неработу) этой кнопки не менялось...

[san]

Добавил конфиги плат VE-01 у пользователя №2
В Блоке А - находятся окончания FXO, у каждого окончания настроен вызов определённого FXS в блоке Б или С, а в этом FXS соответственно настроена горячая линия на этот-же FXO.
Т.е. один и тот-же FXS всегда звонит в один и никто больше и наоборот FXO в один FXS и никто больше

[alx]

Спасибо за лог. Вижу в логе, что канал 13 (канальное окончание FXO) c Nov 23 22:13:01 находится в состоянии Connected, из которого перешло в исходное Nov 24 05:58:41 по команде оператора. Предполагаю, что это и есть "странное состояние", описанное в данном тикете.

К сожалению, в прикрепленном архиве опять отсутствуют интересующие нас события - вызов, в результате которого канальное окончание FXO перешло в состояние Connected, в котором оно "застряло" до разъединения оператором 24 ноября. Находящиеся в прикрепленном архиве логи начинаются с Nov 23 22:13:01, когда канальное окончание FXO уже находилось в состоянии Connected. Таким образом, в прикрепленных логах отсутствует предмет анализа.

Прошу приложить к тикету более ранние файлы журнала (предшествующие уже приложенным).

[alx]

Replying to alx:

Прошу приложить к тикету более ранние файлы журнала (предшествующие уже приложенным).

Подозреваю, что более ранние файлы отсутствуют, так как syslogd при ротации сохраняет только один файл.

В таком случае, предлагаю увеличить размер лог-файла (опция log_size в файле /etc/config/system) и дождаться нового воспроизведения ситуации.

[san]

Добавил логи нового эксперимента

Снова поймали зависание 5 канала. В 9 часов дня сегодня ориентировочно запустили запись логов. В промежуток с 11-12:00 было зависание. В 12:15 сбросили окончание путем нажатия на трубку со стороны FXO.

время указано в UTC
"5 канал" - это fxo5@..., ts4
Логи записаны со стороны FXO и со стороны FXS

[alx]

В 11:12:11 поступил входящий вызов со стороны IP. Канальное окончание замкнуло шлейф абонентской линии и перешло в состояние Connected.
В 12:14:51 оператор отбил соединение кнопкой в веб-интерфейсе.
В промежутке между занятием в 11:12:11 и отбоем в 12:14:51 в плату не поступало ни отбоя (BYE) со стороны вызывающего (об этом свидетельствуют записи

Nov 25 12:14:51 sip_ua[416]: repro.cpp:716: doSessionAccounting(): Session Ended 'branch=z9hG4bK123475744'
Nov 25 12:14:51 sip_ua[416]: repro.cpp:734: --> duration=3759, [FXS]tel:fxs5@10.236.120.211: ---> [FXO]tel:fxo5@10.236.120.184:
Nov 25 12:14:51 sip_ua[416]: repro.cpp:995: --> CDR: {"answer":1637838732,"duration":3759,"hangup":1637842491,"org-host":"10.236.120.211","org-scheme":"tel","org-type":"FXS","org-user":"fxs5","to-host":"1

сразу после Hangup (то есть прокси-сервер только сейчас "увидел" отбой, сессия была активной более часа), ни сигнала "занято" в абонентской линии - об этом свидетельствует отсутствие строк

fxo.cpp:343: ---> ts=4, state=Connected: TDM Call Progress detected, ts=4, flags=0000, data=52

Таким образом, исходя из лога вызываемой стороны, все работало нормально, отбоя от вызывающей стороны не было.

Как видно из лога вызывающей стороны, после снятия трубки и вызова fxo5@10.236.120.184 в ту же секунду абонент положил трубку, однако отбой в сторону вызываемого почему-то не ушел.

Когда абонент канального окончания FXS кладет трубку, это событие обрабатывается цепочкой вызовов
hangup() --> ua_hangup() --> eXosip_call_terminate_with_reason(). Если последний вызов возвращает ошибку (за исключением OSIP_WRONG_STATE), в лог выводится ошибка (даже два раза), но в нашем случае в логе ошибок нет.

Картина пока выглядит странно: если верить логу, все выполняется правильно, но сообщение CANCEL/BYE не отправляется...

Есть особый случай - когда hangup() вызывается до того как диалог установлен (до того как получен какой-либо ответ на INVITE). В этом случае eXosip_call_terminate_with_reason() возвращает OSIP_WRONG_STATE. В таком случае устанавливается специальный флаг terminated, который проверяется при получении любого ответа на INVITE, и если этот флаг установлен, вызывается eXosip_call_terminate(). В логе мы видим два ответа:

Nov 25 11:12:12 sip_ua[398]: user_agent.cpp:2098: ---> transport 0: SIP event 5 (Call is being processed!): cid=51, did=0, tid=55, rid=0, sid=0, nid=0
Nov 25 11:12:12 sip_ua[398]: user_agent.cpp:2098: ---> transport 0: SIP event 7 (Remote phone has answered!): cid=51, did=52, tid=55, rid=0, sid=0, nid=0

Первый - это "100 Trying", второй - "200 OK". Любое из этих событий при установленном флаге terminated должно было привести к вызову eXosip_call_terminate(). В случае, если eXosip_call_terminate() завершится с ошибкой, в лог также выводится сообщение, но реально в логе его нет. Более того, еще до вызова eXosip_call_terminate() в лог выводится сообщение "'terminated' flag set, calling eXosip_call_terminate(%d)", но и его я в логе не вижу!!!

[alx]

Проводил синтетический тест, проблему воспроизвел. Симптомы те же, по в логе это выглядит как-то по-другому. Попутно воспроизвел ситуацию с неотбоем FXO по нажатию кнопки в веб-интерфейсе - FXO осталось в состоянии Connected. И да, в плате, где FXO, предпоследняя версия прошивки. :) Сейчас попробую обновить до последней...

[san]

Таким образом, исходя из лога вызываемой стороны, все работало нормально, отбоя от вызывающей стороны не было.

А удалённая сторона прервала RTP-поток? а то ведь fxo похоже считал что RTP-поток есть.
И ещё не понятно почему в подобном случае Session-Expires не помогает.

[alx]

Replying to san:

А удалённая сторона прервала RTP-поток?

Нет, RTP поток даже не начинался, так как на момент получения ответа вызываемого вызывающий уже положил трубку.

а то ведь fxo похоже считал что RTP-поток есть.

В логе не вижу записей о приеме RTP потока.

И ещё не понятно почему в подобном случае Session-Expires не помогает.

Потому что сессия существует, и сообщения между абонентами успешно проходят. Для разрыва сессии нет причин.

[san]

В логе не вижу записей о приеме RTP потока.

А почему тогда не сработал RTP-таймаут?

[alx]

Replying to san:

А почему тогда не сработал RTP-таймаут?

Таймаут RTP отключен (установлен в значение 0) в конфигурации канального окончания.

[san]

Насколько я вижу в конфигурации пользователя для fxo5 задано "rtp-timeout":5

[alx]

Replying to san:

Насколько я вижу в конфигурации пользователя для fxo5 задано "rtp-timeout":5

А, виноват, перепутал с fxo13, который рассматривал вчера. RTP таймаут не сработал потому что, как ты сам верно заметил, он начинает отсчет времени от момента прерывания RTP потока, а этого прерывания не было.

Хм... Сейчас посмотрел руководство - там действие параметра "таймаут RTP" описано иначе:

Параметр устанавливает максимально допустимое время отсутствия входящего медиапотока RTP в секундах. Если медиапоток RTP не принимается в течение заданного времени, соединение разрывается.

Описанное поведение мне кажется более правильным и логичным чем реализованное в действительности. Думаю, стоит привести реализацию этой функции в соответствие с текстом РЭ... Создал тикет #378.

[san]

Создал тикет #378

Алексей, а ты можешь побыстрее реализовать этот тикет? Это бы стало хорошим временным обходным путём для решения проблемы у пользователей.

[alx]

Replying to san:

Создал тикет #378

Алексей, а ты можешь побыстрее реализовать этот тикет?

Думаю, что да.

Это бы стало хорошим временным обходным путём для решения проблемы у пользователей.

Чтобы это стало временным обходным путём для решения проблемы у пользователей, мало реализовать этот тикет, надо еще и новую прошивку выпустить. А мне не хотелось бы выпускать прошивку с известным неприятным багом...

[san]

Можно не выпускать для всех, а передать только этому пользователю sip_ua

[alx]

Думаю, что мне удалось воспроизвести ситуацию достаточно близко к оригиналу. Хотя в моих экспериментах система вела себя по-разному, думаю, мне удалось найти причину проблемы.

Когда UAC получает ответ на INVITE, он, как было описано выше, проверяет флаг terminated, но не проверяет, был ли установлен диалог. Ранее я не учел, что когда в ответ на INVITE приходит "100 Trying", диалог еще не установлен. Однако в этом состоянии диалога eXosip_call_terminate() не возвращает ошибки, а возвращает 1 (то есть и не ошибку, и не успех). Последствия этого разные и непонятные: например CANCEL может просто не отправиться из платы. Или CANCEL (без To-tag) отправляется, но игнорируется принимаемой стороной (libeXosip не генерирует никакого события) и т.п.

Сейчас я доработал код так, чтобы eXosip_call_terminate() вызывался только при установленном диалоге (то есть если был получен ответ с кодом больше 100). В моих тестах проблема полностью ушла - после получения ответа "200 OK" вызывающая сторона передает BYS, и вызов корректно завершается с обеих сторон.

Остается непонятным, почему в логе не было записи "'terminated' flag set, calling eXosip_call_terminate", но это можно списать на известное нам "пропадание" строк в логе, которое так полностью и не было устранено...

Есть ли возможность отправить клиенту файл sip_ua для проверки в "боевых" условиях до официального релиза новой прошивки?

Попутно выявил еще одну небольшую проблему - создан тикет #379.

[alx]

In 1958/sip_ua:

При получении ответа в диалоге, ранее помеченног флагом terminated,
eXosip_call_terminate() вызывается только в случае, если диалог установлен (did != 0).
Также флаг terminated сбрасывается только при успешном завершении eXosip_call_terminate().
See #373.

[alx]

Replying to san:

Можно не выпускать для всех, а передать только этому пользователю sip_ua

Вижу, ты отвечаешь раньше, чем я спрашиваю. :) Выслал тебе прошивку мылом. Установить ее надо с той стороны, где FXS. Предварительно очень желательно убедиться, что в плате самая последняя прошивка.

[san]

Выслал тебе прошивку мылом. Установить ее надо с той стороны, где FXS

Пользователь, после установки прошивки сообщил следующее:

проблема сохранилась с зависанием окончания. В этот раз они стали зависать еще чаще. По нашему времени мы начали запись логов сегодня в 09:15, закончили в 10:49. Именно в этот момент мы снова сбросили окончание вручную

Логи прикрепил в сообщении выше

[alx]

Replying to san:

Пользователь, после установки прошивки сообщил следующее:

проблема сохранилась с зависанием окончания.

Как странно... Я в некотором замешательства... Пользователь установил новую программу, но в поведении аппаратуры ничего не изменилось. Настолько ничего, что даже номер строки в сообщении

Dec  6 07:52:10 sip_ua[371]: user_agent.cpp:3615: --> ua_dial_out() <sip:fxs5@10.236.120.211> -> sip:fxo5@10.236.120.184 ()...

остался прежний, хотя в код, расположенный выше этой строки, были добавлены новые строчки... Как это можно объяснить?

[san]

Действительно странно. Либо sip_ua был "не тот", либо пользователь его не установил.

[alx]

Replying to san:

Действительно странно. Либо sip_ua был "не тот", либо пользователь его не установил.

Либо установил, но не перезапустил процесс.

[san]

Он сообщал, что после перезапуска по инструкции, перезапускал ещё раз, и спрашивал ещё не сброситься ли новая прошивка после нового перезапуска....
Может быть он перепутал сторону FXS с FXO, и не туда установил...

[alx]

Replying to san:

Он сообщал, что после перезапуска по инструкции, перезапускал ещё раз,

Может быть инструкция неправильная?

[alx]

Я, как мне кажется, устранил практически все проблемы, обнаруженные по результатам исследований данного тикета, и планировал поставить новую прошивку на нашу АТС для теста, но не успел, так как был отвлечен на проблемы с платами SW-01...

[san]

Может быть инструкция неправильная?

Инструкция обычная. Т.к. у пользователя WinScp, адаптирована под него

0. В плате VE-01 должна быть последняя прошивка 67
1. Скопировать через WinScp прилагаемый файл sip_ua в плату VE-01 в каталог /tmp/.
2. Открыть терминал в WinScp (Command->Terminal) и ввести команды по одной, нажимая Execute (здесь нужно быть внимательным, ошибки в командах могут привести к "окирпичиванию платы")

chmod a+x /tmp/sip_ua

(после выполнения в поле вывода не должно быть ошибок, если ошибки есть не продолжать далее)

ldd /tmp/sip_ua

(просмотреть вывод и убедиться, что выведен только список библиотек и нет сообщений об ошибках)

mv /tmp/sip_ua /usr/bin/

(после выполнения в поле вывода не должно быть ошибок)

reboot

(плата перезапустится)

Я, как мне кажется, устранил практически все проблемы, обнаруженные по результатам исследований данного тикета, и планировал поставить новую прошивку на нашу АТС для теста

Это хорошо, можно некоторое время понаблюдать и если всё хорошо релизить и проверять у пользователя.

[alx]

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