[Freeswitch-dev] Late response from Erlang to dialplan request causing Freeswitch to shut down

[Mark Sobkow]

Platform: Ubuntu 10.04 amd64, 8GB RAM, 500GB HDD, quad-core CPU
Configured to use SIP trunking as a slave off an Asterisk server with a 
T1 connection to the outside world

We're using Erlang and PostgreSQL to provide responses to Freeswitch 
configuration requests and to manage our call queues, operator logins, etc.

With one operator, the system runs fine, so we know the basic coding 
we've done works.

However, with only a couple or three operators on the line and 
concurrent dialing going on, we're getting a consistent problem where 
the responses to requests for dialplan configurations are getting 
seriously delayed -- by well over a minute (an eternity in software terms.)

I had suspected that there may be some sort of blocking IO going on when 
we issue the originate command (which doesn't return control to Erlang 
for up to 30 seconds), but I'm seeing other Freeswitch requests for 
directory information getting handled during this same time period, so 
the communications between Freeswitch and Erlang do support concurrent 
requests.

The only thing I've been able to find in the mail list logs or wiki that 
seem relevant is a comment someone made today about fixing the TCP 
transmissions in Freeswitch so that they'll retry the transmission if 
the IP stream is clogged and would result in a blocking call.  (i.e. FS 
used to be unreliable about sending out messages before this patch was 
done.)

It's worth noting that Erlang threads are quite busy during the minute 
between FS issueing the request and Erlang responding to it.  However, 
the thread/Erlang process that handles the configuration requests is 
idle, so it _should_ be able to respond in a much timelier fashion.

It looks to me like there is some sort of delay between FS issuing the 
request and Erlang getting the message into it's processing queue.

Any suggestions/ideas as to what might be causing this?  And more 
importantly -- what can we do to fix or workaround the issue?

