Одновременный ответ двух членов группы вызова

[alx]

На нашей АТС сконфигурирована группа вызова 803 с тремя абонентами: 122, 123 и 124. На окончание FXO поступил вызывной сигнал, в результате которого была вызвана группа 803. Абоненты 122 и 123 сняли трубки почти одновременно.

В результате никто ничего не слышал. Предположительная причина - в момент ответа оба ответивших канала получили событие RTPparams и сконфигурировали себе RTP поток на один и тот же адрес/порт. Ранее уже было обнаружено, что в такой ситуации каналы "не видят" входящий RTP поток.

Вот лог:

Nov 10 10:08:03 sip_ua[513]: fxo.cpp:338: ---> ts=35, state=Idle: CAS event, ts=35, flags=0000, data=7
Nov 10 10:08:04 sip_ua[513]: fxo.cpp:338: ---> ts=35, state=Ringing: CAS event, ts=35, flags=0000, data=15
Nov 10 10:08:08 sip_ua[513]: fxo.cpp:338: ---> ts=35, state=Ringing: CAS event, ts=35, flags=0000, data=7
Nov 10 10:08:08 sip_ua[513]: fxo.cpp:296: ts 35: dialing 803@192.168.0.4
Nov 10 10:08:08 sip_ua[513]: user_agent.cpp:2477: --> ua_dial_out() "223-21-05" <sip:fxo3@192.168.0.4> -> sip:803@192.168.0.4 ()...
Nov 10 10:08:09 sip_ua[535]: user_agent.cpp:1488: INVITE received: sip:122@127.0.0.1:6060;transport=udp (Call-ID: 1074267781@(null))
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=1, state=Idle: Incoming call, ts=-1, flags=0001, data=4
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=2, state=Idle: Incoming call, ts=-1, flags=0001, data=4
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=3, state=Idle: Incoming call, ts=-1, flags=0001, data=4
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=4, state=Idle: Incoming call, ts=-1, flags=0001, data=4
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=5, state=Idle: Incoming call, ts=-1, flags=0001, data=4
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=6, state=Idle: Incoming call, ts=-1, flags=0001, data=4
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=7, state=Idle: Incoming call, ts=-1, flags=0001, data=4
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=8, state=Idle: Incoming call, ts=-1, flags=0001, data=4
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=9, state=Idle: Incoming call, ts=-1, flags=0001, data=4
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=10, state=Idle: Incoming call, ts=-1, flags=0001, data=4
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=11, state=Idle: Incoming call, ts=-1, flags=0001, data=4
Nov 10 10:08:09 sip_ua[535]: user_agent.cpp:1488: INVITE received: sip:123@127.0.0.1:6060;transport=udp (Call-ID: 1074267781@(null))
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:909: channel 14: ringing
Nov 10 10:08:09 sip_ua[513]: user_agent.cpp:2828: Call 4 routed to TS 14
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=1, state=Idle: Incoming call, ts=-1, flags=0001, data=6
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=2, state=Idle: Incoming call, ts=-1, flags=0001, data=6
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=3, state=Idle: Incoming call, ts=-1, flags=0001, data=6
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=4, state=Idle: Incoming call, ts=-1, flags=0001, data=6
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=5, state=Idle: Incoming call, ts=-1, flags=0001, data=6
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=6, state=Idle: Incoming call, ts=-1, flags=0001, data=6
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=7, state=Idle: Incoming call, ts=-1, flags=0001, data=6
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=8, state=Idle: Incoming call, ts=-1, flags=0001, data=6
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=9, state=Idle: Incoming call, ts=-1, flags=0001, data=6
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=10, state=Idle: Incoming call, ts=-1, flags=0001, data=6
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=11, state=Idle: Incoming call, ts=-1, flags=0001, data=6
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=13, state=Idle: Incoming call, ts=-1, flags=0001, data=6
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=14, state=Ringing: Incoming call, ts=-1, flags=0001, data=6
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=15, state=Idle: Incoming call, ts=-1, flags=0001, data=6
Nov 10 10:08:09 sip_ua[535]: user_agent.cpp:1488: INVITE received: sip:324@127.0.0.1:6060;transport=udp (Call-ID: 1074267781@(null))
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:909: channel 15: ringing
Nov 10 10:08:09 sip_ua[535]: user_agent.cpp:1615: ---> ringing with status code 180
Nov 10 10:08:09 sip_ua[513]: user_agent.cpp:2828: Call 6 routed to TS 15
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=1, state=Idle: Incoming call, ts=-1, flags=0001, data=8
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=2, state=Idle: Incoming call, ts=-1, flags=0001, data=8
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=3, state=Idle: Incoming call, ts=-1, flags=0001, data=8
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=4, state=Idle: Incoming call, ts=-1, flags=0001, data=8
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=5, state=Idle: Incoming call, ts=-1, flags=0001, data=8
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=6, state=Idle: Incoming call, ts=-1, flags=0001, data=8
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=7, state=Idle: Incoming call, ts=-1, flags=0001, data=8
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=8, state=Idle: Incoming call, ts=-1, flags=0001, data=8
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=9, state=Idle: Incoming call, ts=-1, flags=0001, data=8
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=10, state=Idle: Incoming call, ts=-1, flags=0001, data=8
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:407: ---> ts=11, state=Idle: Incoming call, ts=-1, flags=0001, data=8
Nov 10 10:08:09 sip_ua[513]: fxs.cpp:909: channel 17: ringing
Nov 10 10:08:09 sip_ua[513]: user_agent.cpp:2828: Call 8 routed to TS 17
Nov 10 10:08:09 sip_ua[513]: fxo.cpp:338: ---> ts=35, state=Calling: Remote is ringing, ts=35, flags=0000, data=3
Nov 10 10:08:09 sip_ua[535]: user_agent.cpp:1615: ---> ringing with status code 180
Nov 10 10:08:09 sip_ua[513]: fxo.cpp:338: ---> ts=35, state=Calling: Remote is ringing, ts=35, flags=0000, data=3
Nov 10 10:08:09 sip_ua[513]: fxo.cpp:338: ---> ts=35, state=Calling: CAS event, ts=35, flags=0000, data=15
Nov 10 10:08:09 sip_ua[535]: user_agent.cpp:1615: ---> ringing with status code 180
Nov 10 10:08:09 sip_ua[513]: fxo.cpp:338: ---> ts=35, state=Calling: Remote is ringing, ts=35, flags=0000, data=3
Nov 10 10:08:12 sip_ua[513]: fxs.cpp:407: ---> ts=14, state=Ringing: CAS event, ts=14, flags=0000, data=7
Nov 10 10:08:12 sip_ua[513]: comcerto.cpp:3779: channel 14: answer
Nov 10 10:08:12 sip_ua[513]: fxs.cpp:407: ---> ts=14, state=Connected: RTP parameters, ts=14, flags=0000, data=4
Nov 10 10:08:12 sip_ua[513]: comcerto.cpp:4553: --> ts 14: 192.168.0.4[10028] --> 192.168.0.4[10070]
Nov 10 10:08:12 sip_ua[513]: comcerto.cpp:4554: --> ts 14: codec PCMA, VAD is off
Nov 10 10:08:12 sip_ua[513]: comcerto.cpp:4555: --> audio pt: 8/8, event pt: 101/101, VBD pt: 98/98
Nov 10 10:08:12 sip_ua[513]: comcerto.cpp:4655: ts 14: starting RTP stream to 02:ad:c3:00:00:b4
Nov 10 10:08:12 sip_ua[513]: fxs.cpp:407: ---> ts=15, state=Ringing: CAS event, ts=15, flags=0000, data=7
Nov 10 10:08:12 sip_ua[513]: comcerto.cpp:3779: channel 15: answer
Nov 10 10:08:12 sip_ua[513]: fxs.cpp:407: ---> ts=15, state=Connected: RTP parameters, ts=15, flags=0000, data=6
Nov 10 10:08:12 sip_ua[513]: comcerto.cpp:4553: --> ts 15: 192.168.0.4[10030] --> 192.168.0.4[10070]
Nov 10 10:08:12 sip_ua[513]: comcerto.cpp:4554: --> ts 15: codec PCMA, VAD is off
Nov 10 10:08:12 sip_ua[513]: comcerto.cpp:4555: --> audio pt: 8/8, event pt: 101/101, VBD pt: 98/98
Nov 10 10:08:12 sip_ua[513]: comcerto.cpp:4655: ts 15: starting RTP stream to 02:ad:c3:00:00:b4
Nov 10 10:08:13 sip_ua[513]: fxs.cpp:407: ---> ts=14, state=Connected: Statistics received, ts=14, flags=0000, data=0
Nov 10 10:08:13 sip_ua[513]: fxs.cpp:407: ---> ts=14, state=Connected: Statistics received, ts=14, flags=0000, data=0
Nov 10 10:08:13 sip_ua[513]: fxs.cpp:407: ---> ts=15, state=Connected: Statistics received, ts=15, flags=0000, data=0
Nov 10 10:08:13 sip_ua[513]: fxs.cpp:407: ---> ts=15, state=Connected: Statistics received, ts=15, flags=0000, data=0
Nov 10 10:08:13 sip_ua[513]: fxo.cpp:338: ---> ts=35, state=Calling: RTP parameters, ts=35, flags=0000, data=3
Nov 10 10:08:13 sip_ua[513]: comcerto.cpp:4553: --> ts 35: 192.168.0.4[10070] --> 192.168.0.4[10028]
Nov 10 10:08:13 sip_ua[513]: comcerto.cpp:4554: --> ts 35: codec PCMA, VAD is off
Nov 10 10:08:13 sip_ua[513]: comcerto.cpp:4555: --> audio pt: 8/8, event pt: 101/101, VBD pt: 98/98
Nov 10 10:08:13 sip_ua[513]: comcerto.cpp:4655: ts 35: starting RTP stream to 02:ad:c3:00:00:b4
Nov 10 10:08:13 sip_ua[513]: fxo.cpp:338: ---> ts=35, state=Calling: Statistics received, ts=35, flags=0000, data=0
Nov 10 10:08:13 sip_ua[513]: fxo.cpp:338: ---> ts=35, state=Calling: Statistics received, ts=35, flags=0000, data=0
Nov 10 10:08:13 sip_ua[513]: fxo.cpp:338: ---> ts=35, state=Calling: Call answered, ts=35, flags=0000, data=3
Nov 10 10:08:13 sip_ua[513]: fxs.cpp:407: ---> ts=17, state=Ringing: Call disconnected, ts=17, flags=0000, data=8
Nov 10 10:08:13 sip_ua[602]: repro.cpp:510: --> duration=1478772493, []:@: ---> []:@:
Nov 10 10:08:13 sip_ua[602]: repro.cpp:556: --> CDR: {"answer":0,"duration":1478772493,"hangup":1478772493,"org-host":"","org-scheme":"","org-user":"","to-host":"","to-scheme":"","to-user":"","type":""}
Nov 10 10:08:13 sip_ua[513]: fxs.cpp:407: ---> ts=17, state=Idle: Call disconnected, ts=17, flags=0000, data=8
Nov 10 10:08:13 sip_ua[602]: repro.cpp:510: --> duration=1478772493, []:@: ---> []:@:
Nov 10 10:08:13 sip_ua[602]: repro.cpp:556: --> CDR: {"answer":0,"duration":1478772493,"hangup":1478772493,"org-host":"","org-scheme":"","org-user":"","to-host":"","to-scheme":"","to-user":"","type":""}
Nov 10 10:08:14 sip_ua[602]: repro.cpp:510: --> duration=1478772494, []:@: ---> []:@:
Nov 10 10:08:14 sip_ua[602]: repro.cpp:556: --> CDR: {"answer":0,"duration":1478772494,"hangup":1478772494,"org-host":"","org-scheme":"","org-user":"","to-host":"","to-scheme":"","to-user":"","type":""}
Nov 10 10:08:15 sip_ua[602]: repro.cpp:510: --> duration=1478772494, []:@: ---> []:@:
Nov 10 10:08:15 sip_ua[602]: repro.cpp:556: --> CDR: {"answer":0,"duration":1478772494,"hangup":1478772494,"org-host":"","org-scheme":"","org-user":"","to-host":"","to-scheme":"","to-user":"","type":""}
Nov 10 10:08:16 sip_ua[602]: repro.cpp:510: --> duration=1478772496, []:@: ---> []:@:
Nov 10 10:08:16 sip_ua[602]: repro.cpp:556: --> CDR: {"answer":0,"duration":1478772496,"hangup":1478772496,"org-host":"","org-scheme":"","org-user":"","to-host":"","to-scheme":"","to-user":"","type":""}
Nov 10 10:08:16 sip_ua[602]: repro.cpp:510: --> duration=1478772496, []:@: ---> []:@:
Nov 10 10:08:17 sip_ua[602]: repro.cpp:556: --> CDR: {"answer":0,"duration":1478772496,"hangup":1478772496,"org-host":"","org-scheme":"","org-user":"","to-host":"","to-scheme":"","to-user":"","type":""}
Nov 10 10:08:17 sip_ua[513]: fxs.cpp:407: ---> ts=14, state=Connected: Statistics received, ts=14, flags=0000, data=0
Nov 10 10:08:17 sip_ua[513]: fxs.cpp:407: ---> ts=14, state=Connected: Statistics received, ts=14, flags=0000, data=0
Nov 10 10:08:18 sip_ua[513]: fxs.cpp:407: ---> ts=15, state=Connected: Statistics received, ts=15, flags=0000, data=0
Nov 10 10:08:18 sip_ua[513]: fxs.cpp:407: ---> ts=15, state=Connected: Statistics received, ts=15, flags=0000, data=0
Nov 10 10:08:18 sip_ua[513]: fxo.cpp:338: ---> ts=35, state=Connected: Statistics received, ts=35, flags=0000, data=0
Nov 10 10:08:18 sip_ua[513]: fxo.cpp:338: ---> ts=35, state=Connected: Statistics received, ts=35, flags=0000, data=0
Nov 10 10:08:19 sip_ua[602]: repro.cpp:510: --> duration=1478772499, []:@: ---> []:@:
Nov 10 10:08:19 sip_ua[602]: repro.cpp:556: --> CDR: {"answer":0,"duration":1478772499,"hangup":1478772499,"org-host":"","org-scheme":"","org-user":"","to-host":"","to-scheme":"","to-user":"","type":""}
Nov 10 10:08:19 sip_ua[602]: repro.cpp:510: --> duration=1478772499, []:@: ---> []:@:
Nov 10 10:08:19 sip_ua[602]: repro.cpp:556: --> CDR: {"answer":0,"duration":1478772499,"hangup":1478772499,"org-host":"","org-scheme":"","org-user":"","to-host":"","to-scheme":"","to-user":"","type":""}
Nov 10 10:08:22 sip_ua[513]: fxs.cpp:407: ---> ts=14, state=Connected: Statistics received, ts=14, flags=0000, data=0
Nov 10 10:08:22 sip_ua[513]: fxs.cpp:407: ---> ts=14, state=Connected: Statistics received, ts=14, flags=0000, data=0
Nov 10 10:08:23 sip_ua[513]: fxs.cpp:407: ---> ts=15, state=Connected: Statistics received, ts=15, flags=0000, data=0
Nov 10 10:08:23 sip_ua[513]: fxs.cpp:407: ---> ts=15, state=Connected: Statistics received, ts=15, flags=0000, data=0
Nov 10 10:08:23 sip_ua[513]: fxo.cpp:338: ---> ts=35, state=Connected: Statistics received, ts=35, flags=0000, data=0
Nov 10 10:08:23 sip_ua[513]: fxo.cpp:338: ---> ts=35, state=Connected: Statistics received, ts=35, flags=0000, data=0
Nov 10 10:08:24 sip_ua[513]: fxs.cpp:407: ---> ts=14, state=Connected: CAS event, ts=14, flags=0000, data=15
Nov 10 10:08:24 sip_ua[513]: fxs.cpp:407: ---> ts=14, state=Idle: Call disconnected, ts=14, flags=0000, data=4
Nov 10 10:08:24 sip_ua[602]: repro.cpp:510: --> duration=1478772504, []:@: ---> []:@:
Nov 10 10:08:24 sip_ua[602]: repro.cpp:556: --> CDR: {"answer":0,"duration":1478772504,"hangup":1478772504,"org-host":"","org-scheme":"","org-user":"","to-host":"","to-scheme":"","to-user":"","type":""}
Nov 10 10:08:24 sip_ua[535]: user_agent.cpp:2094: ---> BYE in call received
Nov 10 10:08:24 sip_ua[513]: fxo.cpp:338: ---> ts=35, state=Connected: Call disconnected, ts=35, flags=0000, data=3
Nov 10 10:08:24 sip_ua[602]: repro.cpp:510: --> duration=1478772504, []:@: ---> []:@:
Nov 10 10:08:24 sip_ua[602]: repro.cpp:556: --> CDR: {"answer":0,"duration":1478772504,"hangup":1478772504,"org-host":"","org-scheme":"","org-user":"","to-host":"","to-scheme":"","to-user":"","type":""}
Nov 10 10:08:24 sip_ua[513]: fxs.cpp:407: ---> ts=14, state=Idle: Message answered 2xx, ts=14, flags=0000, data=4
Nov 10 10:08:24 sip_ua[602]: repro.cpp:510: --> duration=1478772504, []:@: ---> []:@:
Nov 10 10:08:24 sip_ua[602]: repro.cpp:556: --> CDR: {"answer":0,"duration":1478772504,"hangup":1478772504,"org-host":"","org-scheme":"","org-user":"","to-host":"","to-scheme":"","to-user":"","type":""}
Nov 10 10:08:25 sip_ua[513]: fxs.cpp:407: ---> ts=15, state=Connected: ACK received, ts=15, flags=0000, data=6
Nov 10 10:08:25 sip_ua[602]: repro.cpp:510: --> duration=1478772505, []:@: ---> []:@:
Nov 10 10:08:25 sip_ua[602]: repro.cpp:556: --> CDR: {"answer":0,"duration":1478772505,"hangup":1478772505,"org-host":"","org-scheme":"","org-user":"","to-host":"","to-scheme":"","to-user":"","type":""}
Nov 10 10:08:25 sip_ua[535]: user_agent.cpp:2094: ---> BYE in call received
Nov 10 10:08:25 sip_ua[513]: fxs.cpp:407: ---> ts=15, state=Connected: Call disconnected, ts=15, flags=0000, data=6
Nov 10 10:08:27 sip_ua[513]: fxs.cpp:407: ---> ts=15, state=Busy: CAS event, ts=15, flags=0000, data=15

[alx]

Здесь сразу две проблемы:

• одновременное назначение одного и того же удаленного адреса/порта RTP потока разными каналами;
• отсутствие отбой у одного из ответивших (кто ответил позже).

Первую проблему можно попробовать решить созданием множества активных комбинаций "адрес/порт" и проверкой их использования. Или просто перебором всех каналов для поиска совпадений (их немного, поэтому много времени это не займет).

Вторая проблема требует дополнительного анализа.

[alx]

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

[alx]

Коммутировал два окончания FXS на один и тот же телефон и, таким образом, "снимал трубку" на двух окончаниях сразу. Ни ту, ни другую проблему воспроизвести не смог (r1353).

Предполагаю, что в процессе изменений кода, создающего/пересоздающего каналы, проблема была устранена.