Opened 4 years ago

Closed 4 years ago

Last modified 4 years ago

#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).

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

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

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

  1. У одного из FS01 настроена горячая линия в соответствующее окончание PPS
  2. При подъёме трубки на телефоне этого 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 =Idle: DTMF detected, ts=1, flags=0000, data=12
Jun 16 05:11:29 comcerto daemon.info sip_ua[451]: pps.cpp:37: ts 1: dialing 51 @10.41.114.152
Jun 16 05:11:29 comcerto daemon.info sip_ua[451]: user_agent.cpp:3509: --> ua_ dial_out() <sip:0@10.41.114.152> -> sip:51@10.41.114.152 ()...
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 =Calling: Incoming call, ts=-1, flags=0001, data=26
Jun 16 05:11:29 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Idle: Incoming call, ts=-1, flags=0001, data=26
Jun 16 05:11:29 comcerto daemon.info sip_ua[451]: fxs.cpp:1023: channel 254: r inging
Jun 16 05:11:29 comcerto daemon.info sip_ua[451]: user_agent.cpp:3940: Call 26 routed to TS 254
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 =Calling: Remote is ringing, ts=1, flags=0000, data=25
Jun 16 05:11:29 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Calling: Message answered 2xx, ts=1, flags=0000, data=25
Jun 16 05:11:29 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Calling: Tone detected, ts=1, flags=0000, data=255
Jun 16 05:11:32 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Ringing: Caller ID sending complete, ts=254, flags=0000, data=0
Jun 16 05:11:35 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Ringing: CAS event, ts=254, flags=0000, data=7
Jun 16 05:11:35 comcerto daemon.info sip_ua[451]: comcerto.cpp:6288: channel 2 54: answer
Jun 16 05:11:35 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Connected: RTP parameters, ts=254, flags=0000, data=26
Jun 16 05:11:35 comcerto daemon.info sip_ua[451]: comcerto.cpp:7058: --> ts 25 4: 10.41.114.152[10508] --> 10.41.114.152[10002]
Jun 16 05:11:35 comcerto daemon.info sip_ua[451]: comcerto.cpp:7059: --> ts 25 4: codec PCMA, VAD is on, red=0
Jun 16 05:11:35 comcerto daemon.info sip_ua[451]: comcerto.cpp:7060: --> audio pt: 8/8, event pt: 101/101, VBD pt: 98/98
Jun 16 05:11:35 comcerto daemon.info sip_ua[451]: comcerto.cpp:7184: ts 254: R TP destination is 02:ad:c5:00:00:75
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 =Calling: RTP parameters, ts=1, flags=0000, data=25
Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: comcerto.cpp:7058: --> ts 1: 10.41.114.152[10002] --> 10.41.114.152[10508]
Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: comcerto.cpp:7059: --> ts 1: codec PCMA, VAD is on, red=0
Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: comcerto.cpp:7060: --> audio pt: 8/8, event pt: 101/101, VBD pt: 98/98
Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: comcerto.cpp:7184: ts 1: RTP destination is 02:ad:c5:00:00:75
Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Calling: Call answered, ts=1, flags=0000, data=25
Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Connected: ACK received, ts=254, flags=0000, data=26
Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Connected: Statistics received, ts=254, flags=0000, data=0
Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Connected: Statistics received, ts=254, flags=0000, data=0
Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Connected: Statistics received, ts=1, flags=0000, data=0
Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Connected: Statistics received, ts=1, flags=0000, data=0
Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Connected: RTP monitor, ts=254, flags=0000, data=1
Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Connected: Remote tone detected, ts=254, flags=0000, data=4100
Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Connected: RTP monitor, ts=1, flags=0000, data=1
Jun 16 05:11:36 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Connected: RTP monitor, ts=1, flags=0000, data=0
Jun 16 05:11:41 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Connected: Statistics received, ts=254, flags=0000, data=0
Jun 16 05:11:41 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Connected: Statistics received, ts=254, flags=0000, data=0
Jun 16 05:11:41 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Connected: Statistics received, ts=1, flags=0000, data=0
Jun 16 05:11:41 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Connected: Statistics received, ts=1, flags=0000, data=0
Jun 16 05:11:44 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Connected: RTP monitor, ts=1, flags=0000, data=1
Jun 16 05:11:46 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Connected: Statistics received, ts=254, flags=0000, data=0
Jun 16 05:11:46 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Connected: Statistics received, ts=254, flags=0000, data=0
Jun 16 05:11:46 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Connected: Statistics received, ts=1, flags=0000, data=0
Jun 16 05:11:46 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Connected: Statistics received, ts=1, flags=0000, data=0
Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Connected: Statistics received, ts=254, flags=0000, data=0
Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Connected: Statistics received, ts=254, flags=0000, data=0
Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Connected: Statistics received, ts=1, flags=0000, data=0
Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Connected: Statistics received, ts=1, flags=0000, data=0
Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Connected: CAS event, ts=254, flags=0000, data=15
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"," to-scheme":"tel","to-type":"FS01","to-
Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Idle: Call disconnected, ts=254, flags=0000, data=26
Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Connected: Call disconnected, ts=1, flags=0000, data=25
Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: fxs.cpp:432: ---> ts=254, st ate=Idle: Message answered 2xx, ts=254, flags=0000, data=26
Jun 16 05:11:51 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Idle: RTP monitor, ts=1, flags=0000, data=0
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=15
Jun 16 05:11:53 comcerto daemon.info sip_ua[451]: pps.cpp:56: ---> ts=1, state =Idle: Tone detected, ts=1, flags=0000, data=255

comment:4 by san, 4 years ago

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

  1. Пробовали звонить на FS01 не с окончания PPS, а с другого телефона, много много раз, баг не воспроизводится. А при вызове с PPS Саша П. умудряется поймать его за минуту.
  1. Записали звук этого гудка(файл ниже приложу) - спектрометр говорит, что это DTMF D.

by san, 4 years ago

Attachment: gudok.m4a added

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)

comment:7 by san, 4 years ago

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

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

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

Version 0, edited 4 years ago by san (next)

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

Replying to san:

Уточняю.

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

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 "застрял" в буффере с прошлого "сеанса связи", который завершился именно таким сигналом. А затем в момент начала нового "сеанса связи" он проигрывается абоненту.

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. Я считаю, что надо двигаться дальше по пути прохождения сигнала. А дальше у нас есть два места:

  1. соединение канальных окончаний FXS и PPS через сеть IP;
  2. соединение канального окончания 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).

  1. Подготовительный вызов:
    • поднимаю трубку диспетчера;
    • получаю вызов на IP-телефон;
    • отвечаю на вызов (никаких посторонних сигналов);
    • диспетчер кладет трубку - соединение отбивается.
  1. "Боевой" вызов - делаю все то же самое, что и в п. 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: newclosed

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.