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

Thu May 26 23:49:31 MSD 2011

On further review of the log and matching up notices about FS requests 
to Erlang responses, it looks like the request that's timing out is 
getting lost completely and is never processed by Erlang.

On 26/05/2011 1:40 PM, Mark Sobkow wrote:
> 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/