Context Navigation

← Previous Ticket
Next Ticket →

#351 closed баг (fixed)

Продолжительный "гудок"в трубке после ответа на вызов PPS->FS01

Reported by:	san	Owned by:	alx
Priority:	средний	Milestone:	1 очередь
Component:	VE-02	Keywords:
Cc:

Description (last modified by san)

В схеме связи организован групповой канал со всесторонним суммированием (каждый слышит всех кроме себя).
Окончания подключенные к групповому каналу - PPS, их настройки "Вызывать URI:" указывют на: Диспетчер(sip телефон), ГРС1(FS01), ГРС2(FS01), ГРС3(FS01).

Эксперимент:

Диспетчер вызывает своё окончание PPS
Окончание отправляет в групповой канал DTMF A
Телефоны на ГРС, подключенyые к соответствующим FS01, звонят
Если у звонящего огончания FS01 поднять трубку, то иногда(очень редко), вместо аудио из групового канала, в трубке слышен продолжительный(порядка 5 секунд) сигнал.

Есть ещё один вариант воспроизведения "гудка"
Эксперимент 2:

У одного из FS01 настроена горячая линия в соответствующее окончание PPS
При подъёме трубки на телефоне этого FS01 - можно услышать в трубке тот-же "гудок".

Воспроизводится, как минимум на 2-х разных FS01 и телефонных аппаратах.

Attachments (1)

gudok.m4a (62.5 KB ) - added by san 4 years ago.

Download all attachments as: .zip

Change History (24)

comment:1 by san, 4 years ago

В прошлый раз наметили несколько уточняющих экспериментов:

"вынести" телефон оператора ГРС на другое(чужое) окончание
проверить не воспроизводится ли "гудок" при "обычном" звонке на окончание FS01
посмотреть нет ли в логе платы VE-02 записей "DTMF detected" в момент гудка

comment:2 by san, 4 years ago

Description:	modified (diff)

Добавил в текст ещё один вариант воспроизведения "гудка"

comment:3 by san, 4 years ago

посмотреть нет ли в логе платы VE-02 записей "DTMF detected" в момент гудка

Воспроизвёл гудок, прикладываю его лог.
Вот поднятие трубки:

Jun 16 05:11:35 comcerto daemon.info sip_ua[451]: comcerto.cpp:6288: channel 254: answer

и после него я ничего интересного не увидел

Jun 16 05:11:53

это уже конец разговора - DTMFD от Диспетчера

