[Freeswitch-dev] Unintended call termination

Tue Jan 23 02:34:20 EST 2007

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