[Freeswitch-users] javascript originate timeout problem

Wed Apr 16 06:29:53 PDT 2008

Hello again =)

I've made a call queue in javascript where the js takes orders from a
server through a socket.
The server monitors all extensions (through eventsocket) in the queue
and tells the javascript to originate the call to a extension as soon
as it becomes idle.

Everything works fine except when the extension do not answer.
Freeswitch seems to kill the javascript and executes the dialplan
instead.
This only happens when the destination do not answer.

Small log (from when entering the javascript and forward)

2008-04-16 15:21:01 [CONSOLE] mod_spidermonkey_socket.c:109
socket_connect() Connecting to: 127.0.0.1:23341.
2008-04-16 15:21:01 [DEBUG] switch_core_session.c:383
switch_core_session_receive_message() Kill
sofia/default/anonymous at anonymous.invalid [BREAK]
2008-04-16 15:21:01 [NOTICE] mod_spidermonkey.c:1948 session_answer()
Channel [sofia/default/anonymous at anonymous.invalid] has been answered
2008-04-16 15:21:01 [DEBUG] mod_spidermonkey.c:3132 js_api_use() Loading Socket
2008-04-16 15:21:01 [DEBUG] log.js:7 console_log() DEBUG: Sending register
2008-04-16 15:21:01 [DEBUG] sofia.c:1648 sofia_handle_sip_i_state()
Channel sofia/default/anonymous at anonymous.invalid entering state
[completed]
2008-04-16 15:21:01 [DEBUG] sofia.c:1648 sofia_handle_sip_i_state()
Channel sofia/default/anonymous at anonymous.invalid entering state
[ready]
2008-04-16 15:21:02 [DEBUG] log.js:7 console_log() DEBUG: Receivied:
transfer   20      192.168.1.110   u1000022
2008-04-16 15:21:02 [DEBUG] log.js:7 console_log() DEBUG: Calling
sofia/192.168.1.110/u1000022
2008-04-16 15:21:02 [DEBUG] log.js:7 console_log() DEBUG: DESTINATION:
{ignore_early_media=true,originate_timeout=15}sofia/192.168.1.110/u1000022
2008-04-16 15:21:02 [DEBUG] switch_ivr_originate.c:607
switch_ivr_originate() variable string 0 = [ignore_early_media=true]
2008-04-16 15:21:02 [DEBUG] switch_ivr_originate.c:607
switch_ivr_originate() variable string 1 = [originate_timeout=15]
2008-04-16 15:21:02 [NOTICE] switch_channel.c:531
switch_channel_set_name() New Channel sofia/default/u1000022
[91daaf25-4f6f-8848-8d10-596f45c13238]
2008-04-16 15:21:02 [DEBUG] mod_sofia.c:1830 sofia_outgoing_channel()
sofia/default/u1000022 State Change CS_NEW -> CS_INIT
2008-04-16 15:21:02 [DEBUG] switch_core_session.c:670
switch_core_session_signal_state_change() Kill sofia/default/u1000022
[BREAK]
2008-04-16 15:21:02 [DEBUG] switch_core_state_machine.c:364
switch_core_session_run() sofia/default/u1000022 Running State Change
CS_INIT
2008-04-16 15:21:02 [DEBUG] switch_core_state_machine.c:413
switch_core_session_run() (sofia/default/u1000022) State INIT
2008-04-16 15:21:02 [DEBUG] mod_sofia.c:80 sofia_on_init()
sofia/default/u1000022 SOFIA INIT
2008-04-16 15:21:02 [DEBUG] mod_sofia.c:107 sofia_on_init()
sofia/default/u1000022 State Change CS_INIT -> CS_RING
2008-04-16 15:21:02 [DEBUG] switch_core_session.c:670
switch_core_session_signal_state_change() Kill sofia/default/u1000022
[BREAK]
2008-04-16 15:21:02 [DEBUG] switch_core_state_machine.c:413
switch_core_session_run() (sofia/default/u1000022) State INIT going to
sleep
2008-04-16 15:21:02 [DEBUG] switch_core_state_machine.c:364
switch_core_session_run() sofia/default/u1000022 Running State Change
CS_RING
2008-04-16 15:21:02 [DEBUG] sofia.c:222 sofia_event_callback() event
[nua_i_state] status [0][INVITE sent] session: sofia/default/u1000022
2008-04-16 15:21:02 [DEBUG] sofia.c:1648 sofia_handle_sip_i_state()
Channel sofia/default/u1000022 entering state [calling]
2008-04-16 15:21:02 [DEBUG] switch_ivr_originate.c:951
switch_ivr_originate() Raw Codec Activation Success L16 at 8000hz 1
channel 20ms
2008-04-16 15:21:02 [DEBUG] switch_core_state_machine.c:418
switch_core_session_run() (sofia/default/u1000022) State RING
2008-04-16 15:21:02 [DEBUG] mod_sofia.c:119 sofia_on_ring()
sofia/default/u1000022 SOFIA RING
2008-04-16 15:21:02 [DEBUG] switch_ivr_originate.c:55
originate_on_ring() sofia/default/u1000022 State Change CS_RING ->
CS_HOLD
2008-04-16 15:21:02 [DEBUG] switch_core_session.c:670
switch_core_session_signal_state_change() Kill sofia/default/u1000022
[BREAK]
2008-04-16 15:21:02 [DEBUG] switch_core_state_machine.c:418
switch_core_session_run() (sofia/default/u1000022) State RING going to
sleep
2008-04-16 15:21:02 [DEBUG] switch_core_state_machine.c:364
switch_core_session_run() sofia/default/u1000022 Running State Change
CS_HOLD
2008-04-16 15:21:02 [DEBUG] switch_core_state_machine.c:440
switch_core_session_run() (sofia/default/u1000022) State HOLD
2008-04-16 15:21:02 [DEBUG] sofia.c:222 sofia_event_callback() event
[nua_r_invite] status [180][Ringing] session: sofia/default/u1000022
2008-04-16 15:21:02 [DEBUG] sofia.c:222 sofia_event_callback() event
[nua_i_state] status [180][Ringing] session: sofia/default/u1000022
2008-04-16 15:21:02 [DEBUG] sofia.c:1648 sofia_handle_sip_i_state()
Channel sofia/default/u1000022 entering state [proceeding]
2008-04-16 15:21:02 [NOTICE] sofia.c:1686 sofia_handle_sip_i_state()
Ring-Ready sofia/default/u1000022!
2008-04-16 15:21:02 [DEBUG] switch_core_session.c:383
switch_core_session_receive_message() Kill
sofia/default/anonymous at anonymous.invalid [BREAK]
2008-04-16 15:21:02 [DEBUG] sofia.c:350 sofia_event_callback()
nua_r_prack: unknown event 39: 200 OK
2008-04-16 15:21:33 [DEBUG] sofia.c:1648 sofia_handle_sip_i_state()
Channel sofia/default/u1000022 entering state [calling]
2008-04-16 15:21:33 [NOTICE] switch_channel.c:531
switch_channel_set_name() New Channel sofia/default/1202 at 192.168.1.110
[e59265ba-8486-7546-af60-8da7b25e87
2008-04-16 15:21:33 [DEBUG] sofia.c:1648 sofia_handle_sip_i_state()
Channel sofia/default/1202 at 192.168.1.110 entering state [received]
2008-04-16 15:21:33 [DEBUG] switch_core_state_machine.c:364
switch_core_session_run() sofia/default/1202 at 192.168.1.110 Running
State Change CS_NEW
2008-04-16 15:21:33 [DEBUG] sofia.c:1652 sofia_handle_sip_i_state() Remote SDP:
v=0
o=FreeSWITCH 4934107701406015977 4314135494661389300 IN IP4 192.168.1.110
s=FreeSWITCH
c=IN IP4 192.168.1.110
t=0 0
a=sendrecv
m=audio 25866 RTP/AVP 0 8 9 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20

2008-04-16 15:21:33 [DEBUG] sofia_glue.c:2011
sofia_glue_negotiate_sdp() Audio Codec Compare
[PCMU:0:8000]/[PCMU:0:8000]
2008-04-16 15:21:33 [DEBUG] sofia_glue.c:1333
sofia_glue_tech_set_codec() Set Codec sofia/default/1202 at 192.168.1.110
PCMU/8000 20 ms 160 samples
2008-04-16 15:21:33 [DEBUG] switch_core_state_machine.c:368
switch_core_session_run() (sofia/default/1202 at 192.168.1.110) State NEW
2008-04-16 15:21:33 [DEBUG] sofia_glue.c:1975
sofia_glue_negotiate_sdp() Set 2833 dtmf payload to 101
2008-04-16 15:21:33 [DEBUG] sofia_glue.c:1983
sofia_glue_negotiate_sdp() Set comfort noise payload to 13
2008-04-16 15:21:33 [DEBUG] sofia.c:1789 sofia_handle_sip_i_state()
sofia/default/1202 at 192.168.1.110 State Change CS_NEW -> CS_INIT
2008-04-16 15:21:33 [DEBUG] switch_core_session.c:670
switch_core_session_signal_state_change() Kill
sofia/default/1202 at 192.168.1.110 [BREAK]
2008-04-16 15:21:33 [DEBUG] switch_core_state_machine.c:364
switch_core_session_run() sofia/default/1202 at 192.168.1.110 Running
State Change CS_INIT
2008-04-16 15:21:33 [DEBUG] switch_core_state_machine.c:413
switch_core_session_run() (sofia/default/1202 at 192.168.1.110) State
INIT
2008-04-16 15:21:33 [DEBUG] mod_sofia.c:80 sofia_on_init()
sofia/default/1202 at 192.168.1.110 SOFIA INIT
2008-04-16 15:21:33 [DEBUG] mod_sofia.c:107 sofia_on_init()
sofia/default/1202 at 192.168.1.110 State Change CS_INIT -> CS_RING
2008-04-16 15:21:33 [DEBUG] switch_core_session.c:670
switch_core_session_signal_state_change() Kill
sofia/default/1202 at 192.168.1.110 [BREAK]
2008-04-16 15:21:33 [DEBUG] switch_core_state_machine.c:413
switch_core_session_run() (sofia/default/1202 at 192.168.1.110) State
INIT going to sleep
2008-04-16 15:21:33 [DEBUG] switch_core_state_machine.c:364
switch_core_session_run() sofia/default/1202 at 192.168.1.110 Running
State Change CS_RING
2008-04-16 15:21:33 [DEBUG] switch_core_state_machine.c:418
switch_core_session_run() (sofia/default/1202 at 192.168.1.110) State
RING
2008-04-16 15:21:33 [DEBUG] mod_sofia.c:119 sofia_on_ring()
sofia/default/1202 at 192.168.1.110 SOFIA RING
2008-04-16 15:21:33 [DEBUG] switch_core_state_machine.c:65
switch_core_standard_on_ring() Standard RING
sofia/default/1202 at 192.168.1.110
2008-04-16 15:21:33 [INFO] mod_dialplan_xml.c:223 dialplan_hunt()
Processing Arne Rubin->82378009 at public
2008-04-16 15:21:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test
conditions destination_number(82378009) =~ /^\+4623666(12[01][0-9])$/
2008-04-16 15:21:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-04-16 15:21:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test
conditions destination_number(82378009) =~ /^(5551212)$/
2008-04-16 15:21:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-04-16 15:21:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test
conditions destination_number(82378009) =~ /1202/
2008-04-16 15:21:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-04-16 15:21:35 [INFO] switch_core_state_machine.c:113
switch_core_standard_on_ring() No Route, Aborting