[Freeswitch-users] NORMAL_UNSPECIFIED Disconnect
Antonio
asilva at wirelessmundi.com
Wed Feb 26 03:10:15 MSK 2014
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 at lists.freeswitch.org
> [mailto:freeswitch-users-bounces at 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 at lists.freeswitch.org
> [mailto:freeswitch-users-bounces at 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 at 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 at 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 at 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 at lists.freeswitch.org
> [mailto:freeswitch-users-bounces at 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 at lists.freeswitch.org [mailto:freeswitch-users-bounces at 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 at 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 at 216.238.XXX.XXX SOFIA INIT
>
>
> 2014-02-25 11:00:04.816713 [DEBUG]
> sofia_glue.c:2744 sofia/internal/517NXXXXXX at 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 at 216.238.XXX.XXX[BREAK]
>
>
> 2014-02-25 11:00:04.836881 [DEBUG] mod_sofia.c:127
> (sofia/internal/517NXXXXXX at 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 at 216.238.XXX.XXX[BREAK]
>
>
> 2014-02-25 11:00:04.836881 [DEBUG] switch_core_state_machine.c:455
> (sofia/internal/517NXXXXXX at 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 at 216.238.XXX.XXX) Running State Change
> CS_ROUTING
>
>
> 2014-02-25 11:00:04.836881 [DEBUG] sofia.c:5811
> Channel sofia/internal/517NXXXXXX at 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 at 216.238.XXX.XXX) State ROUTING
>
>
> 2014-02-25 11:00:04.836881 [DEBUG]
> mod_sofia.c:150 sofia/internal/517NXXXXXX at 216.238.XXX.XXX SOFIA
> ROUTING
>
>
> 2014-02-25 11:00:04.836881 [DEBUG] switch_ivr_originate.c:67
> (sofia/internal/517NXXXXXX at 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 at 216.238.XXX.XXX[BREAK]
>
>
> 2014-02-25 11:00:04.836881 [DEBUG] switch_core_state_machine.c:471
> (sofia/internal/517NXXXXXX at 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 at 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 at 216.238.XXX.XXX) State CONSUME_MEDIA
>
>
> 2014-02-25 11:00:04.836881 [DEBUG] switch_core_state_machine.c:490
> (sofia/internal/517NXXXXXX at 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 at 10.100.0.59 [BREAK]
>
>
> 2014-02-25 11:00:05.716715 [DEBUG] switch_core_session.c:1016 Send
> signal sofia/internal/888NXXXXXX at 10.100.0.59 [BREAK]
>
>
> 2014-02-25 11:00:05.716715 [DEBUG] switch_core_session.c:1016 Send
> signal sofia/internal/888NXXXXXX at 10.100.0.59 [BREAK]
>
>
> 2014-02-25 11:00:05.716715 [DEBUG] switch_core_session.c:1016 Send
> signal sofia/internal/888NXXXXXX at 10.100.0.59 [BREAK]
>
>
> 2014-02-25 11:00:05.716715 [DEBUG] switch_core_session.c:1016 Send
> signal sofia/internal/888NXXXXXX at 10.100.0.59 [BREAK]
>
>
> 2014-02-25 11:00:05.736724 [DEBUG] sofia.c:5811
> Channel sofia/internal/888NXXXXXX at 10.100.0.59 entering state
> [terminating][0]
>
>
> 2014-02-25 11:00:05.736724 [NOTICE] sofia.c:6655
> Hangup sofia/internal/888NXXXXXX at 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 at 10.100.0.59 [KILL]
>
>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:
> consulting at freeswitch.org
> http://www.freeswitchsolutions.com
>
>
>
>
> Official FreeSWITCH Sites
> http://www.freeswitch.org
> http://wiki.freeswitch.org
> http://www.cluecon.com
>
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
>
>
>
>
>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:
> consulting at freeswitch.org
> http://www.freeswitchsolutions.com
>
>
>
>
> Official FreeSWITCH Sites
> http://www.freeswitch.org
> http://wiki.freeswitch.org
> http://www.cluecon.com
>
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
>
>
>
>
>
>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:
> consulting at freeswitch.org
> http://www.freeswitchsolutions.com
>
>
>
>
> Official FreeSWITCH Sites
> http://www.freeswitch.org
> http://wiki.freeswitch.org
> http://www.cluecon.com
>
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20140226/4873d634/attachment-0001.html
Join us at ClueCon 2013 Aug 6-8, 2013
More information about the FreeSWITCH-users
mailing list