mod_erlang_event problem
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@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@10.1.1.1 [93975342-7f8e-11df-bae2-7b19ef829fd0] 2010-06-24 17:46:58.265274 [DEBUG] sofia.c:4153 Channel sofia/external/1220139@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@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@10.1.1.1 [BREAK] 2010-06-24 17:46:58.265274 [DEBUG] switch_core_state_machine.c:314 (sofia/external/1220139@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@10.1.1.1) State INIT 2010-06-24 17:46:58.265274 [DEBUG] mod_sofia.c:83 sofia/external/1220139@10.1.1.1 SOFIA INIT 2010-06-24 17:46:58.265274 [DEBUG] mod_sofia.c:117 (sofia/external/1220139@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@10.1.1.1 [BREAK] 2010-06-24 17:46:58.265274 [DEBUG] switch_core_state_machine.c:338 (sofia/external/1220139@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@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@10.1.1.1) State ROUTING 2010-06-24 17:46:58.265274 [DEBUG] mod_sofia.c:140 sofia/external/1220139@10.1.1.1 SOFIA ROUTING 2010-06-24 17:46:58.265274 [DEBUG] switch_core_state_machine.c:77 sofia/external/1220139@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@10.1.1.1 parsing [public->unloop] continue=false Dialplan: sofia/external/1220139@10.1.1.1 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/1220139@10.1.1.1 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/1220139@10.1.1.1 parsing [public->outside_call] continue=true Dialplan: sofia/external/1220139@10.1.1.1 Absolute Condition [outside_call] Dialplan: sofia/external/1220139@10.1.1.1 Action set(outside_call=true) Dialplan: sofia/external/1220139@10.1.1.1 parsing [public->call_debug] continue=true Dialplan: sofia/external/1220139@10.1.1.1 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/1220139@10.1.1.1 parsing [public->public_extensions] continue=false Dialplan: sofia/external/1220139@10.1.1.1 Regex (FAIL) [public_extensions] destination_number(0003707057) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/external/1220139@10.1.1.1 parsing [public->public_did] continue=false Dialplan: sofia/external/1220139@10.1.1.1 Regex (FAIL) [public_did] destination_number(0003707057) =~ /^(5551212)$/ break=on-false Dialplan: sofia/external/1220139@10.1.1.1 parsing [public->phonebooth] continue=false Dialplan: sofia/external/1220139@10.1.1.1 Regex (PASS) [phonebooth] destination_number(0003707057) =~ /^000([0-9]+)$/ break=on-false Dialplan: sofia/external/1220139@10.1.1.1 Action erlang(phonebooth:launch test@test-server) 2010-06-24 17:46:58.265274 [DEBUG] switch_core_state_machine.c:119 (sofia/external/1220139@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@10.1.1.1 [BREAK] 2010-06-24 17:46:58.265274 [DEBUG] switch_core_state_machine.c:341 (sofia/external/1220139@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@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@10.1.1.1) State EXECUTE 2010-06-24 17:46:58.265274 [DEBUG] mod_sofia.c:226 sofia/external/1220139@10.1.1.1 SOFIA EXECUTE 2010-06-24 17:46:58.265274 [DEBUG] switch_core_state_machine.c:157 sofia/external/1220139@10.1.1.1 Standard EXECUTE EXECUTE sofia/external/1220139@10.1.1.1 set(outside_call=true) 2010-06-24 17:46:58.265274 [DEBUG] mod_dptools.c:816 sofia/external/1220139@10.1.1.1 SET [outside_call]=[true] EXECUTE sofia/external/1220139@10.1.1.1 erlang(phonebooth:launch test@test-server) 2010-06-24 17:46:58.265274 [DEBUG] mod_erlang_event.c:1403 enter erlang_outbound_function phonebooth:launch test@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@freeswitch@test-server 2010-06-24 17:46:58.271280 [DEBUG] handle_msg.c:787 Found waiting slot for 4.0.0@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@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@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@10.1.1.1 [KILL] 2010-06-24 17:46:58.281273 [DEBUG] switch_core_session.c:1021 Send signal sofia/external/1220139@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@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@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@10.1.1.1) State HANGUP 2010-06-24 17:46:58.281273 [DEBUG] mod_sofia.c:414 Channel sofia/external/1220139@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@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@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@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@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@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@10.1.1.1) State REPORTING 2010-06-24 17:46:58.281273 [DEBUG] switch_core_state_machine.c:53 sofia/external/1220139@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@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@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@10.1.1.1 [BREAK] 2010-06-24 17:46:58.281273 [DEBUG] switch_core_session.c:1164 Session 4 (sofia/external/1220139@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@10.1.1.1) Ended 2010-06-24 17:46:58.283274 [NOTICE] switch_core_session.c:1184 Close Channel sofia/external/1220139@10.1.1.1 [CS_DESTROY] 2010-06-24 17:46:58.283274 [DEBUG] switch_core_state_machine.c:428 (sofia/external/1220139@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@10.1.1.1) State DESTROY 2010-06-24 17:46:58.283274 [DEBUG] mod_sofia.c:341 sofia/external/1220139@10.1.1.1 SOFIA DESTROY 2010-06-24 17:46:58.283274 [DEBUG] switch_core_state_machine.c:60 sofia/external/1220139@10.1.1.1 Standard DESTROY 2010-06-24 17:46:58.283274 [DEBUG] switch_core_state_machine.c:439 (sofia/external/1220139@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@jabber.ru
On Thu, Jun 24, 2010 at 05:58:44PM +0500, Timur Irmatov wrote:
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@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
Yeah, I think this is a bug - Can you show me the code that's running? I think the bug is in the RPC mechanism vs the ! variant, unfortunately I don't have a box with *both* freeswitch and erlang on it handy at the moment - can you write a simple daemon that waits for the get_pid messages and spawns on demand, as described on the wiki, and see if it works that way (that's the way I usually do it). Thanks, Andrew
Hi, Andrew! On Thu, Jun 24, 2010 at 7:57 PM, Andrew Thompson <andrew@hijacked.us> wrote:
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
Yeah, I think this is a bug - Can you show me the code that's running?
The code is very simple, just a gen_server that does nothing excepting printing info about events via io:format. See attached phonebooth.erl (I would paste it inline, but it would break formatting).
I think the bug is in the RPC mechanism vs the ! variant, unfortunately I don't have a box with *both* freeswitch and erlang on it handy at the moment - can you write a simple daemon that waits for the get_pid messages and spawns on demand, as described on the wiki, and see if it works that way (that's the way I usually do it).
That's the way it is done on my other server. And it works there fine. But, also, on that server I also use RPC mechanism the same way I done it on new one, and it works there fine too. It's just older freeswitch and older erlang there. Don't know if that matters, or may be RPC works there simply because I also use registered process and get_pid. Ok, now I have switched to processing of get_pid messages: <extension name="phonebooth"> <condition field="destination_number" expression="^000([0-9]+)$"> <!-- <action application="erlang" data="phonebooth:launch test@test-server" /> --> <action application="erlang" data="phonebooth:! test@test-server" /> </condition> </extension> I have added spawner.erl (attached), which is being registered as phonebooth process, processes get_new messages and starts new process for each call. phonebooth.erl is not changed. Same problem: 2010-06-25 09:23:41.891156 [DEBUG] mod_erlang_event.c:1316 got pid! 2010-06-25 09:23:41.891156 [DEBUG] mod_erlang_event.c:1446 exit erlang_outbound_function Log is attached. I am ready to perform further testing/ debugging if you'll tell me what to try next. -- Timur Irmatov, xmpp:irmatov@jabber.ru
On Fri, Jun 25, 2010 at 09:32:44AM +0500, Timur Irmatov wrote:
Hi, Andrew! That's the way it is done on my other server. And it works there fine. But, also, on that server I also use RPC mechanism the same way I done it on new one, and it works there fine too. It's just older freeswitch and older erlang there. Don't know if that matters, or may be RPC works there simply because I also use registered process and get_pid.
So you use both mechanisms on a box with older freeswitch and erlang and both work fine? Can you narrow it down by matching versions on one side (freeswitch might be best) and see if the bug goes away/comes back? Its possible the new erlang releases have changed something in ei, but its more likely that I broke something in FreeSWITCH. What are the versions of FS/erlang on the box that works? Andrew
On Fri, Jun 25, 2010 at 8:06 PM, Andrew Thompson <andrew@hijacked.us> wrote:
On Fri, Jun 25, 2010 at 09:32:44AM +0500, Timur Irmatov wrote:
Hi, Andrew! That's the way it is done on my other server. And it works there fine. But, also, on that server I also use RPC mechanism the same way I done it on new one, and it works there fine too. It's just older freeswitch and older erlang there. Don't know if that matters, or may be RPC works there simply because I also use registered process and get_pid.
So you use both mechanisms on a box with older freeswitch and erlang and both work fine? Can you narrow it down by matching versions on one side (freeswitch might be best) and see if the bug goes away/comes back? Its possible the new erlang releases have changed something in ei, but its more likely that I broke something in FreeSWITCH. What are the versions of FS/erlang on the box that works?
Yes, both mechanisms work on other box. It is Debian Lenny, 64 bit. Erlang is installed from Debian packages, it is 12B03. As for freeswitch, it is a little bit difficult to tell its version. I was installing it from svn repository, and can't tell exactly what revision that was. May be 16041, but definitely before 17000. version command reports just 'FreeSWITCH Version 1.0.trunk (hacked)'. I'll try compiling 16041 on Red Hat machine and tell you the results. Thank you for your support. -- Timur Irmatov, xmpp:irmatov@jabber.ru
Ok, this is getting pretty confusing.
So you use both mechanisms on a box with older freeswitch and erlang and both work fine? Can you narrow it down by matching versions on one side (freeswitch might be best) and see if the bug goes away/comes back? Its possible the new erlang releases have changed something in ei, but its more likely that I broke something in FreeSWITCH. What are the versions of FS/erlang on the box that works?
Yes, both mechanisms work on other box. It is Debian Lenny, 64 bit. Erlang is installed from Debian packages, it is 12B03. As for freeswitch, it is a little bit difficult to tell its version. I was installing it from svn repository, and can't tell exactly what revision that was. May be 16041, but definitely before 17000. version command reports just 'FreeSWITCH Version 1.0.trunk (hacked)'. I'll try compiling 16041 on Red Hat machine and tell you the results.
I can't get freeswitch and erlang play together even on old (working) server. It *has* a working installation of freeswitch and erlang (debian packages) that works. What I cannot do - is install another freeswitch on this same machine and make it work with either system provided erlang (R12B03) nor latest R13B04. I have tried newest freeswitch from git, and old revision 16041 from svn with both erlangs. Both exhibit exact same behaviour - call is disconnected, log file says 'got pid!' and 'exit erlang_outbound_session'. I am completely confused. Banging my head against the wall.. :) Any suggestions? -- Timur Irmatov, xmpp:irmatov@jabber.ru
On Wed, Jun 30, 2010 at 12:02 PM, Timur Irmatov <irmatov@gmail.com> wrote:
Ok, this is getting pretty confusing.
It seems that my problem was related to host name part was not properly configured in /etc/hosts. After fixing that *and* restarting epmd, I was able to connect latest freeswitch and erlang. -- Timur Irmatov, xmpp:irmatov@jabber.ru
On Wed, Jun 30, 2010 at 5:21 PM, Timur Irmatov <irmatov@gmail.com> wrote:
On Wed, Jun 30, 2010 at 12:02 PM, Timur Irmatov <irmatov@gmail.com> wrote:
Ok, this is getting pretty confusing.
It seems that my problem was related to host name part was not properly configured in /etc/hosts. After fixing that *and* restarting epmd, I was able to connect latest freeswitch and erlang.
I was too quick to rejoice. It was really working for some time, then I have restarted freeswitch, and my problem returned. Could it be that there's some race condition between call initialisation/parking/whatever and mod_erlang_event interaction? Does anyone have any hints on debugging? What is the latest freeswitch and erlang that you people seem to have stable and working? -- Timur Irmatov, xmpp:irmatov@jabber.ru
participants (2)
-
Andrew Thompson
-
Timur Irmatov