Jun 16 05:11:29 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:29 comcerto daemon.info sip_ua[451]: pps.cpp:37: ts 1: dialing 51 Jun 16 05:11:29 comcerto daemon.info sip_ua[451]: user_agent.cpp:3509: --> ua_ Jun 16 05:11:29 comcerto daemon.info sip_ua[536]: repro.cpp:567: doSessionAcco unting(): Session Created 'branch=z9hG4bK755015460'
Jun 16 05:11:29 comcerto daemon.info sip_ua[477]: user_agent.cpp:2161: INVITE received: sip:51@127.0.0.1:6060;transport=udp (Call-ID: 961905101@(null))
Jun 16 05:11:29 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:29 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:29 comcerto daemon.info sip_ua[451]: fxs.cpp:1023: channel 254: r Jun 16 05:11:29 comcerto daemon.info sip_ua[451]: user_agent.cpp:3940: Call 26 Jun 16 05:11:29 comcerto daemon.info sip_ua[477]: user_agent.cpp:2411: ---> ri nging with status code 180
Jun 16 05:11:29 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:29 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:29 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:32 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:35 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:35 comcerto daemon.info sip_ua[451]: comcerto.cpp:6288: channel 2 Jun 16 05:11:35 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:35 comcerto daemon.info sip_ua[451]: comcerto.cpp:7058: --> ts 25 Jun 16 05:11:35 comcerto daemon.info sip_ua[451]: comcerto.cpp:7059: --> ts 25 Jun 16 05:11:35 comcerto daemon.info sip_ua[451]: comcerto.cpp:7060: --> audio Jun 16 05:11:35 comcerto daemon.info sip_ua[451]: comcerto.cpp:7184: ts 254: R Jun 16 05:11:35 comcerto daemon.info sip_ua[536]: repro.cpp:732: doSessionAcco unting(): Session Established 'branch=z9hG4bK755015460'
Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: comcerto.cpp:7058: --> ts 1: Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: comcerto.cpp:7059: --> ts 1: Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: comcerto.cpp:7060: --> audio Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: comcerto.cpp:7184: ts 1: RTP Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:41 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:41 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:41 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:41 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:44 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:46 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:46 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:46 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:46 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:51 comcerto daemon.info sip_ua[536]: repro.cpp:670: doSessionAcco unting(): Session Ended 'branch=z9hG4bK1423555667'
Jun 16 05:11:51 comcerto daemon.info sip_ua[536]: repro.cpp:688: --> duration= 16, [PPS]tel:0@10.41.114.152: ---> [FS01]tel:51@10.41.114.152:
Jun 16 05:11:51 comcerto daemon.info sip_ua[536]: repro.cpp:855: --> CDR: {"an swer":1592284295,"duration":16,"hangup":1592284311,"org-host":"10.41.114.152", "org-scheme":"tel","org-type":"PPS","org-user":"0","to-host":"10.41.114.152"," Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:53 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state Jun 16 05:11:53 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Idle: DTMF detected, ts=1, flags=0000, data=12
@10.41.114.152
dial_out() <sip:0@10.41.114.152> -> sip:51@10.41.114.152 ()...
=Calling: Incoming call, ts=-1, flags=0001, data=26
ate=Idle: Incoming call, ts=-1, flags=0001, data=26
inging
routed to TS 254
=Calling: Remote is ringing, ts=1, flags=0000, data=25
=Calling: Message answered 2xx, ts=1, flags=0000, data=25
=Calling: Tone detected, ts=1, flags=0000, data=255
ate=Ringing: Caller ID sending complete, ts=254, flags=0000, data=0
ate=Ringing: CAS event, ts=254, flags=0000, data=7
54: answer
ate=Connected: RTP parameters, ts=254, flags=0000, data=26
4: 10.41.114.152[10508] --> 10.41.114.152[10002]
4: codec PCMA, VAD is on, red=0
pt: 8/8, event pt: 101/101, VBD pt: 98/98
TP destination is 02:ad:c5:00:00:75
=Calling: RTP parameters, ts=1, flags=0000, data=25
10.41.114.152[10002] --> 10.41.114.152[10508]
codec PCMA, VAD is on, red=0
pt: 8/8, event pt: 101/101, VBD pt: 98/98
destination is 02:ad:c5:00:00:75
=Calling: Call answered, ts=1, flags=0000, data=25
ate=Connected: ACK received, ts=254, flags=0000, data=26
ate=Connected: Statistics received, ts=254, flags=0000, data=0
ate=Connected: Statistics received, ts=254, flags=0000, data=0
=Connected: Statistics received, ts=1, flags=0000, data=0
=Connected: Statistics received, ts=1, flags=0000, data=0
ate=Connected: RTP monitor, ts=254, flags=0000, data=1
ate=Connected: Remote tone detected, ts=254, flags=0000, data=4100
=Connected: RTP monitor, ts=1, flags=0000, data=1
=Connected: RTP monitor, ts=1, flags=0000, data=0
ate=Connected: Statistics received, ts=254, flags=0000, data=0
ate=Connected: Statistics received, ts=254, flags=0000, data=0
=Connected: Statistics received, ts=1, flags=0000, data=0
=Connected: Statistics received, ts=1, flags=0000, data=0
=Connected: RTP monitor, ts=1, flags=0000, data=1
ate=Connected: Statistics received, ts=254, flags=0000, data=0
ate=Connected: Statistics received, ts=254, flags=0000, data=0
=Connected: Statistics received, ts=1, flags=0000, data=0
=Connected: Statistics received, ts=1, flags=0000, data=0
ate=Connected: Statistics received, ts=254, flags=0000, data=0
ate=Connected: Statistics received, ts=254, flags=0000, data=0
=Connected: Statistics received, ts=1, flags=0000, data=0
=Connected: Statistics received, ts=1, flags=0000, data=0
ate=Connected: CAS event, ts=254, flags=0000, data=15
to-scheme":"tel","to-type":"FS01","to-
ate=Idle: Call disconnected, ts=254, flags=0000, data=26
=Connected: Call disconnected, ts=1, flags=0000, data=25
ate=Idle: Message answered 2xx, ts=254, flags=0000, data=26
=Idle: RTP monitor, ts=1, flags=0000, data=0
=Idle: DTMF detected, ts=1, flags=0000, data=15
=Idle: Tone detected, ts=1, flags=0000, data=255

comment:4 by san, 4 years ago

Провели ещё серию экспериментов.

Пробовали звонить на FS01 не с окончания PPS, а с другого телефона, много много раз, баг не воспроизводится. А при вызове с PPS Саша П. умудряется поймать его за минуту.

Записали звук этого гудка(файл ниже приложу) - спектрометр говорит, что это DTMF D.

by san, 4 years ago

Attachment:	gudok.m4a added

follow-up: 6 comment:5 by san, 4 years ago

Эщё один эксперимент.
Вместо FS01 подключил окончание FXS а телефон оператора вынес на PD-04.
В TDM-коммутаторе сделал прослушку того что приходит от платы VE-02.
Баг воспроизвёлся, гудок слышно в динамике, т.е. он приходит из VE-02

in reply to: 5 comment:6 by alx, 4 years ago

Replying to san:

он приходит из VE-02

"из VE-02" - это очень неконкретно. У VE-02 может быть 256 каналов. Уточни, пожалуйста, откуда именно "из VE-02" приходит сигнал.

Last edited 4 years ago by alx (previous) (diff)

follow-up: 8 comment:7 by san, 4 years ago

Уточняю.
Схема соединения была такая

Групповой Канал(с прослушкой)--|-PPS-FXS-|-------PD-04(FS01)---телефон
                               | VE-02   |--->--> EM-04 --> динамик прослушки

После того как из группового канала пришёл DTMF A телефон зазвонил. Когда Саша поднял трубку он услышал в телефоне гудок. В динамике в это время тоже был слышен гудок. В групповом канале гудка не было.

Last edited 4 years ago by san (previous) (diff)

in reply to: 7 comment:8 by alx, 4 years ago

Replying to san:

Уточняю.

Спасибо за уточнение, но из него я, к сожалению, так и не понял, откуда именно был взят сигнал для прослушки на EM-04. Приложи, пожалуйста, конфиг-файл эксперимента. Надеюсь, из него схема эксперимента станет ясна.

follow-up: 11 comment:9 by san, 4 years ago

Попробую словами. Сигнал для динамика прослушки взят из канала TDM соответствующего окончанию FXS платы VE-02, смотри схему.

Я тут ещё один эксперимет провёл. Убрал из схемы групповой канал:
телефон1 - PD-04(FS-01)-->FXS(горячая линия)->PPS1->TDM->PPS2->FS01- телефон2

Телефон1 один поднимает трубку, горячая линия вызывает PPS, телефон2 звонит, телефон2 поднимает трубку и "гудок" воспроизводится .

Учитывая что генерить DTMFD умеет только PPS, подозреваю что это он виноват.
У меня дурацкая гипотеза...А может быть так что этот сигнал DTMF D "застрял" в буффере с прошлого "сеанса связи", который завершился именно таким сигналом. А затем в момент начала нового "сеанса связи" он проигрывается абоненту.

follow-ups: 12 13 14 comment:10 by san, 4 years ago

Алексей, ещё интересная информация.

Если "дальнее" окончание PPS заканчивает сеанс связи сигналом DTMF D, пока ближний абонент ещё не положил трубку, то при следующем "сеансе связи" баг всегда воспроизводится.

in reply to: 9 comment:11 by alx, 4 years ago

Replying to san:

Попробую словами. Сигнал для динамика прослушки взят из канала TDM соответствующего окончанию FXS платы VE-02, смотри схему.

Спасибо за еще одно уточнение, теперь ясно (из схемы в comment:7 этого ясно не было).

Учитывая что генерить DTMFD умеет только PPS, подозреваю что это он виноват.

Это подозрение неправдоподобно сразу по двум причинам.

Во-первых, канальное окончание PPS генерирует сигнал в направлении группового канала, а не в направлении абонента (в сторону IP). Следовательно, генерируемый сигнал должен был бы быть слышен в групповом канале, а не вызываемым абонентом. Мы же имеем обратную картину: сигнал слышит вызываемый абонент, а в групповом канале его не слышно.

Во-вторых, если бы сигнал генерировало канальное окончание, то оно оставило бы следы в логе: в момент окончания генерации сигнала MSP выдает индицирующее этот факт сообщение, при получении которого формируется событие "Tone completed" для соответствующего канального окончания. При его обработке канальное окончание должно было вывести в лог примерно такое сообщение:

pps.cpp:56: ---> ts=1, state=Connected: Tone completed, ts=1, flags=0000, data=15

Однако в логе такого сообщения нет...

На данном этапе, я считаю, что мы исключили из круга подозреваемых телефонный аппарат и плату FS01. Я считаю, что надо двигаться дальше по пути прохождения сигнала. А дальше у нас есть два места:

соединение канальных окончаний FXS и PPS через сеть IP;
соединение канального окончания PPS с групповым каналом (то есть с другим окончанием PPS).

Второе место проверить просто - надо соединить EM-04 с выходом PPS1 (по схеме из comment:9). Это необходимо чтобы удостовериться, что в канале сигнала, действительно, нет. Чтобы посмотреть, что передается в RTP между PPS и FXS, придется разнести их на разные платы VE-02. Или, как вариант, заменить FXS на IP-телефон.

У меня дурацкая гипотеза...А может быть так что этот сигнал DTMF D "застрял" в буффере с прошлого "сеанса связи", который завершился именно таким сигналом. А затем в момент начала нового "сеанса связи" он проигрывается абоненту.

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

    send_TONEGEN(0, 300, 100, 941, 100, 1633, 100);         // DTMF "D"

Что означает "генерировать сигнал 941 Гц уровнем -4 дБм плюс 1633 Гц уровнем -4 дБм в течение 300 мс, затем сгенерировать паузу длительностью 100 мс, затем повторить последовательность 0 раз (то есть последовательность выполняется однократно)".

Ровно таким же способом, например, передается номер вызываемого окончанием FXO. Если бы в MSP был какой-то баг, если бы он мог "залипнуть" генерируя частотную посылку, это было бы замечено в тех же окончаниях FXO, но ничего подобного замечено не было. Поэтому предположение неправдоподобно.

Во-вторых, даже если предположить, что окончание PPS "залипло" генерируя DTMF D при отбое, для того чтобы снова вызвать абонента, оно должно перестать передавать D и передать A, иначе вызываемый не вызовется. Так как он вызывается, мы знаем, что сигнал DTMF A в канал действительно был передан. Предположение о том, что MSP сначала "забыл" выключить DTMF D через 300 мс, затем, получив команду сгенерировать DTMF A, выполнил ее, а потом "вспомнил", что его грубо прервали в процессе генерирования DTMF D и снова возобновил генерирование D - еще более неправдоподобно. :)

