[Freeswitch-dev] FreeSWITCH api hangup and answer hook - call sometimes prematurely ends

Thu Oct 9 04:43:30 EDT 2008

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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at fs.voip.domain.com)
State INIT
2008-10-09 10:35:53 [DEBUG] mod_sofia.c:80 sofia_on_init()
sofia/internal/polycom501 at fs.voip.domain.com SOFIA INIT
2008-10-09 10:35:53 [DEBUG] mod_sofia.c:107 sofia_on_init()
sofia/internal/polycom501 at 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 at 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 at 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 at 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 at fs.voip.domain.com)
State ROUTING
2008-10-09 10:35:53 [DEBUG] mod_sofia.c:121 sofia_on_routing()
sofia/internal/polycom501 at 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 at 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 at 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 at 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 at 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 at 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 at fs.voip.domain.com)
State EXECUTE
2008-10-09 10:35:53 [DEBUG] mod_sofia.c:164 sofia_on_execute()
sofia/internal/polycom501 at 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 at 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 at fs.voip.domain.com Execute respond(407)
2008-10-09 10:35:53 [DEBUG] mod_sofia.c:1030 sofia_receive_message()
Challenging call 198 at fs.voip.domain.com
2008-10-09 10:35:53 [NOTICE] mod_sofia.c:1032 sofia_receive_message()
Hangup sofia/internal/polycom501 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at fs.voip.domain.com)
State HANGUP
2008-10-09 10:35:53 [DEBUG] mod_sofia.c:272 sofia_on_hangup() Channel
sofia/internal/polycom501 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at fs.voip.domain.com)
State INIT
2008-10-09 10:35:53 [DEBUG] mod_sofia.c:80 sofia_on_init()
sofia/internal/polycom501 at fs.voip.domain.com SOFIA INIT
2008-10-09 10:35:53 [DEBUG] mod_sofia.c:107 sofia_on_init()
sofia/internal/polycom501 at 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 at 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 at 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 at 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 at fs.voip.domain.com)
State ROUTING
2008-10-09 10:35:53 [DEBUG] mod_sofia.c:121 sofia_on_routing()
sofia/internal/polycom501 at 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 at 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 at 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 at 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 at 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 at 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 at fs.voip.domain.com)
State EXECUTE
2008-10-09 10:35:53 [DEBUG] mod_sofia.c:164 sofia_on_execute()
sofia/internal/polycom501 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at fs.voip.domain.com [BREAK]
2008-10-09 10:35:53 [NOTICE] mod_spidermonkey.c:2034 session_answer()
Channel [sofia/internal/polycom501 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at fs.voip.domain.com)
State HANGUP
2008-10-09 10:35:53 [DEBUG] mod_sofia.c:272 sofia_on_hangup() Channel
sofia/internal/polycom501 at 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 at 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 at 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 at 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 at 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 at 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 at 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>