Skip to content

Instantly share code, notes, and snippets.

@lpradovera
Last active December 15, 2016 15:46
Show Gist options
  • Save lpradovera/d60a9b127c3dc12cf5bf422c616652bd to your computer and use it in GitHub Desktop.
Save lpradovera/d60a9b127c3dc12cf5bf422c616652bd to your computer and use it in GitHub Desktop.
grammar = RubySpeech::GRXML.draw mode: :dtmf, root: 'digits' do
rule id: 'digits', scope: 'public' do
item repeat: "0-1" do
one_of do
0.upto(9) { |d| item { d.to_s } }
end
end
end
end
result = ask step_config['prompt'], limit: limit, grammars: [grammar]
[2016-12-15 07:38:13.519] INFO Adhearsion::Initializer: Adhearsion v3.0.0.rc1 initialized in "development"!
[2016-12-15 07:39:13.532] TRACE Adhearsion::Rayo::Connection::XMPP: SENDING: (/home/mojolingo/.rvm/gems/ruby-2.3.1/gems/blather-1.2.0/lib/blather/client/client.rb:153:in `write') <iq type="get" to="192.168.65.201" id="blather0008">
<ping xmlns="urn:xmpp:ping"/>
</iq>
[2016-12-15 07:39:13.533] TRACE Adhearsion::Rayo::Connection::XMPP: RECEIVING (iq) <iq type="result" from="192.168.65.201" to="usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139" id="blather0008"/>
[2016-12-15 07:39:16.612] TRACE Adhearsion::Rayo::Connection::XMPP: RECEIVING (presence) <presence from="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" to="usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139">
<c xmlns="http://jabber.org/protocol/caps" hash="sha-1" node="urn:xmpp:rayo:call:1" ver="L9rOKMEJl9rssEggArljiapRd9k="/>
<offer xmlns="urn:xmpp:rayo:1" from="sip:4044754849@192.168.65.114" to="sip:7472022074@192.168.65.114">
<header name="from" value="&lt;sip:4044754849@192.168.65.114&gt;;tag=192.168.65.134+1+3e970e+15721d68"/>
<header name="to" value="&lt;sip:7472022074@192.168.65.114&gt;"/>
<header name="via" value="SIP/2.0/UDP 192.168.65.134:5060;rport=5060;branch=z9hG4bK-f93ec6f4c173d5dd13a0c9ae0aa852f71-192.168.65.134-1"/>
<header name="P-DCS-Billing-Info" value="gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9"/>
<header name="P-Charging-Vector" value="icid-value=1ed17a"/>
</offer>
<delay xmlns="urn:xmpp:delay" stamp="2016-12-15T15:39:16Z"/>
</presence>
[2016-12-15 07:39:16.621] DEBUG Adhearsion::Call: @: Receiving message: #<Adhearsion::Event::Offer target_call_id="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32", target_mixer_name=nil, component_id=nil, source_uri="xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201", domain="192.168.65.201", transport="xmpp", timestamp=Thu, 15 Dec 2016 15:39:16 +0000, headers={"from"=>"<sip:4044754849@192.168.65.114>;tag=192.168.65.134+1+3e970e+15721d68", "to"=>"<sip:7472022074@192.168.65.114>", "via"=>"SIP/2.0/UDP 192.168.65.134:5060;rport=5060;branch=z9hG4bK-f93ec6f4c173d5dd13a0c9ae0aa852f71-192.168.65.134-1", "P-DCS-Billing-Info"=>"gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9", "P-Charging-Vector"=>"icid-value=1ed17a"}, to="sip:7472022074@192.168.65.114", from="sip:4044754849@192.168.65.114">
[2016-12-15 07:39:16.624] INFO Adhearsion::Router: Call 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32 selected route "default" (WelcomeController)
[2016-12-15 07:39:16.627] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing command #<Adhearsion::Rayo::Command::Accept target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:16 -0800, request_id="4cd0e6de-f7f1-454f-bc2f-e65553b78e04", headers={}>
[2016-12-15 07:39:16.628] TRACE Adhearsion::Rayo::Connection::XMPP: SENDING: (/home/mojolingo/.rvm/gems/ruby-2.3.1/gems/blather-1.2.0/lib/blather/client/client.rb:153:in `write') <iq type="set" to="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" id="4cd0e6de-f7f1-454f-bc2f-e65553b78e04">
<accept xmlns="urn:xmpp:rayo:1"/>
</iq>
[2016-12-15 07:39:16.650] TRACE Adhearsion::Rayo::Connection::XMPP: RECEIVING (iq) <iq from="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" to="usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139" type="result" id="4cd0e6de-f7f1-454f-bc2f-e65553b78e04"/>
[2016-12-15 07:39:16.652] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing controller WelcomeController
[2016-12-15 07:39:16.653] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Receiving message: #<Adhearsion::Event::Offer target_call_id="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32", target_mixer_name=nil, component_id=nil, source_uri="xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201", domain="192.168.65.201", transport="xmpp", timestamp=Thu, 15 Dec 2016 15:39:16 +0000, headers={"from"=>"<sip:4044754849@192.168.65.114>;tag=192.168.65.134+1+3e970e+15721d68", "to"=>"<sip:7472022074@192.168.65.114>", "via"=>"SIP/2.0/UDP 192.168.65.134:5060;rport=5060;branch=z9hG4bK-f93ec6f4c173d5dd13a0c9ae0aa852f71-192.168.65.134-1", "P-DCS-Billing-Info"=>"gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9", "P-Charging-Vector"=>"icid-value=1ed17a"}, to="sip:7472022074@192.168.65.114", from="sip:4044754849@192.168.65.114">
[2016-12-15 07:39:16.655] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing command #<Adhearsion::Rayo::Command::Answer target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:16 -0800, request_id="b6fd52cc-26da-41c4-bce5-d982c2fed724", headers={}>
[2016-12-15 07:39:16.655] TRACE Adhearsion::Rayo::Connection::XMPP: SENDING: (/home/mojolingo/.rvm/gems/ruby-2.3.1/gems/blather-1.2.0/lib/blather/client/client.rb:153:in `write') <iq type="set" to="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" id="b6fd52cc-26da-41c4-bce5-d982c2fed724">
<answer xmlns="urn:xmpp:rayo:1"/>
</iq>
[2016-12-15 07:39:16.677] TRACE Adhearsion::Rayo::Connection::XMPP: RECEIVING (iq) <iq from="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" to="usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139" type="result" id="b6fd52cc-26da-41c4-bce5-d982c2fed724"/>
[2016-12-15 07:39:16.680] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Caller ID match to account #<Account @values={:id=>2, :name=>"Demo Flow 2", :phone_number=>"7472022074", :created_at=>"2016-12-12T08:03:31.000-08:00", :updated_at=>nil}>
[2016-12-15 07:39:16.682] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Finished executing controller WelcomeController
[2016-12-15 07:39:16.685] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing #<Step @values={:id=>6, :menu_id=>4, :step_number=>1, :type=>"condition", :configuration=>"{\"expression\":\"TIME_time_day >= 0 AND TIME_time_day <= 23\",\"when_true\":\"open_hours_with_menu\",\"when_false\":\"closed_hours_voicemail\"}", :created_at=>nil, :updated_at=>nil}>
[2016-12-15 07:39:16.686] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing #<Step @values={:id=>6, :menu_id=>4, :step_number=>1, :type=>"condition", :configuration=>"{\"expression\":\"TIME_time_day >= 0 AND TIME_time_day <= 23\",\"when_true\":\"open_hours_with_menu\",\"when_false\":\"closed_hours_voicemail\"}", :created_at=>nil, :updated_at=>nil}> in menu #<Menu @values={:id=>4, :account_id=>2, :tag=>"main", :configuration=>nil, :created_at=>nil, :updated_at=>nil}>: ConditionStep
[2016-12-15 07:39:16.688] DEBUG ConditionStep: Expression TIME_time_day >= 0 AND TIME_time_day <= 23 with variables {"from"=>"<sip:4044754849@192.168.65.114>;tag=192.168.65.134+1+3e970e+15721d68", "to"=>"<sip:7472022074@192.168.65.114>", "via"=>"SIP/2.0/UDP 192.168.65.134:5060;rport=5060;branch=z9hG4bK-f93ec6f4c173d5dd13a0c9ae0aa852f71-192.168.65.134-1", "p_dcs_billing_info"=>"gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9", "p_charging_vector"=>"icid-value=1ed17a", "account_id"=>2, "call_from"=>"sip:4044754849@192.168.65.114", "call_to"=>"sip:7472022074@192.168.65.114", "TIME_week_day"=>4, "TIME_time_day"=>7, "TIME_month_day"=>15, "TIME_month"=>12, "TIME_minutes"=>39} evaluated to true
[2016-12-15 07:39:16.690] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Finished executing controller MainController
[2016-12-15 07:39:16.692] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing #<Step @values={:id=>7, :menu_id=>5, :step_number=>1, :type=>"play_audio", :configuration=>"{\"text\":\"Our offices are open, please wait\"}", :created_at=>nil, :updated_at=>nil}>
[2016-12-15 07:39:16.693] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing #<Step @values={:id=>7, :menu_id=>5, :step_number=>1, :type=>"play_audio", :configuration=>"{\"text\":\"Our offices are open, please wait\"}", :created_at=>nil, :updated_at=>nil}> in menu #<Menu @values={:id=>5, :account_id=>2, :tag=>"open_hours_with_menu", :configuration=>nil, :created_at=>nil, :updated_at=>nil}>: PlayAudioStep
[2016-12-15 07:39:16.697] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing command #<Adhearsion::Rayo::Component::Output target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:16 -0800, request_id="20d644dc-b5be-4518-b54d-a0d0391c1c88", headers={}, voice=nil, interrupt_on=nil, start_offset=nil, start_paused=nil, repeat_interval=nil, repeat_times=nil, max_time=nil, renderer="unimrcp", render_documents=[#<Adhearsion::Rayo::Component::Output::Document target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:16 -0800, url=nil, content_type="application/ssml+xml", value=<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">Our offices are open, please wait</speak>>]>
[2016-12-15 07:39:16.698] TRACE Adhearsion::Rayo::Connection::XMPP: SENDING: (/home/mojolingo/.rvm/gems/ruby-2.3.1/gems/blather-1.2.0/lib/blather/client/client.rb:153:in `write') <iq type="set" to="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" id="20d644dc-b5be-4518-b54d-a0d0391c1c88">
<output xmlns="urn:xmpp:rayo:output:1" renderer="unimrcp">
<document content-type="application/ssml+xml"><![CDATA[<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">Our offices are open, please wait</speak>]]></document>
</output>
</iq>
[2016-12-15 07:39:16.699] TRACE Adhearsion::Rayo::Connection::XMPP: RECEIVING (presence) <presence from="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" to="usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139">
<answered xmlns="urn:xmpp:rayo:1">
<header name="P-DCS-Billing-Info" value="gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9"/>
<header name="P-Charging-Vector" value="icid-value=1ed17a"/>
</answered>
<delay xmlns="urn:xmpp:delay" stamp="2016-12-15T15:39:16Z"/>
</presence>
[2016-12-15 07:39:16.702] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Receiving message: #<Adhearsion::Event::Answered target_call_id="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32", target_mixer_name=nil, component_id=nil, source_uri="xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201", domain="192.168.65.201", transport="xmpp", timestamp=Thu, 15 Dec 2016 15:39:16 +0000, headers={"P-DCS-Billing-Info"=>"gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9", "P-Charging-Vector"=>"icid-value=1ed17a"}>
[2016-12-15 07:39:16.739] TRACE Adhearsion::Rayo::Connection::XMPP: RECEIVING (iq) <iq from="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" to="usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139" type="result" id="20d644dc-b5be-4518-b54d-a0d0391c1c88">
<ref xmlns="urn:xmpp:rayo:1" uri="xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-1"/>
</iq>
[2016-12-15 07:39:19.678] TRACE Adhearsion::Rayo::Connection::XMPP: RECEIVING (presence) <presence from="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-1" to="usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139" type="unavailable">
<complete xmlns="urn:xmpp:rayo:ext:1">
<finish xmlns="urn:xmpp:rayo:output:complete:1"/>
</complete>
<delay xmlns="urn:xmpp:delay" stamp="2016-12-15T15:39:19Z"/>
</presence>
[2016-12-15 07:39:19.681] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Receiving message: #<Adhearsion::Event::Complete target_call_id="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32", target_mixer_name=nil, component_id="output-1", source_uri="xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-1", domain="192.168.65.201", transport="xmpp", timestamp=Thu, 15 Dec 2016 15:39:19 +0000, reason=#<Adhearsion::Rayo::Component::Output::Complete::Finish target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:19 -0800, name=:finish>, recording=nil, fax=nil, fax_metadata={}>
[2016-12-15 07:39:19.682] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Current variables: {"from"=>"<sip:4044754849@192.168.65.114>;tag=192.168.65.134+1+3e970e+15721d68", "to"=>"<sip:7472022074@192.168.65.114>", "via"=>"SIP/2.0/UDP 192.168.65.134:5060;rport=5060;branch=z9hG4bK-f93ec6f4c173d5dd13a0c9ae0aa852f71-192.168.65.134-1", "p_dcs_billing_info"=>"gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9", "p_charging_vector"=>"icid-value=1ed17a", "account_id"=>2, "call_from"=>"sip:4044754849@192.168.65.114", "call_to"=>"sip:7472022074@192.168.65.114"}
[2016-12-15 07:39:19.682] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing #<Step @values={:id=>8, :menu_id=>5, :step_number=>2, :type=>"dialer", :configuration=>"{\"destination\":\"sofia/external/7183519970\"}", :created_at=>nil, :updated_at=>nil}>
[2016-12-15 07:39:19.682] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing #<Step @values={:id=>8, :menu_id=>5, :step_number=>2, :type=>"dialer", :configuration=>"{\"destination\":\"sofia/external/7183519970\"}", :created_at=>nil, :updated_at=>nil}> in menu #<Menu @values={:id=>5, :account_id=>2, :tag=>"open_hours_with_menu", :configuration=>nil, :created_at=>nil, :updated_at=>nil}>: DialerStep
[2016-12-15 07:39:19.686] DEBUG Adhearsion::OutboundCall: 94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201: Executing command #<Adhearsion::Rayo::Command::Dial target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:19 -0800, request_id="c7d67f7d-01dc-4721-986d-7b42968d36b9", headers={}, to="sofia/external/7183519970", from="sip:4044754849@192.168.65.114", uri="xmpp:94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201", timeout=nil, join=nil>
[2016-12-15 07:39:19.687] TRACE Adhearsion::Rayo::Connection::XMPP: SENDING: (/home/mojolingo/.rvm/gems/ruby-2.3.1/gems/blather-1.2.0/lib/blather/client/client.rb:153:in `write') <iq type="set" to="192.168.65.201" id="c7d67f7d-01dc-4721-986d-7b42968d36b9">
<dial xmlns="urn:xmpp:rayo:1" to="sofia/external/7183519970" from="sip:4044754849@192.168.65.114" uri="xmpp:94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201"/>
</iq>
[2016-12-15 07:39:19.708] TRACE Adhearsion::Rayo::Connection::XMPP: RECEIVING (iq) <iq from="192.168.65.201" to="usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139" id="c7d67f7d-01dc-4721-986d-7b42968d36b9" type="result">
<ref xmlns="urn:xmpp:rayo:1" uri="xmpp:94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201"/>
</iq>
[2016-12-15 07:39:19.748] TRACE Adhearsion::Rayo::Connection::XMPP: RECEIVING (presence) <presence from="94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201" to="usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139" type="unavailable">
<end xmlns="urn:xmpp:rayo:1">
<error platform-code="20"/>
</end>
<delay xmlns="urn:xmpp:delay" stamp="2016-12-15T15:39:19Z"/>
</presence>
[2016-12-15 07:39:19.750] DEBUG Adhearsion::OutboundCall: 94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201: Receiving message: #<Adhearsion::Event::End target_call_id="94ac8658-c212-49f8-994f-a59b970fe4e6", target_mixer_name=nil, component_id=nil, source_uri="xmpp:94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201", domain="192.168.65.201", transport="xmpp", timestamp=Thu, 15 Dec 2016 15:39:19 +0000, headers={}, reason=:error, platform_code="20">
[2016-12-15 07:39:19.750] INFO Adhearsion::OutboundCall: 94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201: Call sip:4044754849@192.168.65.114 -> sofia/external/7183519970 ended due to error (code 20)
[2016-12-15 07:39:19.751] INFO Adhearsion::CallController::Dial::Dial: 48ba5869-47f3-44d8-9c58-b7d369b74ce1: #dial finished with no remaining outbound calls
[2016-12-15 07:39:19.752] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Current variables: {"from"=>"<sip:4044754849@192.168.65.114>;tag=192.168.65.134+1+3e970e+15721d68", "to"=>"<sip:7472022074@192.168.65.114>", "via"=>"SIP/2.0/UDP 192.168.65.134:5060;rport=5060;branch=z9hG4bK-f93ec6f4c173d5dd13a0c9ae0aa852f71-192.168.65.134-1", "p_dcs_billing_info"=>"gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9", "p_charging_vector"=>"icid-value=1ed17a", "account_id"=>2, "call_from"=>"sip:4044754849@192.168.65.114", "call_to"=>"sip:7472022074@192.168.65.114", "open_hours_with_menu_2"=>"error"}
[2016-12-15 07:39:19.752] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing #<Step @values={:id=>18, :menu_id=>5, :step_number=>2, :type=>"play_audio", :configuration=>"{\"text\":\"Our offices are open, please wait\"}", :created_at=>nil, :updated_at=>nil}>
[2016-12-15 07:39:19.753] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing #<Step @values={:id=>18, :menu_id=>5, :step_number=>2, :type=>"play_audio", :configuration=>"{\"text\":\"Our offices are open, please wait\"}", :created_at=>nil, :updated_at=>nil}> in menu #<Menu @values={:id=>5, :account_id=>2, :tag=>"open_hours_with_menu", :configuration=>nil, :created_at=>nil, :updated_at=>nil}>: PlayAudioStep
[2016-12-15 07:39:19.754] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing command #<Adhearsion::Rayo::Component::Output target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:19 -0800, request_id="310ca5f0-10d8-4114-97c7-4af86be0e5f1", headers={}, voice=nil, interrupt_on=nil, start_offset=nil, start_paused=nil, repeat_interval=nil, repeat_times=nil, max_time=nil, renderer="unimrcp", render_documents=[#<Adhearsion::Rayo::Component::Output::Document target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:19 -0800, url=nil, content_type="application/ssml+xml", value=<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">Our offices are open, please wait</speak>>]>
[2016-12-15 07:39:19.755] TRACE Adhearsion::Rayo::Connection::XMPP: SENDING: (/home/mojolingo/.rvm/gems/ruby-2.3.1/gems/blather-1.2.0/lib/blather/client/client.rb:153:in `write') <iq type="set" to="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" id="310ca5f0-10d8-4114-97c7-4af86be0e5f1">
<output xmlns="urn:xmpp:rayo:output:1" renderer="unimrcp">
<document content-type="application/ssml+xml"><![CDATA[<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">Our offices are open, please wait</speak>]]></document>
</output>
</iq>
[2016-12-15 07:39:19.776] TRACE Adhearsion::Rayo::Connection::XMPP: RECEIVING (iq) <iq from="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" to="usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139" type="result" id="310ca5f0-10d8-4114-97c7-4af86be0e5f1">
<ref xmlns="urn:xmpp:rayo:1" uri="xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-2"/>
</iq>
[2016-12-15 07:39:22.709] TRACE Adhearsion::Rayo::Connection::XMPP: RECEIVING (presence) <presence from="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-2" to="usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139" type="unavailable">
<complete xmlns="urn:xmpp:rayo:ext:1">
<finish xmlns="urn:xmpp:rayo:output:complete:1"/>
</complete>
<delay xmlns="urn:xmpp:delay" stamp="2016-12-15T15:39:22Z"/>
</presence>
[2016-12-15 07:39:22.714] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Current variables: {"from"=>"<sip:4044754849@192.168.65.114>;tag=192.168.65.134+1+3e970e+15721d68", "to"=>"<sip:7472022074@192.168.65.114>", "via"=>"SIP/2.0/UDP 192.168.65.134:5060;rport=5060;branch=z9hG4bK-f93ec6f4c173d5dd13a0c9ae0aa852f71-192.168.65.134-1", "p_dcs_billing_info"=>"gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9", "p_charging_vector"=>"icid-value=1ed17a", "account_id"=>2, "call_from"=>"sip:4044754849@192.168.65.114", "call_to"=>"sip:7472022074@192.168.65.114", "open_hours_with_menu_2"=>"error"}
[2016-12-15 07:39:22.715] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Receiving message: #<Adhearsion::Event::Complete target_call_id="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32", target_mixer_name=nil, component_id="output-2", source_uri="xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-2", domain="192.168.65.201", transport="xmpp", timestamp=Thu, 15 Dec 2016 15:39:22 +0000, reason=#<Adhearsion::Rayo::Component::Output::Complete::Finish target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:22 -0800, name=:finish>, recording=nil, fax=nil, fax_metadata={}>
[2016-12-15 07:39:22.715] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing #<Step @values={:id=>9, :menu_id=>5, :step_number=>3, :type=>"condition", :configuration=>"{\"expression\":\"open_hours_with_menu_2 = 'answer'\",\"when_false\":\"no_answer_open\"}", :created_at=>nil, :updated_at=>nil}>
[2016-12-15 07:39:22.716] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing #<Step @values={:id=>9, :menu_id=>5, :step_number=>3, :type=>"condition", :configuration=>"{\"expression\":\"open_hours_with_menu_2 = 'answer'\",\"when_false\":\"no_answer_open\"}", :created_at=>nil, :updated_at=>nil}> in menu #<Menu @values={:id=>5, :account_id=>2, :tag=>"open_hours_with_menu", :configuration=>nil, :created_at=>nil, :updated_at=>nil}>: ConditionStep
[2016-12-15 07:39:22.716] DEBUG ConditionStep: Expression open_hours_with_menu_2 = 'answer' with variables {"from"=>"<sip:4044754849@192.168.65.114>;tag=192.168.65.134+1+3e970e+15721d68", "to"=>"<sip:7472022074@192.168.65.114>", "via"=>"SIP/2.0/UDP 192.168.65.134:5060;rport=5060;branch=z9hG4bK-f93ec6f4c173d5dd13a0c9ae0aa852f71-192.168.65.134-1", "p_dcs_billing_info"=>"gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9", "p_charging_vector"=>"icid-value=1ed17a", "account_id"=>2, "call_from"=>"sip:4044754849@192.168.65.114", "call_to"=>"sip:7472022074@192.168.65.114", "open_hours_with_menu_2"=>"error", "TIME_week_day"=>4, "TIME_time_day"=>7, "TIME_month_day"=>15, "TIME_month"=>12, "TIME_minutes"=>39} evaluated to false
[2016-12-15 07:39:22.718] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Finished executing controller MainController
[2016-12-15 07:39:22.726] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing #<Step @values={:id=>10, :menu_id=>6, :step_number=>1, :type=>"gather_input", :configuration=>"{\"prompt\":\"Sorry. Press 1 to do something or 2 to do something else\",\"limit\":1}", :created_at=>nil, :updated_at=>nil}>
[2016-12-15 07:39:22.726] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing #<Step @values={:id=>10, :menu_id=>6, :step_number=>1, :type=>"gather_input", :configuration=>"{\"prompt\":\"Sorry. Press 1 to do something or 2 to do something else\",\"limit\":1}", :created_at=>nil, :updated_at=>nil}> in menu #<Menu @values={:id=>6, :account_id=>2, :tag=>"no_answer_open", :configuration=>nil, :created_at=>nil, :updated_at=>nil}>: GatherInputStep
[2016-12-15 07:39:22.735] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing command #<Adhearsion::Rayo::Component::Prompt target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:22 -0800, request_id="c652731d-2639-420f-b99f-56f996356ea9", barge_in=true, output=#<Adhearsion::Rayo::Component::Output target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:22 -0800, request_id="a8e1f55b-beb2-428c-a88d-d3015f651ce3", headers={}, voice=nil, interrupt_on=nil, start_offset=nil, start_paused=nil, repeat_interval=nil, repeat_times=nil, max_time=nil, renderer="unimrcp", render_documents=[#<Adhearsion::Rayo::Component::Output::Document target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:22 -0800, url=nil, content_type="application/ssml+xml", value=<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">Sorry. Press 1 to do something or 2 to do something else</speak>>]>, input=#<Adhearsion::Rayo::Component::Input target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:22 -0800, request_id="ac41824c-48a0-4788-8a8a-323c46a513ed", headers={}, max_silence=5000, min_confidence=0.5, mode=:dtmf, recognizer="unimrcp", language="en-US", terminator=nil, sensitivity=nil, initial_timeout=5000, inter_digit_timeout=2000, recognition_timeout=nil, grammars=[#<Adhearsion::Rayo::Component::Input::Grammar target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:22 -0800, value=<grammar xmlns="http://www.w3.org/2001/06/grammar" version="1.0" xml:lang="en-US" mode="dtmf" root="digits">
<rule id="digits" scope="public">
<item repeat="0-1">
<one-of>
<item>0</item>
<item>1</item>
<item>2</item>
<item>3</item>
<item>4</item>
<item>5</item>
<item>6</item>
<item>7</item>
<item>8</item>
<item>9</item>
<item>#</item>
<item>*</item>
</one-of>
</item>
</rule>
</grammar>, content_type="application/srgs+xml", url=nil>]>>
[2016-12-15 07:39:22.737] TRACE Adhearsion::Rayo::Connection::XMPP: SENDING: (/home/mojolingo/.rvm/gems/ruby-2.3.1/gems/blather-1.2.0/lib/blather/client/client.rb:153:in `write') <iq type="set" to="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" id="c652731d-2639-420f-b99f-56f996356ea9">
<prompt xmlns="urn:xmpp:rayo:prompt:1" barge-in="true">
<input xmlns="urn:xmpp:rayo:input:1" max-silence="5000" min-confidence="0.5" mode="dtmf" recognizer="unimrcp" language="en-US" initial-timeout="5000" inter-digit-timeout="2000">
<grammar content-type="application/srgs+xml"><![CDATA[<grammar xmlns="http://www.w3.org/2001/06/grammar" version="1.0" xml:lang="en-US" mode="dtmf" root="digits">
<rule id="digits" scope="public">
<item repeat="0-1">
<one-of>
<item>0</item>
<item>1</item>
<item>2</item>
<item>3</item>
<item>4</item>
<item>5</item>
<item>6</item>
<item>7</item>
<item>8</item>
<item>9</item>
<item>#</item>
<item>*</item>
</one-of>
</item>
</rule>
</grammar>]]></grammar>
</input>
<output xmlns="urn:xmpp:rayo:output:1" renderer="unimrcp">
<document content-type="application/ssml+xml"><![CDATA[<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">Sorry. Press 1 to do something or 2 to do something else</speak>]]></document>
</output>
</prompt>
</iq>
[2016-12-15 07:39:22.879] TRACE Adhearsion::Rayo::Connection::XMPP: RECEIVING (iq) <iq from="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" to="usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139" type="result" id="c652731d-2639-420f-b99f-56f996356ea9">
<ref xmlns="urn:xmpp:rayo:1" uri="xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3"/>
</iq>
[2016-12-15 07:39:26.461] TRACE Adhearsion::Rayo::Connection::XMPP: RECEIVING (presence) <presence from="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3" to="usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139" type="unavailable">
<complete xmlns="urn:xmpp:rayo:ext:1">
<match xmlns="urn:xmpp:rayo:input:complete:1" content-type="application/nlsml+xml">&lt;result xmlns='http://www.ietf.org/xml/ns/mrcpv2' xmlns:xf='http://www.w3.org/2000/xforms'&gt;&lt;interpretation&gt;&lt;input mode='dtmf' confidence='100'&gt;1&lt;/input&gt;&lt;instance&gt;1&lt;/instance&gt;&lt;/interpretation&gt;&lt;/result&gt;</match>
</complete>
<delay xmlns="urn:xmpp:delay" stamp="2016-12-15T15:39:26Z"/>
</presence>
[2016-12-15 07:39:26.467] DEBUG Adhearsion::CallController::Input::PromptBuilder: Ask completed with result #<Adhearsion::CallController::Input::Result status=:match, confidence=0.0, utterance="1", interpretation="1", nlsml='<?xml version="1.0"?> <result xmlns="http://www.ietf.org/xml/ns/mrcpv2" xmlns:xf="http://www.w3.org/2000/xforms"> <interpretation> <input mode="dtmf" confidence="100">1</input> <instance>1</instance> </interpretation> </result>'>
[2016-12-15 07:39:26.468] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Current variables: {"from"=>"<sip:4044754849@192.168.65.114>;tag=192.168.65.134+1+3e970e+15721d68", "to"=>"<sip:7472022074@192.168.65.114>", "via"=>"SIP/2.0/UDP 192.168.65.134:5060;rport=5060;branch=z9hG4bK-f93ec6f4c173d5dd13a0c9ae0aa852f71-192.168.65.134-1", "p_dcs_billing_info"=>"gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9", "p_charging_vector"=>"icid-value=1ed17a", "account_id"=>2, "call_from"=>"sip:4044754849@192.168.65.114", "call_to"=>"sip:7472022074@192.168.65.114", "open_hours_with_menu_2"=>"error", "no_answer_open_1"=>"1"}
[2016-12-15 07:39:26.469] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing #<Step @values={:id=>11, :menu_id=>6, :step_number=>2, :type=>"play_audio", :configuration=>"{\"text\":\"You pressed {no_answer_open_1}. Goodbye.\"}", :created_at=>nil, :updated_at=>nil}>
[2016-12-15 07:39:26.469] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing #<Step @values={:id=>11, :menu_id=>6, :step_number=>2, :type=>"play_audio", :configuration=>"{\"text\":\"You pressed {no_answer_open_1}. Goodbye.\"}", :created_at=>nil, :updated_at=>nil}> in menu #<Menu @values={:id=>6, :account_id=>2, :tag=>"no_answer_open", :configuration=>nil, :created_at=>nil, :updated_at=>nil}>: PlayAudioStep
[2016-12-15 07:39:26.472] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing command #<Adhearsion::Rayo::Component::Output target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:26 -0800, request_id="d51f79eb-24f6-4661-a997-caaa21a960df", headers={}, voice=nil, interrupt_on=nil, start_offset=nil, start_paused=nil, repeat_interval=nil, repeat_times=nil, max_time=nil, renderer="unimrcp", render_documents=[#<Adhearsion::Rayo::Component::Output::Document target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:26 -0800, url=nil, content_type="application/ssml+xml", value=<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">You pressed 1. Goodbye.</speak>>]>
[2016-12-15 07:39:26.474] TRACE Adhearsion::Rayo::Connection::XMPP: SENDING: (/home/mojolingo/.rvm/gems/ruby-2.3.1/gems/blather-1.2.0/lib/blather/client/client.rb:153:in `write') <iq type="set" to="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" id="d51f79eb-24f6-4661-a997-caaa21a960df">
<output xmlns="urn:xmpp:rayo:output:1" renderer="unimrcp">
<document content-type="application/ssml+xml"><![CDATA[<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">You pressed 1. Goodbye.</speak>]]></document>
</output>
</iq>
[2016-12-15 07:39:26.475] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Receiving message: #<Adhearsion::Event::Complete target_call_id="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32", target_mixer_name=nil, component_id="prompt-3", source_uri="xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3", domain="192.168.65.201", transport="xmpp", timestamp=Thu, 15 Dec 2016 15:39:26 +0000, reason=#<Adhearsion::Rayo::Component::Input::Complete::Match target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:26 -0800, name=:match, content_type="application/nlsml+xml", nlsml=#<Nokogiri::XML::Element:0x13ff920 name="result" namespace=#<Nokogiri::XML::Namespace:0x13ff8d0 href="http://www.ietf.org/xml/ns/mrcpv2"> children=[#<Nokogiri::XML::Element:0x1697a0c name="interpretation" namespace=#<Nokogiri::XML::Namespace:0x13ff8d0 href="http://www.ietf.org/xml/ns/mrcpv2"> children=[#<Nokogiri::XML::Element:0x1696cb0 name="input" namespace=#<Nokogiri::XML::Namespace:0x13ff8d0 href="http://www.ietf.org/xml/ns/mrcpv2"> attributes=[#<Nokogiri::XML::Attr:0x176e1d8 name="mode" value="dtmf">, #<Nokogiri::XML::Attr:0x176e1b0 name="confidence" value="100">] children=[#<Nokogiri::XML::Text:0x1775140 "1">]>, #<Nokogiri::XML::Element:0x1696620 name="instance" namespace=#<Nokogiri::XML::Namespace:0x13ff8d0 href="http://www.ietf.org/xml/ns/mrcpv2"> children=[#<Nokogiri::XML::Text:0x16965a8 "1">]>]>]>>, recording=nil, fax=nil, fax_metadata={}>
[2016-12-15 07:39:26.476] TRACE Adhearsion::Rayo::Connection::XMPP: RECEIVING (iq) <iq from="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" to="usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139" type="result" id="d51f79eb-24f6-4661-a997-caaa21a960df">
<ref xmlns="urn:xmpp:rayo:1" uri="xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-6"/>
</iq>
[2016-12-15 07:39:28.734] TRACE Adhearsion::Rayo::Connection::XMPP: RECEIVING (presence) <presence from="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-6" to="usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139" type="unavailable">
<complete xmlns="urn:xmpp:rayo:ext:1">
<finish xmlns="urn:xmpp:rayo:output:complete:1"/>
</complete>
<delay xmlns="urn:xmpp:delay" stamp="2016-12-15T15:39:28Z"/>
</presence>
[2016-12-15 07:39:28.738] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Receiving message: #<Adhearsion::Event::Complete target_call_id="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32", target_mixer_name=nil, component_id="output-6", source_uri="xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-6", domain="192.168.65.201", transport="xmpp", timestamp=Thu, 15 Dec 2016 15:39:28 +0000, reason=#<Adhearsion::Rayo::Component::Output::Complete::Finish target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:28 -0800, name=:finish>, recording=nil, fax=nil, fax_metadata={}>
[2016-12-15 07:39:28.739] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Current variables: {"from"=>"<sip:4044754849@192.168.65.114>;tag=192.168.65.134+1+3e970e+15721d68", "to"=>"<sip:7472022074@192.168.65.114>", "via"=>"SIP/2.0/UDP 192.168.65.134:5060;rport=5060;branch=z9hG4bK-f93ec6f4c173d5dd13a0c9ae0aa852f71-192.168.65.134-1", "p_dcs_billing_info"=>"gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9", "p_charging_vector"=>"icid-value=1ed17a", "account_id"=>2, "call_from"=>"sip:4044754849@192.168.65.114", "call_to"=>"sip:7472022074@192.168.65.114", "open_hours_with_menu_2"=>"error", "no_answer_open_1"=>"1"}
[2016-12-15 07:39:28.739] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Finished executing controller MainController
[2016-12-15 07:39:28.740] INFO Adhearsion::Router::Route: Call 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32 routing completed. Hanging up now.
[2016-12-15 07:39:28.740] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Hanging up
[2016-12-15 07:39:28.741] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Executing command #<Adhearsion::Rayo::Command::Hangup target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 15 Dec 2016 07:39:28 -0800, request_id="6e3f347d-375b-4e13-904b-35e749a28f26", headers={}>
[2016-12-15 07:39:28.742] TRACE Adhearsion::Rayo::Connection::XMPP: SENDING: (/home/mojolingo/.rvm/gems/ruby-2.3.1/gems/blather-1.2.0/lib/blather/client/client.rb:153:in `write') <iq type="set" to="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" id="6e3f347d-375b-4e13-904b-35e749a28f26">
<hangup xmlns="urn:xmpp:rayo:1"/>
</iq>
[2016-12-15 07:39:28.743] TRACE Adhearsion::Rayo::Connection::XMPP: RECEIVING (iq) <iq from="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" to="usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139" type="result" id="6e3f347d-375b-4e13-904b-35e749a28f26"/>
[2016-12-15 07:39:28.783] TRACE Adhearsion::Rayo::Connection::XMPP: RECEIVING (presence) <presence from="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" to="usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139" type="unavailable">
<end xmlns="urn:xmpp:rayo:1">
<hangup-command/>
<header name="P-DCS-Billing-Info" value="gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9"/>
<header name="P-Charging-Vector" value="icid-value=1ed17a"/>
</end>
<delay xmlns="urn:xmpp:delay" stamp="2016-12-15T15:39:28Z"/>
</presence>
[2016-12-15 07:39:28.786] DEBUG Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Receiving message: #<Adhearsion::Event::End target_call_id="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32", target_mixer_name=nil, component_id=nil, source_uri="xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201", domain="192.168.65.201", transport="xmpp", timestamp=Thu, 15 Dec 2016 15:39:28 +0000, headers={"P-DCS-Billing-Info"=>"gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9", "P-Charging-Vector"=>"icid-value=1ed17a"}, reason=:"hangup-command", platform_code=nil>
[2016-12-15 07:39:28.786] INFO Adhearsion::Call: 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: Call sip:4044754849@192.168.65.114 -> sip:7472022074@192.168.65.114 ended due to hangup-command
[2016-12-15 07:39:28.788] DEBUG Adhearsion::CallController::Dial::Dial: 48ba5869-47f3-44d8-9c58-b7d369b74ce1: Root call ended, unblocking connected calls
2016-12-15 07:39:13.531815 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in RECV <iq type="get" to="192.168.65.201" id="blather0008"><ping xmlns="urn:xmpp:ping"/></iq>
2016-12-15 07:39:13.531815 [DEBUG] xmpp_streams.c:1073 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, state = READY, node type = NODE_NORMAL
2016-12-15 07:39:13.531815 [DEBUG] mod_rayo.c:4197 Lock usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:13.531815 [DEBUG] mod_rayo.c:3143 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, recv iq, availability = ONLINE
2016-12-15 07:39:13.531815 [DEBUG] mod_rayo.c:4281 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:13.531815 [DEBUG] mod_rayo.c:842 Locate (jid) 192.168.65.201: ref count = 2
2016-12-15 07:39:13.531815 [DEBUG] mod_rayo.c:3146 Deliver usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 => 192.168.65.201 <iq type='get' to='192.168.65.201' id='blather0008' from='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139'><ping xmlns='urn:xmpp:ping'/></iq>
2016-12-15 07:39:13.531815 [DEBUG] mod_rayo.c:723 192.168.65.201, looking for SERVER::get:urn:xmpp:ping:ping command
2016-12-15 07:39:13.531815 [DEBUG] mod_rayo.c:849 Release 192.168.65.201: ref count = 1
2016-12-15 07:39:13.531815 [DEBUG] mod_rayo.c:842 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:13.531815 [DEBUG] mod_rayo.c:1831 Deliver 192.168.65.201 => usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 <iq type='result' from='192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' id='blather0008'/>
2016-12-15 07:39:13.531815 [DEBUG] mod_rayo.c:849 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:13.531815 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in SEND <iq type='result' from='192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' id='blather0008'/>
2016-12-15 07:39:16.551450 [NOTICE] switch_channel.c:1104 New Channel sofia/external/4044754849@192.168.65.114 [0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32]
2016-12-15 07:39:16.551450 [DEBUG] switch_core_state_machine.c:584 (sofia/external/4044754849@192.168.65.114) Running State Change CS_NEW
2016-12-15 07:39:16.551450 [DEBUG] sofia.c:9771 sofia/external/4044754849@192.168.65.114 receiving invite from 192.168.65.134:5060 version: 1.9.0 git cd520f8 2016-11-04 23:12:09Z 64bit
2016-12-15 07:39:16.551450 [DEBUG] sofia.c:7054 Channel sofia/external/4044754849@192.168.65.114 entering state [received][100]
2016-12-15 07:39:16.551450 [DEBUG] sofia.c:7064 Remote SDP:
v=0
o=- 52639441 52639441 IN IP4 192.168.24.199
s=-
c=IN IP4 192.168.24.199
t=0 0
m=audio 50358 RTP/AVP 0 18 96 101
a=fmtp:18 annexb=no
a=rtpmap:96 iLBC/8000
a=fmtp:96 mode=30
a=rtpmap:101 telephone-event/8000
a=ptime:20
2016-12-15 07:39:16.551450 [DEBUG] sofia.c:7432 (sofia/external/4044754849@192.168.65.114) State Change CS_NEW -> CS_INIT
2016-12-15 07:39:16.551450 [DEBUG] switch_core_state_machine.c:603 (sofia/external/4044754849@192.168.65.114) State NEW
2016-12-15 07:39:16.551450 [DEBUG] switch_core_state_machine.c:584 (sofia/external/4044754849@192.168.65.114) Running State Change CS_INIT
2016-12-15 07:39:16.551450 [DEBUG] switch_core_state_machine.c:627 (sofia/external/4044754849@192.168.65.114) State INIT
2016-12-15 07:39:16.551450 [DEBUG] mod_sofia.c:92 sofia/external/4044754849@192.168.65.114 SOFIA INIT
2016-12-15 07:39:16.551450 [DEBUG] switch_core_state_machine.c:40 sofia/external/4044754849@192.168.65.114 Standard INIT
2016-12-15 07:39:16.551450 [DEBUG] switch_core_state_machine.c:48 (sofia/external/4044754849@192.168.65.114) State Change CS_INIT -> CS_ROUTING
2016-12-15 07:39:16.551450 [DEBUG] switch_core_state_machine.c:627 (sofia/external/4044754849@192.168.65.114) State INIT going to sleep
2016-12-15 07:39:16.551450 [DEBUG] switch_core_state_machine.c:584 (sofia/external/4044754849@192.168.65.114) Running State Change CS_ROUTING
2016-12-15 07:39:16.551450 [DEBUG] switch_channel.c:2249 (sofia/external/4044754849@192.168.65.114) Callstate Change DOWN -> RINGING
2016-12-15 07:39:16.551450 [DEBUG] switch_core_state_machine.c:643 (sofia/external/4044754849@192.168.65.114) State ROUTING
2016-12-15 07:39:16.551450 [DEBUG] mod_sofia.c:145 sofia/external/4044754849@192.168.65.114 SOFIA ROUTING
2016-12-15 07:39:16.551450 [DEBUG] switch_core_state_machine.c:236 sofia/external/4044754849@192.168.65.114 Standard ROUTING
2016-12-15 07:39:16.551450 [INFO] mod_dialplan_xml.c:637 Processing 4044754849 <4044754849>->7472022074 in context public
Dialplan: sofia/external/4044754849@192.168.65.114 parsing [public->BVATTENDANT] continue=false
Dialplan: sofia/external/4044754849@192.168.65.114 Regex (PASS) [BVATTENDANT] destination_number(7472022074) =~ /^7472022074$/ break=on-false
|--- Dialplan: Processing recursive conditions level:1 [BVATTENDANT_recur_1] require-nested=TRUE
|--- Dialplan: sofia/external/4044754849@192.168.65.114 Regex (PASS) [BVATTENDANT_recur_1] ${sip_req_params}(transport=udp;role=term) =~ /^(.*?);role=term(.*?)$/ break=on-false
|--- Dialplan: sofia/external/4044754849@192.168.65.114 Action log(INFO Params are transport=udp and )
|--- Dialplan: sofia/external/4044754849@192.168.65.114 Action rayo()
2016-12-15 07:39:16.591391 [DEBUG] switch_core_state_machine.c:286 (sofia/external/4044754849@192.168.65.114) State Change CS_ROUTING -> CS_EXECUTE
2016-12-15 07:39:16.591391 [DEBUG] switch_core_state_machine.c:643 (sofia/external/4044754849@192.168.65.114) State ROUTING going to sleep
2016-12-15 07:39:16.591391 [DEBUG] switch_core_state_machine.c:584 (sofia/external/4044754849@192.168.65.114) Running State Change CS_EXECUTE
2016-12-15 07:39:16.591391 [DEBUG] switch_core_state_machine.c:650 (sofia/external/4044754849@192.168.65.114) State EXECUTE
2016-12-15 07:39:16.591391 [DEBUG] mod_sofia.c:200 sofia/external/4044754849@192.168.65.114 SOFIA EXECUTE
2016-12-15 07:39:16.591391 [DEBUG] switch_core_state_machine.c:328 sofia/external/4044754849@192.168.65.114 Standard EXECUTE
EXECUTE sofia/external/4044754849@192.168.65.114 log(INFO Params are transport=udp and )
2016-12-15 07:39:16.591391 [INFO] mod_dptools.c:1725 Params are transport=udp and
2016-12-15 07:39:16.591391 [DEBUG] mod_rayo.c:3694 got event CHANNEL_EXECUTE
2016-12-15 07:39:16.591391 [DEBUG] mod_rayo.c:3694 got event CHANNEL_EXECUTE_COMPLETE
EXECUTE sofia/external/4044754849@192.168.65.114 rayo()
2016-12-15 07:39:16.591391 [DEBUG] mod_rayo.c:3694 got event CHANNEL_EXECUTE
2016-12-15 07:39:16.591391 [DEBUG] mod_rayo.c:4086 Init 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201
2016-12-15 07:39:16.591391 [DEBUG] mod_rayo.c:4096 Offering call for Rayo 3PCC
2016-12-15 07:39:16.591391 [DEBUG] mod_rayo.c:842 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:16.591391 [DEBUG] mod_rayo.c:3905 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201 => usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 <presence from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139'><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='urn:xmpp:rayo:call:1' ver='L9rOKMEJl9rssEggArljiapRd9k='/><offer xmlns='urn:xmpp:rayo:1' from='sip:4044754849@192.168.65.114' to='sip:7472022074@192.168.65.114'><header name='from' value='&lt;sip:4044754849@192.168.65.114&gt;;tag=192.168.65.134+1+3e970e+15721d68'/><header name='to' value='&lt;sip:7472022074@192.168.65.114&gt;'/><header name='via' value='SIP/2.0/UDP 192.168.65.134:5060;rport=5060;branch=z9hG4bK-f93ec6f4c173d5dd13a0c9ae0aa852f71-192.168.65.134-1'/><header name='P-DCS-Billing-Info' value='gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9'/><header name='P-Charging-Vector' value='icid-value=1ed17a'/></offer><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:16Z'/></presence>
2016-12-15 07:39:16.591391 [DEBUG] mod_rayo.c:849 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:16.591391 [DEBUG] mod_rayo.c:3694 got event CHANNEL_PARK
2016-12-15 07:39:16.591391 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in SEND <presence from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139'><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='urn:xmpp:rayo:call:1' ver='L9rOKMEJl9rssEggArljiapRd9k='/><offer xmlns='urn:xmpp:rayo:1' from='sip:4044754849@192.168.65.114' to='sip:7472022074@192.168.65.114'><header name='from' value='&lt;sip:4044754849@192.168.65.114&gt;;tag=192.168.65.134+1+3e970e+15721d68'/><header name='to' value='&lt;sip:7472022074@192.168.65.114&gt;'/><header name='via' value='SIP/2.0/UDP 192.168.65.134:5060;rport=5060;branch=z9hG4bK-f93ec6f4c173d5dd13a0c9ae0aa852f71-192.168.65.134-1'/><header name='P-DCS-Billing-Info' value='gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9'/><header name='P-Charging-Vector' value='icid-value=1ed17a'/></offer><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:16Z'/></presence>
2016-12-15 07:39:16.611382 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in RECV <iq type="set" to="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" id="4cd0e6de-f7f1-454f-bc2f-e65553b78e04"><accept xmlns="urn:xmpp:rayo:1"/></iq>
2016-12-15 07:39:16.611382 [DEBUG] xmpp_streams.c:1073 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, state = READY, node type = NODE_NORMAL
2016-12-15 07:39:16.611382 [DEBUG] mod_rayo.c:4197 Lock usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:16.611382 [DEBUG] mod_rayo.c:3143 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, recv iq, availability = ONLINE
2016-12-15 07:39:16.611382 [DEBUG] mod_rayo.c:4281 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:16.611382 [DEBUG] mod_rayo.c:842 Locate (jid) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 2
2016-12-15 07:39:16.611382 [DEBUG] mod_rayo.c:3146 Deliver usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 => 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201 <iq type='set' to='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' id='4cd0e6de-f7f1-454f-bc2f-e65553b78e04' from='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139'><accept xmlns='urn:xmpp:rayo:1'/></iq>
2016-12-15 07:39:16.611382 [DEBUG] mod_rayo.c:723 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, looking for CALL::set:urn:xmpp:rayo:1:accept command
2016-12-15 07:39:16.611382 [INFO] mod_rayo.c:1713 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 has control of call
2016-12-15 07:39:16.611382 [DEBUG] mod_rayo.c:1893 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, executing command
2016-12-15 07:39:16.611382 [INFO] mod_rayo.c:2030 Sending early media
2016-12-15 07:39:16.611382 [DEBUG] switch_core_media.c:4816 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2016-12-15 07:39:16.611382 [DEBUG] switch_core_media.c:4871 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2016-12-15 07:39:16.611382 [DEBUG] switch_core_media.c:4816 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2016-12-15 07:39:16.611382 [DEBUG] switch_core_media.c:4816 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2016-12-15 07:39:16.611382 [DEBUG] switch_core_media.c:4816 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2016-12-15 07:39:16.611382 [DEBUG] switch_core_media.c:4816 Audio Codec Compare [iLBC:96:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2016-12-15 07:39:16.611382 [DEBUG] switch_core_media.c:4816 Audio Codec Compare [iLBC:96:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2016-12-15 07:39:16.611382 [DEBUG] switch_core_media.c:4732 Set telephone-event payload to 101@8000
2016-12-15 07:39:16.611382 [DEBUG] switch_core_media.c:3412 Set Codec sofia/external/4044754849@192.168.65.114 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2016-12-15 07:39:16.611382 [DEBUG] switch_core_codec.c:111 sofia/external/4044754849@192.168.65.114 Original read codec set to PCMU:0
2016-12-15 07:39:16.611382 [DEBUG] switch_core_media.c:5075 Set telephone-event payload to 101@8000
2016-12-15 07:39:16.611382 [DEBUG] switch_core_media.c:5134 sofia/external/4044754849@192.168.65.114 Set 2833 dtmf send payload to 101 recv payload to 101
2016-12-15 07:39:16.611382 [DEBUG] switch_core_media.c:7448 AUDIO RTP [sofia/external/4044754849@192.168.65.114] 192.168.65.201 port 30182 -> 192.168.24.199 port 50358 codec: 0 ms: 20
2016-12-15 07:39:16.611382 [DEBUG] switch_rtp.c:3875 Starting timer [soft] 160 bytes per 20ms
2016-12-15 07:39:16.631393 [DEBUG] switch_core_media.c:7747 sofia/external/4044754849@192.168.65.114 Set 2833 dtmf send payload to 101
2016-12-15 07:39:16.631393 [DEBUG] switch_core_media.c:7754 sofia/external/4044754849@192.168.65.114 Set 2833 dtmf receive payload to 101
2016-12-15 07:39:16.631393 [DEBUG] switch_core_media.c:7777 sofia/external/4044754849@192.168.65.114 Set rtp dtmf delay to 40
2016-12-15 07:39:16.631393 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/4044754849@192.168.65.114!
2016-12-15 07:39:16.631393 [DEBUG] mod_rayo.c:3694 got event CHANNEL_PROGRESS_MEDIA
2016-12-15 07:39:16.631393 [DEBUG] mod_rayo.c:3699 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 rayo event CHANNEL_PROGRESS_MEDIA
2016-12-15 07:39:16.631393 [DEBUG] mod_rayo.c:3701 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:16.631393 [DEBUG] mod_rayo.c:3709 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:16.631393 [DEBUG] switch_channel.c:3471 (sofia/external/4044754849@192.168.65.114) Callstate Change RINGING -> EARLY
2016-12-15 07:39:16.631393 [DEBUG] switch_core_media.c:7431 Audio params are unchanged for sofia/external/4044754849@192.168.65.114.
2016-12-15 07:39:16.631393 [DEBUG] mod_sofia.c:2342 Ring SDP:
v=0
o=FreeSWITCH 1481786174 1481786175 IN IP4 192.168.65.201
s=FreeSWITCH
c=IN IP4 192.168.65.201
t=0 0
m=audio 30182 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2016-12-15 07:39:16.631393 [DEBUG] mod_rayo.c:1895 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, done executing command
2016-12-15 07:39:16.631393 [DEBUG] mod_rayo.c:849 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 1
2016-12-15 07:39:16.631393 [DEBUG] mod_rayo.c:842 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:16.631393 [DEBUG] mod_rayo.c:1901 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201 => usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='result' id='4cd0e6de-f7f1-454f-bc2f-e65553b78e04'/>
2016-12-15 07:39:16.631393 [DEBUG] mod_rayo.c:849 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:16.631393 [DEBUG] sofia.c:7054 Channel sofia/external/4044754849@192.168.65.114 entering state [early][183]
2016-12-15 07:39:16.631393 [DEBUG] switch_ivr.c:980 Codec Activated L16@8000hz 1 channels 20ms
2016-12-15 07:39:16.631393 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in SEND <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='result' id='4cd0e6de-f7f1-454f-bc2f-e65553b78e04'/>
2016-12-15 07:39:16.651524 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in RECV <iq type="set" to="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" id="b6fd52cc-26da-41c4-bce5-d982c2fed724"><answer xmlns="urn:xmpp:rayo:1"/></iq>
2016-12-15 07:39:16.651524 [DEBUG] xmpp_streams.c:1073 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, state = READY, node type = NODE_NORMAL
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:4197 Lock usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:3143 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, recv iq, availability = ONLINE
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:4281 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:842 Locate (jid) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 2
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:3146 Deliver usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 => 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201 <iq type='set' to='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' id='b6fd52cc-26da-41c4-bce5-d982c2fed724' from='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139'><answer xmlns='urn:xmpp:rayo:1'/></iq>
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:723 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, looking for CALL::set:urn:xmpp:rayo:1:answer command
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:1893 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, executing command
2016-12-15 07:39:16.651524 [DEBUG] switch_core_media.c:7431 Audio params are unchanged for sofia/external/4044754849@192.168.65.114.
2016-12-15 07:39:16.651524 [DEBUG] mod_sofia.c:826 Local SDP sofia/external/4044754849@192.168.65.114:
v=0
o=FreeSWITCH 1481786174 1481786176 IN IP4 192.168.65.201
s=FreeSWITCH
c=IN IP4 192.168.65.201
t=0 0
m=audio 30182 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2016-12-15 07:39:16.651524 [NOTICE] mod_rayo.c:2049 Channel [sofia/external/4044754849@192.168.65.114] has been answered
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:3694 got event CHANNEL_ANSWER
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:3699 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 rayo event CHANNEL_ANSWER
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:3701 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:3467 Locate (id) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 3
2016-12-15 07:39:16.651524 [DEBUG] switch_channel.c:3770 (sofia/external/4044754849@192.168.65.114) Callstate Change EARLY -> ACTIVE
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:1895 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, done executing command
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:849 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 2
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:842 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 3
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:1901 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201 => usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='result' id='b6fd52cc-26da-41c4-bce5-d982c2fed724'/>
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:849 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:3481 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 1
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:3709 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:842 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:3475 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201 => usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 <presence from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139'><answered xmlns='urn:xmpp:rayo:1'><header name='P-DCS-Billing-Info' value='gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9'/><header name='P-Charging-Vector' value='icid-value=1ed17a'/></answered><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:16Z'/></presence>
2016-12-15 07:39:16.651524 [DEBUG] mod_rayo.c:849 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:16.651524 [DEBUG] sofia.c:7054 Channel sofia/external/4044754849@192.168.65.114 entering state [completed][200]
2016-12-15 07:39:16.651524 [DEBUG] sofia.c:7054 Channel sofia/external/4044754849@192.168.65.114 entering state [ready][200]
2016-12-15 07:39:16.671381 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in SEND <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='result' id='b6fd52cc-26da-41c4-bce5-d982c2fed724'/>
2016-12-15 07:39:16.671381 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in SEND <presence from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139'><answered xmlns='urn:xmpp:rayo:1'><header name='P-DCS-Billing-Info' value='gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9'/><header name='P-Charging-Vector' value='icid-value=1ed17a'/></answered><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:16Z'/></presence>
2016-12-15 07:39:16.691379 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in RECV <iq type="set" to="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" id="20d644dc-b5be-4518-b54d-a0d0391c1c88"><output xmlns="urn:xmpp:rayo:output:1" renderer="unimrcp"><document content-type="application/ssml+xml"><![CDATA[<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">Our offices are open, please wait</speak>]]></document></output></iq>
2016-12-15 07:39:16.691379 [DEBUG] xmpp_streams.c:1073 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, state = READY, node type = NODE_NORMAL
2016-12-15 07:39:16.691379 [DEBUG] mod_rayo.c:4197 Lock usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:16.691379 [DEBUG] mod_rayo.c:3143 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, recv iq, availability = ONLINE
2016-12-15 07:39:16.691379 [DEBUG] mod_rayo.c:4281 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:16.691379 [DEBUG] mod_rayo.c:842 Locate (jid) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 2
2016-12-15 07:39:16.691379 [DEBUG] mod_rayo.c:3146 Deliver usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 => 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201 <iq type='set' to='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' id='20d644dc-b5be-4518-b54d-a0d0391c1c88' from='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139'><output xmlns='urn:xmpp:rayo:output:1' renderer='unimrcp'><document content-type='application/ssml+xml'>&lt;speak xmlns=&quot;http://www.w3.org/2001/10/synthesis&quot; version=&quot;1.0&quot; xml:lang=&quot;en-US&quot;&gt;Our offices are open, please wait&lt;/speak&gt;</document></output></iq>
2016-12-15 07:39:16.691379 [DEBUG] mod_rayo.c:723 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, looking for CALL::set:urn:xmpp:rayo:output:1:output command
2016-12-15 07:39:16.691379 [DEBUG] mod_rayo.c:1893 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, executing command
2016-12-15 07:39:16.691379 [DEBUG] mod_rayo.c:1367 Lock 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 3
2016-12-15 07:39:16.691379 [DEBUG] rayo_output_component.c:73 Init 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-1
2016-12-15 07:39:16.691379 [DEBUG] mod_rayo.c:842 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:16.691379 [DEBUG] rayo_components.c:62 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-1 => usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='result' id='20d644dc-b5be-4518-b54d-a0d0391c1c88'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-1'/></iq>
2016-12-15 07:39:16.691379 [DEBUG] mod_rayo.c:849 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:16.691379 [DEBUG] rayo_output_component.c:842 Got path rayo://0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-1
2016-12-15 07:39:16.691379 [DEBUG] rayo_output_component.c:648 Got path 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-1
2016-12-15 07:39:16.691379 [DEBUG] rayo_output_component.c:650 Locate (id) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-1: ref count = 2
2016-12-15 07:39:16.691379 [INFO] mod_unimrcp.c:1624 speech_handle: name = unimrcp, rate = 8000, speed = 0, samples = 0, voice = , engine = unimrcp, param = (null)
2016-12-15 07:39:16.691379 [INFO] mod_unimrcp.c:1627 voice = , rate = 8000
2016-12-15 07:39:16.691379 [DEBUG] mod_unimrcp.c:683 (TTS-40) audio queue created
2016-12-15 07:39:16.691379 [NOTICE] mrcp_application.c:96 (TTS-40) Create MRCP Handle 0x7f257401cce0 [lumenvox]
2016-12-15 07:39:16.691379 [INFO] mrcp_client_session.c:133 (TTS-40) Create Channel TTS-40 <new>
2016-12-15 07:39:16.691379 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2574002940;4;0]
2016-12-15 07:39:16.691379 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in SEND <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='result' id='20d644dc-b5be-4518-b54d-a0d0391c1c88'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-1'/></iq>
2016-12-15 07:39:16.691379 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2574002940;4;0]
2016-12-15 07:39:16.691379 [INFO] mrcp_client_session.c:387 (TTS-40) Receive App Request TTS-40 <new> [2]
2016-12-15 07:39:16.691379 [INFO] mrcp_client.c:700 (TTS-40) Add MRCP Handle TTS-40 <new>
2016-12-15 07:39:16.691379 [DEBUG] mrcp_client_session.c:1283 (TTS-40) Dispatch App Request TTS-40 <new> [2]
2016-12-15 07:39:16.691379 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f253002e0a0;1;0]
2016-12-15 07:39:16.691379 [NOTICE] mrcp_client_session.c:719 (TTS-40) Add Control Channel TTS-40 <new@speechsynth>
2016-12-15 07:39:16.691379 [DEBUG] mrcp_client_session.c:745 (TTS-40) Add Media Termination TTS-40 <new@media-tm>
2016-12-15 07:39:16.691379 [DEBUG] mrcp_client_session.c:777 (TTS-40) Add Media Termination TTS-40 <new@rtp-tm>
2016-12-15 07:39:16.691379 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7f2530021b40;1;0]
2016-12-15 07:39:16.691379 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:16.691379 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2016-12-15 07:39:16.691379 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f253002e0a0;1;0]
2016-12-15 07:39:16.691379 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538024200;2;0]
2016-12-15 07:39:16.691379 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:16.691379 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538024200;2;0]
2016-12-15 07:39:16.691379 [DEBUG] mrcp_client_session.c:294 (TTS-40) Control Channel Added TTS-40 <new@speechsynth>
2016-12-15 07:39:16.691379 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:16.691379 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7f2530021b40;1;0]
2016-12-15 07:39:16.691379 [DEBUG] mpf_context.c:182 () Add Media Context TTS-40
2016-12-15 07:39:16.691379 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2578005350;3;0]
2016-12-15 07:39:16.691379 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2578005350;3;0]
2016-12-15 07:39:16.691379 [DEBUG] mrcp_client_session.c:944 (TTS-40) Media Termination Added TTS-40 <new@media-tm>
2016-12-15 07:39:16.691379 [DEBUG] mrcp_client_session.c:944 (TTS-40) Media Termination Added TTS-40 <new@rtp-tm>
2016-12-15 07:39:16.691379 [INFO] mrcp_client_session.c:411 (TTS-40) Send Offer TTS-40 <new> [c:1 a:1 v:0] to 127.0.0.1:5065
2016-12-15 07:39:16.691379 [INFO] mrcp_sofiasip_client_agent.c:354 (TTS-40) Local SDP TTS-40 <new>
v=0
o=FreeSWITCH 0 0 IN IP4 192.168.65.201
s=-
c=IN IP4 192.168.65.201
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechsynth
a=cmid:1
m=audio 28080 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=recvonly
a=mid:1
2016-12-15 07:39:16.691379 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:16.691379 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 0 INVITE sent [lumenvox]
2016-12-15 07:39:16.691379 [NOTICE] mrcp_sofiasip_client_agent.c:547 (TTS-40) SIP Call State TTS-40 [calling]
2016-12-15 07:39:16.711666 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_r_invite] Status 200 OK [lumenvox]
2016-12-15 07:39:16.711666 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 200 OK [lumenvox]
2016-12-15 07:39:16.711666 [NOTICE] mrcp_sofiasip_client_agent.c:547 (TTS-40) SIP Call State TTS-40 [ready]
2016-12-15 07:39:16.711666 [INFO] mrcp_sofiasip_client_agent.c:433 (TTS-40) Remote SDP TTS-40 <new>
v=0
o=- 1234 5678 IN IP4 127.0.0.1
s=-
c=IN IP4 127.0.0.1
t=0 0
m=application 20054 TCP/MRCPv2 1
a=setup:passive
a=connection:new
a=channel:7c15c47c-8afb-4368-b@speechsynth
a=cmid:1
m=audio 25108 RTP/AVP 0
c=IN IP4 127.0.0.1
a=rtpmap:0 PCMU/8000
a=sendonly
a=mid:1
2016-12-15 07:39:16.711666 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2540021870;1;0]
2016-12-15 07:39:16.711666 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_active] Status 200 Call active [lumenvox]
2016-12-15 07:39:16.711666 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2540021870;1;0]
2016-12-15 07:39:16.711666 [INFO] mrcp_client_session.c:151 (TTS-40) Receive Answer TTS-40 <new> [c:1 a:1 v:0] Status 200
2016-12-15 07:39:16.711666 [DEBUG] mrcp_client_session.c:1141 (TTS-40) Modify Control Channel TTS-40 <7c15c47c-8afb-4368-b>
2016-12-15 07:39:16.711666 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f253002e0a0;1;0]
2016-12-15 07:39:16.711666 [DEBUG] mrcp_client_session.c:1180 (TTS-40) Modify Media Termination TTS-40 <7c15c47c-8afb-4368-b@rtp-tm>
2016-12-15 07:39:16.711666 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7f2530021b40;1;0]
2016-12-15 07:39:16.711666 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:16.711666 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2016-12-15 07:39:16.711666 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f253002e0a0;1;0]
2016-12-15 07:39:16.711666 [NOTICE] mrcp_client_connection.c:338 () Established TCP/MRCPv2 Connection 127.0.0.1:59856 <-> 127.0.0.1:20054
2016-12-15 07:39:16.711666 [INFO] mrcp_client_connection.c:435 (TTS-40) Add Control Channel <7c15c47c-8afb-4368-b@speechsynth> 127.0.0.1:59856 <-> 127.0.0.1:20054 [1]
2016-12-15 07:39:16.711666 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538024480;2;1]
2016-12-15 07:39:16.711666 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:16.711666 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538024480;2;1]
2016-12-15 07:39:16.711666 [DEBUG] mrcp_client_session.c:311 (TTS-40) Control Channel Modified TTS-40 <7c15c47c-8afb-4368-b@speechsynth>
2016-12-15 07:39:16.711666 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:16.711666 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7f2530021b40;1;0]
2016-12-15 07:39:16.711666 [INFO] mpf_rtp_stream.c:331 () Enable RTP Session 192.168.65.201:28080
2016-12-15 07:39:16.711666 [DEBUG] mpf_bridge.c:129 () Create Linear Audio Bridge TTS-40
2016-12-15 07:39:16.711666 [INFO] mpf_rtp_stream.c:509 () Open RTP Receiver 192.168.65.201:28080 <- 127.0.0.1:25108 playout [0 ms] bounds [0 - 600 ms] adaptive [0] skew detection [1]
2016-12-15 07:39:16.711666 [INFO] mpf_bridge.c:93 () Media Path TTS-40 Source->[PCMU/8000/1]->Decoder->[LPCM/8000/1]->Bridge->[LPCM/8000/1]->Sink
2016-12-15 07:39:16.711666 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2578005350;3;0]
2016-12-15 07:39:16.711666 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2578005350;3;0]
2016-12-15 07:39:16.711666 [DEBUG] mrcp_client_session.c:985 (TTS-40) Media Termination Modified TTS-40 <7c15c47c-8afb-4368-b@rtp-tm>
2016-12-15 07:39:16.711666 [INFO] mrcp_client_session.c:455 (TTS-40) Raise App Response TTS-40 <7c15c47c-8afb-4368-b> [2] SUCCESS [0]
2016-12-15 07:39:16.711666 [DEBUG] mod_unimrcp.c:1893 (TTS-40) SYNTHESIZER channel is ready, codec = LPCM, sample rate = 8000
2016-12-15 07:39:16.711666 [DEBUG] mod_unimrcp.c:1577 (TTS-40) CLOSED ==> READY
2016-12-15 07:39:16.711666 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:16.711666 [DEBUG] mod_unimrcp.c:1055 (TTS-40) channel is ready
2016-12-15 07:39:16.711666 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2574002940;4;0]
2016-12-15 07:39:16.711666 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2574002940;4;0]
2016-12-15 07:39:16.711666 [INFO] mrcp_client_session.c:392 (TTS-40) Receive App MRCP Request TTS-40 <7c15c47c-8afb-4368-b>
2016-12-15 07:39:16.711666 [INFO] mrcp_client_session.c:622 (TTS-40) Send MRCP Request TTS-40 <7c15c47c-8afb-4368-b@speechsynth> [1]
2016-12-15 07:39:16.711666 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f253002e0a0;1;0]
2016-12-15 07:39:16.711666 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:16.711666 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2016-12-15 07:39:16.711666 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f253002e0a0;1;0]
2016-12-15 07:39:16.711666 [INFO] mrcp_client_connection.c:530 (TTS-40) Send MRCPv2 Data 127.0.0.1:59856 <-> 127.0.0.1:20054 [249 bytes]
MRCP/2.0 249 SPEAK 1
Channel-Identifier: 7c15c47c-8afb-4368-b@speechsynth
Content-Type: text/plain
Content-Length: 124
}<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">Our offices are open, please wait</speak>
2016-12-15 07:39:16.711666 [DEBUG] apt_poller_task.c:246 () Wait for Messages [MRCPv2ConnectionAgent] timeout [3000]
2016-12-15 07:39:16.771643 [DEBUG] apt_poller_task.c:269 () Process Signalled Descriptor [MRCPv2ConnectionAgent]
2016-12-15 07:39:16.771643 [INFO] mrcp_client_connection.c:635 () Receive MRCPv2 Data 127.0.0.1:59856 <-> 127.0.0.1:20054 [124 bytes]
MRCP/2.0 124 1 200 IN-PROGRESS
Channel-Identifier: 7c15c47c-8afb-4368-b@speechsynth
Speech-Marker: timestamp=421117336
2016-12-15 07:39:16.771643 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538024480;2;3]
2016-12-15 07:39:16.771643 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:16.771643 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538024480;2;3]
2016-12-15 07:39:16.771643 [INFO] mrcp_client_session.c:500 (TTS-40) Raise App MRCP Response TTS-40 <7c15c47c-8afb-4368-b>
2016-12-15 07:39:16.771643 [DEBUG] mod_unimrcp.c:1966 (TTS-40) REQUEST IN PROGRESS
2016-12-15 07:39:16.771643 [DEBUG] mod_unimrcp.c:1577 (TTS-40) READY ==> PROCESSING
2016-12-15 07:39:16.771643 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:16.771643 [DEBUG] rayo_output_component.c:866 Create audio buffer
2016-12-15 07:39:16.771643 [DEBUG] switch_core_media_bug.c:841 Attaching BUG to sofia/external/4044754849@192.168.65.114
2016-12-15 07:39:16.771643 [DEBUG] rayo_output_component.c:139 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-1: ref count = 1
2016-12-15 07:39:16.771643 [DEBUG] mod_rayo.c:1895 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, done executing command
2016-12-15 07:39:16.771643 [DEBUG] mod_rayo.c:849 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 2
2016-12-15 07:39:17.211462 [DEBUG] switch_rtp.c:6979 Correct audio ip/port confirmed.
2016-12-15 07:39:17.211462 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMU:0
2016-12-15 07:39:19.331649 [DEBUG] apt_poller_task.c:269 () Process Signalled Descriptor [MRCPv2ConnectionAgent]
2016-12-15 07:39:19.331649 [INFO] mrcp_client_connection.c:635 () Receive MRCPv2 Data 127.0.0.1:59856 <-> 127.0.0.1:20054 [162 bytes]
MRCP/2.0 162 SPEAK-COMPLETE 1 COMPLETE
Channel-Identifier: 7c15c47c-8afb-4368-b@speechsynth
Completion-Cause: 000 normal
Speech-Marker: timestamp=421138244
2016-12-15 07:39:19.331649 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538024480;2;3]
2016-12-15 07:39:19.331649 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:19.331649 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538024480;2;3]
2016-12-15 07:39:19.331649 [INFO] mrcp_client_session.c:516 (TTS-40) Raise App MRCP Event TTS-40 <7c15c47c-8afb-4368-b>
2016-12-15 07:39:19.331649 [DEBUG] mod_unimrcp.c:1996 (TTS-40) SPEAK-COMPLETE
2016-12-15 07:39:19.331649 [DEBUG] mod_unimrcp.c:1577 (TTS-40) PROCESSING ==> DONE
2016-12-15 07:39:19.331649 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:19.631427 [DEBUG] mod_unimrcp.c:1577 (TTS-40) DONE ==> READY
2016-12-15 07:39:19.631427 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2548003d40;4;0]
2016-12-15 07:39:19.631427 [DEBUG] mod_unimrcp.c:923 (TTS-40) Waiting for MRCP session to terminate
2016-12-15 07:39:19.631427 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2548003d40;4;0]
2016-12-15 07:39:19.631427 [INFO] mrcp_client_session.c:387 (TTS-40) Receive App Request TTS-40 <7c15c47c-8afb-4368-b> [1]
2016-12-15 07:39:19.631427 [DEBUG] mrcp_client_session.c:1283 (TTS-40) Dispatch App Request TTS-40 <7c15c47c-8afb-4368-b> [1]
2016-12-15 07:39:19.631427 [INFO] mrcp_client_session.c:833 (TTS-40) Terminate Session TTS-40 <7c15c47c-8afb-4368-b>
2016-12-15 07:39:19.631427 [DEBUG] mrcp_client_session.c:854 (TTS-40) Remove Control Channel TTS-40 <7c15c47c-8afb-4368-b>
2016-12-15 07:39:19.631427 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:19.631427 [DEBUG] mrcp_client_session.c:864 (TTS-40) Subtract Media Termination TTS-40 <7c15c47c-8afb-4368-b@media-tm>
2016-12-15 07:39:19.631427 [DEBUG] mrcp_client_session.c:885 (TTS-40) Subtract Media Termination TTS-40 <7c15c47c-8afb-4368-b@rtp-tm>
2016-12-15 07:39:19.631427 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7f25300260c0;1;0]
2016-12-15 07:39:19.631427 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:19.631427 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2016-12-15 07:39:19.631427 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:19.631427 [INFO] mrcp_client_connection.c:459 (TTS-40) Remove Control Channel <7c15c47c-8afb-4368-b@speechsynth> [0]
2016-12-15 07:39:19.631427 [INFO] mrcp_client_connection.c:386 () Close TCP/MRCPv2 Connection 127.0.0.1:59856 <-> 127.0.0.1:20054
2016-12-15 07:39:19.631427 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538024480;2;2]
2016-12-15 07:39:19.631427 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:19.631427 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538024480;2;2]
2016-12-15 07:39:19.631427 [DEBUG] mrcp_client_session.c:331 (TTS-40) Control Channel Removed TTS-40 <7c15c47c-8afb-4368-b@speechsynth>
2016-12-15 07:39:19.631427 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:19.631427 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_r_bye] Status 200 OK [lumenvox]
2016-12-15 07:39:19.651368 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 200 to BYE [lumenvox]
2016-12-15 07:39:19.651368 [NOTICE] mrcp_sofiasip_client_agent.c:547 (TTS-40) SIP Call State TTS-40 [terminated]
2016-12-15 07:39:19.651368 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2540021870;1;1]
2016-12-15 07:39:19.651368 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2540021870;1;1]
2016-12-15 07:39:19.651368 [INFO] mrcp_client_session.c:209 (TTS-40) Session Terminated TTS-40 <7c15c47c-8afb-4368-b>
2016-12-15 07:39:19.651368 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:19.651368 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7f25300260c0;1;0]
2016-12-15 07:39:19.651368 [DEBUG] mpf_bridge.c:100 () Destroy Audio Bridge TTS-40
2016-12-15 07:39:19.651368 [INFO] mpf_rtp_stream.c:541 () Close RTP Receiver 192.168.65.201:28080 <- 127.0.0.1:25108 [r:131 l:0 j:83 p:0 d:0 i:0]
2016-12-15 07:39:19.651368 [DEBUG] mpf_context.c:238 () Remove Media Context TTS-40
2016-12-15 07:39:19.651368 [INFO] mpf_rtp_stream.c:418 () Remove RTP Session 192.168.65.201:28080
2016-12-15 07:39:19.651368 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2578005350;3;0]
2016-12-15 07:39:19.651368 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2578005350;3;0]
2016-12-15 07:39:19.651368 [DEBUG] mrcp_client_session.c:1014 (TTS-40) Media Termination Subtracted TTS-40 <7c15c47c-8afb-4368-b@media-tm>
2016-12-15 07:39:19.651368 [DEBUG] mrcp_client_session.c:1014 (TTS-40) Media Termination Subtracted TTS-40 <7c15c47c-8afb-4368-b@rtp-tm>
2016-12-15 07:39:19.651368 [NOTICE] mrcp_client_connection.c:235 () Destroy TCP/MRCPv2 Connection 127.0.0.1:59856 <-> 127.0.0.1:20054
2016-12-15 07:39:19.651368 [INFO] mrcp_client.c:710 (TTS-40) Remove MRCP Handle TTS-40 <7c15c47c-8afb-4368-b>
2016-12-15 07:39:19.651368 [INFO] mrcp_client_session.c:455 (TTS-40) Raise App Response TTS-40 <7c15c47c-8afb-4368-b> [1] SUCCESS [0]
2016-12-15 07:39:19.651368 [DEBUG] mod_unimrcp.c:1828 (TTS-40) Destroying MRCP session
2016-12-15 07:39:19.651368 [NOTICE] mrcp_application.c:182 (TTS-40) Destroy MRCP Handle TTS-40
2016-12-15 07:39:19.651368 [DEBUG] mod_unimrcp.c:1577 (TTS-40) READY ==> CLOSED
2016-12-15 07:39:19.651368 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:19.651368 [DEBUG] mod_unimrcp.c:851 (TTS-40) audio queue destroyed
2016-12-15 07:39:19.651368 [INFO] rayo_output_component.c:552 Done playing
2016-12-15 07:39:19.651368 [DEBUG] rayo_components.c:117 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-1: ref count = 0
2016-12-15 07:39:19.651368 [DEBUG] rayo_components.c:118 Destroy 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-1 requested: ref_count = 0
2016-12-15 07:39:19.651368 [DEBUG] rayo_components.c:118 Destroying 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-1
2016-12-15 07:39:19.651368 [DEBUG] mod_rayo.c:1035 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 1
2016-12-15 07:39:19.651368 [DEBUG] mod_rayo.c:842 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:19.651368 [DEBUG] rayo_components.c:116 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-1 => usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 <presence from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-1' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='unavailable'><complete xmlns='urn:xmpp:rayo:ext:1'><finish xmlns='urn:xmpp:rayo:output:complete:1'/></complete><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:19Z'/></presence>
2016-12-15 07:39:19.651368 [DEBUG] mod_rayo.c:849 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:19.651368 [DEBUG] switch_core_media_bug.c:1208 Removing BUG from sofia/external/4044754849@192.168.65.114
2016-12-15 07:39:19.671370 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in SEND <presence from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-1' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='unavailable'><complete xmlns='urn:xmpp:rayo:ext:1'><finish xmlns='urn:xmpp:rayo:output:complete:1'/></complete><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:19Z'/></presence>
2016-12-15 07:39:19.671370 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in RECV <iq type="set" to="192.168.65.201" id="c7d67f7d-01dc-4721-986d-7b42968d36b9"><dial xmlns="urn:xmpp:rayo:1" to="sofia/external/7183519970" from="sip:4044754849@192.168.65.114" uri="xmpp:94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201"/></iq>
2016-12-15 07:39:19.671370 [DEBUG] xmpp_streams.c:1073 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, state = READY, node type = NODE_NORMAL
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:4197 Lock usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:3143 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, recv iq, availability = ONLINE
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:4281 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:842 Locate (jid) 192.168.65.201: ref count = 2
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:3146 Deliver usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 => 192.168.65.201 <iq type='set' to='192.168.65.201' id='c7d67f7d-01dc-4721-986d-7b42968d36b9' from='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139'><dial xmlns='urn:xmpp:rayo:1' to='sofia/external/7183519970' from='sip:4044754849@192.168.65.114' uri='xmpp:94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201'/></iq>
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:723 192.168.65.201, looking for SERVER::set:urn:xmpp:rayo:1:dial command
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:849 Release 192.168.65.201: ref count = 1
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:2678 Init 94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201
2016-12-15 07:39:19.671370 [INFO] mod_rayo.c:2685 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 has control of call
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:2716 dial: sip_from_uri=sip:4044754849@192.168.65.114
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:2725 dial: origination_caller_id_number=sip:4044754849@192.168.65.114
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:2799 dial: Using dialstring: sofia/external/7183519970
2016-12-15 07:39:19.671370 [DEBUG] switch_ivr_originate.c:2138 Parsing global variables
2016-12-15 07:39:19.671370 [WARNING] mod_sofia.c:4635 Cannot locate registered user 7183519970@external
2016-12-15 07:39:19.671370 [NOTICE] mod_sofia.c:4889 Close Channel N/A [CS_NEW]
2016-12-15 07:39:19.671370 [DEBUG] switch_core_state_machine.c:741 () Running State Change CS_DESTROY
2016-12-15 07:39:19.671370 [DEBUG] switch_core_state_machine.c:751 (N/A) State DESTROY
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:3437 Locate (id) 94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201: ref count = 2
2016-12-15 07:39:19.671370 [DEBUG] mod_sofia.c:345 N/A SOFIA DESTROY
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:3447 Got channel destroy event
2016-12-15 07:39:19.671370 [DEBUG] switch_core_state_machine.c:751 (N/A) State DESTROY going to sleep
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:3456 Release 94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201: ref count = 1
2016-12-15 07:39:19.671370 [NOTICE] switch_ivr_originate.c:2841 Cannot create outgoing channel of type [sofia] cause: [USER_NOT_REGISTERED]
2016-12-15 07:39:19.671370 [DEBUG] switch_ivr_originate.c:3829 Originate Resulted in Error Cause: 606 [USER_NOT_REGISTERED]
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:2816 dial: Failed to originate call: USER_NOT_REGISTERED
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:1186 Sending <end> to DCP usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:842 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:2848 Destroy 94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201 requested: ref_count = 1
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:2842 Deliver 192.168.65.201 => usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 <iq from='192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' id='c7d67f7d-01dc-4721-986d-7b42968d36b9' type='result'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201'/></iq>
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:2849 Release 94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201: ref count = 0
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:2849 Destroying 94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:849 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:842 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:1188 Deliver 94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201 => usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 <presence from='94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='unavailable'><end xmlns='urn:xmpp:rayo:1'><error platform-code='20'/></end><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:19Z'/></presence>
2016-12-15 07:39:19.671370 [DEBUG] mod_rayo.c:849 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:19.691377 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in SEND <iq from='192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' id='c7d67f7d-01dc-4721-986d-7b42968d36b9' type='result'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201'/></iq>
2016-12-15 07:39:19.691377 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in SEND <presence from='94ac8658-c212-49f8-994f-a59b970fe4e6@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='unavailable'><end xmlns='urn:xmpp:rayo:1'><error platform-code='20'/></end><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:19Z'/></presence>
2016-12-15 07:39:19.751379 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in RECV <iq type="set" to="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" id="310ca5f0-10d8-4114-97c7-4af86be0e5f1"><output xmlns="urn:xmpp:rayo:output:1" renderer="unimrcp"><document content-type="application/ssml+xml"><![CDATA[<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">Our offices are open, please wait</speak>]]></document></output></iq>
2016-12-15 07:39:19.751379 [DEBUG] xmpp_streams.c:1073 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, state = READY, node type = NODE_NORMAL
2016-12-15 07:39:19.751379 [DEBUG] mod_rayo.c:4197 Lock usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:19.751379 [DEBUG] mod_rayo.c:3143 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, recv iq, availability = ONLINE
2016-12-15 07:39:19.751379 [DEBUG] mod_rayo.c:4281 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:19.751379 [DEBUG] mod_rayo.c:842 Locate (jid) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 2
2016-12-15 07:39:19.751379 [DEBUG] mod_rayo.c:3146 Deliver usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 => 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201 <iq type='set' to='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' id='310ca5f0-10d8-4114-97c7-4af86be0e5f1' from='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139'><output xmlns='urn:xmpp:rayo:output:1' renderer='unimrcp'><document content-type='application/ssml+xml'>&lt;speak xmlns=&quot;http://www.w3.org/2001/10/synthesis&quot; version=&quot;1.0&quot; xml:lang=&quot;en-US&quot;&gt;Our offices are open, please wait&lt;/speak&gt;</document></output></iq>
2016-12-15 07:39:19.751379 [DEBUG] mod_rayo.c:723 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, looking for CALL::set:urn:xmpp:rayo:output:1:output command
2016-12-15 07:39:19.751379 [DEBUG] mod_rayo.c:1893 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, executing command
2016-12-15 07:39:19.751379 [DEBUG] mod_rayo.c:1367 Lock 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 3
2016-12-15 07:39:19.751379 [DEBUG] rayo_output_component.c:73 Init 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-2
2016-12-15 07:39:19.751379 [DEBUG] mod_rayo.c:842 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:19.751379 [DEBUG] rayo_components.c:62 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-2 => usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='result' id='310ca5f0-10d8-4114-97c7-4af86be0e5f1'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-2'/></iq>
2016-12-15 07:39:19.751379 [DEBUG] mod_rayo.c:849 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:19.751379 [DEBUG] rayo_output_component.c:842 Got path rayo://0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-2
2016-12-15 07:39:19.751379 [DEBUG] rayo_output_component.c:648 Got path 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-2
2016-12-15 07:39:19.751379 [DEBUG] rayo_output_component.c:650 Locate (id) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-2: ref count = 2
2016-12-15 07:39:19.751379 [INFO] mod_unimrcp.c:1624 speech_handle: name = unimrcp, rate = 8000, speed = 0, samples = 0, voice = , engine = unimrcp, param = (null)
2016-12-15 07:39:19.751379 [INFO] mod_unimrcp.c:1627 voice = , rate = 8000
2016-12-15 07:39:19.751379 [DEBUG] mod_unimrcp.c:683 (TTS-41) audio queue created
2016-12-15 07:39:19.751379 [NOTICE] mrcp_application.c:96 (TTS-41) Create MRCP Handle 0x7f2570016900 [lumenvox]
2016-12-15 07:39:19.751379 [INFO] mrcp_client_session.c:133 (TTS-41) Create Channel TTS-41 <new>
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2570001130;4;0]
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2570001130;4;0]
2016-12-15 07:39:19.751379 [INFO] mrcp_client_session.c:387 (TTS-41) Receive App Request TTS-41 <new> [2]
2016-12-15 07:39:19.751379 [INFO] mrcp_client.c:700 (TTS-41) Add MRCP Handle TTS-41 <new>
2016-12-15 07:39:19.751379 [DEBUG] mrcp_client_session.c:1283 (TTS-41) Dispatch App Request TTS-41 <new> [2]
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:19.751379 [NOTICE] mrcp_client_session.c:719 (TTS-41) Add Control Channel TTS-41 <new@speechsynth>
2016-12-15 07:39:19.751379 [DEBUG] mrcp_client_session.c:745 (TTS-41) Add Media Termination TTS-41 <new@media-tm>
2016-12-15 07:39:19.751379 [DEBUG] mrcp_client_session.c:777 (TTS-41) Add Media Termination TTS-41 <new@rtp-tm>
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7f2530026440;1;0]
2016-12-15 07:39:19.751379 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:19.751379 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538024480;2;0]
2016-12-15 07:39:19.751379 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538024480;2;0]
2016-12-15 07:39:19.751379 [DEBUG] mrcp_client_session.c:294 (TTS-41) Control Channel Added TTS-41 <new@speechsynth>
2016-12-15 07:39:19.751379 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7f2530026440;1;0]
2016-12-15 07:39:19.751379 [DEBUG] mpf_context.c:182 () Add Media Context TTS-41
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2578000c20;3;0]
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2578000c20;3;0]
2016-12-15 07:39:19.751379 [DEBUG] mrcp_client_session.c:944 (TTS-41) Media Termination Added TTS-41 <new@media-tm>
2016-12-15 07:39:19.751379 [DEBUG] mrcp_client_session.c:944 (TTS-41) Media Termination Added TTS-41 <new@rtp-tm>
2016-12-15 07:39:19.751379 [INFO] mrcp_client_session.c:411 (TTS-41) Send Offer TTS-41 <new> [c:1 a:1 v:0] to 127.0.0.1:5065
2016-12-15 07:39:19.751379 [INFO] mrcp_sofiasip_client_agent.c:354 (TTS-41) Local SDP TTS-41 <new>
v=0
o=FreeSWITCH 0 0 IN IP4 192.168.65.201
s=-
c=IN IP4 192.168.65.201
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechsynth
a=cmid:1
m=audio 28082 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=recvonly
a=mid:1
2016-12-15 07:39:19.751379 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:19.751379 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 0 INVITE sent [lumenvox]
2016-12-15 07:39:19.751379 [NOTICE] mrcp_sofiasip_client_agent.c:547 (TTS-41) SIP Call State TTS-41 [calling]
2016-12-15 07:39:19.751379 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_r_invite] Status 200 OK [lumenvox]
2016-12-15 07:39:19.751379 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 200 OK [lumenvox]
2016-12-15 07:39:19.751379 [NOTICE] mrcp_sofiasip_client_agent.c:547 (TTS-41) SIP Call State TTS-41 [ready]
2016-12-15 07:39:19.751379 [INFO] mrcp_sofiasip_client_agent.c:433 (TTS-41) Remote SDP TTS-41 <new>
v=0
o=- 1234 5678 IN IP4 127.0.0.1
s=-
c=IN IP4 127.0.0.1
t=0 0
m=application 20055 TCP/MRCPv2 1
a=setup:passive
a=connection:new
a=channel:1672836c-1130-4bce-a@speechsynth
a=cmid:1
m=audio 25110 RTP/AVP 0
c=IN IP4 127.0.0.1
a=rtpmap:0 PCMU/8000
a=sendonly
a=mid:1
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2540021870;1;0]
2016-12-15 07:39:19.751379 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_active] Status 200 Call active [lumenvox]
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2540021870;1;0]
2016-12-15 07:39:19.751379 [INFO] mrcp_client_session.c:151 (TTS-41) Receive Answer TTS-41 <new> [c:1 a:1 v:0] Status 200
2016-12-15 07:39:19.751379 [DEBUG] mrcp_client_session.c:1141 (TTS-41) Modify Control Channel TTS-41 <1672836c-1130-4bce-a>
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:19.751379 [DEBUG] mrcp_client_session.c:1180 (TTS-41) Modify Media Termination TTS-41 <1672836c-1130-4bce-a@rtp-tm>
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7f2530026440;1;0]
2016-12-15 07:39:19.751379 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:19.751379 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:19.751379 [NOTICE] mrcp_client_connection.c:338 () Established TCP/MRCPv2 Connection 127.0.0.1:52410 <-> 127.0.0.1:20055
2016-12-15 07:39:19.751379 [INFO] mrcp_client_connection.c:435 (TTS-41) Add Control Channel <1672836c-1130-4bce-a@speechsynth> 127.0.0.1:52410 <-> 127.0.0.1:20055 [1]
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538024610;2;1]
2016-12-15 07:39:19.751379 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538024610;2;1]
2016-12-15 07:39:19.751379 [DEBUG] mrcp_client_session.c:311 (TTS-41) Control Channel Modified TTS-41 <1672836c-1130-4bce-a@speechsynth>
2016-12-15 07:39:19.751379 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7f2530026440;1;0]
2016-12-15 07:39:19.751379 [INFO] mpf_rtp_stream.c:331 () Enable RTP Session 192.168.65.201:28082
2016-12-15 07:39:19.751379 [DEBUG] mpf_bridge.c:129 () Create Linear Audio Bridge TTS-41
2016-12-15 07:39:19.751379 [INFO] mpf_rtp_stream.c:509 () Open RTP Receiver 192.168.65.201:28082 <- 127.0.0.1:25110 playout [0 ms] bounds [0 - 600 ms] adaptive [0] skew detection [1]
2016-12-15 07:39:19.751379 [INFO] mpf_bridge.c:93 () Media Path TTS-41 Source->[PCMU/8000/1]->Decoder->[LPCM/8000/1]->Bridge->[LPCM/8000/1]->Sink
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2578000c20;3;0]
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2578000c20;3;0]
2016-12-15 07:39:19.751379 [DEBUG] mrcp_client_session.c:985 (TTS-41) Media Termination Modified TTS-41 <1672836c-1130-4bce-a@rtp-tm>
2016-12-15 07:39:19.751379 [INFO] mrcp_client_session.c:455 (TTS-41) Raise App Response TTS-41 <1672836c-1130-4bce-a> [2] SUCCESS [0]
2016-12-15 07:39:19.751379 [DEBUG] mod_unimrcp.c:1893 (TTS-41) SYNTHESIZER channel is ready, codec = LPCM, sample rate = 8000
2016-12-15 07:39:19.751379 [DEBUG] mod_unimrcp.c:1577 (TTS-41) CLOSED ==> READY
2016-12-15 07:39:19.751379 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:19.751379 [DEBUG] mod_unimrcp.c:1055 (TTS-41) channel is ready
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2570001130;4;0]
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2570001130;4;0]
2016-12-15 07:39:19.751379 [INFO] mrcp_client_session.c:392 (TTS-41) Receive App MRCP Request TTS-41 <1672836c-1130-4bce-a>
2016-12-15 07:39:19.751379 [INFO] mrcp_client_session.c:622 (TTS-41) Send MRCP Request TTS-41 <1672836c-1130-4bce-a@speechsynth> [1]
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:19.751379 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:19.751379 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2016-12-15 07:39:19.751379 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:19.751379 [INFO] mrcp_client_connection.c:530 (TTS-41) Send MRCPv2 Data 127.0.0.1:52410 <-> 127.0.0.1:20055 [249 bytes]
MRCP/2.0 249 SPEAK 1
Channel-Identifier: 1672836c-1130-4bce-a@speechsynth
Content-Type: text/plain
Content-Length: 124
}<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">Our offices are open, please wait</speak>
2016-12-15 07:39:19.751379 [DEBUG] apt_poller_task.c:246 () Wait for Messages [MRCPv2ConnectionAgent] timeout [3000]
2016-12-15 07:39:19.771594 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in SEND <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='result' id='310ca5f0-10d8-4114-97c7-4af86be0e5f1'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-2'/></iq>
2016-12-15 07:39:19.792825 [DEBUG] apt_poller_task.c:269 () Process Signalled Descriptor [MRCPv2ConnectionAgent]
2016-12-15 07:39:19.792825 [INFO] mrcp_client_connection.c:635 () Receive MRCPv2 Data 127.0.0.1:52410 <-> 127.0.0.1:20055 [124 bytes]
MRCP/2.0 124 1 200 IN-PROGRESS
Channel-Identifier: 1672836c-1130-4bce-a@speechsynth
Speech-Marker: timestamp=421141488
2016-12-15 07:39:19.792825 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538024610;2;3]
2016-12-15 07:39:19.792825 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:19.792825 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538024610;2;3]
2016-12-15 07:39:19.792825 [INFO] mrcp_client_session.c:500 (TTS-41) Raise App MRCP Response TTS-41 <1672836c-1130-4bce-a>
2016-12-15 07:39:19.792825 [DEBUG] mod_unimrcp.c:1966 (TTS-41) REQUEST IN PROGRESS
2016-12-15 07:39:19.792825 [DEBUG] mod_unimrcp.c:1577 (TTS-41) READY ==> PROCESSING
2016-12-15 07:39:19.792825 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:19.792825 [DEBUG] rayo_output_component.c:866 Create audio buffer
2016-12-15 07:39:19.792825 [DEBUG] switch_core_media_bug.c:841 Attaching BUG to sofia/external/4044754849@192.168.65.114
2016-12-15 07:39:19.792825 [DEBUG] rayo_output_component.c:139 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-2: ref count = 1
2016-12-15 07:39:19.792825 [DEBUG] mod_rayo.c:1895 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, done executing command
2016-12-15 07:39:19.792825 [DEBUG] mod_rayo.c:849 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 2
2016-12-15 07:39:19.792825 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMU:0
2016-12-15 07:39:21.611451 [DEBUG] mod_rayo.c:3982 Locate (jid) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 3
2016-12-15 07:39:21.611451 [DEBUG] mod_rayo.c:3999 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 2
2016-12-15 07:39:22.371377 [DEBUG] apt_poller_task.c:269 () Process Signalled Descriptor [MRCPv2ConnectionAgent]
2016-12-15 07:39:22.391381 [INFO] mrcp_client_connection.c:635 () Receive MRCPv2 Data 127.0.0.1:52410 <-> 127.0.0.1:20055 [162 bytes]
MRCP/2.0 162 SPEAK-COMPLETE 1 COMPLETE
Channel-Identifier: 1672836c-1130-4bce-a@speechsynth
Completion-Cause: 000 normal
Speech-Marker: timestamp=421162396
2016-12-15 07:39:22.391381 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538024610;2;3]
2016-12-15 07:39:22.391381 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:22.391381 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538024610;2;3]
2016-12-15 07:39:22.391381 [INFO] mrcp_client_session.c:516 (TTS-41) Raise App MRCP Event TTS-41 <1672836c-1130-4bce-a>
2016-12-15 07:39:22.391381 [DEBUG] mod_unimrcp.c:1996 (TTS-41) SPEAK-COMPLETE
2016-12-15 07:39:22.391381 [DEBUG] mod_unimrcp.c:1577 (TTS-41) PROCESSING ==> DONE
2016-12-15 07:39:22.391381 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:22.651375 [DEBUG] mod_unimrcp.c:1577 (TTS-41) DONE ==> READY
2016-12-15 07:39:22.651375 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2548004680;4;0]
2016-12-15 07:39:22.651375 [DEBUG] mod_unimrcp.c:923 (TTS-41) Waiting for MRCP session to terminate
2016-12-15 07:39:22.651375 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2548004680;4;0]
2016-12-15 07:39:22.651375 [INFO] mrcp_client_session.c:387 (TTS-41) Receive App Request TTS-41 <1672836c-1130-4bce-a> [1]
2016-12-15 07:39:22.651375 [DEBUG] mrcp_client_session.c:1283 (TTS-41) Dispatch App Request TTS-41 <1672836c-1130-4bce-a> [1]
2016-12-15 07:39:22.651375 [INFO] mrcp_client_session.c:833 (TTS-41) Terminate Session TTS-41 <1672836c-1130-4bce-a>
2016-12-15 07:39:22.651375 [DEBUG] mrcp_client_session.c:854 (TTS-41) Remove Control Channel TTS-41 <1672836c-1130-4bce-a>
2016-12-15 07:39:22.651375 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:22.651375 [DEBUG] mrcp_client_session.c:864 (TTS-41) Subtract Media Termination TTS-41 <1672836c-1130-4bce-a@media-tm>
2016-12-15 07:39:22.651375 [DEBUG] mrcp_client_session.c:885 (TTS-41) Subtract Media Termination TTS-41 <1672836c-1130-4bce-a@rtp-tm>
2016-12-15 07:39:22.651375 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7f2530026910;1;0]
2016-12-15 07:39:22.651375 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2016-12-15 07:39:22.651375 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:22.651375 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:22.651375 [INFO] mrcp_client_connection.c:459 (TTS-41) Remove Control Channel <1672836c-1130-4bce-a@speechsynth> [0]
2016-12-15 07:39:22.651375 [INFO] mrcp_client_connection.c:386 () Close TCP/MRCPv2 Connection 127.0.0.1:52410 <-> 127.0.0.1:20055
2016-12-15 07:39:22.651375 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538024610;2;2]
2016-12-15 07:39:22.651375 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:22.651375 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538024610;2;2]
2016-12-15 07:39:22.651375 [DEBUG] mrcp_client_session.c:331 (TTS-41) Control Channel Removed TTS-41 <1672836c-1130-4bce-a@speechsynth>
2016-12-15 07:39:22.651375 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:22.671371 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_r_bye] Status 200 OK [lumenvox]
2016-12-15 07:39:22.671371 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 200 to BYE [lumenvox]
2016-12-15 07:39:22.671371 [NOTICE] mrcp_sofiasip_client_agent.c:547 (TTS-41) SIP Call State TTS-41 [terminated]
2016-12-15 07:39:22.671371 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2540021870;1;1]
2016-12-15 07:39:22.671371 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2540021870;1;1]
2016-12-15 07:39:22.671371 [INFO] mrcp_client_session.c:209 (TTS-41) Session Terminated TTS-41 <1672836c-1130-4bce-a>
2016-12-15 07:39:22.671371 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:22.671371 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7f2530026910;1;0]
2016-12-15 07:39:22.671371 [DEBUG] mpf_bridge.c:100 () Destroy Audio Bridge TTS-41
2016-12-15 07:39:22.671371 [INFO] mpf_rtp_stream.c:541 () Close RTP Receiver 192.168.65.201:28082 <- 127.0.0.1:25110 [r:131 l:0 j:52 p:0 d:0 i:0]
2016-12-15 07:39:22.671371 [DEBUG] mpf_context.c:238 () Remove Media Context TTS-41
2016-12-15 07:39:22.671371 [INFO] mpf_rtp_stream.c:418 () Remove RTP Session 192.168.65.201:28082
2016-12-15 07:39:22.671371 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2578000c20;3;0]
2016-12-15 07:39:22.671371 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2578000c20;3;0]
2016-12-15 07:39:22.671371 [DEBUG] mrcp_client_session.c:1014 (TTS-41) Media Termination Subtracted TTS-41 <1672836c-1130-4bce-a@media-tm>
2016-12-15 07:39:22.671371 [DEBUG] mrcp_client_session.c:1014 (TTS-41) Media Termination Subtracted TTS-41 <1672836c-1130-4bce-a@rtp-tm>
2016-12-15 07:39:22.671371 [NOTICE] mrcp_client_connection.c:235 () Destroy TCP/MRCPv2 Connection 127.0.0.1:52410 <-> 127.0.0.1:20055
2016-12-15 07:39:22.671371 [INFO] mrcp_client.c:710 (TTS-41) Remove MRCP Handle TTS-41 <1672836c-1130-4bce-a>
2016-12-15 07:39:22.671371 [INFO] mrcp_client_session.c:455 (TTS-41) Raise App Response TTS-41 <1672836c-1130-4bce-a> [1] SUCCESS [0]
2016-12-15 07:39:22.671371 [DEBUG] mod_unimrcp.c:1828 (TTS-41) Destroying MRCP session
2016-12-15 07:39:22.671371 [NOTICE] mrcp_application.c:182 (TTS-41) Destroy MRCP Handle TTS-41
2016-12-15 07:39:22.671371 [DEBUG] mod_unimrcp.c:1577 (TTS-41) READY ==> CLOSED
2016-12-15 07:39:22.671371 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:22.671371 [DEBUG] mod_unimrcp.c:851 (TTS-41) audio queue destroyed
2016-12-15 07:39:22.671371 [INFO] rayo_output_component.c:552 Done playing
2016-12-15 07:39:22.671371 [DEBUG] rayo_components.c:117 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-2: ref count = 0
2016-12-15 07:39:22.671371 [DEBUG] rayo_components.c:118 Destroy 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-2 requested: ref_count = 0
2016-12-15 07:39:22.671371 [DEBUG] rayo_components.c:118 Destroying 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-2
2016-12-15 07:39:22.671371 [DEBUG] mod_rayo.c:1035 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 1
2016-12-15 07:39:22.671371 [DEBUG] mod_rayo.c:842 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:22.671371 [DEBUG] rayo_components.c:116 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-2 => usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 <presence from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-2' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='unavailable'><complete xmlns='urn:xmpp:rayo:ext:1'><finish xmlns='urn:xmpp:rayo:output:complete:1'/></complete><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:22Z'/></presence>
2016-12-15 07:39:22.671371 [DEBUG] mod_rayo.c:849 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:22.671371 [DEBUG] switch_core_media_bug.c:1208 Removing BUG from sofia/external/4044754849@192.168.65.114
2016-12-15 07:39:22.691377 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in SEND <presence from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-2' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='unavailable'><complete xmlns='urn:xmpp:rayo:ext:1'><finish xmlns='urn:xmpp:rayo:output:complete:1'/></complete><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:22Z'/></presence>
2016-12-15 07:39:22.712709 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in RECV <iq type="set" to="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" id="c652731d-2639-420f-b99f-56f996356ea9"><prompt xmlns="urn:xmpp:rayo:prompt:1" barge-in="true"><input xmlns="urn:xmpp:rayo:input:1" max-silence="5000" min-confidence="0.5" mode="dtmf" recognizer="unimrcp" language="en-US" initial-timeout="5000" inter-digit-timeout="2000"><grammar content-type="application/srgs+xml"><![CDATA[<grammar xmlns="http://www.w3.org/2001/06/grammar" version="1.0" xml:lang="en-US" mode="dtmf" root="digits">
<rule id="digits" scope="public">
<item repeat="0-1">
<one-of>
<item>0</item>
<item>1</item>
<item>2</item>
<item>3</item>
<item>4</item>
<item>5</item>
<item>6</item>
<item>7</item>
<item>8</item>
<item>9</item>
<item>#</item>
<item>*</item>
</one-of>
</item>
</rule>
</grammar>]]></grammar></input><output xmlns="urn:xmpp:rayo:output:1" renderer="unimrcp"><document content-type="application/ssml+xml"><![CDATA[<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">Sorry. Press 1 to do something or 2 to do something else</speak>]]></document></output></prompt></iq>
2016-12-15 07:39:22.712709 [DEBUG] xmpp_streams.c:1073 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, state = READY, node type = NODE_NORMAL
2016-12-15 07:39:22.712709 [DEBUG] mod_rayo.c:4197 Lock usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:22.712709 [DEBUG] mod_rayo.c:3143 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, recv iq, availability = ONLINE
2016-12-15 07:39:22.712709 [DEBUG] mod_rayo.c:4281 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:22.712709 [DEBUG] mod_rayo.c:842 Locate (jid) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 2
2016-12-15 07:39:22.712709 [DEBUG] mod_rayo.c:3146 Deliver usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 => 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201 <iq type='set' to='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' id='c652731d-2639-420f-b99f-56f996356ea9' from='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139'><prompt xmlns='urn:xmpp:rayo:prompt:1' barge-in='true'><input xmlns='urn:xmpp:rayo:input:1' max-silence='5000' min-confidence='0.5' mode='dtmf' recognizer='unimrcp' language='en-US' initial-timeout='5000' inter-digit-timeout='2000'><grammar content-type='application/srgs+xml'>&lt;grammar xmlns=&quot;http://www.w3.org/2001/06/grammar&quot; version=&quot;1.0&quot; xml:lang=&quot;en-US&quot; mode=&quot;dtmf&quot; root=&quot;digits&quot;&gt;
&lt;rule id=&quot;digits&quot; scope=&quot;public&quot;&gt;
&lt;item repeat=&quot;0-1&quot;&gt;
&lt;one-of&gt;
&lt;item&gt;0&lt;/item&gt;
&lt;item&gt;1&lt;/item&gt;
&lt;item&gt;2&lt;/item&gt;
&lt;item&gt;3&lt;/item&gt;
&lt;item&gt;4&lt;/item&gt;
&lt;item&gt;5&lt;/item&gt;
&lt;item&gt;6&lt;/item&gt;
&lt;item&gt;7&lt;/item&gt;
&lt;item&gt;8&lt;/item&gt;
&lt;item&gt;9&lt;/item&gt;
&lt;item&gt;#&lt;/item&gt;
&lt;item&gt;*&lt;/item&gt;
&lt;/one-of&gt;
&lt;/item&gt;
&lt;/rule&gt;
&lt;/grammar&gt;</grammar></input><output xmlns='urn:xmpp:rayo:output:1' renderer='unimrcp'><document content-type='application/ssml+xml'>&lt;speak xmlns=&quot;http://www.w3.org/2001/10/synthesis&quot; version=&quot;1.0&quot; xml:lang=&quot;en-US&quot;&gt;Sorry. Press 1 to do something or 2 to do something else&lt;/speak&gt;</document></output></prompt></iq>
2016-12-15 07:39:22.712709 [DEBUG] mod_rayo.c:723 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, looking for CALL::set:urn:xmpp:rayo:prompt:1:prompt command
2016-12-15 07:39:22.712709 [DEBUG] mod_rayo.c:1893 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, executing command
2016-12-15 07:39:22.712709 [DEBUG] mod_rayo.c:1367 Lock 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 3
2016-12-15 07:39:22.712709 [DEBUG] rayo_prompt_component.c:573 Init 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3
2016-12-15 07:39:22.712709 [DEBUG] mod_rayo.c:1895 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, done executing command
2016-12-15 07:39:22.712709 [DEBUG] mod_rayo.c:842 Locate (jid) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 4
2016-12-15 07:39:22.712709 [DEBUG] rayo_prompt_component.c:593 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3 => 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201 <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3' to='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' id='c652731d-2639-420f-b99f-56f996356ea9' type='set'><output xmlns='urn:xmpp:rayo:output:1' renderer='unimrcp'><document content-type='application/ssml+xml'>&lt;speak xmlns=&quot;http://www.w3.org/2001/10/synthesis&quot; version=&quot;1.0&quot; xml:lang=&quot;en-US&quot;&gt;Sorry. Press 1 to do something or 2 to do something else&lt;/speak&gt;</document></output></iq>
2016-12-15 07:39:22.712709 [DEBUG] mod_rayo.c:849 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 3
2016-12-15 07:39:22.712709 [DEBUG] mod_rayo.c:723 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, looking for CALL::set:urn:xmpp:rayo:output:1:output command
2016-12-15 07:39:22.712709 [DEBUG] mod_rayo.c:1893 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, executing command
2016-12-15 07:39:22.712709 [DEBUG] mod_rayo.c:1367 Lock 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 4
2016-12-15 07:39:22.712709 [DEBUG] rayo_output_component.c:73 Init 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4
2016-12-15 07:39:22.712709 [DEBUG] mod_rayo.c:842 Locate (jid) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3: ref count = 2
2016-12-15 07:39:22.712709 [DEBUG] rayo_output_component.c:842 Got path rayo://0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4
2016-12-15 07:39:22.712709 [DEBUG] rayo_output_component.c:648 Got path 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4
2016-12-15 07:39:22.712709 [DEBUG] rayo_output_component.c:650 Locate (id) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4: ref count = 2
2016-12-15 07:39:22.712709 [INFO] mod_unimrcp.c:1624 speech_handle: name = unimrcp, rate = 8000, speed = 0, samples = 0, voice = , engine = unimrcp, param = (null)
2016-12-15 07:39:22.712709 [INFO] mod_unimrcp.c:1627 voice = , rate = 8000
2016-12-15 07:39:22.712709 [DEBUG] mod_unimrcp.c:683 (TTS-42) audio queue created
2016-12-15 07:39:22.712709 [NOTICE] mrcp_application.c:96 (TTS-42) Create MRCP Handle 0x7f25800188b0 [lumenvox]
2016-12-15 07:39:22.712709 [INFO] mrcp_client_session.c:133 (TTS-42) Create Channel TTS-42 <new>
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2580006240;4;0]
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2580006240;4;0]
2016-12-15 07:39:22.712709 [INFO] mrcp_client_session.c:387 (TTS-42) Receive App Request TTS-42 <new> [2]
2016-12-15 07:39:22.712709 [INFO] mrcp_client.c:700 (TTS-42) Add MRCP Handle TTS-42 <new>
2016-12-15 07:39:22.712709 [DEBUG] mrcp_client_session.c:1283 (TTS-42) Dispatch App Request TTS-42 <new> [2]
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:22.712709 [NOTICE] mrcp_client_session.c:719 (TTS-42) Add Control Channel TTS-42 <new@speechsynth>
2016-12-15 07:39:22.712709 [DEBUG] mrcp_client_session.c:745 (TTS-42) Add Media Termination TTS-42 <new@media-tm>
2016-12-15 07:39:22.712709 [DEBUG] mrcp_client_session.c:777 (TTS-42) Add Media Termination TTS-42 <new@rtp-tm>
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7f2530026440;1;0]
2016-12-15 07:39:22.712709 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:22.712709 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538024610;2;0]
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7f2530026440;1;0]
2016-12-15 07:39:22.712709 [DEBUG] mpf_context.c:182 () Add Media Context TTS-42
2016-12-15 07:39:22.712709 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2578001d80;3;0]
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538024610;2;0]
2016-12-15 07:39:22.712709 [DEBUG] mrcp_client_session.c:294 (TTS-42) Control Channel Added TTS-42 <new@speechsynth>
2016-12-15 07:39:22.712709 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2578001d80;3;0]
2016-12-15 07:39:22.712709 [DEBUG] mrcp_client_session.c:944 (TTS-42) Media Termination Added TTS-42 <new@media-tm>
2016-12-15 07:39:22.712709 [DEBUG] mrcp_client_session.c:944 (TTS-42) Media Termination Added TTS-42 <new@rtp-tm>
2016-12-15 07:39:22.712709 [INFO] mrcp_client_session.c:411 (TTS-42) Send Offer TTS-42 <new> [c:1 a:1 v:0] to 127.0.0.1:5065
2016-12-15 07:39:22.712709 [INFO] mrcp_sofiasip_client_agent.c:354 (TTS-42) Local SDP TTS-42 <new>
v=0
o=FreeSWITCH 0 0 IN IP4 192.168.65.201
s=-
c=IN IP4 192.168.65.201
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechsynth
a=cmid:1
m=audio 28084 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=recvonly
a=mid:1
2016-12-15 07:39:22.712709 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:22.712709 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 0 INVITE sent [lumenvox]
2016-12-15 07:39:22.712709 [NOTICE] mrcp_sofiasip_client_agent.c:547 (TTS-42) SIP Call State TTS-42 [calling]
2016-12-15 07:39:22.712709 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_r_invite] Status 200 OK [lumenvox]
2016-12-15 07:39:22.712709 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 200 OK [lumenvox]
2016-12-15 07:39:22.712709 [NOTICE] mrcp_sofiasip_client_agent.c:547 (TTS-42) SIP Call State TTS-42 [ready]
2016-12-15 07:39:22.712709 [INFO] mrcp_sofiasip_client_agent.c:433 (TTS-42) Remote SDP TTS-42 <new>
v=0
o=- 1234 5678 IN IP4 127.0.0.1
s=-
c=IN IP4 127.0.0.1
t=0 0
m=application 20056 TCP/MRCPv2 1
a=setup:passive
a=connection:new
a=channel:ce52ddf1-57ba-4844-8@speechsynth
a=cmid:1
m=audio 25112 RTP/AVP 0
c=IN IP4 127.0.0.1
a=rtpmap:0 PCMU/8000
a=sendonly
a=mid:1
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2540021870;1;0]
2016-12-15 07:39:22.712709 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_active] Status 200 Call active [lumenvox]
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2540021870;1;0]
2016-12-15 07:39:22.712709 [INFO] mrcp_client_session.c:151 (TTS-42) Receive Answer TTS-42 <new> [c:1 a:1 v:0] Status 200
2016-12-15 07:39:22.712709 [DEBUG] mrcp_client_session.c:1141 (TTS-42) Modify Control Channel TTS-42 <ce52ddf1-57ba-4844-8>
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:22.712709 [DEBUG] mrcp_client_session.c:1180 (TTS-42) Modify Media Termination TTS-42 <ce52ddf1-57ba-4844-8@rtp-tm>
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7f2530026440;1;0]
2016-12-15 07:39:22.712709 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:22.712709 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:22.712709 [NOTICE] mrcp_client_connection.c:338 () Established TCP/MRCPv2 Connection 127.0.0.1:34800 <-> 127.0.0.1:20056
2016-12-15 07:39:22.712709 [INFO] mrcp_client_connection.c:435 (TTS-42) Add Control Channel <ce52ddf1-57ba-4844-8@speechsynth> 127.0.0.1:34800 <-> 127.0.0.1:20056 [1]
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538024660;2;1]
2016-12-15 07:39:22.712709 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538024660;2;1]
2016-12-15 07:39:22.712709 [DEBUG] mrcp_client_session.c:311 (TTS-42) Control Channel Modified TTS-42 <ce52ddf1-57ba-4844-8@speechsynth>
2016-12-15 07:39:22.712709 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7f2530026440;1;0]
2016-12-15 07:39:22.712709 [INFO] mpf_rtp_stream.c:331 () Enable RTP Session 192.168.65.201:28084
2016-12-15 07:39:22.712709 [DEBUG] mpf_bridge.c:129 () Create Linear Audio Bridge TTS-42
2016-12-15 07:39:22.712709 [INFO] mpf_rtp_stream.c:509 () Open RTP Receiver 192.168.65.201:28084 <- 127.0.0.1:25112 playout [0 ms] bounds [0 - 600 ms] adaptive [0] skew detection [1]
2016-12-15 07:39:22.712709 [INFO] mpf_bridge.c:93 () Media Path TTS-42 Source->[PCMU/8000/1]->Decoder->[LPCM/8000/1]->Bridge->[LPCM/8000/1]->Sink
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2578001d80;3;0]
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2578001d80;3;0]
2016-12-15 07:39:22.712709 [DEBUG] mrcp_client_session.c:985 (TTS-42) Media Termination Modified TTS-42 <ce52ddf1-57ba-4844-8@rtp-tm>
2016-12-15 07:39:22.712709 [INFO] mrcp_client_session.c:455 (TTS-42) Raise App Response TTS-42 <ce52ddf1-57ba-4844-8> [2] SUCCESS [0]
2016-12-15 07:39:22.712709 [DEBUG] mod_unimrcp.c:1893 (TTS-42) SYNTHESIZER channel is ready, codec = LPCM, sample rate = 8000
2016-12-15 07:39:22.712709 [DEBUG] mod_unimrcp.c:1577 (TTS-42) CLOSED ==> READY
2016-12-15 07:39:22.712709 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:22.712709 [DEBUG] mod_unimrcp.c:1055 (TTS-42) channel is ready
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2580006240;4;0]
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2580006240;4;0]
2016-12-15 07:39:22.712709 [INFO] mrcp_client_session.c:392 (TTS-42) Receive App MRCP Request TTS-42 <ce52ddf1-57ba-4844-8>
2016-12-15 07:39:22.712709 [INFO] mrcp_client_session.c:622 (TTS-42) Send MRCP Request TTS-42 <ce52ddf1-57ba-4844-8@speechsynth> [1]
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:22.712709 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:22.712709 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2016-12-15 07:39:22.712709 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:22.712709 [INFO] mrcp_client_connection.c:530 (TTS-42) Send MRCPv2 Data 127.0.0.1:34800 <-> 127.0.0.1:20056 [272 bytes]
MRCP/2.0 272 SPEAK 1
Channel-Identifier: ce52ddf1-57ba-4844-8@speechsynth
Content-Type: text/plain
Content-Length: 147
}<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">Sorry. Press 1 to do something or 2 to do something else</speak>
2016-12-15 07:39:22.712709 [DEBUG] apt_poller_task.c:246 () Wait for Messages [MRCPv2ConnectionAgent] timeout [3000]
2016-12-15 07:39:22.851376 [DEBUG] apt_poller_task.c:269 () Process Signalled Descriptor [MRCPv2ConnectionAgent]
2016-12-15 07:39:22.851376 [INFO] mrcp_client_connection.c:635 () Receive MRCPv2 Data 127.0.0.1:34800 <-> 127.0.0.1:20056 [124 bytes]
MRCP/2.0 124 1 200 IN-PROGRESS
Channel-Identifier: ce52ddf1-57ba-4844-8@speechsynth
Speech-Marker: timestamp=421165984
2016-12-15 07:39:22.851376 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538024660;2;3]
2016-12-15 07:39:22.851376 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:22.851376 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538024660;2;3]
2016-12-15 07:39:22.851376 [INFO] mrcp_client_session.c:500 (TTS-42) Raise App MRCP Response TTS-42 <ce52ddf1-57ba-4844-8>
2016-12-15 07:39:22.851376 [DEBUG] mod_unimrcp.c:1966 (TTS-42) REQUEST IN PROGRESS
2016-12-15 07:39:22.851376 [DEBUG] mod_unimrcp.c:1577 (TTS-42) READY ==> PROCESSING
2016-12-15 07:39:22.851376 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:22.851376 [DEBUG] rayo_output_component.c:866 Create audio buffer
2016-12-15 07:39:22.851376 [DEBUG] switch_core_media_bug.c:841 Attaching BUG to sofia/external/4044754849@192.168.65.114
2016-12-15 07:39:22.851376 [DEBUG] rayo_output_component.c:139 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4: ref count = 1
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:1895 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, done executing command
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:849 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 3
2016-12-15 07:39:22.851376 [DEBUG] rayo_components.c:62 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4 => 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3 <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3' type='result' id='c652731d-2639-420f-b99f-56f996356ea9'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4'/></iq>
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:723 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3, looking for COMPONENT_CALL:prompt:result:urn:xmpp:rayo:1:ref command
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:1960 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3, executing command
2016-12-15 07:39:22.851376 [DEBUG] rayo_prompt_component.c:244 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3, got <ref> from 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4: <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3' type='result' id='c652731d-2639-420f-b99f-56f996356ea9'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4'/></iq>
2016-12-15 07:39:22.851376 [DEBUG] rayo_prompt_component.c:161 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3 (START_OUTPUT_BARGE) output start
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:1962 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3, done executing command
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:849 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3: ref count = 1
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:842 Locate (jid) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 4
2016-12-15 07:39:22.851376 [DEBUG] rayo_prompt_component.c:136 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3 => 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201 <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3' to='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' id='mod_rayo-prompt-1' type='set'><input xmlns='urn:xmpp:rayo:input:1' max-silence='5000' min-confidence='0.5' mode='dtmf' recognizer='unimrcp' language='en-US' initial-timeout='5000' inter-digit-timeout='2000' start-timers='false' barge-event='true'><grammar content-type='application/srgs+xml'>&lt;grammar xmlns=&quot;http://www.w3.org/2001/06/grammar&quot; version=&quot;1.0&quot; xml:lang=&quot;en-US&quot; mode=&quot;dtmf&quot; root=&quot;digits&quot;&gt;
&lt;rule id=&quot;digits&quot; scope=&quot;public&quot;&gt;
&lt;item repeat=&quot;0-1&quot;&gt;
&lt;one-of&gt;
&lt;item&gt;0&lt;/item&gt;
&lt;item&gt;1&lt;/item&gt;
&lt;item&gt;2&lt;/item&gt;
&lt;item&gt;3&lt;/item&gt;
&lt;item&gt;4&lt;/item&gt;
&lt;item&gt;5&lt;/item&gt;
&lt;item&gt;6&lt;/item&gt;
&lt;item&gt;7&lt;/item&gt;
&lt;item&gt;8&lt;/item&gt;
&lt;item&gt;9&lt;/item&gt;
&lt;item&gt;#&lt;/item&gt;
&lt;item&gt;*&lt;/item&gt;
&lt;/one-of&gt;
&lt;/item&gt;
&lt;/rule&gt;
&lt;/grammar&gt;</grammar></input></iq>
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:723 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, looking for CALL::set:urn:xmpp:rayo:input:1:input command
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:1893 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, executing command
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:1367 Lock 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 5
2016-12-15 07:39:22.851376 [DEBUG] rayo_input_component.c:816 Init 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/input-5
2016-12-15 07:39:22.851376 [DEBUG] rayo_input_component.c:324 Adding DTMF callback
2016-12-15 07:39:22.851376 [DEBUG] switch_core_media_bug.c:841 Attaching BUG to sofia/external/4044754849@192.168.65.114
2016-12-15 07:39:22.851376 [DEBUG] srgs.c:1219 Using cached grammar
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:1895 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, done executing command
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:849 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 4
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:842 Locate (jid) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3: ref count = 2
2016-12-15 07:39:22.851376 [DEBUG] rayo_components.c:62 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/input-5 => 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3 <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3' type='result' id='mod_rayo-prompt-1'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/input-5'/></iq>
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:723 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3, looking for COMPONENT_CALL:prompt:result:urn:xmpp:rayo:1:ref command
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:1960 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3, executing command
2016-12-15 07:39:22.851376 [DEBUG] rayo_prompt_component.c:244 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3, got <ref> from 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/input-5: <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3' type='result' id='mod_rayo-prompt-1'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/input-5'/></iq>
2016-12-15 07:39:22.851376 [DEBUG] rayo_prompt_component.c:198 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3 (START_INPUT_OUTPUT) input start
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:1962 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3, done executing command
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:849 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3: ref count = 1
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:842 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:22.851376 [DEBUG] rayo_components.c:62 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3 => usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='result' id='c652731d-2639-420f-b99f-56f996356ea9'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3'/></iq>
2016-12-15 07:39:22.851376 [DEBUG] mod_rayo.c:849 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:22.871373 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMU:0
2016-12-15 07:39:22.871373 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in SEND <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='result' id='c652731d-2639-420f-b99f-56f996356ea9'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3'/></iq>
2016-12-15 07:39:26.411393 [DEBUG] switch_rtp.c:7215 RTP RECV DTMF 1:1520
2016-12-15 07:39:26.411393 [DEBUG] rayo_input_component.c:216 Collected digits = "1"
2016-12-15 07:39:26.411393 [DEBUG] srgs.c:1303 match = 1
2016-12-15 07:39:26.411393 [DEBUG] srgs.c:1270 is match end
2016-12-15 07:39:26.411393 [DEBUG] rayo_input_component.c:257 MATCH = 1
2016-12-15 07:39:26.411393 [DEBUG] rayo_components.c:117 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/input-5: ref count = 0
2016-12-15 07:39:26.411393 [DEBUG] rayo_components.c:118 Destroy 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/input-5 requested: ref_count = 0
2016-12-15 07:39:26.411393 [DEBUG] rayo_components.c:118 Destroying 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/input-5
2016-12-15 07:39:26.411393 [DEBUG] mod_rayo.c:1035 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 3
2016-12-15 07:39:26.411393 [INFO] switch_channel.c:515 RECV DTMF 1:1520
2016-12-15 07:39:26.411393 [DEBUG] mod_rayo.c:842 Locate (jid) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3: ref count = 2
2016-12-15 07:39:26.411393 [DEBUG] rayo_cpa_detector.c:175 Got Rayo CPA event dtmf
2016-12-15 07:39:26.411393 [DEBUG] rayo_components.c:116 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/input-5 => 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3 <presence from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/input-5' to='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3' type='unavailable'><complete xmlns='urn:xmpp:rayo:ext:1'><match xmlns='urn:xmpp:rayo:input:complete:1' content-type='application/nlsml+xml'>&lt;result xmlns=&apos;http://www.ietf.org/xml/ns/mrcpv2&apos; xmlns:xf=&apos;http://www.w3.org/2000/xforms&apos;&gt;&lt;interpretation&gt;&lt;input mode=&apos;dtmf&apos; confidence=&apos;100&apos;&gt;1&lt;/input&gt;&lt;instance&gt;1&lt;/instance&gt;&lt;/interpretation&gt;&lt;/result&gt;</match></complete><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:26Z'/></presence>
2016-12-15 07:39:26.411393 [DEBUG] mod_rayo.c:787 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/input-5 => 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3, looking for COMPONENT_CALL:input:COMPONENT_CALL:prompt:unavailable:urn:xmpp:rayo:ext:1:complete event handler
2016-12-15 07:39:26.411393 [DEBUG] mod_rayo.c:1982 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3, forwarding event
2016-12-15 07:39:26.411393 [DEBUG] rayo_prompt_component.c:423 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3 (INPUT_OUTPUT) input complete
2016-12-15 07:39:26.411393 [DEBUG] rayo_cpa_component.c:130 Subscriber execute urn:xmpp:rayo:cpa:dtmf:1
2016-12-15 07:39:26.411393 [DEBUG] rayo_cpa_component.c:143 No subscribers for urn:xmpp:rayo:cpa:dtmf:1
2016-12-15 07:39:26.411393 [DEBUG] mod_rayo.c:849 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3: ref count = 1
2016-12-15 07:39:26.411393 [DEBUG] mod_rayo.c:842 Locate (jid) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4: ref count = 2
2016-12-15 07:39:26.411393 [DEBUG] rayo_prompt_component.c:117 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3 => 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4 <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3' to='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4' type='set' id='mod_rayo-prompt-2'><stop xmlns='urn:xmpp:rayo:ext:1'/></iq>
2016-12-15 07:39:26.411393 [DEBUG] mod_rayo.c:723 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4, looking for COMPONENT_CALL:output:set:urn:xmpp:rayo:ext:1:stop command
2016-12-15 07:39:26.411393 [DEBUG] mod_rayo.c:1960 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4, executing command
2016-12-15 07:39:26.411393 [INFO] rayo_output_component.c:257 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4 stopping
2016-12-15 07:39:26.411393 [DEBUG] rayo_output_component.c:1225 Stopping file
2016-12-15 07:39:26.411393 [DEBUG] mod_rayo.c:1962 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4, done executing command
2016-12-15 07:39:26.411393 [DEBUG] mod_rayo.c:849 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4: ref count = 1
2016-12-15 07:39:26.411393 [DEBUG] mod_rayo.c:842 Locate (jid) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3: ref count = 2
2016-12-15 07:39:26.411393 [DEBUG] mod_rayo.c:1967 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4 => 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3 <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4' to='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3' type='result' id='mod_rayo-prompt-2'/>
2016-12-15 07:39:26.411393 [DEBUG] mod_rayo.c:723 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3, looking for COMPONENT_CALL:prompt:result:: command
2016-12-15 07:39:26.411393 [DEBUG] mod_rayo.c:1960 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3, executing command
2016-12-15 07:39:26.411393 [DEBUG] mod_rayo.c:1962 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3, done executing command
2016-12-15 07:39:26.411393 [DEBUG] mod_rayo.c:849 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3: ref count = 1
2016-12-15 07:39:26.431374 [DEBUG] rayo_components.c:117 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4: ref count = 0
2016-12-15 07:39:26.431374 [DEBUG] rayo_components.c:118 Destroy 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4 requested: ref_count = 0
2016-12-15 07:39:26.431374 [DEBUG] rayo_components.c:118 Destroying 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4
2016-12-15 07:39:26.431374 [DEBUG] mod_rayo.c:1035 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 2
2016-12-15 07:39:26.431374 [DEBUG] mod_unimrcp.c:1388 (TTS-42) Stopping SYNTHESIZER
2016-12-15 07:39:26.431374 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2548008780;4;0]
2016-12-15 07:39:26.431374 [DEBUG] mod_rayo.c:842 Locate (jid) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3: ref count = 2
2016-12-15 07:39:26.431374 [DEBUG] rayo_components.c:116 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4 => 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3 <presence from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4' to='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3' type='unavailable'><complete xmlns='urn:xmpp:rayo:ext:1'><stop xmlns='urn:xmpp:rayo:ext:complete:1'/></complete><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:26Z'/></presence>
2016-12-15 07:39:26.431374 [DEBUG] mod_rayo.c:787 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-4 => 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3, looking for COMPONENT_CALL:output:COMPONENT_CALL:prompt:unavailable:urn:xmpp:rayo:ext:1:complete event handler
2016-12-15 07:39:26.431374 [DEBUG] mod_rayo.c:1982 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3, forwarding event
2016-12-15 07:39:26.431374 [DEBUG] rayo_prompt_component.c:491 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3 (DONE_STOP_OUTPUT) output complete
2016-12-15 07:39:26.431374 [DEBUG] rayo_components.c:117 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3: ref count = 1
2016-12-15 07:39:26.431374 [DEBUG] rayo_components.c:118 Destroy 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3 requested: ref_count = 1
2016-12-15 07:39:26.431374 [DEBUG] mod_rayo.c:849 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3: ref count = 0
2016-12-15 07:39:26.431374 [DEBUG] mod_rayo.c:849 Destroying 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3
2016-12-15 07:39:26.431374 [DEBUG] mod_rayo.c:1035 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 1
2016-12-15 07:39:26.431374 [DEBUG] mod_rayo.c:842 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:26.431374 [DEBUG] rayo_components.c:116 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3 => usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 <presence from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='unavailable'><complete xmlns='urn:xmpp:rayo:ext:1'><match xmlns='urn:xmpp:rayo:input:complete:1' content-type='application/nlsml+xml'>&lt;result xmlns=&apos;http://www.ietf.org/xml/ns/mrcpv2&apos; xmlns:xf=&apos;http://www.w3.org/2000/xforms&apos;&gt;&lt;interpretation&gt;&lt;input mode=&apos;dtmf&apos; confidence=&apos;100&apos;&gt;1&lt;/input&gt;&lt;instance&gt;1&lt;/instance&gt;&lt;/interpretation&gt;&lt;/result&gt;</match></complete><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:26Z'/></presence>
2016-12-15 07:39:26.431374 [DEBUG] mod_rayo.c:849 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:26.431374 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2548008780;4;0]
2016-12-15 07:39:26.431374 [INFO] mrcp_client_session.c:392 (TTS-42) Receive App MRCP Request TTS-42 <ce52ddf1-57ba-4844-8>
2016-12-15 07:39:26.431374 [INFO] mrcp_client_session.c:622 (TTS-42) Send MRCP Request TTS-42 <ce52ddf1-57ba-4844-8@speechsynth> [2]
2016-12-15 07:39:26.431374 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:26.431374 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:26.431374 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2016-12-15 07:39:26.431374 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:26.431374 [INFO] mrcp_client_connection.c:530 (TTS-42) Send MRCPv2 Data 127.0.0.1:34800 <-> 127.0.0.1:20056 [76 bytes]
MRCP/2.0 76 STOP 2
Channel-Identifier: ce52ddf1-57ba-4844-8@speechsynth
2016-12-15 07:39:26.431374 [DEBUG] apt_poller_task.c:246 () Wait for Messages [MRCPv2ConnectionAgent] timeout [3000]
2016-12-15 07:39:26.431374 [DEBUG] apt_poller_task.c:269 () Process Signalled Descriptor [MRCPv2ConnectionAgent]
2016-12-15 07:39:26.431374 [INFO] mrcp_client_connection.c:635 () Receive MRCPv2 Data 127.0.0.1:34800 <-> 127.0.0.1:20056 [112 bytes]
MRCP/2.0 112 2 200 COMPLETE
Channel-Identifier: ce52ddf1-57ba-4844-8@speechsynth
Active-Request-Id-List: 1
2016-12-15 07:39:26.431374 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538023fe0;2;3]
2016-12-15 07:39:26.431374 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:26.431374 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538023fe0;2;3]
2016-12-15 07:39:26.431374 [INFO] mrcp_client_session.c:500 (TTS-42) Raise App MRCP Response TTS-42 <ce52ddf1-57ba-4844-8>
2016-12-15 07:39:26.431374 [DEBUG] mod_unimrcp.c:1978 (TTS-42) COMPLETE
2016-12-15 07:39:26.431374 [DEBUG] mod_unimrcp.c:1577 (TTS-42) PROCESSING ==> DONE
2016-12-15 07:39:26.431374 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:26.431374 [DEBUG] mod_unimrcp.c:1410 (TTS-42) SYNTHESIZER stopped
2016-12-15 07:39:26.431374 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2548008780;4;0]
2016-12-15 07:39:26.431374 [DEBUG] mod_unimrcp.c:923 (TTS-42) Waiting for MRCP session to terminate
2016-12-15 07:39:26.431374 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2548008780;4;0]
2016-12-15 07:39:26.431374 [INFO] mrcp_client_session.c:387 (TTS-42) Receive App Request TTS-42 <ce52ddf1-57ba-4844-8> [1]
2016-12-15 07:39:26.431374 [DEBUG] mrcp_client_session.c:1283 (TTS-42) Dispatch App Request TTS-42 <ce52ddf1-57ba-4844-8> [1]
2016-12-15 07:39:26.431374 [INFO] mrcp_client_session.c:833 (TTS-42) Terminate Session TTS-42 <ce52ddf1-57ba-4844-8>
2016-12-15 07:39:26.431374 [DEBUG] mrcp_client_session.c:854 (TTS-42) Remove Control Channel TTS-42 <ce52ddf1-57ba-4844-8>
2016-12-15 07:39:26.431374 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:26.431374 [DEBUG] mrcp_client_session.c:864 (TTS-42) Subtract Media Termination TTS-42 <ce52ddf1-57ba-4844-8@media-tm>
2016-12-15 07:39:26.431374 [DEBUG] mrcp_client_session.c:885 (TTS-42) Subtract Media Termination TTS-42 <ce52ddf1-57ba-4844-8@rtp-tm>
2016-12-15 07:39:26.431374 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7f2530026ac0;1;0]
2016-12-15 07:39:26.431374 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:26.431374 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2016-12-15 07:39:26.431374 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:26.431374 [INFO] mrcp_client_connection.c:459 (TTS-42) Remove Control Channel <ce52ddf1-57ba-4844-8@speechsynth> [0]
2016-12-15 07:39:26.431374 [INFO] mrcp_client_connection.c:386 () Close TCP/MRCPv2 Connection 127.0.0.1:34800 <-> 127.0.0.1:20056
2016-12-15 07:39:26.431374 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538023fe0;2;2]
2016-12-15 07:39:26.431374 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:26.431374 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538023fe0;2;2]
2016-12-15 07:39:26.431374 [DEBUG] mrcp_client_session.c:331 (TTS-42) Control Channel Removed TTS-42 <ce52ddf1-57ba-4844-8@speechsynth>
2016-12-15 07:39:26.431374 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:26.431374 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_r_bye] Status 200 OK [lumenvox]
2016-12-15 07:39:26.431374 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 200 to BYE [lumenvox]
2016-12-15 07:39:26.431374 [NOTICE] mrcp_sofiasip_client_agent.c:547 (TTS-42) SIP Call State TTS-42 [terminated]
2016-12-15 07:39:26.431374 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2540021870;1;1]
2016-12-15 07:39:26.431374 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2540021870;1;1]
2016-12-15 07:39:26.431374 [INFO] mrcp_client_session.c:209 (TTS-42) Session Terminated TTS-42 <ce52ddf1-57ba-4844-8>
2016-12-15 07:39:26.431374 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:26.452865 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7f2530026ac0;1;0]
2016-12-15 07:39:26.452865 [DEBUG] mpf_bridge.c:100 () Destroy Audio Bridge TTS-42
2016-12-15 07:39:26.452865 [INFO] mpf_rtp_stream.c:541 () Close RTP Receiver 192.168.65.201:28084 <- 127.0.0.1:25112 [r:181 l:0 j:66 p:0 d:0 i:0]
2016-12-15 07:39:26.452865 [DEBUG] mpf_context.c:238 () Remove Media Context TTS-42
2016-12-15 07:39:26.452865 [INFO] mpf_rtp_stream.c:418 () Remove RTP Session 192.168.65.201:28084
2016-12-15 07:39:26.452865 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f257802c000;3;0]
2016-12-15 07:39:26.452865 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f257802c000;3;0]
2016-12-15 07:39:26.452865 [DEBUG] mrcp_client_session.c:1014 (TTS-42) Media Termination Subtracted TTS-42 <ce52ddf1-57ba-4844-8@media-tm>
2016-12-15 07:39:26.452865 [DEBUG] mrcp_client_session.c:1014 (TTS-42) Media Termination Subtracted TTS-42 <ce52ddf1-57ba-4844-8@rtp-tm>
2016-12-15 07:39:26.452865 [NOTICE] mrcp_client_connection.c:235 () Destroy TCP/MRCPv2 Connection 127.0.0.1:34800 <-> 127.0.0.1:20056
2016-12-15 07:39:26.452865 [INFO] mrcp_client.c:710 (TTS-42) Remove MRCP Handle TTS-42 <ce52ddf1-57ba-4844-8>
2016-12-15 07:39:26.452865 [INFO] mrcp_client_session.c:455 (TTS-42) Raise App Response TTS-42 <ce52ddf1-57ba-4844-8> [1] SUCCESS [0]
2016-12-15 07:39:26.452865 [DEBUG] mod_unimrcp.c:1828 (TTS-42) Destroying MRCP session
2016-12-15 07:39:26.452865 [NOTICE] mrcp_application.c:182 (TTS-42) Destroy MRCP Handle TTS-42
2016-12-15 07:39:26.452865 [DEBUG] mod_unimrcp.c:1577 (TTS-42) DONE ==> CLOSED
2016-12-15 07:39:26.452865 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:26.452865 [DEBUG] mod_unimrcp.c:851 (TTS-42) audio queue destroyed
2016-12-15 07:39:26.452865 [DEBUG] switch_core_media_bug.c:1208 Removing BUG from sofia/external/4044754849@192.168.65.114
2016-12-15 07:39:26.452865 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in SEND <presence from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/prompt-3' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='unavailable'><complete xmlns='urn:xmpp:rayo:ext:1'><match xmlns='urn:xmpp:rayo:input:complete:1' content-type='application/nlsml+xml'>&lt;result xmlns=&apos;http://www.ietf.org/xml/ns/mrcpv2&apos; xmlns:xf=&apos;http://www.w3.org/2000/xforms&apos;&gt;&lt;interpretation&gt;&lt;input mode=&apos;dtmf&apos; confidence=&apos;100&apos;&gt;1&lt;/input&gt;&lt;instance&gt;1&lt;/instance&gt;&lt;/interpretation&gt;&lt;/result&gt;</match></complete><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:26Z'/></presence>
2016-12-15 07:39:26.472794 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in RECV <iq type="set" to="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" id="d51f79eb-24f6-4661-a997-caaa21a960df"><output xmlns="urn:xmpp:rayo:output:1" renderer="unimrcp"><document content-type="application/ssml+xml"><![CDATA[<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">You pressed 1. Goodbye.</speak>]]></document></output></iq>
2016-12-15 07:39:26.472794 [DEBUG] xmpp_streams.c:1073 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, state = READY, node type = NODE_NORMAL
2016-12-15 07:39:26.472794 [DEBUG] mod_rayo.c:4197 Lock usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:26.472794 [DEBUG] mod_rayo.c:3143 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, recv iq, availability = ONLINE
2016-12-15 07:39:26.472794 [DEBUG] mod_rayo.c:4281 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:26.472794 [DEBUG] mod_rayo.c:842 Locate (jid) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 2
2016-12-15 07:39:26.472794 [DEBUG] mod_rayo.c:3146 Deliver usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 => 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201 <iq type='set' to='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' id='d51f79eb-24f6-4661-a997-caaa21a960df' from='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139'><output xmlns='urn:xmpp:rayo:output:1' renderer='unimrcp'><document content-type='application/ssml+xml'>&lt;speak xmlns=&quot;http://www.w3.org/2001/10/synthesis&quot; version=&quot;1.0&quot; xml:lang=&quot;en-US&quot;&gt;You pressed 1. Goodbye.&lt;/speak&gt;</document></output></iq>
2016-12-15 07:39:26.472794 [DEBUG] mod_rayo.c:723 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, looking for CALL::set:urn:xmpp:rayo:output:1:output command
2016-12-15 07:39:26.472794 [DEBUG] mod_rayo.c:1893 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, executing command
2016-12-15 07:39:26.472794 [DEBUG] mod_rayo.c:1367 Lock 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 3
2016-12-15 07:39:26.472794 [DEBUG] rayo_output_component.c:73 Init 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-6
2016-12-15 07:39:26.472794 [DEBUG] rayo_output_component.c:842 Got path rayo://0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-6
2016-12-15 07:39:26.472794 [DEBUG] rayo_output_component.c:648 Got path 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-6
2016-12-15 07:39:26.472794 [DEBUG] mod_rayo.c:842 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:26.472794 [DEBUG] rayo_components.c:62 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-6 => usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='result' id='d51f79eb-24f6-4661-a997-caaa21a960df'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-6'/></iq>
2016-12-15 07:39:26.472794 [DEBUG] mod_rayo.c:849 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:26.472794 [DEBUG] rayo_output_component.c:650 Locate (id) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-6: ref count = 2
2016-12-15 07:39:26.472794 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in SEND <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='result' id='d51f79eb-24f6-4661-a997-caaa21a960df'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-6'/></iq>
2016-12-15 07:39:26.472794 [INFO] mod_unimrcp.c:1624 speech_handle: name = unimrcp, rate = 8000, speed = 0, samples = 0, voice = , engine = unimrcp, param = (null)
2016-12-15 07:39:26.472794 [INFO] mod_unimrcp.c:1627 voice = , rate = 8000
2016-12-15 07:39:26.472794 [DEBUG] mod_unimrcp.c:683 (TTS-43) audio queue created
2016-12-15 07:39:26.472794 [NOTICE] mrcp_application.c:96 (TTS-43) Create MRCP Handle 0x7f257803a0e0 [lumenvox]
2016-12-15 07:39:26.472794 [INFO] mrcp_client_session.c:133 (TTS-43) Create Channel TTS-43 <new>
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2578004e90;4;0]
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2578004e90;4;0]
2016-12-15 07:39:26.472794 [INFO] mrcp_client_session.c:387 (TTS-43) Receive App Request TTS-43 <new> [2]
2016-12-15 07:39:26.472794 [INFO] mrcp_client.c:700 (TTS-43) Add MRCP Handle TTS-43 <new>
2016-12-15 07:39:26.472794 [DEBUG] mrcp_client_session.c:1283 (TTS-43) Dispatch App Request TTS-43 <new> [2]
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:26.472794 [NOTICE] mrcp_client_session.c:719 (TTS-43) Add Control Channel TTS-43 <new@speechsynth>
2016-12-15 07:39:26.472794 [DEBUG] mrcp_client_session.c:745 (TTS-43) Add Media Termination TTS-43 <new@media-tm>
2016-12-15 07:39:26.472794 [DEBUG] mrcp_client_session.c:777 (TTS-43) Add Media Termination TTS-43 <new@rtp-tm>
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7f2530026ae0;1;0]
2016-12-15 07:39:26.472794 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:26.472794 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538023fe0;2;0]
2016-12-15 07:39:26.472794 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538023fe0;2;0]
2016-12-15 07:39:26.472794 [DEBUG] mrcp_client_session.c:294 (TTS-43) Control Channel Added TTS-43 <new@speechsynth>
2016-12-15 07:39:26.472794 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7f2530026ae0;1;0]
2016-12-15 07:39:26.472794 [DEBUG] mpf_context.c:182 () Add Media Context TTS-43
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2578005d90;3;0]
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2578005d90;3;0]
2016-12-15 07:39:26.472794 [DEBUG] mrcp_client_session.c:944 (TTS-43) Media Termination Added TTS-43 <new@media-tm>
2016-12-15 07:39:26.472794 [DEBUG] mrcp_client_session.c:944 (TTS-43) Media Termination Added TTS-43 <new@rtp-tm>
2016-12-15 07:39:26.472794 [INFO] mrcp_client_session.c:411 (TTS-43) Send Offer TTS-43 <new> [c:1 a:1 v:0] to 127.0.0.1:5065
2016-12-15 07:39:26.472794 [INFO] mrcp_sofiasip_client_agent.c:354 (TTS-43) Local SDP TTS-43 <new>
v=0
o=FreeSWITCH 0 0 IN IP4 192.168.65.201
s=-
c=IN IP4 192.168.65.201
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechsynth
a=cmid:1
m=audio 28086 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=recvonly
a=mid:1
2016-12-15 07:39:26.472794 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:26.472794 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 0 INVITE sent [lumenvox]
2016-12-15 07:39:26.472794 [NOTICE] mrcp_sofiasip_client_agent.c:547 (TTS-43) SIP Call State TTS-43 [calling]
2016-12-15 07:39:26.472794 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_r_invite] Status 200 OK [lumenvox]
2016-12-15 07:39:26.472794 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 200 OK [lumenvox]
2016-12-15 07:39:26.472794 [NOTICE] mrcp_sofiasip_client_agent.c:547 (TTS-43) SIP Call State TTS-43 [ready]
2016-12-15 07:39:26.472794 [INFO] mrcp_sofiasip_client_agent.c:433 (TTS-43) Remote SDP TTS-43 <new>
v=0
o=- 1234 5678 IN IP4 127.0.0.1
s=-
c=IN IP4 127.0.0.1
t=0 0
m=application 20057 TCP/MRCPv2 1
a=setup:passive
a=connection:new
a=channel:ff924f89-ee96-40af-8@speechsynth
a=cmid:1
m=audio 25114 RTP/AVP 0
c=IN IP4 127.0.0.1
a=rtpmap:0 PCMU/8000
a=sendonly
a=mid:1
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2540021870;1;0]
2016-12-15 07:39:26.472794 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_active] Status 200 Call active [lumenvox]
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2540021870;1;0]
2016-12-15 07:39:26.472794 [INFO] mrcp_client_session.c:151 (TTS-43) Receive Answer TTS-43 <new> [c:1 a:1 v:0] Status 200
2016-12-15 07:39:26.472794 [DEBUG] mrcp_client_session.c:1141 (TTS-43) Modify Control Channel TTS-43 <ff924f89-ee96-40af-8>
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:26.472794 [DEBUG] mrcp_client_session.c:1180 (TTS-43) Modify Media Termination TTS-43 <ff924f89-ee96-40af-8@rtp-tm>
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7f253002baf0;1;0]
2016-12-15 07:39:26.472794 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:26.472794 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:26.472794 [NOTICE] mrcp_client_connection.c:338 () Established TCP/MRCPv2 Connection 127.0.0.1:58956 <-> 127.0.0.1:20057
2016-12-15 07:39:26.472794 [INFO] mrcp_client_connection.c:435 (TTS-43) Add Control Channel <ff924f89-ee96-40af-8@speechsynth> 127.0.0.1:58956 <-> 127.0.0.1:20057 [1]
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538024430;2;1]
2016-12-15 07:39:26.472794 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538024430;2;1]
2016-12-15 07:39:26.472794 [DEBUG] mrcp_client_session.c:311 (TTS-43) Control Channel Modified TTS-43 <ff924f89-ee96-40af-8@speechsynth>
2016-12-15 07:39:26.472794 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7f253002baf0;1;0]
2016-12-15 07:39:26.472794 [INFO] mpf_rtp_stream.c:331 () Enable RTP Session 192.168.65.201:28086
2016-12-15 07:39:26.472794 [DEBUG] mpf_bridge.c:129 () Create Linear Audio Bridge TTS-43
2016-12-15 07:39:26.472794 [INFO] mpf_rtp_stream.c:509 () Open RTP Receiver 192.168.65.201:28086 <- 127.0.0.1:25114 playout [0 ms] bounds [0 - 600 ms] adaptive [0] skew detection [1]
2016-12-15 07:39:26.472794 [INFO] mpf_bridge.c:93 () Media Path TTS-43 Source->[PCMU/8000/1]->Decoder->[LPCM/8000/1]->Bridge->[LPCM/8000/1]->Sink
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2578005d90;3;0]
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2578005d90;3;0]
2016-12-15 07:39:26.472794 [DEBUG] mrcp_client_session.c:985 (TTS-43) Media Termination Modified TTS-43 <ff924f89-ee96-40af-8@rtp-tm>
2016-12-15 07:39:26.472794 [INFO] mrcp_client_session.c:455 (TTS-43) Raise App Response TTS-43 <ff924f89-ee96-40af-8> [2] SUCCESS [0]
2016-12-15 07:39:26.472794 [DEBUG] mod_unimrcp.c:1893 (TTS-43) SYNTHESIZER channel is ready, codec = LPCM, sample rate = 8000
2016-12-15 07:39:26.472794 [DEBUG] mod_unimrcp.c:1577 (TTS-43) CLOSED ==> READY
2016-12-15 07:39:26.472794 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:26.472794 [DEBUG] mod_unimrcp.c:1055 (TTS-43) channel is ready
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f25780029f0;4;0]
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f25780029f0;4;0]
2016-12-15 07:39:26.472794 [INFO] mrcp_client_session.c:392 (TTS-43) Receive App MRCP Request TTS-43 <ff924f89-ee96-40af-8>
2016-12-15 07:39:26.472794 [INFO] mrcp_client_session.c:622 (TTS-43) Send MRCP Request TTS-43 <ff924f89-ee96-40af-8@speechsynth> [1]
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:26.472794 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:26.472794 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2016-12-15 07:39:26.472794 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:26.472794 [INFO] mrcp_client_connection.c:530 (TTS-43) Send MRCPv2 Data 127.0.0.1:58956 <-> 127.0.0.1:20057 [239 bytes]
MRCP/2.0 239 SPEAK 1
Channel-Identifier: ff924f89-ee96-40af-8@speechsynth
Content-Type: text/plain
Content-Length: 114
}<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">You pressed 1. Goodbye.</speak>
2016-12-15 07:39:26.472794 [DEBUG] apt_poller_task.c:246 () Wait for Messages [MRCPv2ConnectionAgent] timeout [3000]
2016-12-15 07:39:26.551381 [DEBUG] apt_poller_task.c:269 () Process Signalled Descriptor [MRCPv2ConnectionAgent]
2016-12-15 07:39:26.551381 [INFO] mrcp_client_connection.c:635 () Receive MRCPv2 Data 127.0.0.1:58956 <-> 127.0.0.1:20057 [124 bytes]
MRCP/2.0 124 1 200 IN-PROGRESS
Channel-Identifier: ff924f89-ee96-40af-8@speechsynth
Speech-Marker: timestamp=421195488
2016-12-15 07:39:26.551381 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538024430;2;3]
2016-12-15 07:39:26.551381 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:26.551381 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538024430;2;3]
2016-12-15 07:39:26.551381 [INFO] mrcp_client_session.c:500 (TTS-43) Raise App MRCP Response TTS-43 <ff924f89-ee96-40af-8>
2016-12-15 07:39:26.551381 [DEBUG] mod_unimrcp.c:1966 (TTS-43) REQUEST IN PROGRESS
2016-12-15 07:39:26.551381 [DEBUG] mod_unimrcp.c:1577 (TTS-43) READY ==> PROCESSING
2016-12-15 07:39:26.551381 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:26.551381 [DEBUG] rayo_output_component.c:866 Create audio buffer
2016-12-15 07:39:26.551381 [DEBUG] switch_core_media_bug.c:841 Attaching BUG to sofia/external/4044754849@192.168.65.114
2016-12-15 07:39:26.551381 [DEBUG] rayo_output_component.c:139 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-6: ref count = 1
2016-12-15 07:39:26.551381 [DEBUG] mod_rayo.c:1895 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, done executing command
2016-12-15 07:39:26.551381 [DEBUG] mod_rayo.c:849 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 2
2016-12-15 07:39:28.531380 [DEBUG] apt_poller_task.c:269 () Process Signalled Descriptor [MRCPv2ConnectionAgent]
2016-12-15 07:39:28.531380 [INFO] mrcp_client_connection.c:635 () Receive MRCPv2 Data 127.0.0.1:58956 <-> 127.0.0.1:20057 [162 bytes]
MRCP/2.0 162 SPEAK-COMPLETE 1 COMPLETE
Channel-Identifier: ff924f89-ee96-40af-8@speechsynth
Completion-Cause: 000 normal
Speech-Marker: timestamp=421211673
2016-12-15 07:39:28.531380 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538024470;2;3]
2016-12-15 07:39:28.531380 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:28.531380 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538024470;2;3]
2016-12-15 07:39:28.531380 [INFO] mrcp_client_session.c:516 (TTS-43) Raise App MRCP Event TTS-43 <ff924f89-ee96-40af-8>
2016-12-15 07:39:28.531380 [DEBUG] mod_unimrcp.c:1996 (TTS-43) SPEAK-COMPLETE
2016-12-15 07:39:28.531380 [DEBUG] mod_unimrcp.c:1577 (TTS-43) PROCESSING ==> DONE
2016-12-15 07:39:28.531380 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:28.691403 [DEBUG] mod_unimrcp.c:1577 (TTS-43) DONE ==> READY
2016-12-15 07:39:28.691403 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2548012840;4;0]
2016-12-15 07:39:28.691403 [DEBUG] mod_unimrcp.c:923 (TTS-43) Waiting for MRCP session to terminate
2016-12-15 07:39:28.691403 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2548012840;4;0]
2016-12-15 07:39:28.691403 [INFO] mrcp_client_session.c:387 (TTS-43) Receive App Request TTS-43 <ff924f89-ee96-40af-8> [1]
2016-12-15 07:39:28.691403 [DEBUG] mrcp_client_session.c:1283 (TTS-43) Dispatch App Request TTS-43 <ff924f89-ee96-40af-8> [1]
2016-12-15 07:39:28.691403 [INFO] mrcp_client_session.c:833 (TTS-43) Terminate Session TTS-43 <ff924f89-ee96-40af-8>
2016-12-15 07:39:28.691403 [DEBUG] mrcp_client_session.c:854 (TTS-43) Remove Control Channel TTS-43 <ff924f89-ee96-40af-8>
2016-12-15 07:39:28.691403 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:28.691403 [DEBUG] mrcp_client_session.c:864 (TTS-43) Subtract Media Termination TTS-43 <ff924f89-ee96-40af-8@media-tm>
2016-12-15 07:39:28.691403 [DEBUG] mrcp_client_session.c:885 (TTS-43) Subtract Media Termination TTS-43 <ff924f89-ee96-40af-8@rtp-tm>
2016-12-15 07:39:28.691403 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7f2530021e20;1;0]
2016-12-15 07:39:28.691403 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:28.691403 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2016-12-15 07:39:28.691403 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f253002b820;1;0]
2016-12-15 07:39:28.691403 [INFO] mrcp_client_connection.c:459 (TTS-43) Remove Control Channel <ff924f89-ee96-40af-8@speechsynth> [0]
2016-12-15 07:39:28.691403 [INFO] mrcp_client_connection.c:386 () Close TCP/MRCPv2 Connection 127.0.0.1:58956 <-> 127.0.0.1:20057
2016-12-15 07:39:28.691403 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2538024470;2;2]
2016-12-15 07:39:28.691403 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2016-12-15 07:39:28.691403 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2538024470;2;2]
2016-12-15 07:39:28.691403 [DEBUG] mrcp_client_session.c:331 (TTS-43) Control Channel Removed TTS-43 <ff924f89-ee96-40af-8@speechsynth>
2016-12-15 07:39:28.691403 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:28.711384 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_r_bye] Status 200 OK [lumenvox]
2016-12-15 07:39:28.711384 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 200 to BYE [lumenvox]
2016-12-15 07:39:28.711384 [NOTICE] mrcp_sofiasip_client_agent.c:547 (TTS-43) SIP Call State TTS-43 [terminated]
2016-12-15 07:39:28.711384 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2540021870;1;1]
2016-12-15 07:39:28.711384 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2540021870;1;1]
2016-12-15 07:39:28.711384 [INFO] mrcp_client_session.c:209 (TTS-43) Session Terminated TTS-43 <ff924f89-ee96-40af-8>
2016-12-15 07:39:28.711384 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:28.711384 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7f2530021e20;1;0]
2016-12-15 07:39:28.711384 [DEBUG] mpf_bridge.c:100 () Destroy Audio Bridge TTS-43
2016-12-15 07:39:28.711384 [INFO] mpf_rtp_stream.c:541 () Close RTP Receiver 192.168.65.201:28086 <- 127.0.0.1:25114 [r:102 l:0 j:127 p:0 d:0 i:0]
2016-12-15 07:39:28.711384 [DEBUG] mpf_context.c:238 () Remove Media Context TTS-43
2016-12-15 07:39:28.711384 [INFO] mpf_rtp_stream.c:418 () Remove RTP Session 192.168.65.201:28086
2016-12-15 07:39:28.711384 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f2578005980;3;0]
2016-12-15 07:39:28.711384 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f2578005980;3;0]
2016-12-15 07:39:28.711384 [DEBUG] mrcp_client_session.c:1014 (TTS-43) Media Termination Subtracted TTS-43 <ff924f89-ee96-40af-8@media-tm>
2016-12-15 07:39:28.711384 [DEBUG] mrcp_client_session.c:1014 (TTS-43) Media Termination Subtracted TTS-43 <ff924f89-ee96-40af-8@rtp-tm>
2016-12-15 07:39:28.711384 [NOTICE] mrcp_client_connection.c:235 () Destroy TCP/MRCPv2 Connection 127.0.0.1:58956 <-> 127.0.0.1:20057
2016-12-15 07:39:28.711384 [INFO] mrcp_client.c:710 (TTS-43) Remove MRCP Handle TTS-43 <ff924f89-ee96-40af-8>
2016-12-15 07:39:28.711384 [INFO] mrcp_client_session.c:455 (TTS-43) Raise App Response TTS-43 <ff924f89-ee96-40af-8> [1] SUCCESS [0]
2016-12-15 07:39:28.711384 [DEBUG] mod_unimrcp.c:1828 (TTS-43) Destroying MRCP session
2016-12-15 07:39:28.711384 [NOTICE] mrcp_application.c:182 (TTS-43) Destroy MRCP Handle TTS-43
2016-12-15 07:39:28.711384 [DEBUG] mod_unimrcp.c:1577 (TTS-43) READY ==> CLOSED
2016-12-15 07:39:28.711384 [DEBUG] mod_unimrcp.c:851 (TTS-43) audio queue destroyed
2016-12-15 07:39:28.711384 [INFO] rayo_output_component.c:552 Done playing
2016-12-15 07:39:28.711384 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2016-12-15 07:39:28.711384 [DEBUG] rayo_components.c:117 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-6: ref count = 0
2016-12-15 07:39:28.711384 [DEBUG] rayo_components.c:118 Destroy 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-6 requested: ref_count = 0
2016-12-15 07:39:28.711384 [DEBUG] rayo_components.c:118 Destroying 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-6
2016-12-15 07:39:28.711384 [DEBUG] mod_rayo.c:1035 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 1
2016-12-15 07:39:28.711384 [DEBUG] mod_rayo.c:842 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:28.711384 [DEBUG] rayo_components.c:116 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-6 => usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 <presence from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-6' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='unavailable'><complete xmlns='urn:xmpp:rayo:ext:1'><finish xmlns='urn:xmpp:rayo:output:complete:1'/></complete><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:28Z'/></presence>
2016-12-15 07:39:28.711384 [DEBUG] mod_rayo.c:849 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:28.711384 [DEBUG] switch_core_media_bug.c:1208 Removing BUG from sofia/external/4044754849@192.168.65.114
2016-12-15 07:39:28.731388 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in SEND <presence from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201/output-6' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='unavailable'><complete xmlns='urn:xmpp:rayo:ext:1'><finish xmlns='urn:xmpp:rayo:output:complete:1'/></complete><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:28Z'/></presence>
2016-12-15 07:39:28.731388 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in RECV <iq type="set" to="0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201" id="6e3f347d-375b-4e13-904b-35e749a28f26"><hangup xmlns="urn:xmpp:rayo:1"/></iq>
2016-12-15 07:39:28.731388 [DEBUG] xmpp_streams.c:1073 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, state = READY, node type = NODE_NORMAL
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:4197 Lock usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:3143 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, recv iq, availability = ONLINE
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:4281 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:842 Locate (jid) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 2
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:3146 Deliver usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 => 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201 <iq type='set' to='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' id='6e3f347d-375b-4e13-904b-35e749a28f26' from='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139'><hangup xmlns='urn:xmpp:rayo:1'/></iq>
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:723 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, looking for CALL::set:urn:xmpp:rayo:1:hangup command
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:1893 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, executing command
2016-12-15 07:39:28.731388 [NOTICE] switch_ivr.c:4267 Hangup sofia/external/4044754849@192.168.65.114 [CS_EXECUTE] [NORMAL_CLEARING]
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:1895 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201, done executing command
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:849 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 1
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:842 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:1901 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201 => usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='result' id='6e3f347d-375b-4e13-904b-35e749a28f26'/>
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:849 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:28.731388 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in SEND <iq from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='result' id='6e3f347d-375b-4e13-904b-35e749a28f26'/>
2016-12-15 07:39:28.731388 [DEBUG] switch_core_session.c:2840 sofia/external/4044754849@192.168.65.114 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2016-12-15 07:39:28.731388 [DEBUG] switch_core_state_machine.c:650 (sofia/external/4044754849@192.168.65.114) State EXECUTE going to sleep
2016-12-15 07:39:28.731388 [DEBUG] switch_core_state_machine.c:584 (sofia/external/4044754849@192.168.65.114) Running State Change CS_HANGUP
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:3694 got event CHANNEL_EXECUTE_COMPLETE
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:3699 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 rayo event CHANNEL_EXECUTE_COMPLETE
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:3701 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:3636 Locate (id) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 2
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:3639 Application rayo execute complete: _none_
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:3642 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 1
2016-12-15 07:39:28.731388 [DEBUG] mod_rayo.c:3709 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:28.731388 [DEBUG] rayo_input_component.c:365 Removing DTMF callback
2016-12-15 07:39:28.731388 [DEBUG] switch_core_media_bug.c:1133 Removing BUG from sofia/external/4044754849@192.168.65.114
2016-12-15 07:39:28.731388 [DEBUG] switch_core_state_machine.c:850 (sofia/external/4044754849@192.168.65.114) Callstate Change ACTIVE -> HANGUP
2016-12-15 07:39:28.751373 [DEBUG] switch_core_state_machine.c:852 (sofia/external/4044754849@192.168.65.114) State HANGUP
2016-12-15 07:39:28.751373 [DEBUG] mod_sofia.c:440 Channel sofia/external/4044754849@192.168.65.114 hanging up, cause: NORMAL_CLEARING
2016-12-15 07:39:28.751373 [DEBUG] mod_sofia.c:493 Sending BYE to sofia/external/4044754849@192.168.65.114
2016-12-15 07:39:28.751373 [DEBUG] switch_core_state_machine.c:60 sofia/external/4044754849@192.168.65.114 Standard HANGUP, cause: NORMAL_CLEARING
2016-12-15 07:39:28.751373 [DEBUG] switch_core_state_machine.c:852 (sofia/external/4044754849@192.168.65.114) State HANGUP going to sleep
2016-12-15 07:39:28.751373 [DEBUG] switch_core_state_machine.c:619 (sofia/external/4044754849@192.168.65.114) State Change CS_HANGUP -> CS_REPORTING
2016-12-15 07:39:28.751373 [DEBUG] switch_core_state_machine.c:584 (sofia/external/4044754849@192.168.65.114) Running State Change CS_REPORTING
2016-12-15 07:39:28.751373 [DEBUG] switch_core_state_machine.c:938 (sofia/external/4044754849@192.168.65.114) State REPORTING
2016-12-15 07:39:28.751373 [DEBUG] switch_core_state_machine.c:174 sofia/external/4044754849@192.168.65.114 Standard REPORTING, cause: NORMAL_CLEARING
2016-12-15 07:39:28.751373 [DEBUG] switch_core_state_machine.c:938 (sofia/external/4044754849@192.168.65.114) State REPORTING going to sleep
2016-12-15 07:39:28.751373 [DEBUG] switch_core_state_machine.c:610 (sofia/external/4044754849@192.168.65.114) State Change CS_REPORTING -> CS_DESTROY
2016-12-15 07:39:28.751373 [DEBUG] switch_core_session.c:1677 Session 67 (sofia/external/4044754849@192.168.65.114) Locked, Waiting on external entities
2016-12-15 07:39:28.751373 [NOTICE] switch_core_session.c:1695 Session 67 (sofia/external/4044754849@192.168.65.114) Ended
2016-12-15 07:39:28.751373 [DEBUG] rayo_cpa_component.c:130 Subscriber execute hangup
2016-12-15 07:39:28.751373 [NOTICE] switch_core_session.c:1699 Close Channel sofia/external/4044754849@192.168.65.114 [CS_DESTROY]
2016-12-15 07:39:28.751373 [DEBUG] rayo_cpa_component.c:143 No subscribers for hangup
2016-12-15 07:39:28.751373 [DEBUG] switch_core_state_machine.c:741 (sofia/external/4044754849@192.168.65.114) Running State Change CS_DESTROY
2016-12-15 07:39:28.751373 [DEBUG] mod_rayo.c:3437 Locate (id) 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 2
2016-12-15 07:39:28.751373 [DEBUG] mod_rayo.c:3447 Got channel destroy event
2016-12-15 07:39:28.751373 [DEBUG] switch_core_state_machine.c:751 (sofia/external/4044754849@192.168.65.114) State DESTROY
2016-12-15 07:39:28.751373 [DEBUG] mod_sofia.c:345 sofia/external/4044754849@192.168.65.114 SOFIA DESTROY
2016-12-15 07:39:28.751373 [DEBUG] switch_core_state_machine.c:181 sofia/external/4044754849@192.168.65.114 Standard DESTROY
2016-12-15 07:39:28.751373 [DEBUG] switch_core_state_machine.c:751 (sofia/external/4044754849@192.168.65.114) State DESTROY going to sleep
2016-12-15 07:39:28.751373 [DEBUG] mod_rayo.c:3452 Destroy 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201 requested: ref_count = 2
2016-12-15 07:39:28.751373 [DEBUG] mod_rayo.c:3453 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 1
2016-12-15 07:39:28.751373 [DEBUG] mod_rayo.c:3456 Release 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201: ref count = 0
2016-12-15 07:39:28.751373 [DEBUG] mod_rayo.c:3456 Destroying 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201
2016-12-15 07:39:28.751373 [DEBUG] mod_rayo.c:1179 Sending <end> to offered client usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139
2016-12-15 07:39:28.751373 [DEBUG] mod_rayo.c:842 Locate (jid) usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 2
2016-12-15 07:39:28.751373 [DEBUG] mod_rayo.c:1180 Deliver 0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201 => usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139 <presence from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='unavailable'><end xmlns='urn:xmpp:rayo:1'><hangup-command/><header name='P-DCS-Billing-Info' value='gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9'/><header name='P-Charging-Vector' value='icid-value=1ed17a'/></end><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:28Z'/></presence>
2016-12-15 07:39:28.751373 [DEBUG] mod_rayo.c:849 Release usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139: ref count = 1
2016-12-15 07:39:28.751373 [DEBUG] xmpp_streams.c:192 usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139, 192.168.65.201:34062, c2s_in SEND <presence from='0fc60ee5-1cc9-4aeb-bba4-60dc728d6b32@192.168.65.201' to='usera@192.168.65.201/appserver02.lab.lax.qualityspeaks.net-25139' type='unavailable'><end xmlns='urn:xmpp:rayo:1'><hangup-command/><header name='P-DCS-Billing-Info' value='gK080c83c6z9hG4bK08Bcbdeaaef64ffb5fa235447510_125265048@192.168.13.9'/><header name='P-Charging-Vector' value='icid-value=1ed17a'/></end><delay xmlns='urn:xmpp:delay' stamp='2016-12-15T15:39:28Z'/></presence>
freeswitch@appserver02.lab.lax.qualityspeaks.net>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment