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

Thu May 26 23:54:51 MSD 2011

On 3:59 PM, Peter Olsson wrote:

> >>  Did you try latest git? I recently submitted a patch to handle resend on the socket, if the socket is really busy (and returns "would block" state). It's in latest git.
Would this fix affect the sending of messages to Erlang nodes as well?  
(I suspect it might as it would only make sense to reuse the network IO 
APIs rather than having seperate ones for each module.  Andrew Thompson 
would know for sure.)

If it does affect Erlang communications, I'll have to do a git-pull and 
schedule some regression testing.

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