Во-третьих, сигнал D при отбое передается окончанием диспетчера, и тогда его должно было быть слышно в групповом канале, но его не слышно (см. пункт 2 выше, который должен этот факт подтвердить).

in reply to: 10 comment:12 by alx, 4 years ago

Replying to san:

Если "дальнее" окончание PPS заканчивает сеанс связи сигналом DTMF D, пока ближний абонент ещё не положил трубку, то при следующем "сеансе связи" баг всегда воспроизводится.

Я верно догадался, что "дальнее" окончание - это окончание, работающее с диспетчером (судя по тому, что оно передает D при отбое)?

in reply to: 10 comment:13 by alx, 4 years ago

Replying to san:

Если "дальнее" окончание PPS заканчивает сеанс связи сигналом DTMF D, пока ближний абонент ещё не положил трубку, то при следующем "сеансе связи" баг всегда воспроизводится.

Это, действительно, очень интересное наблюдение. Так как сторона диспетчера не может знать, положил ли уже трубку оператор или еще нет, то, получается, что мы можем исключить канальное окончание PPS диспетчера (PPS1 по терминологии comment:9). Следовательно, круг подозреваемых сужается до PPS2 и FXS! Логично?

in reply to: 10 comment:14 by alx, 4 years ago

Replying to san:

Если "дальнее" окончание PPS заканчивает сеанс связи сигналом DTMF D, пока ближний абонент ещё не положил трубку, то при следующем "сеансе связи" баг всегда воспроизводится.

Собрал схему, описанную в comment:9, только вместо окончания FS01 с аналоговым телефоном у меня IP-телефон (и еще у меня VE-01, а не VE-02).

Подготовительный вызов:
- поднимаю трубку диспетчера;
- получаю вызов на IP-телефон;
- отвечаю на вызов (никаких посторонних сигналов);
- диспетчер кладет трубку - соединение отбивается.

"Боевой" вызов - делаю все то же самое, что и в п. 1. При ответе на вызов диспетчера опять не слышу никаких посторонних сигналов. Повторял несколько раз с тем же результатом.

То есть в данном эксперименте проблема не воспроизводится. Получается, что окончание PPS в сторону IP никаких сигналов не передает, и его из списка подозреваемых можно исключить. Следовательно, остается единственный подозреваемый - окончание FXS, которое без видимых причин выдает в канал TDM какой-то сигнал... Странный вывод...

Может быть я что-то неверно понял в твоей интересной информации, и мой эксперимент неправильный?

comment:15 by san, 4 years ago

Эксперимент правильный.
Да, подтверждаю, что проблема не воспроизводится, если в роли Оператора ГРС Ip-телефон, а не окончание VE-01.

остается единственный подозреваемый - окончание FXS

согласен

выдает в канал TDM какой-то сигнал

ну не какойто, достоверно известно, что это DTMF D и только тогда, когда он был получен в момент разрыва предыдущего соединения.

comment:16 by alx, 4 years ago

Изменил условия последнего эксперимента.

Напомню схему вчерашнего эксперимента:

==(TDM)==>FXS--(IP)-->PPS==(TDM)==>PPS--(IP)-->телефон

Теперь я собрал такую цепочку:

==(TDM)==>FXS--(IP)-->PPS==(TDM)==>PPS--(IP)-->FXS==(TDM)==>FXO--(IP)-->телефон

На вход цепочки (с левой стороны) из TDM-маппера одновременно подаю 1 кГц и замыкание шлейфа. Вызов проходит по цепочке, звонит телефон. Отвечаю и слышу 1 кГц.
Отбиваю вызов с левой стороны цепочки (размыкаю шлейф диспетчера).

Теперь повторяю тот же эксперимент:

Снова одновременно подаю 1 кГц и замыкание шлейфа со стороны диспетчера.
Снимаю трубку телефона. В трубке тишина. Жду, ничего не делаю. Через 25 секунд после снятия трубки начинаю слышать 1 кГц.

Если отбиться в обратном порядке - сначала положить трубку телефона, а потом разомкнуть шлейф диспетчеру, то при следующем эксперименте задержки нет!

Это очень похоже на то, что было описано, только вместо сигнала DTMF D у меня в телефоне тишина!!!

comment:17 by alx, 4 years ago

В паре очередных воспроизводящих баг экспериментов обнаружил в логе такой фрагмент:

