Git v1.2.17 ca447fe 2014-01-02 - Polycom IP-330 outbound calls hang on answer
Debian Wheezy 7.3 32bit Version 1.2.17 -n20140102T213421Z-1~wheezy+1git ca447fe 2014-01-02 11:34:22Z 32bit Phone firmware: 3.3.5 Configured as EXT 1000 Incoming calls work fine, but outgoing calls, either to local extensions or though a gateway hang up the instant the call is answered by the remote party. The IP-330 shows the call as answered and in progress and there is a split second of audio before it drops, but the actual call has dropped and the other party is idle. Calling three different endpoints has the same effect: Grandstream GXP2124 (extension 1002) Zoiper communicator on Android Sip trunk to PSTN A capture in wireshark shows the following sequence immediately after the call is established: 3963 8.986119000 10.0.0.124 10.0.0.119 SIP/SDP 1017 Request: UPDATE sip:1000@10.0.0.119:5060, with session description 3963 8.986119000 10.0.0.124 10.0.0.119 SIP/SDP 1017 Request: UPDATE sip:1000@10.0.0.119:5060, with session description 3994 9.002869000 10.0.0.119 10.0.0.124 SIP 443 Status: 481 Call Leg/Transaction Does Not Exist 3996 9.003466000 10.0.0.124 10.0.0.119 SIP 687 Request: BYE sip:1000@10.0.0.119:5060 4029 9.019642000 10.0.0.119 10.0.0.124 SIP 440 Status: 481 Call Leg/Transaction Does Not Exist .... at which point, a BYE is sent to the b leg and the call terminates, with the IP-330 left dangling with an empty call leg, not realizing that nobody is listening anymore. This is what I gleaned from fs_cli: 2014-01-05 18:13:08.904735 [DEBUG] sofia.c:5779 Channel sofia/internal/1000@hpbx.nest entering state [calling][0] 2014-01-05 18:13:08.904735 [DEBUG] switch_rtp.c:927 [ zrtp utils]: Send <HELLO> ssrc=1538954628 seq=54771 size=144. Stream 40:CLEAR:START 2014-01-05 18:13:08.924723 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.924723 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.924723 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.924723 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.924723 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.944752 [DEBUG] sofia.c:5779 Channel sofia/internal/1000@hpbx.nest entering state [terminating][487] 2014-01-05 18:13:08.944752 [NOTICE] sofia.c:6623 Hangup sofia/internal/1000@hpbx.nest [CS_EXECUTE] [ORIGINATOR_CANCEL] 2014-01-05 18:13:08.944752 [DEBUG] switch_channel.c:3183 Send signal sofia/internal/1000@hpbx.nest [KILL] 2014-01-05 18:13:08.944752 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.944752 [DEBUG] switch_ivr_bridge.c:633 BRIDGE THREAD DONE [sofia/internal/1000@hpbx.nest] 2014-01-05 18:13:08.944752 [DEBUG] switch_ivr_bridge.c:658 Send signal sofia/internal/sip:1002@10.0.0.120:5060 [BREAK] 2014-01-05 18:13:08.964735 [DEBUG] switch_ivr_bridge.c:633 BRIDGE THREAD DONE [sofia/internal/sip:1002@10.0.0.120:5060] 2014-01-05 18:13:08.964735 [DEBUG] switch_ivr_bridge.c:658 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.964735 [NOTICE] switch_ivr_bridge.c:721 Hangup sofia/internal/sip:1002@10.0.0.120:5060 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2014-01-05 18:13:08.964735 [DEBUG] switch_channel.c:3183 Send signal sofia/internal/sip:1002@10.0.0.120:5060 [KILL] 2014-01-05 18:13:08.964735 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:1002@10.0.0.120:5060 [BREAK] 2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/sip:1002@10.0.0.120:5060) State EXCHANGE_MEDIA going to sleep 2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1002@10.0.0.120:5060) Running State Change CS_HANGUP 2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:679 (sofia/internal/sip:1002@10.0.0.120:5060) State HANGUP 2014-01-05 18:13:08.964735 [DEBUG] mod_sofia.c:500 sofia/internal/sip:1002@10.0.0.120:5060 Overriding SIP cause 480 with 487 from the other leg 2014-01-05 18:13:08.964735 [DEBUG] mod_sofia.c:506 Channel sofia/internal/sip:1002@10.0.0.120:5060 hanging up, cause: NORMAL_CLEARING 2014-01-05 18:13:08.964735 [DEBUG] switch_ivr_bridge.c:1524 sofia/internal/sip:1002@10.0.0.120:5060 skip receive message [UNBRIDGE] (channel is hungup already) 2014-01-05 18:13:08.964735 [DEBUG] switch_ivr_bridge.c:1527 sofia/internal/1000@hpbx.nest skip receive message [UNBRIDGE] (channel is hungup already) 2014-01-05 18:13:08.964735 [DEBUG] switch_core_session.c:2810 sofia/internal/1000@hpbx.nest skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:478 (sofia/internal/1000@hpbx.nest) State EXECUTE going to sleep 2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@hpbx.nest) Running State Change CS_HANGUP 2014-01-05 18:13:08.964735 [DEBUG] mod_sofia.c:558 Sending BYE to sofia/internal/sip:1002@10.0.0.120:5060 2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:48 sofia/internal/sip:1002@10.0.0.120:5060 Standard HANGUP, cause: NORMAL_CLEARING Version 1.2.17 git 7712626 2013-12-27 20:52:28Z 64bit works fine.
Bug reports belong at jira.freeswitch.org with traces attached not inlined. On Jan 5, 2014 2:41 AM, "Francis" <sms@icefire.qza.net.au> wrote:
Debian Wheezy 7.3 32bit Version 1.2.17 -n20140102T213421Z-1~wheezy+1git ca447fe 2014-01-02 11:34:22Z 32bit Phone firmware: 3.3.5 Configured as EXT 1000
Incoming calls work fine, but outgoing calls, either to local extensions or though a gateway hang up the instant the call is answered by the remote party. The IP-330 shows the call as answered and in progress and there is a split second of audio before it drops, but the actual call has dropped and the other party is idle.
Calling three different endpoints has the same effect:
Grandstream GXP2124 (extension 1002) Zoiper communicator on Android Sip trunk to PSTN
A capture in wireshark shows the following sequence immediately after the call is established:
3963 8.986119000 10.0.0.124 10.0.0.119 SIP/SDP 1017 Request: UPDATE sip:1000@10.0.0.119:5060, with session description 3963 8.986119000 10.0.0.124 10.0.0.119 SIP/SDP 1017 Request: UPDATE sip:1000@10.0.0.119:5060, with session description 3994 9.002869000 10.0.0.119 10.0.0.124 SIP 443 Status: 481 Call Leg/Transaction Does Not Exist 3996 9.003466000 10.0.0.124 10.0.0.119 SIP 687 Request: BYE sip:1000@10.0.0.119:5060 4029 9.019642000 10.0.0.119 10.0.0.124 SIP 440 Status: 481 Call Leg/Transaction Does Not Exist
.... at which point, a BYE is sent to the b leg and the call terminates, with the IP-330 left dangling with an empty call leg, not realizing that nobody is listening anymore.
This is what I gleaned from fs_cli:
2014-01-05 18:13:08.904735 [DEBUG] sofia.c:5779 Channel sofia/internal/1000@hpbx.nest entering state [calling][0] 2014-01-05 18:13:08.904735 [DEBUG] switch_rtp.c:927 [ zrtp utils]: Send <HELLO> ssrc=1538954628 seq=54771 size=144. Stream 40:CLEAR:START 2014-01-05 18:13:08.924723 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.924723 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.924723 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.924723 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.924723 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.944752 [DEBUG] sofia.c:5779 Channel sofia/internal/1000@hpbx.nest entering state [terminating][487] 2014-01-05 18:13:08.944752 [NOTICE] sofia.c:6623 Hangup sofia/internal/1000@hpbx.nest [CS_EXECUTE] [ORIGINATOR_CANCEL] 2014-01-05 18:13:08.944752 [DEBUG] switch_channel.c:3183 Send signal sofia/internal/1000@hpbx.nest [KILL] 2014-01-05 18:13:08.944752 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.944752 [DEBUG] switch_ivr_bridge.c:633 BRIDGE THREAD DONE [sofia/internal/1000@hpbx.nest] 2014-01-05 18:13:08.944752 [DEBUG] switch_ivr_bridge.c:658 Send signal sofia/internal/sip:1002@10.0.0.120:5060 [BREAK] 2014-01-05 18:13:08.964735 [DEBUG] switch_ivr_bridge.c:633 BRIDGE THREAD DONE [sofia/internal/sip:1002@10.0.0.120:5060] 2014-01-05 18:13:08.964735 [DEBUG] switch_ivr_bridge.c:658 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.964735 [NOTICE] switch_ivr_bridge.c:721 Hangup sofia/internal/sip:1002@10.0.0.120:5060 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2014-01-05 18:13:08.964735 [DEBUG] switch_channel.c:3183 Send signal sofia/internal/sip:1002@10.0.0.120:5060 [KILL] 2014-01-05 18:13:08.964735 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:1002@10.0.0.120:5060 [BREAK] 2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/sip:1002@10.0.0.120:5060) State EXCHANGE_MEDIA going to sleep 2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1002@10.0.0.120:5060) Running State Change CS_HANGUP 2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:679 (sofia/internal/sip:1002@10.0.0.120:5060) State HANGUP 2014-01-05 18:13:08.964735 [DEBUG] mod_sofia.c:500 sofia/internal/sip:1002@10.0.0.120:5060 Overriding SIP cause 480 with 487 from the other leg 2014-01-05 18:13:08.964735 [DEBUG] mod_sofia.c:506 Channel sofia/internal/sip:1002@10.0.0.120:5060 hanging up, cause: NORMAL_CLEARING 2014-01-05 18:13:08.964735 [DEBUG] switch_ivr_bridge.c:1524 sofia/internal/sip:1002@10.0.0.120:5060 skip receive message [UNBRIDGE] (channel is hungup already)
2014-01-05 18:13:08.964735 [DEBUG] switch_ivr_bridge.c:1527 sofia/internal/1000@hpbx.nest skip receive message [UNBRIDGE] (channel is hungup already)
2014-01-05 18:13:08.964735 [DEBUG] switch_core_session.c:2810 sofia/internal/1000@hpbx.nest skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:478 (sofia/internal/1000@hpbx.nest) State EXECUTE going to sleep 2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@hpbx.nest) Running State Change CS_HANGUP 2014-01-05 18:13:08.964735 [DEBUG] mod_sofia.c:558 Sending BYE to sofia/internal/sip:1002@10.0.0.120:5060 2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:48 sofia/internal/sip:1002@10.0.0.120:5060 Standard HANGUP, cause: NORMAL_CLEARING
Version 1.2.17 git 7712626 2013-12-27 20:52:28Z 64bit works fine.
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
No worries, logged it just now. On 6/01/2014 1:46 AM, Anthony Minessale wrote:
This is what I gleaned from fs_cli:
2014-01-05 18:13:08.904735 [DEBUG] sofia.c:5779 Channel sofia/internal/1000@hpbx.nest entering state [calling][0] 2014-01-05 18:13:08.904735 [DEBUG] switch_rtp.c:927 [ zrtp utils]: Send <HELLO> ssrc=1538954628 seq=54771 size=144. Stream 40:CLEAR:START 2014-01-05 18:13:08.924723 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.924723 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.924723 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.924723 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.924723 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.944752 [DEBUG] sofia.c:5779 Channel sofia/internal/1000@hpbx.nest entering state [terminating][487] 2014-01-05 18:13:08.944752 [NOTICE] sofia.c:6623 Hangup sofia/internal/1000@hpbx.nest [CS_EXECUTE] [ORIGINATOR_CANCEL] 2014-01-05 18:13:08.944752 [DEBUG] switch_channel.c:3183 Send signal sofia/internal/1000@hpbx.nest [KILL] 2014-01-05 18:13:08.944752 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.944752 [DEBUG] switch_ivr_bridge.c:633 BRIDGE THREAD DONE [sofia/internal/1000@hpbx.nest] 2014-01-05 18:13:08.944752 [DEBUG] switch_ivr_bridge.c:658 Send signal sofia/internal/sip:1002@10.0.0.120:5060 <http://sip:1002@10.0.0.120:5060> [BREAK] 2014-01-05 18:13:08.964735 [DEBUG] switch_ivr_bridge.c:633 BRIDGE THREAD DONE [sofia/internal/sip:1002@10.0.0.120:5060 <http://sip:1002@10.0.0.120:5060>] 2014-01-05 18:13:08.964735 [DEBUG] switch_ivr_bridge.c:658 Send signal sofia/internal/1000@hpbx.nest [BREAK] 2014-01-05 18:13:08.964735 [NOTICE] switch_ivr_bridge.c:721 Hangup sofia/internal/sip:1002@10.0.0.120:5060 <http://sip:1002@10.0.0.120:5060> [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2014-01-05 18:13:08.964735 [DEBUG] switch_channel.c:3183 Send signal sofia/internal/sip:1002@10.0.0.120:5060 <http://sip:1002@10.0.0.120:5060> [KILL] 2014-01-05 18:13:08.964735 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:1002@10.0.0.120:5060 <http://sip:1002@10.0.0.120:5060> [BREAK] 2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/sip:1002@10.0.0.120:5060 <http://sip:1002@10.0.0.120:5060>) State EXCHANGE_MEDIA going to sleep 2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1002@10.0.0.120:5060 <http://sip:1002@10.0.0.120:5060>) Running State Change CS_HANGUP 2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:679 (sofia/internal/sip:1002@10.0.0.120:5060 <http://sip:1002@10.0.0.120:5060>) State HANGUP 2014-01-05 18:13:08.964735 [DEBUG] mod_sofia.c:500 sofia/internal/sip:1002@10.0.0.120:5060 <http://sip:1002@10.0.0.120:5060> Overriding SIP cause 480 with 487 from the other leg 2014-01-05 18:13:08.964735 [DEBUG] mod_sofia.c:506 Channel sofia/internal/sip:1002@10.0.0.120:5060 <http://sip:1002@10.0.0.120:5060> hanging up, cause: NORMAL_CLEARING 2014-01-05 18:13:08.964735 [DEBUG] switch_ivr_bridge.c:1524 sofia/internal/sip:1002@10.0.0.120:5060 <http://sip:1002@10.0.0.120:5060> skip receive message [UNBRIDGE] (channel is hungup already)
2014-01-05 18:13:08.964735 [DEBUG] switch_ivr_bridge.c:1527 sofia/internal/1000@hpbx.nest skip receive message [UNBRIDGE] (channel is hungup already)
2014-01-05 18:13:08.964735 [DEBUG] switch_core_session.c:2810 sofia/internal/1000@hpbx.nest skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:478 (sofia/internal/1000@hpbx.nest) State EXECUTE going to sleep 2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@hpbx.nest) Running State Change CS_HANGUP 2014-01-05 18:13:08.964735 [DEBUG] mod_sofia.c:558 Sending BYE to sofia/internal/sip:1002@10.0.0.120:5060 <http://sip:1002@10.0.0.120:5060> 2014-01-05 18:13:08.964735 [DEBUG] switch_core_state_machine.c:48 sofia/internal/sip:1002@10.0.0.120:5060 <http://sip:1002@10.0.0.120:5060> Standard HANGUP, cause: NORMAL_CLEARING
Version 1.2.17 git 7712626 2013-12-27 20:52:28Z 64bit works fine.
participants (2)
-
Anthony Minessale
-
Francis