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] 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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto:sofia/internal/888NXXXXXX@10.100.0.59> [KILL] _________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org<mailto:consulting@freeswitch.org> http://www.freeswitchsolutions.com<http://www.freeswitchsolutions.com/> FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com<http://www.cudatel.com/> Official FreeSWITCH Sites http://www.freeswitch.org<http://www.freeswitch.org/> http://wiki.freeswitch.org<http://wiki.freeswitch.org/> http://www.cluecon.com<http://www.cluecon.com/> FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto:FreeSWITCH-users@lists.freeswitch.org> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users<http://lists.freeswitch.org/mailman/options/freeswitch-users> http://www.freeswitch.org<http://www.freeswitch.org/>

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] 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] 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

Here is debug with tracelevel at 9 and debug at 9 http://pastebin.com/vVPdACvZ TIA! Brian From: freeswitch-users-bounces@lists.freeswitch.org [mailto: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> [mailto: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<mailto: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<mailto: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<mailto: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> [mailto: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> [mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto:sofia/internal/888NXXXXXX@10.100.0.59> [KILL] _________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org<mailto:consulting@freeswitch.org> http://www.freeswitchsolutions.com<http://www.freeswitchsolutions.com/> FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com<http://www.cudatel.com/> Official FreeSWITCH Sites http://www.freeswitch.org<http://www.freeswitch.org/> http://wiki.freeswitch.org<http://wiki.freeswitch.org/> http://www.cluecon.com<http://www.cluecon.com/> FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org<mailto:FreeSWITCH-users@lists.freeswitch.org> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users<http://lists.freeswitch.org/mailman/options/freeswitch-users> http://www.freeswitch.org<http://www.freeswitch.org/> _________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org<mailto: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<mailto: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

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

http://pastebin.com/vVPdACvZ

TIA!

Brian

From: freeswitch-users-bounces@lists.freeswitch.org [mailto: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] 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] 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] 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 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

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

http://pastebin.com/vVPdACvZ

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

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