FreeSWITCH api hangup and answer hook - call sometimes prematurely ends
Hi, when using the hangup and answer hooks a call *sometimes* ends prematurely. This happens about 1 of 10 times regardless of phone type and number dialled. The logs show nothing strange as you can see below. The only thing I see is that the call is hung up and that everything happens in the same second. Removing the hooks solves the issue. Logs: FreeSWITCH>2008-10-09 10:35:53 [NOTICE] switch_channel.c:552 switch_channel_set_name() New Channel sofia/internal/polycom501@fs.voip.domain.com [48ca287c-95dd-11dd-868f-bf36e200c978] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_NEW 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:371 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State NEW 2008-10-09 10:35:53 [DEBUG] sofia.c:2257 sofia_handle_sip_i_state() Channel sofia/internal/polycom501@fs.voip.domain.com entering state [received] 2008-10-09 10:35:53 [DEBUG] sofia.c:2261 sofia_handle_sip_i_state() Remote SDP: v=0 o=- 1223463186 1223463186 IN IP4 192.168.1.190 s=Polycom IP Phone c=IN IP4 192.168.1.190 t=0 0 a=sendrecv m=audio 2242 RTP/AVP 8 0 18 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:2353 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMA:8:8000]/[G722:9:8000] 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:2353 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMA:8:8000]/[PCMA:8:8000] 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:1562 sofia_glue_tech_set_codec() Set Codec sofia/internal/polycom501@fs.voip.domain.com PCMA/8000 20 ms 160 samples 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:2317 sofia_glue_negotiate_sdp() Set 2833 dtmf payload to 101 2008-10-09 10:35:53 [DEBUG] sofia.c:2402 sofia_handle_sip_i_state() sofia/internal/polycom501@fs.voip.domain.com State Change CS_NEW -> CS_INIT 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_INIT 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:417 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State INIT 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:80 sofia_on_init() sofia/internal/polycom501@fs.voip.domain.com SOFIA INIT 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:107 sofia_on_init() sofia/internal/polycom501@fs.voip.domain.com State Change CS_INIT -> CS_ROUTING 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:417 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State INIT going to sleep 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_ROUTING 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:422 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State ROUTING 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:121 sofia_on_routing() sofia/internal/polycom501@fs.voip.domain.com SOFIA ROUTING 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:64 switch_core_standard_on_routing() sofia/internal/polycom501@fs.voip.domain.com Standard ROUTING 2008-10-09 10:35:53 [INFO] mod_dialplan_xml.c:232 dialplan_hunt() Processing polycom501->198 in context default 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:97 switch_core_standard_on_routing() sofia/internal/polycom501@fs.voip.domain.com State Change CS_ROUTING -> CS_EXECUTE 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:422 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State ROUTING going to sleep 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_EXECUTE 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:432 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State EXECUTE 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:164 sofia_on_execute() sofia/internal/polycom501@fs.voip.domain.com SOFIA EXECUTE 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:129 switch_core_standard_on_execute() sofia/internal/polycom501@fs.voip.domain.com Standard EXECUTE 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:144 switch_core_standard_on_execute() sofia/internal/polycom501@fs.voip.domain.com Execute respond(407) 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:1030 sofia_receive_message() Challenging call 198@fs.voip.domain.com 2008-10-09 10:35:53 [NOTICE] mod_sofia.c:1032 sofia_receive_message() Hangup sofia/internal/polycom501@fs.voip.domain.com [CS_EXECUTE] [USER_CHALLENGE] 2008-10-09 10:35:53 [DEBUG] switch_channel.c:1434 switch_channel_perform_hangup() Send signal sofia/internal/polycom501@fs.voip.domain.com [KILL] 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] sofia.c:200 sofia_event_callback() event [nua_i_state] status [407][Proxy Authentication Required] session: sofia/internal/polycom501@fs.voip.domain.com 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:435 switch_core_session_receive_message() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] sofia.c:208 sofia_event_callback() Channel is already hungup. 2008-10-09 10:35:53 [DEBUG] sofia.c:200 sofia_event_callback() event [nua_i_terminated] status [407][Proxy Authentication Required] session: sofia/internal/polycom501@fs.voip.domain.com 2008-10-09 10:35:53 [DEBUG] sofia.c:208 sofia_event_callback() Channel is already hungup. 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:432 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State EXECUTE going to sleep 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_HANGUP 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:395 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State HANGUP 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:272 sofia_on_hangup() Channel sofia/internal/polycom501@fs.voip.domain.com hanging up, cause: USER_CHALLENGE 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:346 sofia_on_hangup() Responding to INVITE with: 480 2008-10-09 10:35:53 [DEBUG] sofia.c:200 sofia_event_callback() event [nua_i_error] status [500][Responding to a Non-Existing Request] session: n/a 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() sofia/internal/polycom501@fs.voip.domain.com Standard HANGUP, cause: USER_CHALLENGE 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:395 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State HANGUP going to sleep 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:815 switch_core_session_thread() Session 69 (sofia/internal/polycom501@fs.voip.domain.com) Locked, Waiting on external entities 2008-10-09 10:35:53 [NOTICE] switch_core_session.c:833 switch_core_session_thread() Session 69 (sofia/internal/polycom501@fs.voip.domain.com) Ended 2008-10-09 10:35:53 [NOTICE] switch_core_session.c:835 switch_core_session_thread() Close Channel sofia/internal/polycom501@fs.voip.domain.com [CS_HANGUP] 2008-10-09 10:35:53 [NOTICE] switch_channel.c:552 switch_channel_set_name() New Channel sofia/internal/polycom501@fs.voip.domain.com [48e48e06-95dd-11dd-868f-bf36e200c978] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_NEW 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:371 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State NEW 2008-10-09 10:35:53 [DEBUG] sofia.c:2257 sofia_handle_sip_i_state() Channel sofia/internal/polycom501@fs.voip.domain.com entering state [received] 2008-10-09 10:35:53 [DEBUG] sofia.c:2261 sofia_handle_sip_i_state() Remote SDP: v=0 o=- 1223463186 1223463186 IN IP4 192.168.1.190 s=Polycom IP Phone c=IN IP4 192.168.1.190 t=0 0 a=sendrecv m=audio 2242 RTP/AVP 8 0 18 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:2353 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMA:8:8000]/[G722:9:8000] 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:2353 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMA:8:8000]/[PCMA:8:8000] 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:1562 sofia_glue_tech_set_codec() Set Codec sofia/internal/polycom501@fs.voip.domain.com PCMA/8000 20 ms 160 samples 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:2317 sofia_glue_negotiate_sdp() Set 2833 dtmf payload to 101 2008-10-09 10:35:53 [DEBUG] sofia.c:2402 sofia_handle_sip_i_state() sofia/internal/polycom501@fs.voip.domain.com State Change CS_NEW -> CS_INIT 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_INIT 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:417 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State INIT 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:80 sofia_on_init() sofia/internal/polycom501@fs.voip.domain.com SOFIA INIT 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:107 sofia_on_init() sofia/internal/polycom501@fs.voip.domain.com State Change CS_INIT -> CS_ROUTING 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:417 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State INIT going to sleep 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_ROUTING 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:422 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State ROUTING 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:121 sofia_on_routing() sofia/internal/polycom501@fs.voip.domain.com SOFIA ROUTING 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:64 switch_core_standard_on_routing() sofia/internal/polycom501@fs.voip.domain.com Standard ROUTING 2008-10-09 10:35:53 [INFO] mod_dialplan_xml.c:232 dialplan_hunt() Processing polycom501->198 in context default 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:97 switch_core_standard_on_routing() sofia/internal/polycom501@fs.voip.domain.com State Change CS_ROUTING -> CS_EXECUTE 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:422 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State ROUTING going to sleep 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_EXECUTE 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:432 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State EXECUTE 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:164 sofia_on_execute() sofia/internal/polycom501@fs.voip.domain.com SOFIA EXECUTE 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:129 switch_core_standard_on_execute() sofia/internal/polycom501@fs.voip.domain.com Standard EXECUTE 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:144 switch_core_standard_on_execute() sofia/internal/polycom501@fs.voip.domain.com Execute set(destination_number_normalized=47198) 2008-10-09 10:35:53 [DEBUG] mod_dptools.c:703 set_function() SET [destination_number_normalized]=[47198] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:144 switch_core_standard_on_execute() sofia/internal/polycom501@fs.voip.domain.com Execute set(destination_number_type=special_number) 2008-10-09 10:35:53 [DEBUG] mod_dptools.c:703 set_function() SET [destination_number_type]=[special_number] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:144 switch_core_standard_on_execute() sofia/internal/polycom501@fs.voip.domain.com Execute set(execute_on_answer=lua fire_channel_answered_event.lua) 2008-10-09 10:35:53 [DEBUG] mod_dptools.c:703 set_function() SET [execute_on_answer]=[lua fire_channel_answered_event.lua] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:144 switch_core_standard_on_execute() sofia/internal/polycom501@fs.voip.domain.com Execute set(api_hangup_hook=lua fire_channel_hangup_event.lua ${uuid}) 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:1080 switch_core_session_execute_application() sofia/internal/polycom501@fs.voip.domain.com Expanded String set(api_hangup_hook=lua fire_channel_hangup_event.lua 48e48e06-95dd-11dd-868f-bf36e200c978) 2008-10-09 10:35:53 [DEBUG] mod_dptools.c:703 set_function() SET [api_hangup_hook]=[lua fire_channel_hangup_event.lua 48e48e06-95dd-11dd-868f-bf36e200c978] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:144 switch_core_standard_on_execute() sofia/internal/polycom501@fs.voip.domain.com Execute javascript(ps_pizza.js) 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:1779 sofia_glue_activate_rtp() AUDIO RTP [sofia/internal/polycom501@fs.voip.domain.com] 10.100.4.192 port 58534 -> 192.168.1.190 port 2242 codec: 8 ms: 20 2008-10-09 10:35:53 [DEBUG] switch_rtp.c:833 switch_rtp_create() Starting timer [soft] 160 bytes per 20000ms 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:1949 sofia_glue_activate_rtp() Set comfort noise payload to 13 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:446 sofia_answer_channel() Local SDP sofia/internal/polycom501@fs.voip.domain.com: v=0 o=FreeSWITCH 1223482819 1223482820 IN IP4 10.100.4.192 s=FreeSWITCH c=IN IP4 10.100.4.192 t=0 0 a=sendrecv m=audio 58534 RTP/AVP 8 101 13 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:435 switch_core_session_receive_message() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [NOTICE] mod_spidermonkey.c:2034 session_answer() Channel [sofia/internal/polycom501@fs.voip.domain.com] has been answered 2008-10-09 10:35:53 [DEBUG] switch_channel.c:1658 switch_channel_perform_mark_answered() sofia/internal/polycom501@fs.voip.domain.com execute on answer: lua(fire_channel_answered_event.lua)2008-10-09 10:35:53 [DEBUG] sofia.c:2257 sofia_handle_sip_i_state() Channel sofia/internal/polycom501@fs.voip.domain.com entering state [completed] 2008-10-09 10:35:53 [INFO] switch_cpp.cpp:1090 console_log() Firing a CUSTOM event with subclass call::startmonitor... 2008-10-09 10:35:53 [INFO] switch_cpp.cpp:1090 console_log() Channel answered event fired. 2008-10-09 10:35:53 [DEBUG] switch_cpp.cpp:881 destroy() destroy/unlink session from object 2008-10-09 10:35:53 [NOTICE] switch_cpp.cpp:883 destroy() Hangup sofia/internal/polycom501@fs.voip.domain.com [CS_EXECUTE] [NORMAL_CLEARING] 2008-10-09 10:35:53 [DEBUG] switch_channel.c:1434 switch_channel_perform_hangup() Send signal sofia/internal/polycom501@fs.voip.domain.com [KILL] 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:432 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State EXECUTE going to sleep 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_HANGUP 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:395 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State HANGUP 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:272 sofia_on_hangup() Channel sofia/internal/polycom501@fs.voip.domain.com hanging up, cause: NORMAL_CLEARING 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:329 sofia_on_hangup() Sending BYE to sofia/internal/polycom501@fs.voip.domain.com 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() sofia/internal/polycom501@fs.voip.domain.com Standard HANGUP, cause: NORMAL_CLEARING 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:395 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State HANGUP going to sleep 2008-10-09 10:35:53 [INFO] switch_cpp.cpp:1090 console_log() Firing a CUSTOM event with subclass call::stopmonitor... 2008-10-09 10:35:53 [INFO] switch_cpp.cpp:1090 console_log() Channel hangup event fired. 2008-10-09 10:35:53 [DEBUG] switch_cpp.cpp:881 destroy() destroy/unlink session from object 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:409 switch_core_session_run() Hangup Command lua(fire_channel_hangup_event.lua 48e48e06-95dd-11dd-868f-bf36e200c978): 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:815 switch_core_session_thread() Session 70 (sofia/internal/polycom501@fs.voip.domain.com) Locked, Waiting on external entities 2008-10-09 10:35:53 [NOTICE] switch_core_session.c:833 switch_core_session_thread() Session 70 (sofia/internal/polycom501@fs.voip.domain.com) Ended 2008-10-09 10:35:53 [NOTICE] switch_core_session.c:835 switch_core_session_thread() Close Channel sofia/internal/polycom501@fs.voip.domain.com [CS_HANGUP] The dialplan: <document type="freeswitch/xml"> <section name="dialplan" description="special_number Dialplan for 47196 (196)"> <context name="default"> <extension name="test"> <condition> <action application="set" data="destination_number_normalized=47196"/> <action application="set" data="destination_number_type=special_number"/> <action application="set" data="execute_on_answer=lua fire_channel_answered_event.lua"/> <action application="set" data="api_hangup_hook=lua fire_channel_hangup_event.lua ${uuid}"/> <action application="answer" data=""/> <action application="playback" data="$${hold_music}"/> </condition> </extension> </context> </section> </document>
I think there is an uninitialized member in the c++ class that makes the autoHangup flag set when it shouldnt be. you can fix it in your lua by doing session:setAutoHangup(false) or if you update to latest trunk it should be ok. On Thu, Oct 9, 2008 at 3:43 AM, Mikael A. Bjerkeland <mikael@bjerkeland.com>wrote:
Hi,
when using the hangup and answer hooks a call *sometimes* ends prematurely. This happens about 1 of 10 times regardless of phone type and number dialled.
The logs show nothing strange as you can see below. The only thing I see is that the call is hung up and that everything happens in the same second. Removing the hooks solves the issue.
Logs:
FreeSWITCH>2008-10-09 10:35:53 [NOTICE] switch_channel.c:552 switch_channel_set_name() New Channel sofia/internal/polycom501@fs.voip.domain.com [48ca287c-95dd-11dd-868f-bf36e200c978] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_NEW 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:371 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State NEW 2008-10-09 10:35:53 [DEBUG] sofia.c:2257 sofia_handle_sip_i_state() Channel sofia/internal/polycom501@fs.voip.domain.com entering state [received] 2008-10-09 10:35:53 [DEBUG] sofia.c:2261 sofia_handle_sip_i_state() Remote SDP: v=0 o=- 1223463186 1223463186 IN IP4 192.168.1.190 s=Polycom IP Phone c=IN IP4 192.168.1.190 t=0 0 a=sendrecv m=audio 2242 RTP/AVP 8 0 18 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000
2008-10-09 10:35:53 [DEBUG] sofia_glue.c:2353 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMA:8:8000]/[G722:9:8000] 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:2353 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMA:8:8000]/[PCMA:8:8000] 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:1562 sofia_glue_tech_set_codec() Set Codec sofia/internal/polycom501@fs.voip.domain.com PCMA/8000 20 ms 160 samples 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:2317 sofia_glue_negotiate_sdp() Set 2833 dtmf payload to 101 2008-10-09 10:35:53 [DEBUG] sofia.c:2402 sofia_handle_sip_i_state() sofia/internal/polycom501@fs.voip.domain.com State Change CS_NEW -> CS_INIT 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_INIT 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:417 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State INIT 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:80 sofia_on_init() sofia/internal/polycom501@fs.voip.domain.com SOFIA INIT 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:107 sofia_on_init() sofia/internal/polycom501@fs.voip.domain.com State Change CS_INIT -> CS_ROUTING 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:417 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State INIT going to sleep 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_ROUTING 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:422 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State ROUTING 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:121 sofia_on_routing() sofia/internal/polycom501@fs.voip.domain.com SOFIA ROUTING 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:64 switch_core_standard_on_routing() sofia/internal/polycom501@fs.voip.domain.com Standard ROUTING 2008-10-09 10:35:53 [INFO] mod_dialplan_xml.c:232 dialplan_hunt() Processing polycom501->198 in context default 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:97 switch_core_standard_on_routing() sofia/internal/polycom501@fs.voip.domain.com State Change CS_ROUTING -> CS_EXECUTE 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:422 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State ROUTING going to sleep 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_EXECUTE 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:432 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State EXECUTE 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:164 sofia_on_execute() sofia/internal/polycom501@fs.voip.domain.com SOFIA EXECUTE 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:129 switch_core_standard_on_execute() sofia/internal/polycom501@fs.voip.domain.com Standard EXECUTE 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:144 switch_core_standard_on_execute() sofia/internal/polycom501@fs.voip.domain.com Execute respond(407) 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:1030 sofia_receive_message() Challenging call 198@fs.voip.domain.com 2008-10-09 10:35:53 [NOTICE] mod_sofia.c:1032 sofia_receive_message() Hangup sofia/internal/polycom501@fs.voip.domain.com [CS_EXECUTE] [USER_CHALLENGE] 2008-10-09 10:35:53 [DEBUG] switch_channel.c:1434 switch_channel_perform_hangup() Send signal sofia/internal/polycom501@fs.voip.domain.com [KILL] 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] sofia.c:200 sofia_event_callback() event [nua_i_state] status [407][Proxy Authentication Required] session: sofia/internal/polycom501@fs.voip.domain.com 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:435 switch_core_session_receive_message() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] sofia.c:208 sofia_event_callback() Channel is already hungup. 2008-10-09 10:35:53 [DEBUG] sofia.c:200 sofia_event_callback() event [nua_i_terminated] status [407][Proxy Authentication Required] session: sofia/internal/polycom501@fs.voip.domain.com 2008-10-09 10:35:53 [DEBUG] sofia.c:208 sofia_event_callback() Channel is already hungup. 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:432 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State EXECUTE going to sleep 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_HANGUP 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:395 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State HANGUP 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:272 sofia_on_hangup() Channel sofia/internal/polycom501@fs.voip.domain.com hanging up, cause: USER_CHALLENGE 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:346 sofia_on_hangup() Responding to INVITE with: 480 2008-10-09 10:35:53 [DEBUG] sofia.c:200 sofia_event_callback() event [nua_i_error] status [500][Responding to a Non-Existing Request] session: n/a 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() sofia/internal/polycom501@fs.voip.domain.com Standard HANGUP, cause: USER_CHALLENGE 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:395 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State HANGUP going to sleep 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:815 switch_core_session_thread() Session 69 (sofia/internal/polycom501@fs.voip.domain.com) Locked, Waiting on external entities 2008-10-09 10:35:53 [NOTICE] switch_core_session.c:833 switch_core_session_thread() Session 69 (sofia/internal/polycom501@fs.voip.domain.com) Ended 2008-10-09 10:35:53 [NOTICE] switch_core_session.c:835 switch_core_session_thread() Close Channel sofia/internal/polycom501@fs.voip.domain.com [CS_HANGUP] 2008-10-09 10:35:53 [NOTICE] switch_channel.c:552 switch_channel_set_name() New Channel sofia/internal/polycom501@fs.voip.domain.com [48e48e06-95dd-11dd-868f-bf36e200c978] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_NEW 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:371 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State NEW 2008-10-09 10:35:53 [DEBUG] sofia.c:2257 sofia_handle_sip_i_state() Channel sofia/internal/polycom501@fs.voip.domain.com entering state [received] 2008-10-09 10:35:53 [DEBUG] sofia.c:2261 sofia_handle_sip_i_state() Remote SDP: v=0 o=- 1223463186 1223463186 IN IP4 192.168.1.190 s=Polycom IP Phone c=IN IP4 192.168.1.190 t=0 0 a=sendrecv m=audio 2242 RTP/AVP 8 0 18 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000
2008-10-09 10:35:53 [DEBUG] sofia_glue.c:2353 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMA:8:8000]/[G722:9:8000] 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:2353 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMA:8:8000]/[PCMA:8:8000] 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:1562 sofia_glue_tech_set_codec() Set Codec sofia/internal/polycom501@fs.voip.domain.com PCMA/8000 20 ms 160 samples 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:2317 sofia_glue_negotiate_sdp() Set 2833 dtmf payload to 101 2008-10-09 10:35:53 [DEBUG] sofia.c:2402 sofia_handle_sip_i_state() sofia/internal/polycom501@fs.voip.domain.com State Change CS_NEW -> CS_INIT 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_INIT 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:417 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State INIT 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:80 sofia_on_init() sofia/internal/polycom501@fs.voip.domain.com SOFIA INIT 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:107 sofia_on_init() sofia/internal/polycom501@fs.voip.domain.com State Change CS_INIT -> CS_ROUTING 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:417 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State INIT going to sleep 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_ROUTING 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:422 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State ROUTING 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:121 sofia_on_routing() sofia/internal/polycom501@fs.voip.domain.com SOFIA ROUTING 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:64 switch_core_standard_on_routing() sofia/internal/polycom501@fs.voip.domain.com Standard ROUTING 2008-10-09 10:35:53 [INFO] mod_dialplan_xml.c:232 dialplan_hunt() Processing polycom501->198 in context default 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:97 switch_core_standard_on_routing() sofia/internal/polycom501@fs.voip.domain.com State Change CS_ROUTING -> CS_EXECUTE 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:422 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State ROUTING going to sleep 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_EXECUTE 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:432 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State EXECUTE 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:164 sofia_on_execute() sofia/internal/polycom501@fs.voip.domain.com SOFIA EXECUTE 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:129 switch_core_standard_on_execute() sofia/internal/polycom501@fs.voip.domain.com Standard EXECUTE 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:144 switch_core_standard_on_execute() sofia/internal/polycom501@fs.voip.domain.com Execute set(destination_number_normalized=47198) 2008-10-09 10:35:53 [DEBUG] mod_dptools.c:703 set_function() SET [destination_number_normalized]=[47198] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:144 switch_core_standard_on_execute() sofia/internal/polycom501@fs.voip.domain.com Execute set(destination_number_type=special_number) 2008-10-09 10:35:53 [DEBUG] mod_dptools.c:703 set_function() SET [destination_number_type]=[special_number] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:144 switch_core_standard_on_execute() sofia/internal/polycom501@fs.voip.domain.com Execute set(execute_on_answer=lua fire_channel_answered_event.lua) 2008-10-09 10:35:53 [DEBUG] mod_dptools.c:703 set_function() SET [execute_on_answer]=[lua fire_channel_answered_event.lua] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:144 switch_core_standard_on_execute() sofia/internal/polycom501@fs.voip.domain.com Execute set(api_hangup_hook=lua fire_channel_hangup_event.lua ${uuid}) 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:1080 switch_core_session_execute_application() sofia/internal/polycom501@fs.voip.domain.com Expanded String set(api_hangup_hook=lua fire_channel_hangup_event.lua 48e48e06-95dd-11dd-868f-bf36e200c978) 2008-10-09 10:35:53 [DEBUG] mod_dptools.c:703 set_function() SET [api_hangup_hook]=[lua fire_channel_hangup_event.lua 48e48e06-95dd-11dd-868f-bf36e200c978] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:144 switch_core_standard_on_execute() sofia/internal/polycom501@fs.voip.domain.com Execute javascript(ps_pizza.js) 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:1779 sofia_glue_activate_rtp() AUDIO RTP [sofia/internal/polycom501@fs.voip.domain.com] 10.100.4.192 port 58534 -> 192.168.1.190 port 2242 codec: 8 ms: 20 2008-10-09 10:35:53 [DEBUG] switch_rtp.c:833 switch_rtp_create() Starting timer [soft] 160 bytes per 20000ms 2008-10-09 10:35:53 [DEBUG] sofia_glue.c:1949 sofia_glue_activate_rtp() Set comfort noise payload to 13 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:446 sofia_answer_channel() Local SDP sofia/internal/polycom501@fs.voip.domain.com: v=0 o=FreeSWITCH 1223482819 1223482820 IN IP4 10.100.4.192 s=FreeSWITCH c=IN IP4 10.100.4.192 t=0 0 a=sendrecv m=audio 58534 RTP/AVP 8 101 13 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20
2008-10-09 10:35:53 [DEBUG] switch_core_session.c:435 switch_core_session_receive_message() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [NOTICE] mod_spidermonkey.c:2034 session_answer() Channel [sofia/internal/polycom501@fs.voip.domain.com] has been answered 2008-10-09 10:35:53 [DEBUG] switch_channel.c:1658 switch_channel_perform_mark_answered() sofia/internal/polycom501@fs.voip.domain.com execute on answer: lua(fire_channel_answered_event.lua)2008-10-09 10:35:53 [DEBUG] sofia.c:2257 sofia_handle_sip_i_state() Channel sofia/internal/polycom501@fs.voip.domain.com entering state [completed] 2008-10-09 10:35:53 [INFO] switch_cpp.cpp:1090 console_log() Firing a CUSTOM event with subclass call::startmonitor... 2008-10-09 10:35:53 [INFO] switch_cpp.cpp:1090 console_log() Channel answered event fired. 2008-10-09 10:35:53 [DEBUG] switch_cpp.cpp:881 destroy() destroy/unlink session from object 2008-10-09 10:35:53 [NOTICE] switch_cpp.cpp:883 destroy() Hangup sofia/internal/polycom501@fs.voip.domain.com [CS_EXECUTE] [NORMAL_CLEARING] 2008-10-09 10:35:53 [DEBUG] switch_channel.c:1434 switch_channel_perform_hangup() Send signal sofia/internal/polycom501@fs.voip.domain.com [KILL] 2008-10-09 10:35:53 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/internal/polycom501@fs.voip.domain.com [BREAK] 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:432 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State EXECUTE going to sleep 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() sofia/internal/polycom501@fs.voip.domain.com Running State Change CS_HANGUP 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:395 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State HANGUP 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:272 sofia_on_hangup() Channel sofia/internal/polycom501@fs.voip.domain.com hanging up, cause: NORMAL_CLEARING 2008-10-09 10:35:53 [DEBUG] mod_sofia.c:329 sofia_on_hangup() Sending BYE to sofia/internal/polycom501@fs.voip.domain.com 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() sofia/internal/polycom501@fs.voip.domain.com Standard HANGUP, cause: NORMAL_CLEARING 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:395 switch_core_session_run() (sofia/internal/polycom501@fs.voip.domain.com) State HANGUP going to sleep 2008-10-09 10:35:53 [INFO] switch_cpp.cpp:1090 console_log() Firing a CUSTOM event with subclass call::stopmonitor... 2008-10-09 10:35:53 [INFO] switch_cpp.cpp:1090 console_log() Channel hangup event fired. 2008-10-09 10:35:53 [DEBUG] switch_cpp.cpp:881 destroy() destroy/unlink session from object 2008-10-09 10:35:53 [DEBUG] switch_core_state_machine.c:409 switch_core_session_run() Hangup Command lua(fire_channel_hangup_event.lua 48e48e06-95dd-11dd-868f-bf36e200c978):
2008-10-09 10:35:53 [DEBUG] switch_core_session.c:815 switch_core_session_thread() Session 70 (sofia/internal/polycom501@fs.voip.domain.com) Locked, Waiting on external entities 2008-10-09 10:35:53 [NOTICE] switch_core_session.c:833 switch_core_session_thread() Session 70 (sofia/internal/polycom501@fs.voip.domain.com) Ended 2008-10-09 10:35:53 [NOTICE] switch_core_session.c:835 switch_core_session_thread() Close Channel sofia/internal/polycom501@fs.voip.domain.com [CS_HANGUP]
The dialplan: <document type="freeswitch/xml"> <section name="dialplan" description="special_number Dialplan for 47196 (196)"> <context name="default"> <extension name="test"> <condition> <action application="set" data="destination_number_normalized=47196"/> <action application="set" data="destination_number_type=special_number"/> <action application="set" data="execute_on_answer=lua fire_channel_answered_event.lua"/> <action application="set" data="api_hangup_hook=lua fire_channel_hangup_event.lua ${uuid}"/> <action application="answer" data=""/> <action application="playback" data="$${hold_music}"/> </condition> </extension> </context> </section> </document>
_______________________________________________ Freeswitch-dev mailing list Freeswitch-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
-- Anthony Minessale II FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ AIM: anthm MSN:anthony_minessale@hotmail.com <MSN%3Aanthony_minessale@hotmail.com> GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com<PAYPAL%3Aanthony.minessale@gmail.com> IRC: irc.freenode.net #freeswitch FreeSWITCH Developer Conference sip:888@conference.freeswitch.org <sip%3A888@conference.freeswitch.org> iax:guest@conference.freeswitch.org/888 googletalk:conf+888@conference.freeswitch.org<googletalk%3Aconf%2B888@conference.freeswitch.org> pstn:213-799-1400
participants (2)
-
Anthony Minessale
-
Mikael A. Bjerkeland