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