[Freeswitch-users] NORMAL_UNSPECIFIED Disconnect

Tue Feb 25 23:56:55 MSK 2014

>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> [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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto: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<mailto:sofia/internal/888NXXXXXX at 10.100.0.59> [KILL]
_________________________________________________________________________
Professional FreeSWITCH Consulting Services:
consulting at freeswitch.org<mailto:consulting at freeswitch.org>
http://www.freeswitchsolutions.com<http://www.freeswitchsolutions.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 at lists.freeswitch.org<mailto:FreeSWITCH-users at 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/>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20140225/734673af/attachment-0001.html 