[Freeswitch-users] NORMAL_UNSPECIFIED Disconnect

Wed Feb 26 01:21:19 MSK 2014

with freeswitch debug and sip trace would provide some useful information and context.

On Feb 25, 2014, at 4:52 PM, Brian Fertig <BFertig at doublepositive.com> 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/20140225/2b86ecfa/attachment-0001.html 