Jun 20 18:07:56 comcerto daemon.info sip_ua[368]: comcerto.cpp:7088: ts 109: RTP destination is 02:ad:c3:00:00:06
Jun 20 18:07:56 comcerto daemon.info sip_ua[368]: pps.cpp:56: ---> ts=109, state=Calling: Call answered, ts=109, flags=0000, data=167
Jun 20 18:07:56 comcerto daemon.info sip_ua[368]: fxs.cpp:431: ---> ts=110, state=Connected: ACK received, ts=110, flags=0000, data=168
Jun 20 18:07:56 comcerto daemon.info sip_ua[368]: fxs.cpp:431: ---> ts=110, state=Connected: Statistics received, ts=110, flags=0000, data=0
Jun 20 18:07:56 comcerto daemon.info sip_ua[368]: fxs.cpp:431: ---> ts=110, state=Connected: Statistics received, ts=110, flags=0000, data=0
Jun 20 18:07:56 comcerto daemon.info sip_ua[368]: pps.cpp:56: ---> ts=109, state=Connected: Statistics received, ts=109, flags=0000, data=0
Jun 20 18:07:56 comcerto daemon.info sip_ua[368]: pps.cpp:56: ---> ts=109, state=Connected: Statistics received, ts=109, flags=0000, data=0
Jun 20 18:07:56 comcerto daemon.info sip_ua[368]: fxs.cpp:431: ---> ts=110, state=Connected: RTP monitor, ts=110, flags=0000, data=1
Jun 20 18:07:56 comcerto daemon.info sip_ua[368]: fxs.cpp:431: ---> ts=110, state=Connected: Remote tone detected, ts=110, flags=0000, data=4100
Jun 20 18:07:56 comcerto daemon.info sip_ua[368]: pps.cpp:56: ---> ts=109, state=Connected: RTP monitor, ts=109, flags=0000, data=1
Jun 20 18:07:56 comcerto daemon.info sip_ua[368]: fxo.cpp:340: ---> ts=111, state=Connected: DTMF detected, ts=111, flags=0000, data=15
Jun 20 18:07:57 comcerto daemon.info sip_ua[368]: fxo.cpp:340: ---> ts=111, state=Connected: Statistics received, ts=111, flags=0000, data=0

Здесь строка "ts=110, state=Connected: Remote tone detected, ts=110, flags=0000, data=4100" говорит о том, что сразу после активации медиапотока канальное окончание FXS получило со стороны IP (то есть от окончания PPS) сигнал DTMF D. Это объясняет, почему оно воспроизвело этот DTMF D в канал TDM.

comment:18 by alx, 4 years ago

Сделал в окончании PPS такую модификацию:

            // Принят сигнал отключения ретрансляторов. Отключаемся от диспетчера.
            state = channelStateInitial;
            hangup();
+           // Пересоздаем соединение
+           createConnection(eVOIP);
            break;
        }
        break;

Суть его в том, что сразу после того как при получении из канала TDM сигнала отключения (DTMF D) канальное окончание выполняет отбой (внутри hangup()) выполняется уничтожение и повторное создание канала в MSP.

После описанной модификации баг воспроизводиться перестал: при ответе в телефоне сразу слышен 1 кГц, в логе нет сообщений о приеме DTMF D ни окончанием FXS со стороны IP, ни окончанием FXO из TDM.

Вывод: Саша, ты гений! :) Похоже, все ровно так: в MSP есть хитрый баг: если на момент выключения медиапотока со стороны TDM приходил DTMF, это каким-то образом запоминается у него в кишках, и когда через какое-то время медиапоток активируется снова, канал продолжает передавать в сторону IP тот старый DTMF. Уничтожение же канала после деактивации медиапотока приводит к тому, что MSP никакого DTMF уже "не помнит" (так как канал создан заново).

Печально, что эта проблема может возникнуть, видимо, у любого канального окончания, которое не уничтожает канал при разъединении.

comment:19 by alx, 4 years ago

Вот такой (менее жестокий) патч тоже помогает:

        if(event->data == 15 && state != channelStateInitial) {
            // Принят сигнал отключения ретрансляторов. Отключаемся от диспетчера.
            state = channelStateInitial;
+           send_DTMFOPT(-1);
            hangup();
            break;
        }

Здесь прежде чем выполнить отбой, выполняется send_DTMFOPT(-1), которая отключает RFC2833 DTMF relay. То есть если MSP в данный момент релеит DTMF из TDM в IP, и ему командуют перестать релеить, то он, очевидно, релеить DTMF прекращает, и когда затем получает команду выключить медиапоток, в его кишках уже не остается следов DTMF, вызывавших баг.

Думаю, что будет вполне безопасно выполнять send_DTMFOPT(-1) перед любым отключением медиапотока.

comment:20 by alx, 4 years ago

Провел уже предлагавшийся мной ранее эксперимент - вынес связку FXS-FXO на другую плату и посмотрел, что окончание PPS передает в RTP при старте медиапотока (непатченный оригинальный код). А вот что:

