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> [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/>