Collect a SIP trace (sofia global siptrace on) and check if the Contact header contains the IP:port you'd expect, if that's an internal (not external) address because of the NAT it might be the endpoint is replying to there rather than where the 200 was received from, and therefore the reply is never received. On 26 February 2014 14:43, Brian Fertig <BFertig@doublepositive.com> wrote:
Antonio,
Thanks for the info.. That is what I was thinking. I do have external NAT setup for calls traversing the outside but I believe its not ACK'ing on an internal server. I will look more into this.
Brian
*From:* freeswitch-users-bounces@lists.freeswitch.org [mailto: freeswitch-users-bounces@lists.freeswitch.org] *On Behalf Of *Antonio *Sent:* Tuesday, February 25, 2014 7:10 PM *To:* freeswitch-users@lists.freeswitch.org
*Subject:* Re: [Freeswitch-users] NORMAL_UNSPECIFIED Disconnect
Hi,
It seams to be a connection/network problem, for what i see FS send's the bye with cause "ACK timeout", the ACK to the 200 OK message never arrive to FS so the call is drop.
"nua_stack.c:271 nua_stack_event() nua(0x7f291800c980): event i_error 408 ACK Timeout"
Do you have configure ext-sip-ip / ext-rtp-ip configure in your profile? see https://wiki.freeswitch.org/wiki/Sofia.conf.xml#ext-rtp-ip
Regards, António
On Tue, 2014-02-25 at 21:52 +0000, Brian Fertig wrote:
Here is debug with tracelevel at 9 and debug at 9
TIA!
Brian
*From:* freeswitch-users-bounces@lists.freeswitch.org [ mailto:freeswitch-users-bounces@lists.freeswitch.org<freeswitch-users-bounces@lists.freeswitch.org>] *On Behalf Of *Brian Fertig *Sent:* Tuesday, February 25, 2014 4:12 PM *To:* FreeSWITCH Users Help *Subject:* Re: [Freeswitch-users] NORMAL_UNSPECIFIED Disconnect
Ok.. I will get it together. I tried to setup an account on fs.org but the capcha isn't working so I couldn't signup for an account.
Brian
*From:*freeswitch-users-bounces@lists.freeswitch.org [ mailto:freeswitch-users-bounces@lists.freeswitch.org<freeswitch-users-bounces@lists.freeswitch.org>] *On Behalf Of *Michael Jerris *Sent:* Tuesday, February 25, 2014 4:02 PM *To:* FreeSWITCH Users Help *Subject:* Re: [Freeswitch-users] NORMAL_UNSPECIFIED Disconnect
with freeswitch debug and sip trace would provide some useful information and context.
On Feb 25, 2014, at 3:56 PM, Brian Fertig <BFertig@doublepositive.com> wrote:
From what I can tell it looks like the other machine 10.100.0.43 isnt communicating or timing out. Is that true what I am seeing? Is it the options causing the timeout?
Brian
soa.c:358 soa_destroy() soa_destroy(static::0x7f29182208c0) called
nua_stack.c:529 nua_signal() nua(0x7f29180238a0): sent signal r_destroy
nta.c:6874 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
tport.c:3241 tport_tsend() tport_tsend(0x7f2918004480) tpn = UDP/ 10.100.0.43:5060
tport.c:4030 tport_resolve() tport_resolve addrinfo = 10.100.0.43:5060
tport.c:4664 tport_by_addrinfo() tport_by_addrinfo(0x7f2918004480): not found by name UDP/10.100.0.43:5060
tport.c:3578 tport_vsend() tport_vsend(0x7f2918004480): 1093 bytes of 1093 to udp/10.100.0.43:5060
tport.c:3476 tport_send_msg() tport_vsend returned 1093
nta.c:7066 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/2 term, 0/3 free
nta.c:1289 agent_timer() nta: timer set next to 1008 ms
nta.c:7037 _nta_incoming_timer() nta: timer J fired, terminate 200 response
nta.c:5709 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f2928c25ab0)
nta.c:7066 _nta_incoming_timer() nta_incoming_timer: 0/1 resent, 0/1 tout, 1/2 term, 1/3 free
nta.c:1289 agent_timer() nta: timer set next to 2991 ms
nta.c:6874 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
tport.c:3241 tport_tsend() tport_tsend(0x7f2918004480) tpn = UDP/ 10.100.0.43:5060
tport.c:4030 tport_resolve() tport_resolve addrinfo = 10.100.0.43:5060
tport.c:4664 tport_by_addrinfo() tport_by_addrinfo(0x7f2918004480): not found by name UDP/10.100.0.43:5060
tport.c:3578 tport_vsend() tport_vsend(0x7f2918004480): 1093 bytes of 1093 to udp/10.100.0.43:5060
tport.c:3476 tport_send_msg() tport_vsend returned 1093
nta.c:7066 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free
nta.c:1289 agent_timer() nta: timer set next to 4000 ms
nta.c:6874 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
tport.c:3241 tport_tsend() tport_tsend(0x7f2918004480) tpn = UDP/ 10.100.0.43:5060
tport.c:4030 tport_resolve() tport_resolve addrinfo = 10.100.0.43:5060
tport.c:4664 tport_by_addrinfo() tport_by_addrinfo(0x7f2918004480): not found by name UDP/10.100.0.43:5060
tport.c:3578 tport_vsend() tport_vsend(0x7f2918004480): 1093 bytes of 1093 to udp/10.100.0.43:5060
tport.c:3476 tport_send_msg() tport_vsend returned 1093
nta.c:7066 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free
nta.c:1289 agent_timer() nta: timer set next to 4000 ms
nta.c:6874 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
tport.c:3241 tport_tsend() tport_tsend(0x7f2918004480) tpn = UDP/ 10.100.0.43:5060
tport.c:4030 tport_resolve() tport_resolve addrinfo = 10.100.0.43:5060
tport.c:4664 tport_by_addrinfo() tport_by_addrinfo(0x7f2918004480): not found by name UDP/10.100.0.43:5060
tport.c:3578 tport_vsend() tport_vsend(0x7f2918004480): 1093 bytes of 1093 to udp/10.100.0.43:5060
tport.c:3476 tport_send_msg() tport_vsend returned 1093
nta.c:7066 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free
nta.c:1289 agent_timer() nta: timer set next to 4000 ms
nta.c:6874 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
tport.c:3241 tport_tsend() tport_tsend(0x7f2918004480) tpn = UDP/ 10.100.0.43:5060
tport.c:4030 tport_resolve() tport_resolve addrinfo = 10.100.0.43:5060
tport.c:4664 tport_by_addrinfo() tport_by_addrinfo(0x7f2918004480): not found by name UDP/10.100.0.43:5060
tport.c:3578 tport_vsend() tport_vsend(0x7f2918004480): 1093 bytes of 1093 to udp/10.100.0.43:5060
tport.c:3476 tport_send_msg() tport_vsend returned 1093
nta.c:7066 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free
nta.c:1289 agent_timer() nta: timer set next to 4000 ms
nta.c:6874 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
tport.c:3241 tport_tsend() tport_tsend(0x7f2918004480) tpn = UDP/ 10.100.0.43:5060
tport.c:4030 tport_resolve() tport_resolve addrinfo = 10.100.0.43:5060
tport.c:4664 tport_by_addrinfo() tport_by_addrinfo(0x7f2918004480): not found by name UDP/10.100.0.43:5060
tport.c:3578 tport_vsend() tport_vsend(0x7f2918004480): 1093 bytes of 1093 to udp/10.100.0.43:5060
tport.c:3476 tport_send_msg() tport_vsend returned 1093
nta.c:7066 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free
nta.c:1289 agent_timer() nta: timer set next to 460 ms
nta.c:8958 outgoing_timer_dk() nta: timer D fired, terminate INVITE (56343509)
nta.c:8656 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f2928c25c20)
nta.c:8786 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/1 term, 1/2 free
nta.c:1289 agent_timer() nta: timer set next to 18 ms
nta.c:8839 outgoing_timer_bf() nta: timer F fired, terminating ACK (56343509)
nta.c:8656 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f2928c25c20)
nta.c:8786 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/1 tout, 0/0 term, 1/1 free
nta.c:1289 agent_timer() nta: timer set next to 19 ms
nta.c:6983 _nta_incoming_timer() nta: timer H fired, timeout and terminate 200 response
nua_session.c:2567 process_ack_or_cancel() nua: process_ack_or_cancel: entering
nua_stack.c:271 nua_stack_event() nua(0x7f291800c610): event i_error 408 ACK Timeout
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:1784 soa_terminate() soa_terminate(static::0x7f291807beb0) called
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f291807beb0) called
nta.c:2650 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3241 tport_tsend() tport_tsend(0x7f2918004480) tpn = */ 10.100.0.43:5060
tport.c:4030 tport_resolve() tport_resolve addrinfo = 10.100.0.43:5060
tport.c:4664 tport_by_addrinfo() tport_by_addrinfo(0x7f2918004480): not found by name */10.100.0.43:5060
tport.c:3578 tport_vsend() tport_vsend(0x7f2918004480): 618 bytes of 618 to udp/10.100.0.43:5060
tport.c:3476 tport_send_msg() tport_vsend returned 618
nta.c:8169 outgoing_send() nta: sent BYE (56343529) to */ 10.100.0.43:5060
tport.c:4144 tport_pend() tport_pend(0x7f2918004480): pending 0x7f2918016a20 for udp/10.100.0.90:5060 (already 0)
nua_session.c:4137 signal_call_state_change() nua(0x7f291800c610): call state changed: completed -> terminating
nua_stack.c:269 nua_stack_event() nua(0x7f291800c610): event i_state ACK Timeout
nta.c:5628 incoming_free() nta: incoming_free(0x7f2918012d60)
nta.c:7066 _nta_incoming_timer() nta_incoming_timer: 0/1 resent, 1/1 tout, 0/1 term, 0/2 free
nta.c:1289 agent_timer() nta: timer set next to 1001 ms
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2014-02-25 15:13:07.836711 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/ds_350@10.100.0.43 [BREAK]
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2014-02-25 15:13:07.836711 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/ds_350@10.100.0.43 [BREAK]
tport.c:2733 tport_wakeup_pri() tport_wakeup_pri(0x7f2918004480): events IN
tport.c:2848 tport_recv_event() tport_recv_event(0x7f2918004480)
tport.c:3189 tport_recv_iovec() tport_recv_iovec(0x7f2918004480) msg 0x7f2918014bf0 from (udp/10.100.0.90:5060) has 441 bytes, veclen = 1
tport.c:3007 tport_deliver() tport_deliver(0x7f2918004480): msg 0x7f2918014bf0 (441 bytes) from udp/10.100.0.43:5060/sip next=(nil)
nta.c:3201 agent_recv_response() nta: received 200 OK for BYE (56343529)
nta.c:3264 agent_recv_response() nta: 200 OK is going to a transaction
nta.c:9421 outgoing_estimate_delay() nta_outgoing: RTT is 0.388 ms
tport.c:4206 tport_release() tport_release(0x7f2918004480): 0x7f2918016a20 by 0x7f2918217030 with 0x7f2918014bf0
nua_stack.c:271 nua_stack_event() nua(0x7f291800c610): event r_bye 200 OK
nua_session.c:4137 signal_call_state_change() nua(0x7f291800c610): call state changed: terminating -> terminated
nua_stack.c:271 nua_stack_event() nua(0x7f291800c610): event i_state 200 to BYE
nua_stack.c:271 nua_stack_event() nua(0x7f291800c610): event i_terminated 200 to BYE
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f291800c610): removing session usage
*From:* freeswitch-users-bounces@lists.freeswitch.org [ mailto:freeswitch-users-bounces@lists.freeswitch.org<freeswitch-users-bounces@lists.freeswitch.org> ] *On Behalf Of *Brian Fertig *Sent:* Tuesday, February 25, 2014 2:27 PM *To:* FreeSWITCH Users Help *Subject:* Re: [Freeswitch-users] NORMAL_UNSPECIFIED Disconnect
Thanks Mike.. Will update if I cant figure it out..
Brian
*From:* freeswitch-users-bounces@lists.freeswitch.org [ mailto:freeswitch-users-bounces@lists.freeswitch.org<freeswitch-users-bounces@lists.freeswitch.org> ] *On Behalf Of *Michael Jerris *Sent:* Tuesday, February 25, 2014 12:33 PM *To:* FreeSWITCH Users Help *Subject:* Re: [Freeswitch-users] NORMAL_UNSPECIFIED Disconnect
turn on sofia debug too, see whats happening there.
On Feb 25, 2014, at 11:55 AM, Brian Fertig <BFertig@doublepositive.com> wrote:
List,
I am having an interesting issue. I have active calls disconnecting at different points and it appears on the ladder graph that FS is sending BYE's to both legs of the call. I have looked at the log and cant make heads or tails as to why. I have included a snippet of the log in this email maybe someone can tell me whats going on.
TIA!
2014-02-25 11:00:04.816713 [DEBUG] mod_sofia.c:87 sofia/internal/517NXXXXXX@216.238.XXX.XXX SOFIA INIT
2014-02-25 11:00:04.816713 [DEBUG] sofia_glue.c:2744 sofia/internal/517NXXXXXX@216.238.XXX.XXX sending invite version: 1.2.22 git f7d5eba 2014-02-18 21:16:05Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1393320114 1393320115 IN IP4 144.202.XXX.XXX
s=FreeSWITCH
c=IN IP4 144.202.XXX.XXX
t=0 0
m=audio 23890 RTP/AVP 18 0 101 13
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2014-02-25 11:00:04.836881 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/517NXXXXXX@216.238.XXX.XXX[BREAK]
2014-02-25 11:00:04.836881 [DEBUG] mod_sofia.c:127 ( sofia/internal/517NXXXXXX@216.238.XXX.XXX) State Change CS_INIT -> CS_ROUTING
2014-02-25 11:00:04.836881 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/517NXXXXXX@216.238.XXX.XXX[BREAK]
2014-02-25 11:00:04.836881 [DEBUG] switch_core_state_machine.c:455 ( sofia/internal/517NXXXXXX@216.238.XXX.XXX) State INIT going to sleep
2014-02-25 11:00:04.836881 [DEBUG] switch_core_state_machine.c:415 ( sofia/internal/517NXXXXXX@216.238.XXX.XXX) Running State Change CS_ROUTING
2014-02-25 11:00:04.836881 [DEBUG] sofia.c:5811 Channel sofia/internal/517NXXXXXX@216.238.XXX.XXX entering state [calling][0]
2014-02-25 11:00:04.836881 [DEBUG] switch_core_state_machine.c:471 ( sofia/internal/517NXXXXXX@216.238.XXX.XXX) State ROUTING
2014-02-25 11:00:04.836881 [DEBUG] mod_sofia.c:150 sofia/internal/517NXXXXXX@216.238.XXX.XXX SOFIA ROUTING
2014-02-25 11:00:04.836881 [DEBUG] switch_ivr_originate.c:67 ( sofia/internal/517NXXXXXX@216.238.XXX.XXX) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2014-02-25 11:00:04.836881 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/517NXXXXXX@216.238.XXX.XXX[BREAK]
2014-02-25 11:00:04.836881 [DEBUG] switch_core_state_machine.c:471 ( sofia/internal/517NXXXXXX@216.238.XXX.XXX) State ROUTING going to sleep
2014-02-25 11:00:04.836881 [DEBUG] switch_core_state_machine.c:415 ( sofia/internal/517NXXXXXX@216.238.XXX.XXX) Running State Change CS_CONSUME_MEDIA
2014-02-25 11:00:04.836881 [DEBUG] switch_core_state_machine.c:490 ( sofia/internal/517NXXXXXX@216.238.XXX.XXX) State CONSUME_MEDIA
2014-02-25 11:00:04.836881 [DEBUG] switch_core_state_machine.c:490 ( sofia/internal/517NXXXXXX@216.238.XXX.XXX) State CONSUME_MEDIA going to sleep
2014-02-25 11:00:05.716715 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/888NXXXXXX@10.100.0.59 [BREAK]
2014-02-25 11:00:05.716715 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/888NXXXXXX@10.100.0.59 [BREAK]
2014-02-25 11:00:05.716715 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/888NXXXXXX@10.100.0.59 [BREAK]
2014-02-25 11:00:05.716715 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/888NXXXXXX@10.100.0.59 [BREAK]
2014-02-25 11:00:05.716715 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/888NXXXXXX@10.100.0.59 [BREAK]
2014-02-25 11:00:05.736724 [DEBUG] sofia.c:5811 Channel sofia/internal/888NXXXXXX@10.100.0.59 entering state [terminating][0]
2014-02-25 11:00:05.736724 [NOTICE] sofia.c:6655 Hangup sofia/internal/888NXXXXXX@10.100.0.59 [CS_EXECUTE] [NORMAL_UNSPECIFIED]
2014-02-25 11:00:05.736724 [DEBUG] switch_channel.c:3184 Send signal sofia/internal/888NXXXXXX@10.100.0.59 [KILL]
_________________________________________________________________________ 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
_________________________________________________________________________ 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
_________________________________________________________________________
Professional FreeSWITCH Consulting Services:
consulting@freeswitch.org
http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server
Official FreeSWITCH Sites
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
_________________________________________________________________________ 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