15:21:43.756815 IP 192.168.1.67.10218 > 192.168.0.127.10004: UDP, length 16
	0x0000:  4500 002c 0000 4000 8011 77ae c0a8 0143
	0x0010:  c0a8 007f 27ea 2714 0018 0c89 80e5 0fd1
	0x0020:  fef5 6a1b 805b 977f 0f81 ffff 0000
15:21:43.776735 IP 192.168.1.67.10218 > 192.168.0.127.10004: UDP, length 16
	0x0000:  4500 002c 0001 4000 8011 77ad c0a8 0143
	0x0010:  c0a8 007f 27ea 2714 0018 0d08 8065 0fd2
	0x0020:  fef5 6a1b 805b 977f 0f81 ffff 0000
15:21:43.795700 IP 192.168.1.67.10218 > 192.168.0.127.10004: UDP, length 16
	0x0000:  4500 002c 0002 4000 8011 77ac c0a8 0143
	0x0010:  c0a8 007f 27ea 2714 0018 0d07 8065 0fd3
	0x0020:  fef5 6a1b 805b 977f 0f81 ffff 0000
15:21:43.795838 IP 192.168.1.67.10218 > 192.168.0.127.10004: UDP, length 172
	0x0000:  4500 00c8 0003 4000 8011 770f c0a8 0143
	0x0010:  c0a8 007f 27ea 2714 00b4 429e 8008 0fd4
	0x0020:  fef9 d9bb 805b 977f 34b4 a1a1 b434 2121
	0x0030:  34b4 a1a1 b434 2121 34b4 a1a1 b434 2121
	0x0040:  34b4 a1a1 b434 2121 34b4 a1a1 b434 2121
	0x0050:  34b4 a1a1 b434 2121 34b4 a1a1 b434 2121
	0x0060:  34b4 a1a1 b434 2121 34b4 a1a1 b434 2121
	0x0070:  34b4 a1a1 b434 2121 34b4 a1a1 b434 2121
	0x0080:  34b4 a1a1 b434 2121 34b4 a1a1 b434 2121
	0x0090:  34b4 a1a1 b434 2121 34b4 a1a1 b434 2121
	0x00a0:  34b4 a1a1 b434 2121 34b4 a1a1 b434 2121
	0x00b0:  34b4 a1a1 b434 2121 34b4 a1a1 b434 2121
	0x00c0:  34b4 a1a1 b434 2121

Здесь мы видим, что медиапоток начинается с трех пакетов с pt=101 (то есть event-пакетов) c событием конец тона "DTMF D", за которыми следуют пакеты с pt=8 (PCMA), в котором ясно виден сигнал 1 кГц.

Если посмотреть на timestamp, то у первых трех пакетов он 0xfef56a1b, а у следующего PCMA пакета - 0xfef9d9bb. Разница таймстампов составляет 36 секунд! То есть это, действительно, пакеты, "унаследованные" от предыдущего сеанса. Длительность тона равна 0xffff, что чуть более 8 секунд - именно такое время в канале и слышен сигнал DTMF.

Если повторить эксперимент с пропатченным PPS, то пакетов c PT101 нет, сразу идут пакеты с PT8.

comment:21 by alx, 4 years ago

Resolution:	→ fixed
Status:	new → closed

In 1751/sip_ua:

Устранен баг, проявлявшийся в случае, когда медиапоток отключали в момент, когда
выполняется релеинг сигнала DTMF (например отбой соединения по приему DTMF из канала TDM).
В этом случае активация медиапотока в следующем сеансе начиналась с передачи RTP end DTMF,
приводившего к генерации ненужного DTMF получатедем медиапотока. Теперь перед отключением
медиапотока выполняется send_DTMFOPT(-1), запрещающая релеинг DTMF. Closes #351.

comment:22 by alx, 4 years ago

In 1752/sip_ua:

Merged from trunk: отключение релеинга DTMF перед отключением медиапотока. See #351.

comment:23 by alx, 4 years ago

Обновления прошивок в репозитории.

Note: See TracTickets for help on using tickets.

Download in other formats: