[Freeswitch-users] FS does not relay BYE

Eric Beard eric at loopfx.com
Thu Apr 7 20:46:16 MSD 2011 

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 at 69.30.55.34>;tag=as1bf91603
   To: "18778502010" <sip:18778502010 at 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 at bert [BREAK]
2011-04-07 12:36:43.440470 [DEBUG] switch_ivr_bridge.c:582 BRIDGE THREAD DONE [sofia/internal/18778502010 at 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 at bert [BREAK]
2011-04-07 12:36:43.440470 [NOTICE] switch_core_state_machine.c:189 sofia/internal/18778502010 at bert has executed the last dialplan instruction, hanging up.
2011-04-07 12:36:43.440470 [DEBUG] switch_channel.c:2563 (sofia/internal/18778502010 at 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 at bert [CS_EXECUTE] [NORMAL_CLEARING]
2011-04-07 12:36:43.440470 [DEBUG] switch_channel.c:2579 Send signal sofia/internal/18778502010 at bert [KILL]
2011-04-07 12:36:43.440470 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/18778502010 at bert [BREAK]
2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:371 (sofia/internal/18778502010 at bert) State EXECUTE going to sleep
2011-04-07 12:36:43.440470 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/18778502010 at 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 at 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 at bert) State HANGUP
2011-04-07 12:36:43.440470 [DEBUG] mod_sofia.c:451 sofia/internal/18778502010 at 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 at bert hanging up, cause: NORMAL_CLEARING
2011-04-07 12:36:43.440470 [DEBUG] mod_sofia.c:500 Sending BYE to sofia/internal/18778502010 at 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 at bert Standard HANGUP, cause: NORMAL_CLEARING
2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:565 (sofia/internal/18778502010 at bert) State HANGUP going to sleep
2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/18778502010 at 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 at bert [BREAK]
2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/18778502010 at bert) Running State Change CS_REPORTING
2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/18778502010 at bert) State REPORTING
2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:53 sofia/internal/18778502010 at bert Standard REPORTING, cause: NORMAL_CLEARING
2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/18778502010 at bert) State REPORTING going to sleep
2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:350 (sofia/internal/18778502010 at 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 at bert [BREAK]
2011-04-07 12:36:43.444692 [DEBUG] switch_core_session.c:1288 Session 1 (sofia/internal/18778502010 at bert) Locked, Waiting on external entities
2011-04-07 12:36:43.444692 [NOTICE] switch_core_session.c:1306 Session 1 (sofia/internal/18778502010 at bert) Ended
2011-04-07 12:36:43.444692 [NOTICE] switch_core_session.c:1308 Close Channel sofia/internal/18778502010 at bert [CS_DESTROY]
2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/18778502010 at bert) Callstate Change HANGUP -> DOWN
2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:457 (sofia/internal/18778502010 at bert) Running State Change CS_DESTROY
2011-04-07 12:36:43.444692 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/18778502010 at bert) State DESTROY
2011-04-07 12:36:43.444692 [DEBUG] mod_sofia.c:362 sofia/internal/18778502010 at 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 at bert Standard DESTROY
2011-04-07 12:36:43.476473 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/18778502010 at 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 at loopfx.com


-----Original Message-----
From: freeswitch-users-bounces at lists.freeswitch.org [mailto:freeswitch-users-bounces at 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 at loopfx.com<mailto:eric at loopfx.com>
> 
> _______________________________________________
> FreeSWITCH-users mailing list
> FreeSWITCH-users at 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 at lists.freeswitch.org
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
http://www.freeswitch.org

More information about the FreeSWITCH-users mailing list