FS does not relay BYE
Hello, I have just started using freeSwitch as a way to terminate calls from Microsoft Speech Server to voip gateways. I have almost everything working with a few exceptions. One of the problems I am having is that the final BYE issued by the terminator does not get relayed back to MSS, so MSS keeps the call open for an additional minute, then issues its own BYE, which freeSwitch can't match up to a call because it tore the call down already. The sequence: - MSS running on my machine originates a call, sends INVITE to freeSwitch running on a separate machine, with an internal and external NIC. - freeSwitch relays the INVITE to the gateway (in this case Affinity, but I get the same behavior with other gateways). - My cell phone rings, I pick it up, then hang up the call. - The gateway issues a BYE to freeSwitch, freeSwitch says OK and tears down the call without passing on the BYE. If I originate a call from my machine with a soft phone, it works fine. The only difference I can see is that the soft phone uses UDP, while MSS only talks SIP over TCP. I have pasted logs for the session at http://pastebin.freeswitch.org/16037. Thanks! ----------------------- Eric Z. Beard, CTO Loop LLC w (877) 850-2010 x9249 m (727) 776-2768 eric@loopfx.com<mailto:eric@loopfx.com>
sofia loglevel all 9 you'll see why its not. /b On Apr 7, 2011, at 10:11 AM, Eric Beard wrote:
Hello,
I have just started using freeSwitch as a way to terminate calls from Microsoft Speech Server to voip gateways. I have almost everything working with a few exceptions. One of the problems I am having is that the final BYE issued by the terminator does not get relayed back to MSS, so MSS keeps the call open for an additional minute, then issues its own BYE, which freeSwitch can't match up to a call because it tore the call down already.
The sequence:
- MSS running on my machine originates a call, sends INVITE to freeSwitch running on a separate machine, with an internal and external NIC.
- freeSwitch relays the INVITE to the gateway (in this case Affinity, but I get the same behavior with other gateways).
- My cell phone rings, I pick it up, then hang up the call.
- The gateway issues a BYE to freeSwitch, freeSwitch says OK and tears down the call without passing on the BYE.
If I originate a call from my machine with a soft phone, it works fine. The only difference I can see is that the soft phone uses UDP, while MSS only talks SIP over TCP.
I have pasted logs for the session at http://pastebin.freeswitch.org/16037.
Thanks!
----------------------- Eric Z. Beard, CTO Loop LLC w (877) 850-2010 x9249 m (727) 776-2768 eric@loopfx.com<mailto:eric@loopfx.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
Here are the logs from the OK that FS sends to the terminator. I don't see anything obvious. send 557 bytes to udp/[69.30.55.34]:5060 at 12:36:43.431454: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 69.30.55.34;branch=z9hG4bKb10d.db340dd6.0 Via: SIP/2.0/UDP 69.30.55.46:5060;branch=z9hG4bK19032810 From: <sip:17277762768@69.30.55.34>;tag=as1bf91603 To: "18778502010" <sip:18778502010@97.76.110.215>;tag=DtZyD89QQvjUj Call-ID: 7fc47854-dbb6-122e-ad9a-0014220d7aff CSeq: 103 BYE User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-8c5586b 2011-04-01 14-22-43 -0500 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY Supported: timer, precondition, path, replaces Content-Length: 0 ------------------------------------------------------------------------ nta: sent 200 OK for BYE (103) nua(0x7fe6a80625f0): removing session usage nua(0x7fe6a80625f0): call state changed: ready -> terminated nua(0x7fe6a80625f0): event i_state 200 Session Terminated nua(0x7fe6a80625f0): event i_terminated 200 Session Terminated soa_destroy(static::0x7fe6b005b390) called nta_leg_destroy(0x7fe6b005ab50) nua(0x7fe6a80625f0): recv signal r_destroy nta_leg_destroy((nil)) 2011-04-07 12:36:43.440470 [DEBUG] switch_ivr_bridge.c:501 sofia/external/17277762768 ending bridge by request from read function 2011-04-07 12:36:43.440470 [DEBUG] switch_ivr_bridge.c:495 sofia/external/17277762768 ending bridge by request from write function 2011-04-07 12:36:43.440470 [DEBUG] switch_ivr_bridge.c:582 BRIDGE THREAD DONE [sofia/external/17277762768] 2011-04-07 12:36:43.440470 [DEBUG] switch_ivr_bridge.c:602 Send signal sofia/internal/18778502010@bert [BREAK] 2011-04-07 12:36:43.440470 [DEBUG] switch_ivr_bridge.c:582 BRIDGE THREAD DONE [sofia/internal/18778502010@bert] 2011-04-07 12:36:43.440470 [DEBUG] switch_ivr_bridge.c:602 Send signal sofia/external/17277762768 [BREAK] 2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:374 (sofia/external/17277762768) State EXCHANGE_MEDIA going to sleep 2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:325 (sofia/external/17277762768) Running State Change CS_HANGUP 2011-04-07 12:36:43.440470 [DEBUG] switch_ivr_bridge.c:1306 sofia/external/17277762768 skip receive message [UNBRIDGE] (channel is hungup already) 2011-04-07 12:36:43.440470 [DEBUG] switch_core_session.c:709 Send signal sofia/internal/18778502010@bert [BREAK] 2011-04-07 12:36:43.440470 [NOTICE] switch_core_state_machine.c:189 sofia/internal/18778502010@bert has executed the last dialplan instruction, hanging up. 2011-04-07 12:36:43.440470 [DEBUG] switch_channel.c:2563 (sofia/internal/18778502010@bert) Callstate Change ACTIVE -> HANGUP 2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:565 (sofia/external/17277762768) State HANGUP 2011-04-07 12:36:43.440470 [DEBUG] mod_sofia.c:451 sofia/external/17277762768 Overriding SIP cause 480 with 200 from the other leg 2011-04-07 12:36:43.440470 [DEBUG] mod_sofia.c:457 Channel sofia/external/17277762768 hanging up, cause: NORMAL_CLEARING 2011-04-07 12:36:43.440470 [NOTICE] switch_core_state_machine.c:191 Hangup sofia/internal/18778502010@bert [CS_EXECUTE] [NORMAL_CLEARING] 2011-04-07 12:36:43.440470 [DEBUG] switch_channel.c:2579 Send signal sofia/internal/18778502010@bert [KILL] 2011-04-07 12:36:43.440470 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/18778502010@bert [BREAK] 2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:371 (sofia/internal/18778502010@bert) State EXECUTE going to sleep 2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/18778502010@bert) Running State Change CS_HANGUP 2011-04-07 12:36:43.440470 [DEBUG] switch_ivr_async.c:936 Stop recording file /usr/local/freeswitch/recordings/2011-04-07-12-36-27_17277762768_18778502010.wav 2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:46 sofia/external/17277762768 Standard HANGUP, cause: NORMAL_CLEARING 2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:565 (sofia/external/17277762768) State HANGUP going to sleep 2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:356 (sofia/external/17277762768) State Change CS_HANGUP -> CS_REPORTING 2011-04-07 12:36:43.440470 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/17277762768 [BREAK] 2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:325 (sofia/external/17277762768) Running State Change CS_REPORTING 2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:625 (sofia/external/17277762768) State REPORTING 2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:53 sofia/external/17277762768 Standard REPORTING, cause: NORMAL_CLEARING 2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:625 (sofia/external/17277762768) State REPORTING going to sleep 2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:350 (sofia/external/17277762768) State Change CS_REPORTING -> CS_DESTROY 2011-04-07 12:36:43.440470 [DEBUG] switch_core_media_bug.c:439 Removing BUG from sofia/internal/18778502010@bert 2011-04-07 12:36:43.440470 [DEBUG] switch_core_session.c:1116 Send signal sofia/external/17277762768 [BREAK] 2011-04-07 12:36:43.440470 [DEBUG] switch_core_session.c:1288 Session 2 (sofia/external/17277762768) Locked, Waiting on external entities 2011-04-07 12:36:43.440470 [NOTICE] switch_core_session.c:1306 Session 2 (sofia/external/17277762768) Ended 2011-04-07 12:36:43.440470 [NOTICE] switch_core_session.c:1308 Close Channel sofia/external/17277762768 [CS_DESTROY] 2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:454 (sofia/external/17277762768) Callstate Change HANGUP -> DOWN 2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:457 (sofia/external/17277762768) Running State Change CS_DESTROY 2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:467 (sofia/external/17277762768) State DESTROY 2011-04-07 12:36:43.440470 [DEBUG] mod_sofia.c:362 sofia/external/17277762768 SOFIA DESTROY 2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:565 (sofia/internal/18778502010@bert) State HANGUP 2011-04-07 12:36:43.440470 [DEBUG] mod_sofia.c:451 sofia/internal/18778502010@bert Overriding SIP cause 480 with 200 from the other leg 2011-04-07 12:36:43.440470 [DEBUG] mod_sofia.c:457 Channel sofia/internal/18778502010@bert hanging up, cause: NORMAL_CLEARING 2011-04-07 12:36:43.440470 [DEBUG] mod_sofia.c:500 Sending BYE to sofia/internal/18778502010@bert nua: nua_bye: entering nua(0x7fe6b00839e0): sent signal r_bye nua(0x7fe6b00839e0): recv signal r_bye nua: nua_stack_set_params: entering soa_set_params(static::0x7fe6b004be90, ...) called soa_terminate(static::0x7fe6b004be90) called soa_init_offer_answer(static::0x7fe6b004be90) called nta: selecting scheme sip tport_tsend(0x7660d0) tpn = Tcp/10.1.0.17:58370 tport_resolve addrinfo = 10.1.0.17:58370 tport_by_addrinfo(0x7660d0): not found by name Tcp/10.1.0.17:58370 tport_alloc_secondary(0x7660d0): new secondary tport 0x7fe6a806f5d0 tport_base_connect(0x7fe6a806f5d0): connecting to tcp/10.1.0.17:58370/sip tport(0x7fe6a806f5d0): reset timer tport_queue(0x7fe6a806f5d0): queueing 0x7fe6a801a950 for tcp/10.1.0.17:58370 nta: sent BYE (10753837) to Tcp/10.1.0.17:58370 tport_pend(0x7fe6a806f5d0): pending 0x7fe6a801a950 for tcp/10.1.0.17:58370 (already 0) nta: timer set to 32000 ms 2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:46 sofia/internal/18778502010@bert Standard HANGUP, cause: NORMAL_CLEARING 2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:565 (sofia/internal/18778502010@bert) State HANGUP going to sleep 2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/18778502010@bert) State Change CS_HANGUP -> CS_REPORTING 2011-04-07 12:36:43.444692 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/18778502010@bert [BREAK] 2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/18778502010@bert) Running State Change CS_REPORTING 2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/18778502010@bert) State REPORTING 2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:53 sofia/internal/18778502010@bert Standard REPORTING, cause: NORMAL_CLEARING 2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/18778502010@bert) State REPORTING going to sleep 2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:350 (sofia/internal/18778502010@bert) State Change CS_REPORTING -> CS_DESTROY 2011-04-07 12:36:43.444692 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/18778502010@bert [BREAK] 2011-04-07 12:36:43.444692 [DEBUG] switch_core_session.c:1288 Session 1 (sofia/internal/18778502010@bert) Locked, Waiting on external entities 2011-04-07 12:36:43.444692 [NOTICE] switch_core_session.c:1306 Session 1 (sofia/internal/18778502010@bert) Ended 2011-04-07 12:36:43.444692 [NOTICE] switch_core_session.c:1308 Close Channel sofia/internal/18778502010@bert [CS_DESTROY] 2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/18778502010@bert) Callstate Change HANGUP -> DOWN 2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:457 (sofia/internal/18778502010@bert) Running State Change CS_DESTROY 2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/18778502010@bert) State DESTROY 2011-04-07 12:36:43.444692 [DEBUG] mod_sofia.c:362 sofia/internal/18778502010@bert SOFIA DESTROY 2011-04-07 12:36:43.452463 [DEBUG] switch_nat.c:544 unmapped public port 17454 protocol UDP to localport 17454 2011-04-07 12:36:43.460474 [DEBUG] switch_nat.c:544 unmapped public port 24894 protocol UDP to localport 24894 2011-04-07 12:36:43.468467 [DEBUG] switch_nat.c:544 unmapped public port 17455 protocol UDP to localport 17455 2011-04-07 12:36:43.469757 [DEBUG] switch_core_state_machine.c:60 sofia/external/17277762768 Standard DESTROY 2011-04-07 12:36:43.469757 [DEBUG] switch_core_state_machine.c:467 (sofia/external/17277762768) State DESTROY going to sleep 2011-04-07 12:36:43.476473 [DEBUG] switch_nat.c:544 unmapped public port 24895 protocol UDP to localport 24895 2011-04-07 12:36:43.476473 [DEBUG] switch_core_state_machine.c:60 sofia/internal/18778502010@bert Standard DESTROY 2011-04-07 12:36:43.476473 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/18778502010@bert) State DESTROY going to sleep nta: timer set next to 4896 ms nta: timer I fired, terminate 200 response incoming_reclaim_all((nil), (nil), 0x40d67e60) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free nta: timer set next to 22305 ms ----------------------- Eric Z. Beard, CTO Loop LLC w (877) 850-2010 x9249 m (727) 776-2768 eric@loopfx.com -----Original Message----- From: freeswitch-users-bounces@lists.freeswitch.org [mailto:freeswitch-users-bounces@lists.freeswitch.org] On Behalf Of Brian West Sent: Thursday, April 07, 2011 12:24 PM To: FreeSWITCH Users Help Subject: Re: [Freeswitch-users] FS does not relay BYE sofia loglevel all 9 you'll see why its not. /b On Apr 7, 2011, at 10:11 AM, Eric Beard wrote:
Hello,
I have just started using freeSwitch as a way to terminate calls from Microsoft Speech Server to voip gateways. I have almost everything working with a few exceptions. One of the problems I am having is that the final BYE issued by the terminator does not get relayed back to MSS, so MSS keeps the call open for an additional minute, then issues its own BYE, which freeSwitch can't match up to a call because it tore the call down already.
The sequence:
- MSS running on my machine originates a call, sends INVITE to freeSwitch running on a separate machine, with an internal and external NIC.
- freeSwitch relays the INVITE to the gateway (in this case Affinity, but I get the same behavior with other gateways).
- My cell phone rings, I pick it up, then hang up the call.
- The gateway issues a BYE to freeSwitch, freeSwitch says OK and tears down the call without passing on the BYE.
If I originate a call from my machine with a soft phone, it works fine. The only difference I can see is that the soft phone uses UDP, while MSS only talks SIP over TCP.
I have pasted logs for the session at http://pastebin.freeswitch.org/16037.
Thanks!
----------------------- Eric Z. Beard, CTO Loop LLC w (877) 850-2010 x9249 m (727) 776-2768 eric@loopfx.com<mailto:eric@loopfx.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
_______________________________________________ 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
participants (2)
-
Brian West
-
Eric Beard