Context Navigation

← Previous Ticket
Next Ticket →

#254 closed баг (fixed)

Не работает Call transfer для "исходящего" вызова

Reported by:	san	Owned by:	alx
Priority:	высокий	Milestone:	1 очередь
Component:	VE-01	Keywords:
Cc:	artem, andrei

Description

Андрей обнаружил в АТС-АДС странное поведение:

С IP телефона T1 вызываем внешний номер через окончание FXO
Установлено соединение
C T1 делаем транзит вызова на IP телефон T2
На T2 поднимаем трубку
В результате Т2 считает что соединён с FxO, а на стороне FxO соединение разорвано и окончание свободно.

Attachments (1)

log1.log (17.8 KB ) - added by alx 7 years ago.: Лог tcpdump на внешней интерфейсе платы

Download all attachments as: .zip

Change History (17)

comment:1 by artem, 7 years ago

раньше вроде это не проверяли.

comment:2 by alx, 7 years ago

В процессе воспроизведения описанного процесса в логе платы VE-01 появляется такая строка:

Nov  7 10:47:45 comcerto daemon.warn sip_ua[363]: comcerto.cpp:6902: 0.0.0.0: host is down

Это значит, что по неизвестной пока причине плата VE-01 хочет передавать поток RTP на адрес 0.0.0.0. Очевидно, что такого быть не должно. Буду искать причину.

comment:3 by san, 7 years ago

Cc:	andrei added; andrey removed

follow-up: 5 comment:4 by andrei, 7 years ago

С Т1 вызываем FXS.
Установлено соединение.
С Т1 делаем транзит на Т2, не общаясь с ним.
У Т2 все нормально, приходит звук от FXS. У FXS длинные гудки.

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

Replying to andrei:

У Т2 все нормально, приходит звук от FXS. У FXS длинные гудки.

??? Как этот комментарий связан с описанным в тикете багом?

by alx, 7 years ago

Attachment:	log1.log added

Лог tcpdump на внешней интерфейсе платы

comment:6 by alx, 7 years ago

Воспроизвел баг, посмотрел обмен между платой и телефонами. Вроде бы ничего криминального нет...

comment:7 by alx, 7 years ago

Подробный лог платы:

