[Freeswitch-users] mod_erlang_event problem

Thu Jun 24 05:58:44 PDT 2010

Hi!

I am trying to use mod_erlang_event with freeswitch 1.0.6 on Red Hat
Enterprise Linux Server release 5.4, 64-bit server. Erlang version is
R13B04. Calls are sent to my erlang application via:

  <extension name="phonebooth">
    <condition field="destination_number" expression="^000([0-9]+)$">
      <action application="erlang" data="phonebooth:launch test at test-server" />
    </condition>
  </extension>

My application is very simple: it just prints all events received from
freeswitch. The problem is, that call is being terminated immidiately.
As far as I can see, phonebooth:launch is called successfully, it
returns a pid of a new process. This new process is still alive after
the call is finished, and it does not receive any events from
freeswitch (if it would, it would print them to screen). Freeswitch
log tells me that erlang_outbound_function exits as soon as it gets
new pid:

2010-06-24 17:46:58.281273 [DEBUG] mod_erlang_event.c:1316 got pid!
2010-06-24 17:46:58.281273 [DEBUG] mod_erlang_event.c:1446 exit
erlang_outbound_function

What is wrong? As this is not my first try with erlang and freeswitch
(previous were successful) I think there's nothing wrong with
configuration, but may be the problem is the box itself, old Red Hat?
Here's full log from freeswitch:

2010-06-24 17:46:58.265274 [NOTICE] switch_channel.c:669 New Channel
sofia/external/1220139 at 10.1.1.1 [93975342-7f8e-11df-bae2-7b19ef829fd0]
2010-06-24 17:46:58.265274 [DEBUG] sofia.c:4153 Channel
sofia/external/1220139 at 10.1.1.1 entering state [received][100]
2010-06-24 17:46:58.265274 [DEBUG] sofia.c:4164 Remote SDP:
v=0
o=HuaweiSoftX3000 282382 282382 IN IP4 10.1.1.1
s=Sip Call
c=IN IP4 172.16.12.1
t=0 0
m=audio 50000 RTP/AVP 8 0 18 4 2
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:4 G723/8000
a=rtpmap:2 G726-32/8000

2010-06-24 17:46:58.265274 [DEBUG] sofia.c:4273
(sofia/external/1220139 at 10.1.1.1) State Change CS_NEW -> CS_INIT
2010-06-24 17:46:58.265274 [DEBUG] switch_core_session.c:1021 Send
signal sofia/external/1220139 at 10.1.1.1 [BREAK]
2010-06-24 17:46:58.265274 [DEBUG] switch_core_state_machine.c:314
(sofia/external/1220139 at 10.1.1.1) Running State Change CS_INIT
2010-06-24 17:46:58.265274 [DEBUG] switch_core_state_machine.c:338
(sofia/external/1220139 at 10.1.1.1) State INIT
2010-06-24 17:46:58.265274 [DEBUG] mod_sofia.c:83
sofia/external/1220139 at 10.1.1.1 SOFIA INIT
2010-06-24 17:46:58.265274 [DEBUG] mod_sofia.c:117
(sofia/external/1220139 at 10.1.1.1) State Change CS_INIT -> CS_ROUTING
2010-06-24 17:46:58.265274 [DEBUG] switch_core_session.c:1021 Send
signal sofia/external/1220139 at 10.1.1.1 [BREAK]
2010-06-24 17:46:58.265274 [DEBUG] switch_core_state_machine.c:338
(sofia/external/1220139 at 10.1.1.1) State INIT going to sleep
2010-06-24 17:46:58.265274 [DEBUG] switch_core_state_machine.c:314
(sofia/external/1220139 at 10.1.1.1) Running State Change CS_ROUTING
2010-06-24 17:46:58.265274 [DEBUG] switch_core_state_machine.c:341
(sofia/external/1220139 at 10.1.1.1) State ROUTING
2010-06-24 17:46:58.265274 [DEBUG] mod_sofia.c:140
sofia/external/1220139 at 10.1.1.1 SOFIA ROUTING
2010-06-24 17:46:58.265274 [DEBUG] switch_core_state_machine.c:77
sofia/external/1220139 at 10.1.1.1 Standard ROUTING
2010-06-24 17:46:58.265274 [INFO] mod_dialplan_xml.c:418 Processing
1220139->0003707057 in context public
Dialplan: sofia/external/1220139 at 10.1.1.1 parsing [public->unloop]
continue=false
Dialplan: sofia/external/1220139 at 10.1.1.1 Regex (PASS) [unloop]
${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/external/1220139 at 10.1.1.1 Regex (FAIL) [unloop]
${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/external/1220139 at 10.1.1.1 parsing
[public->outside_call] continue=true
Dialplan: sofia/external/1220139 at 10.1.1.1 Absolute Condition [outside_call]
Dialplan: sofia/external/1220139 at 10.1.1.1 Action set(outside_call=true)
Dialplan: sofia/external/1220139 at 10.1.1.1 parsing [public->call_debug]
continue=true
Dialplan: sofia/external/1220139 at 10.1.1.1 Regex (FAIL) [call_debug]
${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/external/1220139 at 10.1.1.1 parsing
[public->public_extensions] continue=false
Dialplan: sofia/external/1220139 at 10.1.1.1 Regex (FAIL)
[public_extensions] destination_number(0003707057) =~
/^(10[01][0-9])$/ break=on-false
Dialplan: sofia/external/1220139 at 10.1.1.1 parsing [public->public_did]
continue=false
Dialplan: sofia/external/1220139 at 10.1.1.1 Regex (FAIL) [public_did]
destination_number(0003707057) =~ /^(5551212)$/ break=on-false
Dialplan: sofia/external/1220139 at 10.1.1.1 parsing [public->phonebooth]
continue=false
Dialplan: sofia/external/1220139 at 10.1.1.1 Regex (PASS) [phonebooth]
destination_number(0003707057) =~ /^000([0-9]+)$/ break=on-false
Dialplan: sofia/external/1220139 at 10.1.1.1 Action
erlang(phonebooth:launch test at test-server)
2010-06-24 17:46:58.265274 [DEBUG] switch_core_state_machine.c:119
(sofia/external/1220139 at 10.1.1.1) State Change CS_ROUTING ->
CS_EXECUTE
2010-06-24 17:46:58.265274 [DEBUG] switch_core_session.c:1021 Send
signal sofia/external/1220139 at 10.1.1.1 [BREAK]
2010-06-24 17:46:58.265274 [DEBUG] switch_core_state_machine.c:341
(sofia/external/1220139 at 10.1.1.1) State ROUTING going to sleep
2010-06-24 17:46:58.265274 [DEBUG] switch_core_state_machine.c:314
(sofia/external/1220139 at 10.1.1.1) Running State Change CS_EXECUTE
2010-06-24 17:46:58.265274 [DEBUG] switch_core_state_machine.c:348
(sofia/external/1220139 at 10.1.1.1) State EXECUTE
2010-06-24 17:46:58.265274 [DEBUG] mod_sofia.c:226
sofia/external/1220139 at 10.1.1.1 SOFIA EXECUTE
2010-06-24 17:46:58.265274 [DEBUG] switch_core_state_machine.c:157
sofia/external/1220139 at 10.1.1.1 Standard EXECUTE
EXECUTE sofia/external/1220139 at 10.1.1.1 set(outside_call=true)
2010-06-24 17:46:58.265274 [DEBUG] mod_dptools.c:816
sofia/external/1220139 at 10.1.1.1 SET [outside_call]=[true]
EXECUTE sofia/external/1220139 at 10.1.1.1 erlang(phonebooth:launch
test at test-server)
2010-06-24 17:46:58.265274 [DEBUG] mod_erlang_event.c:1403 enter
erlang_outbound_function phonebooth:launch test at test-server
2010-06-24 17:46:58.265274 [DEBUG] mod_erlang_event.c:1409 Creating
new listener for session
2010-06-24 17:46:58.269275 [DEBUG] mod_erlang_event.c:1418 Launching
new listener
2010-06-24 17:46:58.269275 [DEBUG] mod_erlang_event.c:1424 Creating
new spawned session for listener
2010-06-24 17:46:58.271280 [DEBUG] mod_erlang_event.c:961 Connection Open
2010-06-24 17:46:58.271280 [DEBUG] mod_erlang_event.c:1291 rpc call:
phonebooth:launch(Ref)
2010-06-24 17:46:58.271280 [DEBUG] handle_msg.c:776 Hashed ref to
4.0.0 at freeswitch@test-server
2010-06-24 17:46:58.271280 [DEBUG] handle_msg.c:787 Found waiting slot
for 4.0.0 at freeswitch@test-server
2010-06-24 17:46:58.281273 [DEBUG] mod_erlang_event.c:1316 got pid!
2010-06-24 17:46:58.281273 [DEBUG] mod_erlang_event.c:1446 exit
erlang_outbound_function
2010-06-24 17:46:58.281273 [NOTICE] switch_core_state_machine.c:185
sofia/external/1220139 at 10.1.1.1 has executed the last dialplan
instruction, hanging up.
2010-06-24 17:46:58.281273 [NOTICE] switch_core_state_machine.c:187
Hangup sofia/external/1220139 at 10.1.1.1 [CS_EXECUTE] [NORMAL_CLEARING]
2010-06-24 17:46:58.281273 [DEBUG] mod_erlang_event.c:153 Sending
event CHANNEL_EXECUTE_COMPLETE to attached session for
93975342-7f8e-11df-bae2-7b19ef829fd0
2010-06-24 17:46:58.281273 [DEBUG] switch_channel.c:2102 Send signal
sofia/external/1220139 at 10.1.1.1 [KILL]
2010-06-24 17:46:58.281273 [DEBUG] switch_core_session.c:1021 Send
signal sofia/external/1220139 at 10.1.1.1 [BREAK]
2010-06-24 17:46:58.281273 [DEBUG] mod_erlang_event.c:153 Sending
event CHANNEL_HANGUP to attached session for
93975342-7f8e-11df-bae2-7b19ef829fd0
2010-06-24 17:46:58.281273 [DEBUG] switch_core_state_machine.c:348
(sofia/external/1220139 at 10.1.1.1) State EXECUTE going to sleep
2010-06-24 17:46:58.281273 [DEBUG] switch_core_state_machine.c:314
(sofia/external/1220139 at 10.1.1.1) Running State Change CS_HANGUP
2010-06-24 17:46:58.281273 [DEBUG] mod_erlang_event.c:153 Sending
event CHANNEL_STATE to attached session for
93975342-7f8e-11df-bae2-7b19ef829fd0
2010-06-24 17:46:58.281273 [DEBUG] switch_core_state_machine.c:499
(sofia/external/1220139 at 10.1.1.1) State HANGUP
2010-06-24 17:46:58.281273 [DEBUG] mod_sofia.c:414 Channel
sofia/external/1220139 at 10.1.1.1 hanging up, cause: NORMAL_CLEARING
2010-06-24 17:46:58.281273 [DEBUG] mod_sofia.c:476 Responding to
INVITE with: 480
2010-06-24 17:46:58.281273 [DEBUG] switch_core_state_machine.c:46
sofia/external/1220139 at 10.1.1.1 Standard HANGUP, cause:
NORMAL_CLEARING
2010-06-24 17:46:58.281273 [DEBUG] switch_core_state_machine.c:499
(sofia/external/1220139 at 10.1.1.1) State HANGUP going to sleep
2010-06-24 17:46:58.281273 [DEBUG] switch_core_state_machine.c:333
(sofia/external/1220139 at 10.1.1.1) State Change CS_HANGUP ->
CS_REPORTING
2010-06-24 17:46:58.281273 [DEBUG] switch_core_session.c:1021 Send
signal sofia/external/1220139 at 10.1.1.1 [BREAK]
2010-06-24 17:46:58.281273 [DEBUG] mod_erlang_event.c:153 Sending
event CHANNEL_HANGUP_COMPLETE to attached session for
93975342-7f8e-11df-bae2-7b19ef829fd0
2010-06-24 17:46:58.281273 [DEBUG] switch_core_state_machine.c:314
(sofia/external/1220139 at 10.1.1.1) Running State Change CS_REPORTING
2010-06-24 17:46:58.281273 [DEBUG] switch_core_state_machine.c:590
(sofia/external/1220139 at 10.1.1.1) State REPORTING
2010-06-24 17:46:58.281273 [DEBUG] switch_core_state_machine.c:53
sofia/external/1220139 at 10.1.1.1 Standard REPORTING, cause:
NORMAL_CLEARING
2010-06-24 17:46:58.281273 [DEBUG] switch_core_state_machine.c:590
(sofia/external/1220139 at 10.1.1.1) State REPORTING going to sleep
2010-06-24 17:46:58.281273 [DEBUG] switch_core_state_machine.c:327
(sofia/external/1220139 at 10.1.1.1) State Change CS_REPORTING ->
CS_DESTROY
2010-06-24 17:46:58.281273 [DEBUG] mod_erlang_event.c:153 Sending
event CHANNEL_STATE to attached session for
93975342-7f8e-11df-bae2-7b19ef829fd0
2010-06-24 17:46:58.281273 [DEBUG] switch_core_session.c:1021 Send
signal sofia/external/1220139 at 10.1.1.1 [BREAK]
2010-06-24 17:46:58.281273 [DEBUG] switch_core_session.c:1164 Session
4 (sofia/external/1220139 at 10.1.1.1) Locked, Waiting on external
entities
2010-06-24 17:46:58.283274 [NOTICE] switch_core_session.c:1182 Session
4 (sofia/external/1220139 at 10.1.1.1) Ended
2010-06-24 17:46:58.283274 [NOTICE] switch_core_session.c:1184 Close
Channel sofia/external/1220139 at 10.1.1.1 [CS_DESTROY]
2010-06-24 17:46:58.283274 [DEBUG] switch_core_state_machine.c:428
(sofia/external/1220139 at 10.1.1.1) Running State Change CS_DESTROY
2010-06-24 17:46:58.283274 [DEBUG] mod_erlang_event.c:153 Sending
event CHANNEL_DESTROY to attached session for
93975342-7f8e-11df-bae2-7b19ef829fd0
2010-06-24 17:46:58.283274 [DEBUG] switch_core_state_machine.c:439
(sofia/external/1220139 at 10.1.1.1) State DESTROY
2010-06-24 17:46:58.283274 [DEBUG] mod_sofia.c:341
sofia/external/1220139 at 10.1.1.1 SOFIA DESTROY
2010-06-24 17:46:58.283274 [DEBUG] switch_core_state_machine.c:60
sofia/external/1220139 at 10.1.1.1 Standard DESTROY
2010-06-24 17:46:58.283274 [DEBUG] switch_core_state_machine.c:439
(sofia/external/1220139 at 10.1.1.1) State DESTROY going to sleep
2010-06-24 17:46:58.283274 [DEBUG] mod_erlang_event.c:153 Sending
event CHANNEL_STATE to attached session for
93975342-7f8e-11df-bae2-7b19ef829fd0
2010-06-24 17:46:58.371269 [WARNING] mod_erlang_event.c:531 Can't
locate session 93975342-7f8e-11df-bae2-7b19ef829fd0
2010-06-24 17:46:58.371269 [DEBUG] mod_erlang_event.c:586 Notifying
new session failed
2010-06-24 17:46:58.371269 [DEBUG] mod_erlang_event.c:323 Removing
session element for 93975342-7f8e-11df-bae2-7b19ef829fd0

-- 
Timur Irmatov, xmpp:irmatov at jabber.ru