And no, I have not downloaded and installed the latest version of 
Freeswitch from git.  I'm trying to avoid that if possible because it'll 
cost me two weeks of regression testing and I need to have this out to a 
beta site by the 31st, which doesn't allow enough time to do the 
regression tests if we do an upgrade (and only a fool ships untested 
software to paying customers.)  If someone can confirm that there was a 
fix checked into git for this issue or a related one, then I can justify 
the need for an upgrade and regression testing to my boss (though he 
won't be happy about the delay.)

Here's the relevent snippet of the fs_cli log:

2011-05-26 11:45:50.648334 [INFO] mod_dialplan_xml.c:331 Processing 
Gotham <5311>->219 in context public
2011-05-26 11:45:50.648334 [ERR] mod_dialplan_xml.c:353 Open of dialplan 
failed
2011-05-26 11:45:50.648334 [INFO] switch_core_state_machine.c:142 No 
Route, Aborting
2011-05-26 11:45:50.648334 [DEBUG] switch_channel.c:2535 
(sofia/external/5311 at 10.77.0.12:6080) Callstate Change RINGING -> HANGUP
2011-05-26 11:45:50.657061 [NOTICE] switch_core_state_machine.c:143 
Hangup sofia/external/5311 at 10.77.0.12:6080 [CS_ROUTING] 
[NO_ROUTE_DESTINATION]


And here's the log from where our response is finally being issued to 
the request, long after FS has decided to shut down because it's not 
getting responses from the configuration services:

2011-05-26 11:47:45 DEBUG <0.28104.15>: pbx_bind_cfg:fetch() Invoking 
xml_fetch()
2011-05-26 11:47:45 DEBUG <0.28104.15>: pbx_bind_cfg:xml_fetch( {fetch, 
dialplan, Tag=undefined, Key=undefined, Value=undefined, Params=...} )
2011-05-26 11:47:46 DEBUG <0.28104.15>: pbx_bind_cfg:fetch() Response XML is
<document type="freeswitch/xml">
<section name="dialplan" description="Dial Plan For FreeSwitch">
<context name="default">
<extension required_name="ConferenceDialer">
<condition field="destination_number" expression="^8(\d\d\d)$">
<action application="conference" data="conf$0 at dialer"/>
</condition>
</extension>
<extension required_name="dialer_park">
<condition field="destination_number" expression="^park$">
<action application="fifo" data="park@${domain_name} in" />
</condition>
</extension>
<extension required_name="park">
<condition field="destination_number" expression="^7000$">
<action application="set" data="fifo_music=$${hold_music}" />
<action application="fifo" data="7000@${domain_name} in" />
</condition>
</extension>
<extension required_name="unpark">
<condition field="destination_number" expression="^7001$">
<action application="answer" />
<action application="fifo" data="7000@${domain_name} out nowait" />
</condition>
</extension>
<extension required_name="InternalFS">
<condition field="destination_number" expression="^(\d\d\d\d)$">
<action application="bridge" data="sofia/external/$0%pursuit.marketel"/>
</condition>
</extension>
<extension required_name="RatsExtension">
<condition field="destination_number" expression="^(\d\d\d)$">
<action application="bridge" data="sofia/external/$0 at rats.marketel"/>
</condition>
</extension>
<extension required_name="LocalCall">
<condition field="destination_number" expression="^(9\d\d\d\d\d\d\d)$">
<action application="bridge" data="sofia/external/$0 at rats.marketel"/>
</condition>
</extension>
<extension required_name="LongDistanceCall">
<condition field="destination_number" 
expression="^91(\d\d\d\d\d\d\d\d\d\d)$">
<action application="bridge" data="sofia/external/$0 at rats.marketel"/>
</condition>
</extension>
</context>
<context name="public">
<extension required_name="Operator">
<condition field="destination_number" expression="^(0)$">
<action application="bridge" data="sofia/external/160 at rats.marketel"/>
</condition>
</extension>
<extension required_name="OperatorLogin">
<condition field="destination_number" expression="^620(\d)$">
<action application="answer" />
<action application="set" data="chain_id=$1" />
<action application="set" data="hangup_after_bridge=false" />
<action application="play_and_get_digits" data="4 8 1 30000 # 
/usr/lib/pursuit/lib/pbx-1.2/priv/welcome_please_enter_pin-8000.wav 
/usr/lib/pursuit/lib/pbx-1.2/priv/invalid_pin_try_again-8000.wav 
operator_pin \d+" />
<action application="log" data="INFO operator_pin is ${operator_pin}, 
chain_id is ${chain_id}" />
<action application="erlang" data="pbx_op_logged_in pursuit at pursuit" />
</condition>
</extension>

<extension required_name="OperatorLogin2">
<condition field="destination_number" expression="^62(\d\d)$">
<action application="answer" />
<action application="set" data="chain_id=$1" />
<action application="set" data="hangup_after_bridge=false" />
<action application="play_and_get_digits" data="4 8 1 30000 # 
/usr/lib/pursuit/lib/pbx-1.2/priv/welcome_please_enter_pin-8000.wav 
/usr/lib/pursuit/lib/pbx-1.2/priv/invalid_pin_try_again-8000.wav 
operator_pin \d+" />
<action application="log" data="INFO operator_pin is ${operator_pin}, 
chain_id is ${chain_id}" />
<action application="erlang" data="pbx_op_logged_in pursuit at pursuit" />
</condition>
</extension>
<extension required_name="CollectCallResult">
<condition field="destination_number" expression="^63(\d\d)$">
<action application="answer" />
<action application="set" data="hangup_after_bridge=false" />
<action application="play_and_get_digits" data="1 2 1 30000 # 
/usr/lib/pursuit/lib/pbx-1.2/priv/please_enter_result_code-8000.wav 
/usr/lib/pursuit/lib/pbx-1.2/priv/invalid_result_code-8000.wav 
call_result \d+" />
<action application="log" data="INFO call_result is ${call_result}" />
<action application="erlang" data="pbx_call_result pursuit at pursuit" />
</condition>
</extension>

<extension required_name="DummyCallResult">
<condition field="destination_number" expression="^6400$">
<action application="answer" />
<action application="erlang" data="pbx_dummy_call_result pursuit at pursuit" />
</condition>
</extension>

<extension required_name="CustomerCallin">
<condition field="destination_number" expression="^650(\d)$">
<action application="answer" />
<action application="set" data="chain_id=$1" />
<action application="erlang" data="pbx_cust_called pursuit at pursuit" />
</condition>
</extension>
<extension required_name="CustomerCallin2">
<condition field="destination_number" expression="^65(\d\d)$">
<action application="answer" />
<action application="set" data="chain_id=$1" />
<action application="erlang" data="pbx_cust_called pursuit at pursuit" />
</condition>
</extension>

<extension required_name="TestIVR">
<condition field="destination_number" expression="^6600$">
<action application="answer" />
<action application="ivr" data="demo_ivr" />
</condition>
</extension>

<extension required_name="eavesdrop">
<condition field="destination_number" expression="^67(\d\d\d\d)$">
<action application="answer"/>
<action application="set" data="eavesdrop_extension=$1" />
<action application="erlang" data="pbx_eavesdrop pursuit at pursuit" />
</condition>
</extension>

<extension required_name="park">
<condition field="destination_number" expression="^6003$">
<action application="fifo" data="6003@${domain_name} in" />
</condition>
</extension>
<extension required_name="unpark">
<condition field="destination_number" expression="^6004$">
<action application="answer" />
<action application="fifo" data="6003@${domain_name} out wait" />
</condition>
</extension>

<extension required_name="ConferenceDialer">
<condition field="destination_number" expression="^8(\d\d\d)$">
<action application="conference" data="conf$0 at dialer"/>
</condition>
</extension>
<extension required_name="InternalFS">
<condition field="destination_number" expression="^(\d\d\d\d)$">
<action application="bridge" data="sofia/external/$0%10.77.0.12"/>
</condition>
</extension>
<extension required_name="RatsExtension">
<condition field="destination_number" expression="^(\d\d\d)$">
<action application="bridge" data="sofia/external/$0 at rats.marketel"/>
</condition>
</extension>
<extension required_name="LocalCall">
<condition field="destination_number" expression="^(9\d\d\d\d\d\d\d)$">
<action application="bridge" data="sofia/external/$0 at rats.marketel"/>
</condition>
</extension>
<extension required_name="LongDistanceCall">
<condition field="destination_number" 
expression="^91(\d\d\d\d\d\d\d\d\d\d)$">
<action application="bridge" data="sofia/external/$0 at rats.marketel"/>
</condition>
</extension>
</context>
</section>
</document>


-- 
Mark Sobkow
Senior Developer
MarkeTel Multi-Line Dialing Systems LTD.
428 Victoria Ave
Regina, SK S4N-0P6
Toll-Free: 800-289-8616-X533
Local: 306-359-6893-X533
Fax: 306-359-6879
Email: m.sobkow at marketelsystems.com
Web: http://www.marketelsystems.com

Visit our Blog for industry related information.
http://marketel-systems.blogspot.com/