Nov  7 13:39:51 comcerto daemon.info sip_ua[598]: repro.cpp:434: doSessionAccounting(): Session Created 'branch=z9hG4bK1079308415'
Nov  7 13:39:51 comcerto daemon.info sip_ua[569]: user_agent.cpp:1688: INVITE received: sip:89991156047@127.0.0.1:6060;transport=udp (Call-ID: 1607428044-11520-13@BJC.BGI.A.BBI)
Nov  7 13:39:51 comcerto daemon.info sip_ua[545]: fxs.cpp:419: ---> ts=1, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 13:39:51 comcerto daemon.info sip_ua[545]: fxs.cpp:419: ---> ts=2, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 13:39:51 comcerto daemon.info sip_ua[545]: fxs.cpp:419: ---> ts=3, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 13:39:51 comcerto daemon.info sip_ua[545]: fxs.cpp:419: ---> ts=4, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 13:39:51 comcerto daemon.info sip_ua[545]: fxs.cpp:419: ---> ts=5, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 13:39:51 comcerto daemon.info sip_ua[545]: fxs.cpp:419: ---> ts=6, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 13:39:51 comcerto daemon.info sip_ua[545]: fxs.cpp:419: ---> ts=7, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 13:39:51 comcerto daemon.info sip_ua[545]: fxs.cpp:419: ---> ts=8, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 13:39:51 comcerto daemon.info sip_ua[545]: fxs.cpp:419: ---> ts=9, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 13:39:51 comcerto daemon.info sip_ua[545]: fxs.cpp:419: ---> ts=10, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 13:39:56 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Call Progress detected, ts=33, flags=0000, data=50
Nov  7 13:39:56 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 13:39:58 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 13:39:59 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 13:39:59 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 13:39:59 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 13:39:59 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 13:39:59 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 13:39:59 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 13:39:59 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 13:40:00 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 13:40:00 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 13:40:00 comcerto daemon.info sip_ua[545]: comcerto.cpp:5658: channel 33: answer
Nov  7 13:40:00 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: RTP parameters, ts=33, flags=0000, data=1
Nov  7 13:40:00 comcerto daemon.info sip_ua[545]: comcerto.cpp:6473: --> ts 33: 192.168.0.4[10066] --> 192.168.0.118[31110]
Nov  7 13:40:00 comcerto daemon.info sip_ua[545]: comcerto.cpp:6474: --> ts 33: codec PCMU, VAD is off
Nov  7 13:40:00 comcerto daemon.info sip_ua[545]: comcerto.cpp:6475: --> audio pt: 0/0, event pt: 101/101, VBD pt: -1/-1
Nov  7 13:40:00 comcerto daemon.info sip_ua[545]: comcerto.cpp:6590: ts 33: starting RTP stream to 00:0b:82:53:b7:15
Nov  7 13:40:00 comcerto daemon.info sip_ua[598]: repro.cpp:577: doSessionAccounting(): Session Established 'branch=z9hG4bK1079308415'
Nov  7 13:40:00 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 13:40:00 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 13:40:00 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: ACK received, ts=33, flags=0000, data=1
Nov  7 13:40:05 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 13:40:05 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 13:40:10 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 13:40:10 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 13:40:15 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 13:40:15 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 13:40:17 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: RTP parameters, ts=33, flags=0000, data=1
Nov  7 13:40:17 comcerto daemon.info sip_ua[545]: comcerto.cpp:6473: --> ts 33: 192.168.0.4[10066] --> 0.0.0.0[31110]
Nov  7 13:40:17 comcerto daemon.info sip_ua[545]: comcerto.cpp:6474: --> ts 33: codec PCMU, VAD is off
Nov  7 13:40:17 comcerto daemon.info sip_ua[545]: comcerto.cpp:6475: --> audio pt: 0/0, event pt: 101/101, VBD pt: -1/-1
Nov  7 13:40:17 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: ACK received, ts=33, flags=0000, data=1
Nov  7 13:40:21 comcerto daemon.info sip_ua[569]: user_agent.cpp:2361: ---> REFER in call received
Nov  7 13:40:21 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: REFER received, ts=33, flags=0000, data=1
Nov  7 13:40:21 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Message answered 2xx, ts=33, flags=0000, data=1
Nov  7 13:40:21 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Replace call, ts=33, flags=0000, data=1
Nov  7 13:40:21 comcerto daemon.info sip_ua[598]: repro.cpp:434: doSessionAccounting(): Session Created 'branch=z9hG4bK905291496'
Nov  7 13:40:21 comcerto daemon.warn sip_ua[545]: comcerto.cpp:6902: 0.0.0.0: host is down
Nov  7 13:40:21 comcerto daemon.info sip_ua[569]: user_agent.cpp:1833: ---> ringing with status code 180
Nov  7 13:40:21 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Remote is ringing, ts=33, flags=0000, data=3
Nov  7 13:40:25 comcerto daemon.info sip_ua[598]: repro.cpp:577: doSessionAccounting(): Session Established 'branch=z9hG4bK905291496'
Nov  7 13:40:25 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: RTP parameters, ts=33, flags=0000, data=3
Nov  7 13:40:25 comcerto daemon.info sip_ua[545]: comcerto.cpp:6473: --> ts 33: 192.168.0.4[10066] --> 192.168.0.105[11824]
Nov  7 13:40:25 comcerto daemon.info sip_ua[545]: comcerto.cpp:6474: --> ts 33: codec PCMA, VAD is off
Nov  7 13:40:25 comcerto daemon.info sip_ua[545]: comcerto.cpp:6475: --> audio pt: 8/8, event pt: 101/101, VBD pt: -1/-1
Nov  7 13:40:25 comcerto daemon.info sip_ua[545]: comcerto.cpp:6590: ts 33: starting RTP stream to 00:15:65:a3:cf:58
Nov  7 13:40:25 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Call answered, ts=33, flags=0000, data=3
Nov  7 13:40:25 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 13:40:25 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 13:40:25 comcerto daemon.info sip_ua[598]: repro.cpp:515: doSessionAccounting(): Session Ended 'branch=z9hG4bK168211039'
Nov  7 13:40:25 comcerto daemon.info sip_ua[598]: repro.cpp:533: --> duration=25, []sip:505@192.168.0.4: ---> [FXO]tel:89991156047@192.168.0.4:
Nov  7 13:40:25 comcerto daemon.info sip_ua[598]: repro.cpp:667: --> CDR: {"answer":1510062000,"duration":25,"hangup":1510062025,"org-host":"192.168.0.4","org-name":"Alex Mogilnikov","org-scheme":"sip","org-user":"505","to-host":"192.168.0.4","to-scheme":"tel","to-type":"
Nov  7 13:40:25 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Message answered 2xx, ts=33, flags=0000, data=1
Nov  7 13:40:25 comcerto daemon.info sip_ua[569]: user_agent.cpp:2361: ---> BYE in call received
Nov  7 13:40:25 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Connected: Call disconnected, ts=33, flags=0000, data=1
Nov  7 13:40:35 comcerto daemon.info sip_ua[598]: repro.cpp:515: doSessionAccounting(): Session Ended 'branch=z9hG4bK1117647536'
Nov  7 13:40:35 comcerto daemon.info sip_ua[598]: repro.cpp:533: --> duration=10, [FXO]tel:fxo1@192.168.0.4: ---> []sip:527@192.168.0.4:
Nov  7 13:40:35 comcerto daemon.info sip_ua[598]: repro.cpp:667: --> CDR: {"answer":1510062025,"duration":10,"hangup":1510062035,"org-host":"192.168.0.4","org-name":"АТС1","org-scheme":"tel","org-type":"FXO","org-user":"fxo1","to-host":"192.168.0.4","to-scheme":"sip","
Nov  7 13:40:35 comcerto daemon.info sip_ua[569]: user_agent.cpp:2361: ---> BYE in call received
Nov  7 13:40:35 comcerto daemon.info sip_ua[545]: fxo.cpp:318: ---> ts=33, state=Idle: Call disconnected, ts=33, flags=0000, data=3

comment:8 by alx, 7 years ago

Из приведенного лога видно, что в 13:40:17 канальное окончание FXO пытается инициировать поток RTP на удаленный адрес 0.0.0.0. Это происходит еще до начала трансфера вызова (сообщение REFER приходит только в 13:40:21, 4 секундами позже). Сообщение 0.0.0.0: host is down появляется в то же время, что и выполнение трансфера случайно - было сделано 10 попыток отправки запроса ARP для адреса 0.0.0.0 с ожиданием ответа 300 мс после каждой из них.

Как видно из вывода tcpdump'а, телефон действительно присылает REINVITE с адресом 0.0.0.0 и атрибутом a=sendonly. Очевидно, это постановка соединения на холд. Зачем телефон присылает такой адрес - вопрос к телефону, для нашей проблемы это ложный след. Само по себе неполучение ответа на запрос ARP не должно приводить к отбою. Надо исследовать дальше.

comment:9 by alx, 7 years ago

Предположительно причина проблемы найдена: после завершения трансфера T1 разрывает старое соединение с FXO. В результате канальному окончанию FXO приходит событие Call disconnected, но канальное окончание не проверяет идентификатор соединения в этом сообщении, и думает, что это отбили текущее (то есть новое) соединение с T2.

comment:10 by alx, 7 years ago

После добавления проверки идентификатора соединения баг воспроизводиться перестал. Вот лог успешного трансфера:

Nov  7 14:17:13 comcerto daemon.info sip_ua[708]: repro.cpp:434: doSessionAccounting(): Session Created 'branch=z9hG4bK2064462072'
Nov  7 14:17:14 comcerto daemon.info sip_ua[652]: user_agent.cpp:1688: INVITE received: sip:89991156047@127.0.0.1:6060;transport=udp (Call-ID: 1870545020-11520-14@BJC.BGI.A.BBI)
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=1, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=2, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=3, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=4, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=5, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=6, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=7, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=8, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=9, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=10, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=11, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=14, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=15, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=17, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=29, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=34, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=35, state=Idle: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: virtualChannel.cpp:125: ---> VirtualChannelManager: Incoming call, ts=-1, flags=0001, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=1, state=Idle: Incoming call, ts=-1, flags=0002, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=2, state=Idle: Incoming call, ts=-1, flags=0002, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=3, state=Idle: Incoming call, ts=-1, flags=0002, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=10, state=Idle: Incoming call, ts=-1, flags=0002, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=11, state=Idle: Incoming call, ts=-1, flags=0002, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=13, state=Idle: Incoming call, ts=-1, flags=0002, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=14, state=Idle: Incoming call, ts=-1, flags=0002, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=15, state=Idle: Incoming call, ts=-1, flags=0002, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=17, state=Idle: Incoming call, ts=-1, flags=0002, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxs.cpp:419: ---> ts=29, state=Idle: Incoming call, ts=-1, flags=0002, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Idle: Incoming call, ts=-1, flags=0002, data=1
Nov  7 14:17:14 comcerto daemon.info sip_ua[628]: user_agent.cpp:3075: Call 1 routed to TS 33
Nov  7 14:17:18 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Call Progress detected, ts=33, flags=0000, data=50
Nov  7 14:17:19 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 14:17:21 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 14:17:21 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 14:17:21 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Call Progress detected, ts=33, flags=0000, data=53
Nov  7 14:17:21 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 14:17:21 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 14:17:21 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 14:17:21 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 14:17:22 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 14:17:22 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 14:17:22 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 14:17:22 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Tone completed, ts=33, flags=0000, data=0
Nov  7 14:17:22 comcerto daemon.info sip_ua[628]: comcerto.cpp:5658: channel 33: answer
Nov  7 14:17:22 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: RTP parameters, ts=33, flags=0000, data=1
Nov  7 14:17:22 comcerto daemon.info sip_ua[628]: comcerto.cpp:6476: --> ts 33: 192.168.0.4[10066] --> 192.168.0.118[17994]
Nov  7 14:17:22 comcerto daemon.info sip_ua[628]: comcerto.cpp:6477: --> ts 33: codec PCMU, VAD is off
Nov  7 14:17:22 comcerto daemon.info sip_ua[628]: comcerto.cpp:6478: --> audio pt: 0/0, event pt: 101/101, VBD pt: -1/-1
Nov  7 14:17:22 comcerto daemon.info sip_ua[628]: comcerto.cpp:6593: ts 33: starting RTP stream to 00:0b:82:53:b7:15
Nov  7 14:17:22 comcerto daemon.info sip_ua[708]: repro.cpp:577: doSessionAccounting(): Session Established 'branch=z9hG4bK2064462072'
Nov  7 14:17:22 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:17:22 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:17:22 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: ACK received, ts=33, flags=0000, data=1
Nov  7 14:17:27 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:17:27 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:17:32 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:17:32 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:17:37 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:17:37 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:17:41 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: RTP parameters, ts=33, flags=0000, data=1
Nov  7 14:17:41 comcerto daemon.info sip_ua[628]: comcerto.cpp:6476: --> ts 33: 192.168.0.4[10066] --> 0.0.0.0[17994]
Nov  7 14:17:41 comcerto daemon.info sip_ua[628]: comcerto.cpp:6477: --> ts 33: codec PCMU, VAD is off
Nov  7 14:17:41 comcerto daemon.info sip_ua[628]: comcerto.cpp:6478: --> audio pt: 0/0, event pt: 101/101, VBD pt: -1/-1
Nov  7 14:17:42 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: ACK received, ts=33, flags=0000, data=1
Nov  7 14:17:45 comcerto daemon.warn sip_ua[628]: comcerto.cpp:6905: 0.0.0.0: host is down
Nov  7 14:17:45 comcerto daemon.info sip_ua[652]: user_agent.cpp:2361: ---> REFER in call received
Nov  7 14:17:45 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: REFER received, ts=33, flags=0000, data=1
Nov  7 14:17:45 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Message answered 2xx, ts=33, flags=0000, data=1
Nov  7 14:17:45 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Replace call, ts=33, flags=0000, data=1
Nov  7 14:17:45 comcerto daemon.info sip_ua[708]: repro.cpp:434: doSessionAccounting(): Session Created 'branch=z9hG4bK1129089271'
Nov  7 14:17:45 comcerto daemon.info sip_ua[652]: user_agent.cpp:1833: ---> ringing with status code 180
Nov  7 14:17:45 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Remote is ringing, ts=33, flags=0000, data=3
Nov  7 14:17:52 comcerto daemon.info sip_ua[708]: repro.cpp:577: doSessionAccounting(): Session Established 'branch=z9hG4bK1129089271'
Nov  7 14:17:52 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: RTP parameters, ts=33, flags=0000, data=3
Nov  7 14:17:52 comcerto daemon.info sip_ua[628]: comcerto.cpp:6476: --> ts 33: 192.168.0.4[10066] --> 192.168.0.105[11828]
Nov  7 14:17:52 comcerto daemon.info sip_ua[628]: comcerto.cpp:6477: --> ts 33: codec PCMA, VAD is off
Nov  7 14:17:52 comcerto daemon.info sip_ua[628]: comcerto.cpp:6478: --> audio pt: 8/8, event pt: 101/101, VBD pt: -1/-1
Nov  7 14:17:52 comcerto daemon.info sip_ua[628]: comcerto.cpp:6593: ts 33: starting RTP stream to 00:15:65:a3:cf:58
Nov  7 14:17:52 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Call answered, ts=33, flags=0000, data=3
Nov  7 14:17:52 comcerto daemon.info sip_ua[708]: repro.cpp:515: doSessionAccounting(): Session Ended 'branch=z9hG4bK1569726320'
Nov  7 14:17:52 comcerto daemon.info sip_ua[708]: repro.cpp:533: --> duration=30, []sip:505@192.168.0.4: ---> [FXO]tel:89991156047@192.168.0.4:
Nov  7 14:17:52 comcerto daemon.info sip_ua[708]: repro.cpp:700: --> CDR: {"answer":1510064242,"duration":30,"hangup":1510064272,"org-host":"192.168.0.4","org-name":"Alex Mogilnikov","org-scheme":"sip","org-user":"505","to-host":"192.168.0.4","to-scheme":"tel","to-type":"
Nov  7 14:17:52 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:17:52 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:17:52 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Message answered 2xx, ts=33, flags=0000, data=1
Nov  7 14:17:52 comcerto daemon.info sip_ua[652]: user_agent.cpp:2361: ---> BYE in call received
Nov  7 14:17:52 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Call disconnected, ts=33, flags=0000, data=1
Nov  7 14:17:57 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:17:57 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:18:02 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:18:02 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:18:04 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Call Progress detected, ts=33, flags=0000, data=53
Nov  7 14:18:07 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:18:07 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:18:12 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:18:12 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:18:17 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:18:17 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:18:22 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:18:22 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Statistics received, ts=33, flags=0000, data=0
Nov  7 14:18:22 comcerto daemon.info sip_ua[708]: repro.cpp:515: doSessionAccounting(): Session Ended 'branch=z9hG4bK4209551795'
Nov  7 14:18:22 comcerto daemon.info sip_ua[708]: repro.cpp:533: --> duration=30, [FXO]tel:fxo1@192.168.0.4: ---> []sip:527@192.168.0.4:
Nov  7 14:18:22 comcerto daemon.info sip_ua[708]: repro.cpp:700: --> CDR: {"answer":1510064272,"duration":30,"hangup":1510064302,"org-host":"192.168.0.4","org-name":"АТС1","org-scheme":"tel","org-type":"FXO","org-user":"fxo1","to-host":"192.168.0.4","to-scheme":"sip","
Nov  7 14:18:22 comcerto daemon.info sip_ua[652]: user_agent.cpp:2361: ---> BYE in call received
Nov  7 14:18:22 comcerto daemon.info sip_ua[628]: fxo.cpp:318: ---> ts=33, state=Connected: Call disconnected, ts=33, flags=0000, data=3

comment:11 by alx, 7 years ago

Беглый просмотр кода показал, что подобная проверка отсутствует и в некоторых других канальных окончаниях, например r1.5. Надо исправлять.

Version 0, edited 7 years ago by alx (next)

comment:12 by andrei, 7 years ago

У меня работает правильно.

in reply to: description comment:13 by alx, 7 years ago

Replying to san:

Андрей обнаружил в АТС-АДС странное поведение:

С IP телефона T1 вызываем внешний номер через окончание FXO
Установлено соединение
C T1 делаем транзит вызова на IP телефон T2
На T2 поднимаем трубку
В результате Т2 считает что соединён с FxO, а на стороне FxO соединение разорвано и окончание свободно.

Забыл позанудствовать. :) А где в описанном сценарии переадресация? Переадресация - это Call Forward. Не надо ее путать с Call Transfer!

comment:14 by alx, 7 years ago

Саша, исправь, пожалуйста, краткое описание, чтобы оно отражало суть проблемы. А то потом будет находиться поиском не по делу, а по делу - не находиться...

comment:15 by alx, 7 years ago

Resolution:	→ fixed
Status:	new → closed

In 1337/sip_ua:

Исправлена ошибка: канальные окончания FXO, SS7, PRI и R1.5 не проверяли
идентификатор соединения при получении сообщения eDisconnectEvent, в результате
чего после трансфера соединения сообщение об отбое старого соединения
могло быть воспринято как отбой текущего, что приводило к одностороннему
переходу канального окончания в исходное состояние. Closes #254.

comment:16 by san, 7 years ago

Summary:	Проблема с переадресацией "исходящего" вызова → Не работает Call transfer для "исходящего" вызова

Note: See TracTickets for help on using tickets.

Download in other formats: