[Freeswitch-dev] Unintended call termination
Ivan C Myrvold
ivan at myrvold.org
Fri May 11 02:24:11 EDT 2007
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
>
More information about the Freeswitch-dev
mailing list