[Freeswitch-dev] Unintended call termination

Anthony Minessale anthmct at yahoo.com
Fri May 11 12:28:29 EDT 2007 

whenever you post a trace you should put it on http://pastebin.freeswitch.org and tag it with your name and just put the link in the email.

Also make sure you run freeswitch like this when reproducing:

NUA_DEBUG=9 TPORT_LOG=1 /usr/local/freeswitch/bin/freeswitch


 
Anthony Minessale II

FreeSWITCH http://www.freeswitch.org/
ClueCon http://www.cluecon.com/

AIM: anthm
MSN:anthony_minessale at hotmail.com
JABBER:anthony.minessale at gmail.com
IRC: irc.freenode.net #freeswitch

FreeSWITCH Developer Conference
sip:888 at conference.freeswitch.org
iax:guest at conference.freeswitch.org/888
googletalk:conf+888 at conference.freeswitch.org
pstn:213-799-1400


----- Original Message ----
From: Ivan C Myrvold <ivan at myrvold.org>
To: freeswitch-dev at lists.freeswitch.org
Sent: Friday, May 11, 2007 1:24:11 AM
Subject: Re: [Freeswitch-dev] Unintended call termination

I am also experiencing this, on a SIPURA SPA-2000. The call is  
terminated unintended:

2007-05-10 13:14:09 [NOTICE] sofia_reg.c:69 sofia_reg_check_gateway()  
registered 213.160.242.135
2007-05-10 13:14:10 [NOTICE] sofia_reg.c:69 sofia_reg_check_gateway()  
registered 213.160.242.135
2007-05-10 13:14:10 [NOTICE] sofia_reg.c:69 sofia_reg_check_gateway()  
registered 213.160.242.135
2007-05-10 13:14:12 [NOTICE] sofia_reg.c:69 sofia_reg_check_gateway()  
registered 213.160.242.135
2007-05-10 13:14:12 [NOTICE] sofia_reg.c:69 sofia_reg_check_gateway()  
registered 213.160.242.135
2007-05-10 13:14:16 [DEBUG] switch_rtp.c:802 do_2833() Send start  
packet for [9] ts=4367360 sofar=0 dur=0 seq=26759
2007-05-10 13:14:16 [DEBUG] switch_rtp.c:802 do_2833() Send start  
packet for [9] ts=4367360 sofar=0 dur=0 seq=26759
2007-05-10 13:14:16 [DEBUG] switch_rtp.c:802 do_2833() Send start  
packet for [9] ts=4367360 sofar=0 dur=0 seq=26759
2007-05-10 13:14:16 [DEBUG] switch_rtp.c:758 do_2833() Send middle  
packet for [9] ts=4367360 sofar=160 dur=160 seq=26760
2007-05-10 13:14:16 [DEBUG] switch_rtp.c:758 do_2833() Send middle  
packet for [9] ts=4367360 sofar=320 dur=320 seq=26761
2007-05-10 13:14:16 [DEBUG] switch_rtp.c:758 do_2833() Send middle  
packet for [9] ts=4367360 sofar=480 dur=480 seq=26762
2007-05-10 13:14:16 [DEBUG] switch_rtp.c:758 do_2833() Send middle  
packet for [9] ts=4367360 sofar=640 dur=640 seq=26763
2007-05-10 13:14:16 [DEBUG] switch_rtp.c:758 do_2833() Send end  
packet for [9] ts=4367360 sofar=800 dur=800 seq=26764
2007-05-10 13:14:16 [DEBUG] switch_rtp.c:758 do_2833() Send end  
packet for [9] ts=4367360 sofar=800 dur=800 seq=26765
2007-05-10 13:14:16 [DEBUG] switch_rtp.c:758 do_2833() Send end  
packet for [9] ts=4367360 sofar=800 dur=800 seq=26766
2007-05-10 13:14:17 [NOTICE] sofia_reg.c:69 sofia_reg_check_gateway()  
registered 213.160.242.135
2007-05-10 13:14:18 [NOTICE] sofia_reg.c:69 sofia_reg_check_gateway()  
registered 213.160.242.135
2007-05-10 13:14:24 [NOTICE] sofia_reg.c:69 sofia_reg_check_gateway()  
registered 213.160.242.135
2007-05-10 13:14:25 [NOTICE] sofia_reg.c:69 sofia_reg_check_gateway()  
registered 213.160.242.135
2007-05-10 13:14:25 [NOTICE] sofia_reg.c:69 sofia_reg_check_gateway()  
registered 213.160.242.135
2007-05-10 13:14:26 [NOTICE] sofia_reg.c:69 sofia_reg_check_gateway()  
registered 213.160.242.135
2007-05-10 13:14:28 [NOTICE] sofia_reg.c:69 sofia_reg_check_gateway()  
registered 213.160.242.135
2007-05-10 13:14:29 [DEBUG] sofia.c:987 sofia_handle_sip_i_state()  
Channel sofia/imyrvold.dyndns.org/38791437 at 213.160.242.135:5060  
entering state [terminated]
2007-05-10 13:14:29 [NOTICE] sofia.c:1277 sofia_handle_sip_i_state()  
Hangup sofia/imyrvold.dyndns.org/38791437 at 213.160.242.135:5060  
[CS_EXECUTE] [NORMAL_CLEARING]
2007-05-10 13:14:29 [INFO] switch_channel.c:1055  
switch_channel_perform_hangup() Kill sofia/imyrvold.dyndns.org/ 
38791437 at 213.160.242.135:5060 [KILL]
2007-05-10 13:14:29 [DEBUG] switch_ivr_bridge.c:168  
audio_bridge_thread() write: sofia/imyrvold.dyndns.org/ 
38791437 at 213.160.242.135:5060 Bad Frame....[160] Bubye!
2007-05-10 13:14:29 [DEBUG] mod_sofia.c:779 sofia_receive_message()  
Re-activate timed RTP!
2007-05-10 13:14:29 [INFO] switch_core_session.c:345  
switch_core_session_receive_message() Kill sofia/imyrvold.dyndns.org/ 
100 [BREAK]
2007-05-10 13:14:29 [INFO] switch_ivr_bridge.c:183 audio_bridge_thread 
() Kill sofia/imyrvold.dyndns.org/38791437 at 213.160.242.135:5060 [BREAK]
2007-05-10 13:14:29 [DEBUG] switch_ivr_bridge.c:186  
audio_bridge_thread() BRIDGE THREAD DONE [sofia/imyrvold.dyndns.org/100]
2007-05-10 13:14:29 [NOTICE] switch_ivr_bridge.c:214  
audio_bridge_on_loopback() Hangup sofia/imyrvold.dyndns.org/100  
[CS_LOOPBACK] [NORMAL_CLEARING]
2007-05-10 13:14:29 [INFO] switch_channel.c:1055  
switch_channel_perform_hangup() Kill sofia/imyrvold.dyndns.org/100  
[KILL]
2007-05-10 13:14:29 [DEBUG] switch_core_state_machine.c:342  
switch_core_session_run() (sofia/imyrvold.dyndns.org/100) State HANGUP
2007-05-10 13:14:29 [DEBUG] mod_sofia.c:214 sofia_on_hangup() Channel  
sofia/imyrvold.dyndns.org/100 hanging up, cause: NORMAL_CLEARING
2007-05-10 13:14:29 [DEBUG] mod_sofia.c:230 sofia_on_hangup() Sending  
BYE to sofia/imyrvold.dyndns.org/100
2007-05-10 13:14:29 [DEBUG] switch_core_state_machine.c:45  
switch_core_standard_on_hangup() Standard HANGUP sofia/ 
imyrvold.dyndns.org/100, cause: NORMAL_CLEARING
2007-05-10 13:14:29 [DEBUG] switch_core_session.c:696  
switch_core_session_thread() Session 6 (sofia/imyrvold.dyndns.org/ 
100) Locked, Waiting on external entities
2007-05-10 13:14:29 [DEBUG] switch_ivr_bridge.c:174  
audio_bridge_thread() read: sofia/imyrvold.dyndns.org/ 
38791437 at 213.160.242.135:5060 Bad Frame.... Bubye!
2007-05-10 13:14:29 [DEBUG] mod_sofia.c:779 sofia_receive_message()  
Re-activate timed RTP!
2007-05-10 13:14:29 [INFO] switch_core_session.c:345  
switch_core_session_receive_message() Kill sofia/imyrvold.dyndns.org/ 
38791437 at 213.160.242.135:5060 [BREAK]
2007-05-10 13:14:29 [INFO] switch_ivr_bridge.c:183 audio_bridge_thread 
() Kill sofia/imyrvold.dyndns.org/100 [BREAK]
2007-05-10 13:14:29 [DEBUG] switch_ivr_bridge.c:186  
audio_bridge_thread() BRIDGE THREAD DONE [sofia/imyrvold.dyndns.org/ 
38791437 at 213.160.242.135:5060]
2007-05-10 13:14:29 [DEBUG] switch_core_state_machine.c:342  
switch_core_session_run() (sofia/imyrvold.dyndns.org/ 
38791437 at 213.160.242.135:5060) State HANGUP
2007-05-10 13:14:29 [INFO] switch_core_session.c:702  
switch_core_session_thread() Session 6 (sofia/imyrvold.dyndns.org/ 
100) Ended
2007-05-10 13:14:29 [NOTICE] switch_core_session.c:654  
switch_core_session_destroy() Close Channel sofia/imyrvold.dyndns.org/ 
100
2007-05-10 13:14:29 [DEBUG] mod_sofia.c:214 sofia_on_hangup() Channel  
sofia/imyrvold.dyndns.org/38791437 at 213.160.242.135:5060 hanging up,  
cause: NORMAL_CLEARING
2007-05-10 13:14:29 [DEBUG] switch_core_state_machine.c:45  
switch_core_standard_on_hangup() Standard HANGUP sofia/ 
imyrvold.dyndns.org/38791437 at 213.160.242.135:5060, cause:  
NORMAL_CLEARING
2007-05-10 13:14:29 [DEBUG] switch_core_session.c:696  
switch_core_session_thread() Session 5 (sofia/imyrvold.dyndns.org/ 
38791437 at 213.160.242.135:5060) Locked, Waiting on external entities
2007-05-10 13:14:29 [INFO] switch_core_session.c:702  
switch_core_session_thread() Session 5 (sofia/imyrvold.dyndns.org/ 
38791437 at 213.160.242.135:5060) Ended
2007-05-10 13:14:29 [NOTICE] switch_core_session.c:654  
switch_core_session_destroy() Close Channel sofia/imyrvold.dyndns.org/ 
38791437 at 213.160.242.135:5060

Ivan

Den 23. jan. 2007 kl. 08:34 skrev Per Møller:

> I am testing FS with a range of phones.
>
> My first problem is that when I make a call from a Snom 3xx phone  
> (www.snom.com), the moment the call is answered - the call is  
> terminated.
>
> If I instead make the call from one of my Linksys phones, the call  
> works fine.
>
> Below is the output from the console from the moment the call is  
> answered until the call was terminated. I call from locally  
> attached phone 12 to locally attached phone 11 (in this case 2 Snom  
> 360 phones).
>
> Maybe there is some indication to the problem here:
>
> 2007-01-23 07:19:12 [DEBUG] mod_sofia.c:4447 event_callback() event  
> [nua_i_error] status [500][Responding to a Non-Existing Request]  
> session: sofia/standard/12 at 192.168.11.222
> 2007-01-23 07:19:12 [DEBUG] switch_ivr.c:1961 audio_bridge_thread()  
> read: sofia/standard/12 at 192.168.11.222 Bad Frame.... Bubye!
>
> Somebody have any idea how to fix this, or perhaps some hints on  
> how to debug this further?
>
> // Per
>
> ------------------------------------------------------------
>
> 2007-01-23 07:19:12 [DEBUG] mod_sofia.c:2562 sip_i_state() Channel  
> sofia/standard/11 entering state [ready]
> 2007-01-23 07:19:12 [DEBUG] mod_sofia.c:2567 sip_i_state() Remote SDP:
> v=0
> o=root 217248721 217248722 IN IP4 192.168.11.187
> s=call
> c=IN IP4 192.168.11.187
> t=0 0
> m=audio 29442 RTP/AVP 8 101
> a=rtpmap:8 pcma/8000
> a=rtpmap:101 telephone-event/8000
> a=fmtp:101 0-16
> a=ptime:20
>
> 2007-01-23 07:19:12 [DEBUG] mod_sofia.c:2201 negotiate_sdp() Codec  
> Compare [pcma:8]/[PCMA:8]
> 2007-01-23 07:19:12 [INFO] mod_sofia.c:1379 tech_set_codec() Set  
> Codec sofia/standard/11 pcma/8000 20 ms
> 2007-01-23 07:19:12 [INFO] mod_sofia.c:1427 activate_rtp() RTP  
> [sofia/standard/11] 192.168.11.222:16408->192.168.11.187:29442  
> codec: 8 ms: 20
> 2007-01-23 07:19:12 [DEBUG] switch_rtp.c:500 switch_rtp_create()  
> Starting timer [soft] 160 bytes per 20000ms
> 2007-01-23 07:19:12 [NOTICE] mod_sofia.c:2806 sip_i_state() Channel  
> [sofia/standard/11] has been answered
> 2007-01-23 07:19:12 [INFO] mod_sofia.c:1427 activate_rtp() RTP  
> [sofia/standard/12 at 192.168.11.222] 192.168.11.222:16410- 
> >192.168.11.144:25064 codec: 8 ms: 20
> 2007-01-23 07:19:12 [DEBUG] switch_rtp.c:500 switch_rtp_create()  
> Starting timer [soft] 160 bytes per 20000ms
> 2007-01-23 07:19:12 [DEBUG] mod_sofia.c:1528 sofia_answer_channel()  
> Local SDP sofia/standard/12 at 192.168.11.222:
> v=0
> o=FreeSWITCH 164101169533152819133 164101169533152819133 IN IP4  
> 192.168.11.222
> s=FreeSWITCH
> c=IN IP4 192.168.11.222
> t=0 0
> a=sendrecv
> m=audio 16410 RTP/AVP 8 101
> a=rtpmap:8 pcma/8000
> a=ptime:20
> a=rtpmap:101 telephone-event/8000
> a=fmtp:101 0-16
>
> 2007-01-23 07:19:12 [NOTICE] switch_ivr.c:2870 switch_ivr_originate 
> () Channel [sofia/standard/12 at 192.168.11.222] has been answered
> 2007-01-23 07:19:12 [DEBUG] switch_ivr.c:2894 switch_ivr_originate 
> () Originate Resulted in Success: [sofia/standard/11]
> 2007-01-23 07:19:12 [DEBUG] mod_sofia.c:1890 sofia_receive_message 
> () De-activate timed RTP!
> 2007-01-23 07:19:12 [DEBUG] mod_sofia.c:2562 sip_i_state() Channel  
> sofia/standard/12 at 192.168.11.222 entering state [completed]
> 2007-01-23 07:19:12 [DEBUG] mod_sofia.c:1890 sofia_receive_message 
> () De-activate timed RTP!
> 2007-01-23 07:19:12 [DEBUG] switch_ivr.c:3389  
> switch_ivr_multi_threaded_bridge() sofia/standard/11 State Change  
> CS_HOLD -> CS_LOOPBACK
> 2007-01-23 07:19:12 [DEBUG] switch_core.c:3115  
> switch_core_session_run() (sofia/standard/11) State LOOPBACK
> 2007-01-23 07:19:12 [DEBUG] mod_sofia.c:1302 sofia_on_loopback()  
> SOFIA LOOPBACK
> 2007-01-23 07:19:12 [NOTICE] mod_sofia.c:4467 event_callback()  
> Hangup sofia/standard/12 at 192.168.11.222 [CS_EXECUTE]  
> [DESTINATION_OUT_OF_ORDER]
> 2007-01-23 07:19:12 [INFO] switch_channel.c:969  
> switch_channel_perform_hangup() Kill sofia/standard/ 
> 12 at 192.168.11.222 [1]
> 2007-01-23 07:19:12 [DEBUG] mod_sofia.c:2562 sip_i_state() Channel  
> sofia/standard/12 at 192.168.11.222 entering state [ready]
> 2007-01-23 07:19:12 [DEBUG] mod_sofia.c:4447 event_callback() event  
> [nua_i_error] status [500][Responding to a Non-Existing Request]  
> session: sofia/standard/12 at 192.168.11.222
> 2007-01-23 07:19:12 [DEBUG] switch_ivr.c:1961 audio_bridge_thread()  
> read: sofia/standard/12 at 192.168.11.222 Bad Frame.... Bubye!
> 2007-01-23 07:19:12 [INFO] switch_ivr.c:1968 audio_bridge_thread()  
> Kill sofia/standard/11 [3]
> 2007-01-23 07:19:12 [DEBUG] mod_sofia.c:1896 sofia_receive_message 
> () Re-activate timed RTP!
> 2007-01-23 07:19:12 [DEBUG] switch_ivr.c:1975 audio_bridge_thread()  
> BRIDGE THREAD DONE [sofia/standard/12 at 192.168.11.222]
> 2007-01-23 07:19:12 [NOTICE] switch_ivr.c:2001  
> audio_bridge_on_loopback() Hangup sofia/standard/11 [CS_LOOPBACK]  
> [NORMAL_CLEARING]
> 2007-01-23 07:19:12 [INFO] switch_channel.c:969  
> switch_channel_perform_hangup() Kill sofia/standard/11 [1]
> 2007-01-23 07:19:12 [DEBUG] switch_core.c:2970  
> switch_core_session_run() (sofia/standard/11) State HANGUP
> 2007-01-23 07:19:12 [INFO] switch_ivr.c:1968 audio_bridge_thread()  
> Kill sofia/standard/12 at 192.168.11.222 [3]
> 2007-01-23 07:19:12 [DEBUG] mod_sofia.c:1896 sofia_receive_message 
> () Re-activate timed RTP!
> 2007-01-23 07:19:12 [DEBUG] switch_ivr.c:1975 audio_bridge_thread()  
> BRIDGE THREAD DONE [sofia/standard/11]
> 2007-01-23 07:19:12 [DEBUG] switch_core.c:2970  
> switch_core_session_run() (sofia/standard/12 at 192.168.11.222) State  
> HANGUP
> 2007-01-23 07:19:12 [DEBUG] mod_sofia.c:1251 sofia_on_hangup()  
> Channel sofia/standard/11 hanging up, cause: NORMAL_CLEARING
> 2007-01-23 07:19:12 [DEBUG] mod_sofia.c:1267 sofia_on_hangup()  
> Sending BYE to sofia/standard/11
> 2007-01-23 07:19:12 [DEBUG] switch_core.c:2674  
> switch_core_standard_on_hangup() Standard HANGUP sofia/standard/11,  
> cause: NORMAL_CLEARING
> 2007-01-23 07:19:12 [DEBUG] switch_core.c:3413  
> switch_core_session_thread() Session 14 (sofia/standard/11) Locked,  
> Waiting on external entities
> 2007-01-23 07:19:12 [INFO] switch_core.c:3418  
> switch_core_session_thread() Session 14 (sofia/standard/11) Ended
> 2007-01-23 07:19:12 [NOTICE] switch_core.c:3294  
> switch_core_session_destroy() Close Channel sofia/standard/11
> 2007-01-23 07:19:12 [DEBUG] mod_sofia.c:1251 sofia_on_hangup()  
> Channel sofia/standard/12 at 192.168.11.222 hanging up, cause:  
> DESTINATION_OUT_OF_ORDER
> 2007-01-23 07:19:12 [DEBUG] mod_sofia.c:1267 sofia_on_hangup()  
> Sending BYE to sofia/standard/12 at 192.168.11.222
> 2007-01-23 07:19:12 [DEBUG] switch_core.c:2674  
> switch_core_standard_on_hangup() Standard HANGUP sofia/standard/ 
> 12 at 192.168.11.222,cause: DESTINATION_OUT_OF_ORDER
> 2007-01-23 07:19:12 [DEBUG] switch_core.c:3413  
> switch_core_session_thread() Session 13 (sofia/standard/ 
> 12 at 192.168.11.222) Locked,Waiting on external entities
> 2007-01-23 07:19:12 [INFO] switch_core.c:3418  
> switch_core_session_thread() Session 13 (sofia/standard/ 
> 12 at 192.168.11.222) Ended
> 2007-01-23 07:19:12 [NOTICE] switch_core.c:3294  
> switch_core_session_destroy() Close Channel sofia/standard/ 
> 12 at 192.168.11.222
>
>
> _______________________________________________
> Freeswitch-dev mailing list
> Freeswitch-dev at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev
> http://www.freeswitch.org
>


_______________________________________________
Freeswitch-dev mailing list
Freeswitch-dev at lists.freeswitch.org
http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev
http://www.freeswitch.org







       
____________________________________________________________________________________Be a better Globetrotter. Get better travel answers from someone who knows. Yahoo! Answers - Check it out.
http://answers.yahoo.com/dir/?link=list&sid=396545469
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-dev/attachments/20070511/4564ce08/attachment-0001.html

More information about the Freeswitch-dev mailing list