Re: [Freeswitch-users] FS does not relay BYE

7 Apr 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@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