Skip to content

Instantly share code, notes, and snippets.

@benlangfeld

benlangfeld/ahn.log

Created March 20, 2012 09:52
Show Gist options
  • Save benlangfeld/2133592 to your computer and use it in GitHub Desktop.
Save benlangfeld/2133592 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
ahn.log
{9:51}[ruby-1.9.3]~/code/VoIP/adhearsion/testapps/general ben% be ahn -
Starting Adhearsion server at /Users/ben/code/VoIP/adhearsion/testapps/general
[2012-03-20 09:52:00] WARN Adhearsion::LinuxProcName: Error while attaching libc function prctl: Function 'prctl' not found in [libc.dylib]
[2012-03-20 09:52:00] INFO Adhearsion::Initializer: Setting RAILS_ENV to "development"
[2012-03-20 09:52:01] INFO Adhearsion::PunchblockPlugin::Initializer: Starting connection to server
[2012-03-20 09:52:01] TRACE Punchblock::Connection::XMPP: USING JID: [email protected]/blmbp.home-28910
[2012-03-20 09:52:01] TRACE Punchblock::Connection::XMPP: SENDING: (/Users/ben/code/VoIP/adhearsion/testapps/general/vendor/ruby/1.9.1/gems/blather-0.7.0/lib/blather/stream/client.rb:21:in `start') <stream:stream to='127.0.0.1' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' xml:lang='en' >
[2012-03-20 09:52:01] TRACE Punchblock::Connection::XMPP: RECEIVING (stream) <stream:stream xmlns:db="jabber:server:dialback" xmlns:stream="http://etherx.jabber.org/streams" from="127.0.0.1" id="xmpps_l0328mignyvl" lang="en" version="1.0"/>
[2012-03-20 09:52:01] TRACE Punchblock::Connection::XMPP: RECEIVING (features) <stream:features xmlns:stream="http://etherx.jabber.org/streams">
<mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl">
<mechanism>PLAIN</mechanism>
</mechanisms>
</stream:features>
[2012-03-20 09:52:01] TRACE Punchblock::Connection::XMPP: SENDING: (/Users/ben/code/VoIP/adhearsion/testapps/general/vendor/ruby/1.9.1/gems/blather-0.7.0/lib/blather/stream/features/sasl.rb:177:in `authenticate') <auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="PLAIN">dXNlcmFAMTI3LjAuMC4xAHVzZXJhADE=</auth>
[2012-03-20 09:52:01] TRACE Punchblock::Connection::XMPP: RECEIVING (success) <success xmlns="urn:ietf:params:xml:ns:xmpp-sasl"/>
[2012-03-20 09:52:01] INFO Adhearsion::Console: Launching Adhearsion Console
AHN> [2012-03-20 09:52:01] TRACE Punchblock::Connection::XMPP: SENDING: (/Users/ben/code/VoIP/adhearsion/testapps/general/vendor/ruby/1.9.1/gems/blather-0.7.0/lib/blather/stream/client.rb:21:in `start') <stream:stream to='127.0.0.1' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' xml:lang='en' >
[2012-03-20 09:52:01] TRACE Punchblock::Connection::XMPP: RECEIVING (stream) <stream:stream xmlns:db="jabber:server:dialback" xmlns:stream="http://etherx.jabber.org/streams" from="127.0.0.1" id="xmpps_l0328mignyvl" lang="en" version="1.0"/>
[2012-03-20 09:52:01] TRACE Punchblock::Connection::XMPP: RECEIVING (features) <stream:features xmlns:stream="http://etherx.jabber.org/streams">
<bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"/>
<session xmlns="urn:ietf:params:xml:ns:xmpp-session"/>
</stream:features>
[2012-03-20 09:52:01] TRACE Punchblock::Connection::XMPP: SENDING: (/Users/ben/code/VoIP/adhearsion/testapps/general/vendor/ruby/1.9.1/gems/blather-0.7.0/lib/blather/stream/features/resource.rb:39:in `bind') <iq type="set" id="blather0002"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><resource>blmbp.home-28910</resource></bind></iq>
[2012-03-20 09:52:01] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq from="127.0.0.1" id="blather0002" to="[email protected]" type="result">
<bind xmlns="urn:ietf:params:xml:ns:xmpp-bind">
<jid>[email protected]/blmbp.home-28910</jid>
</bind>
</iq>
[2012-03-20 09:52:01] TRACE Punchblock::Connection::XMPP: USING JID: [email protected]/blmbp.home-28910
[2012-03-20 09:52:01] TRACE Punchblock::Connection::XMPP: SENDING: (/Users/ben/code/VoIP/adhearsion/testapps/general/vendor/ruby/1.9.1/gems/blather-0.7.0/lib/blather/stream/features/session.rb:40:in `session') <iq type="set" id="blather0004" to="127.0.0.1"><session xmlns="urn:ietf:params:xml:ns:xmpp-session"/></iq>
[2012-03-20 09:52:01] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq from="127.0.0.1" id="blather0004" to="[email protected]/blmbp.home-28910" type="result"/>
[2012-03-20 09:52:01] TRACE Punchblock::Connection::XMPP: SENDING: (/Users/ben/code/VoIP/adhearsion/testapps/general/vendor/ruby/1.9.1/gems/blather-0.7.0/lib/blather/client/client.rb:149:in `write') <iq type="get" id="blather0006"><query xmlns="jabber:iq:roster"/></iq>
[2012-03-20 09:52:01] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq from="127.0.0.1" id="blather0006" to="[email protected]/blmbp.home-28910" type="error">
<query xmlns="jabber:iq:roster"/>
<error type="cancel">
<feature-not-implemented xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/>
<text xmlns="urn:ietf:params:xml:ns:xmpp-stanzas" lang="en">Feature not supported</text>
</error>
</iq>
[2012-03-20 09:52:01] TRACE Punchblock::Connection::XMPP: SENDING: (/Users/ben/code/VoIP/adhearsion/testapps/general/vendor/ruby/1.9.1/gems/blather-0.7.0/lib/blather/client/client.rb:149:in `write') <presence/>
[2012-03-20 09:52:01] INFO Punchblock::Connection::XMPP: Connected to XMPP as [email protected]/blmbp.home-28910
[2012-03-20 09:52:01] INFO Adhearsion::PunchblockPlugin::Initializer: Connected to Punchblock server
[2012-03-20 09:52:01] INFO Adhearsion::Process: Transitioning from booting to running with 0 active calls due to booted event.
[2012-03-20 09:52:01] INFO Adhearsion::Initializer: Adhearsion v2.0.0.beta1 initialized in "development"!
[2012-03-20 09:52:04] TRACE Punchblock::Connection::XMPP: RECEIVING (presence) <presence from="[email protected]" id="041c9bc9-7e50-4c5e-a36a-4fa666c46c33" to="[email protected]">
<offer xmlns="urn:xmpp:rayo:1" from="sip:[email protected]" to="sip:[email protected]">
<header name="Max-Forwards" value="70"/>
<header name="Content-Length" value="342"/>
<header name="Contact" value="&lt;sip:[email protected]:59615&gt;"/>
<header name="Supported" value="100rel"/>
<header name="Allow" value="SUBSCRIBE"/>
<header name="To" value="&lt;sip:[email protected]&gt;"/>
<header name="CSeq" value="22123 INVITE"/>
<header name="User-Agent" value="Blink 0.24.1 (MacOSX)"/>
<header name="Via" value="SIP/2.0/UDP 192.168.1.72:59615;rport=59615;branch=z9hG4bKPjE.KMjdg80mb40oy1nHXQiQ.unbXxr31K;received=127.0.0.1"/>
<header name="Call-ID" value="T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u"/>
<header name="Content-Type" value="application/sdp"/>
<header name="From" value="&quot;Ben Langfeld&quot; &lt;sip:[email protected]&gt;;tag=c9hgQjuQkAKpYJSoYBa1ZJFVuQq.M-iL"/>
</offer>
</presence>
[2012-03-20 09:52:04] DEBUG Adhearsion::Call: : Receiving message: #<Punchblock::Event::Offer to="sip:[email protected]", from="sip:[email protected]", call_id="4vg6dkqc-lx7-fxod8zouyy3mb"
[2012-03-20 09:52:04] DEBUG Adhearsion::Call: 4vg6dkqc-lx7-fxod8zouyy3mb: Executing command #<Punchblock::Command::Accept headers_hash={}, call_id=nil, component_id=nil>
[2012-03-20 09:52:04] TRACE Punchblock::Connection::XMPP: SENDING: (/Users/ben/code/VoIP/adhearsion/testapps/general/vendor/ruby/1.9.1/gems/blather-0.7.0/lib/blather/client/client.rb:149:in `write') <iq type="set" to="[email protected]" id="blather0008"><accept xmlns="urn:xmpp:rayo:1"/></iq>
[2012-03-20 09:52:04] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq from="[email protected]" id="blather0008" to="[email protected]/blmbp.home-28910" type="result"/>
[2012-03-20 09:52:04] DEBUG Adhearsion::Router: Call 4vg6dkqc-lx7-fxod8zouyy3mb selected route "default" (#<Proc:0x00000100939b20@/Users/ben/code/VoIP/adhearsion/testapps/general/config/adhearsion.rb:6>)
[2012-03-20 09:52:04] DEBUG Adhearsion::Call: 4vg6dkqc-lx7-fxod8zouyy3mb: Executing command #<Punchblock::Command::Answer headers_hash={}, call_id=nil, component_id=nil>
[2012-03-20 09:52:04] TRACE Punchblock::Connection::XMPP: SENDING: (/Users/ben/code/VoIP/adhearsion/testapps/general/vendor/ruby/1.9.1/gems/blather-0.7.0/lib/blather/client/client.rb:149:in `write') <iq type="set" to="[email protected]" id="blather000a"><answer xmlns="urn:xmpp:rayo:1"/></iq>
[2012-03-20 09:52:04] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq from="[email protected]" id="blather000a" to="[email protected]/blmbp.home-28910" type="result"/>
[2012-03-20 09:52:04] DEBUG Adhearsion::Call: 4vg6dkqc-lx7-fxod8zouyy3mb: Receiving message: #<Punchblock::Event::Offer to="sip:[email protected]", from="sip:[email protected]", call_id="4vg6dkqc-lx7-fxod8zouyy3mb"
[2012-03-20 09:52:05] DEBUG Adhearsion::Call: 4vg6dkqc-lx7-fxod8zouyy3mb: Executing command #<Punchblock::Component::Output voice=nil, ssml="digits/3", call_id=nil, component_id=nil, interrupt_on=nil, start_offset=nil, start_paused=false, repeat_interval=nil, repeat_times=nil, max_time=nil>
[2012-03-20 09:52:05] TRACE Punchblock::Connection::XMPP: SENDING: (/Users/ben/code/VoIP/adhearsion/testapps/general/vendor/ruby/1.9.1/gems/blather-0.7.0/lib/blather/client/client.rb:149:in `write') <iq type="set" to="[email protected]" id="blather000c"><output xmlns="urn:xmpp:rayo:output:1">digits/3</output></iq>
[2012-03-20 09:52:05] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq from="[email protected]" id="blather000c" to="[email protected]/blmbp.home-28910" type="result">
<ref xmlns="urn:xmpp:rayo:1" id="eb5f6969-d096-4e40-97be-4fbece5c1c43"/>
</iq>
[2012-03-20 09:52:06] TRACE Punchblock::Connection::XMPP: RECEIVING (presence) <presence from="[email protected]/eb5f6969-d096-4e40-97be-4fbece5c1c43" id="579ced25-c02c-4e2a-8dae-8ea3b9f13b86" to="[email protected]">
<complete xmlns="urn:xmpp:rayo:ext:1">
<success xmlns="urn:xmpp:rayo:output:complete:1"/>
</complete>
</presence>
[2012-03-20 09:52:06] DEBUG Adhearsion::Call: 4vg6dkqc-lx7-fxod8zouyy3mb: Executing command #<Punchblock::Component::Output voice=nil, ssml=<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">
<audio src="http://static1.grsites.com/archive/sounds/aircraft/aircraft001.mp3"/>
</speak>, call_id=nil, component_id=nil, interrupt_on=nil, start_offset=nil, start_paused=false, repeat_interval=nil, repeat_times=nil, max_time=nil>
[2012-03-20 09:52:06] TRACE Punchblock::Connection::XMPP: SENDING: (/Users/ben/code/VoIP/adhearsion/testapps/general/vendor/ruby/1.9.1/gems/blather-0.7.0/lib/blather/client/client.rb:149:in `write') <iq type="set" to="[email protected]" id="blather000e"><output xmlns="urn:xmpp:rayo:output:1"><speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US"><audio src="http://static1.grsites.com/archive/sounds/aircraft/aircraft001.mp3"/></speak></output></iq>
[2012-03-20 09:52:06] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq from="[email protected]" id="blather000e" to="[email protected]/blmbp.home-28910" type="result">
<ref xmlns="urn:xmpp:rayo:1" id="92f9a63d-6783-40b8-b076-0a9d44871f91"/>
</iq>
[2012-03-20 09:52:06] DEBUG Adhearsion::Call: 4vg6dkqc-lx7-fxod8zouyy3mb: Receiving message: #<Punchblock::Event::Complete reason=#<Punchblock::Component::Output::Complete::Success name=:success, call_id="4vg6dkqc-lx7-fxod8zouyy3mb", component_id="eb5f6969-d096-4e40-97be-4fbece5c1c43">, recording=nil, call_id="4vg6dkqc-lx7-fxod8zouyy3mb", component_id="eb5f6969-d096-4e40-97be-4fbece5c1c43">
[2012-03-20 09:52:11] TRACE Punchblock::Connection::XMPP: RECEIVING (presence) <presence from="[email protected]/92f9a63d-6783-40b8-b076-0a9d44871f91" id="05a322d7-a2ce-4c72-8d76-ed8dad54680f" to="[email protected]">
<complete xmlns="urn:xmpp:rayo:ext:1">
<success xmlns="urn:xmpp:rayo:output:complete:1"/>
</complete>
</presence>
[2012-03-20 09:52:11] DEBUG Adhearsion::Call: 4vg6dkqc-lx7-fxod8zouyy3mb: Executing command #<Punchblock::Component::Output voice=nil, ssml=<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">
<audio src="digits/3"/>
</speak>, call_id=nil, component_id=nil, interrupt_on=nil, start_offset=nil, start_paused=false, repeat_interval=nil, repeat_times=nil, max_time=nil>
[2012-03-20 09:52:11] TRACE Punchblock::Connection::XMPP: SENDING: (/Users/ben/code/VoIP/adhearsion/testapps/general/vendor/ruby/1.9.1/gems/blather-0.7.0/lib/blather/client/client.rb:149:in `write') <iq type="set" to="[email protected]" id="blather0010"><output xmlns="urn:xmpp:rayo:output:1"><speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US"><audio src="digits/3"/></speak></output></iq>
[2012-03-20 09:52:11] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq from="[email protected]" id="blather0010" to="[email protected]/blmbp.home-28910" type="result">
<ref xmlns="urn:xmpp:rayo:1" id="f8440d4f-464b-43d9-b48c-3ec686268457"/>
</iq>
[2012-03-20 09:52:11] DEBUG Adhearsion::Call: 4vg6dkqc-lx7-fxod8zouyy3mb: Receiving message: #<Punchblock::Event::Complete reason=#<Punchblock::Component::Output::Complete::Success name=:success, call_id="4vg6dkqc-lx7-fxod8zouyy3mb", component_id="92f9a63d-6783-40b8-b076-0a9d44871f91">, recording=nil, call_id="4vg6dkqc-lx7-fxod8zouyy3mb", component_id="92f9a63d-6783-40b8-b076-0a9d44871f91">
[2012-03-20 09:52:11] TRACE Punchblock::Connection::XMPP: RECEIVING (presence) <presence from="[email protected]/f8440d4f-464b-43d9-b48c-3ec686268457" id="53797fbe-284b-4138-8f41-7886a7f64b0d" to="[email protected]">
<complete xmlns="urn:xmpp:rayo:ext:1">
<error xmlns="urn:xmpp:rayo:ext:complete:1">Invalid SSML: The prefix "xml" cannot be bound to any namespace other than its usual namespace; neither can the namespace for "xml" be bound to any prefix other than "xml".</error>
</complete>
</presence>
[2012-03-20 09:52:11] DEBUG Adhearsion::Call: 4vg6dkqc-lx7-fxod8zouyy3mb: Receiving message: #<Punchblock::Event::Complete reason=#<Punchblock::Event::Complete::Error details="Invalid SSML: The prefix \"xml\" cannot be bound to any namespace other than its usual namespace; neither can the namespace for \"xml\" be bound to any prefix other than \"xml\".", name=:error, call_id="4vg6dkqc-lx7-fxod8zouyy3mb", component_id="f8440d4f-464b-43d9-b48c-3ec686268457">, recording=nil, call_id="4vg6dkqc-lx7-fxod8zouyy3mb", component_id="f8440d4f-464b-43d9-b48c-3ec686268457">
[2012-03-20 09:52:11] ERROR Adhearsion::Call: 4vg6dkqc-lx7-fxod8zouyy3mb: <StandardError> Invalid SSML: The prefix "xml" cannot be bound to any namespace other than its usual namespace; neither can the namespace for "xml" be bound to any prefix other than "xml".: #<Punchblock::Component::Output voice=nil, ssml=<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">
<audio src="digits/3"/>
</speak>, call_id="4vg6dkqc-lx7-fxod8zouyy3mb", component_id="f8440d4f-464b-43d9-b48c-3ec686268457", interrupt_on=nil, start_offset=nil, start_paused=false, repeat_interval=nil, repeat_times=nil, max_time=nil>
/Users/ben/code/VoIP/adhearsion/core/lib/adhearsion/call_controller.rb:118:in `execute_component_and_await_completion'
/Users/ben/code/VoIP/adhearsion/core/lib/adhearsion/call_controller/output.rb:124:in `output'
/Users/ben/code/VoIP/adhearsion/core/lib/adhearsion/call_controller/output.rb:118:in `play_ssml'
/Users/ben/code/VoIP/adhearsion/core/lib/adhearsion/call_controller/output.rb:185:in `play_ssml_for'
/Users/ben/code/VoIP/adhearsion/core/lib/adhearsion/call_controller/output.rb:46:in `block in play'
/Users/ben/code/VoIP/adhearsion/core/lib/adhearsion/call_controller/output.rb:39:in `each'
/Users/ben/code/VoIP/adhearsion/core/lib/adhearsion/call_controller/output.rb:39:in `inject'
/Users/ben/code/VoIP/adhearsion/core/lib/adhearsion/call_controller/outpu[2012-03-20 09:52:11] DEBUG Adhearsion::Call: 4vg6dkqc-lx7-fxod8zouyy3mb: Executing command #<Punchblock::Command::Hangup headers_hash={}, call_id=nil, component_id=nil>
[2012-03-20 09:52:11] TRACE Punchblock::Connection::XMPP: SENDING: (/Users/ben/code/VoIP/adhearsion/testapps/general/vendor/ruby/1.9.1/gems/blather-0.7.0/lib/blather/client/client.rb:149:in `write') <iq type="set" to="[email protected]" id="blather0012"><hangup xmlns="urn:xmpp:rayo:1"/></iq>
t.rb:39:in `play'
/Users/ben/code/VoIP/adhearsion/testapps/general/config/adhearsion.rb:10:in `block (2 levels) in <top (required)>'
/Users/ben/code/VoIP/adhearsion/core/lib/adhearsion/call_controller.rb:77:in `instance_exec'
/Users/ben/code/VoIP/adhearsion/core/lib/adhearsion/call_controller.rb:77:in `run'
/Users/ben/code/VoIP/adhearsion/core/lib/adhearsion/call_controller.rb:67:in `execute!'
/Users/ben/code/VoIP/adhearsion/core/lib/adhearsion/call_controller.rb:41:in `block in exec'
/Users/ben/code/VoIP/adhearsion/core/lib/adhearsion/call_controller.rb:40:in `catch'
/Users/ben/code/VoIP/adhearsion/core/lib/adhearsion/call_controller.rb:40:in `exec'
/Users/ben/code/VoIP/adhearsion/core/lib/adhearsion/call.rb:262:in `block (2 levels) in execute_controller'
/Users/ben/code/VoIP/adhearsion/core/lib/adhearsion/foundation/exception_handler.rb:6:in `catching_standard_errors'
/Users/ben/code/VoIP/adhearsion/core/lib/adhearsion/call.rb:260:in `block in execute_controller'
[2012-03-20 09:52:11] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq from="[email protected]" id="blather0012" to="[email protected]/blmbp.home-28910" type="result"/>
[2012-03-20 09:52:11] TRACE Punchblock::Connection::XMPP: RECEIVING (presence) <presence from="[email protected]" id="417b829a-1af7-4de2-94ce-b43134d08e15" to="[email protected]">
<end xmlns="urn:xmpp:rayo:1">
<hangup/>
</end>
</presence>
[2012-03-20 09:52:11] DEBUG Adhearsion::Call: 4vg6dkqc-lx7-fxod8zouyy3mb: Receiving message: #<Punchblock::Event::End reason=:hangup, headers_hash={}, call_id="4vg6dkqc-lx7-fxod8zouyy3mb", component_id=nil>
Raw
sipmethod.log
2012-03-20 09:51:53.856 DEBUG [Timer-19] Reading JID Lookup Service configuration from disk [rayo-routing.properties]
2012-03-20 09:52:00.433 DEBUG [Timer-16] #SIP#: NonInviteServerTransaction[, , _state=COMPLETED, _id=z9hG4bKPj0ydf7nvUTkp5N01pqpCEdeqwJfxwFENZ, ] timerRemoveTransaction is fired. #[rayo][sas_2-14-smcie0vnntm7l6rayo][R.HJZ7wtTq45V045uWw8hyBEss1oBgBl][ss_xa80qogedq98][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:00.433 DEBUG [Timer-16] #SIP#: NonInviteServerTransaction[, , _state=TERMINATED, _id=z9hG4bKPj0ydf7nvUTkp5N01pqpCEdeqwJfxwFENZ, ] is released. #[rayo][sas_2-14-smcie0vnntm7l6rayo][R.HJZ7wtTq45V045uWw8hyBEss1oBgBl][ss_xa80qogedq98][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:01.218 DEBUG [SocketAcceptorIoProcessor-0.1] #XMPP#: Creating xmpp session with app: ApplicationImpl[_symbolicName=rayo-0, _state=STARTED, ] #[N/A][N/A][N/A][N/A][?, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.219 DEBUG [SocketAcceptorIoProcessor-0.1] #XMPP#: Created session: XMPPSessionImpl: _id=xmpps_l0328mignyvl, _direction=RECEIVEStream, _sessionType=CLIENT, _remotJID=null, _state=INITIAL, _remoteAddr=/127.0.0.1, _remotePort=59745, _localPort=5222, _localJID=127.0.0.1, _application=ApplicationImpl[_symbolicName=rayo-0, _state=STARTED, ] #[N/A][N/A][N/A][N/A][?, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.220 DEBUG [SocketAcceptorIoProcessor-0.1] #XMPP#: (i)<stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" to="127.0.0.1" version="1.0" xml:lang="en"> #[rayo][null][xmpps_l0328mignyvl][CLIENT][?, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.223 DEBUG [XMPPService-t-24] #XMPP#: (o)<stream:stream xmlns="jabber:client" xmlns:db="jabber:server:dialback" from="127.0.0.1" id="xmpps_l0328mignyvl" xml:lang="en" version="1.0" xmlns:stream="http://etherx.jabber.org/streams"> #[rayo][null][xmpps_l0328mignyvl][CLIENT][?, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.223 DEBUG [XMPPService-t-24] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][?, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.225 DEBUG [XMPPService-t-24] #XMPP#: (o)<stream:features><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>PLAIN</mechanism></mechanisms></stream:features> #[rayo][null][xmpps_l0328mignyvl][CLIENT][?, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.225 DEBUG [XMPPService-t-24] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][?, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.297 DEBUG [SocketAcceptorIoProcessor-0.1] #XMPP#: (i)<auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="PLAIN">dXNlcmFAMTI3LjAuMC4xAHVzZXJhADE=</auth> #[rayo][null][xmpps_l0328mignyvl][CLIENT][?, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.301 DEBUG [XMPPService-t-25] #XMPP#: (o)<success xmlns="urn:ietf:params:xml:ns:xmpp-sasl"/> #[rayo][null][xmpps_l0328mignyvl][CLIENT][?, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.301 DEBUG [XMPPService-t-25] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][?, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.321 DEBUG [SocketAcceptorIoProcessor-0.1] #XMPP#: (i)<stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" to="127.0.0.1" version="1.0" xml:lang="en"> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected], 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.323 DEBUG [XMPPService-t-26] #XMPP#: (o)<stream:stream xmlns="jabber:client" xmlns:db="jabber:server:dialback" from="127.0.0.1" id="xmpps_l0328mignyvl" xml:lang="en" version="1.0" xmlns:stream="http://etherx.jabber.org/streams"> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected], 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.324 DEBUG [XMPPService-t-26] #XMPP#: Session :XMPPSessionImpl: _id=xmpps_l0328mignyvl, _direction=RECEIVEStream, _sessionType=CLIENT, [email protected], _state=CONFIRMED, _remoteAddr=/127.0.0.1, _remotePort=59745, _localPort=5222, _localJID=127.0.0.1, _application=ApplicationImpl[_symbolicName=rayo-0, _state=STARTED, ] negotiatied. The result is:true
2012-03-20 09:52:01.324 DEBUG [XMPPService-t-26] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected], 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.325 DEBUG [XMPPService-t-26] #XMPP#: (o)<stream:features><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"/><session xmlns="urn:ietf:params:xml:ns:xmpp-session"/></stream:features> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected], 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.325 DEBUG [XMPPService-t-26] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected], 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.328 DEBUG [SocketAcceptorIoProcessor-0.1] #XMPP#: (i)<iq id="blather0002" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><resource>blmbp.home-28910</resource></bind></iq> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected], 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.330 DEBUG [XMPPService-t-27] #XMPP#: Intercept iq bind result, set full jid [email protected]/blmbp.home-28910 to session XMPPSessionImpl: _id=xmpps_l0328mignyvl, _direction=RECEIVEStream, _sessionType=CLIENT, [email protected]/blmbp.home-28910, _state=CONFIRMED, _remoteAddr=/127.0.0.1, _remotePort=59745, _localPort=5222, _localJID=127.0.0.1, _application=ApplicationImpl[_symbolicName=rayo-0, _state=STARTED, ] #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.332 DEBUG [XMPPService-t-27] #XMPP#: (o)<iq from="127.0.0.1" id="blather0002" to="[email protected]" type="result"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><jid>[email protected]/blmbp.home-28910</jid></bind></iq> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.332 DEBUG [XMPPService-t-27] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.333 DEBUG [XMPPService-t-27] #XMPP#: Session :XMPPSessionImpl: _id=xmpps_l0328mignyvl, _direction=RECEIVEStream, _sessionType=CLIENT, [email protected]/blmbp.home-28910, _state=CONFIRMED, _remoteAddr=/127.0.0.1, _remotePort=59745, _localPort=5222, _localJID=127.0.0.1, _application=ApplicationImpl[_symbolicName=rayo-0, _state=STARTED, ] negotiatied. The result is:true
2012-03-20 09:52:01.334 DEBUG [XMPPService-t-27] Xmpp Session created
2012-03-20 09:52:01.335 DEBUG [XMPPService-t-27] Returning cached instance of singleton bean 'callRegistry'
2012-03-20 09:52:01.336 DEBUG [XMPPService-t-27] Returning cached instance of singleton bean 'jidRegistry'
2012-03-20 09:52:01.337 DEBUG [XMPPService-t-27] Returning cached instance of singleton bean 'sessionCleanupConfig'
2012-03-20 09:52:01.337 DEBUG [SocketAcceptorIoProcessor-0.1] #XMPP#: (i)<iq id="blather0004" to="127.0.0.1" type="set"><session xmlns="urn:ietf:params:xml:ns:xmpp-session"/></iq> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.338 DEBUG [XMPPService-t-28] #XMPP#: Invoke application:rayo null
2012-03-20 09:52:01.338 DEBUG [XMPPService-t-28] #XMPP#: Forwarding Request #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][null]
2012-03-20 09:52:01.339 DEBUG [XMPPService-t-28] <iq from="[email protected]/blmbp.home-28910" id="blather0004" to="127.0.0.1" type="set"><session xmlns="urn:ietf:params:xml:ns:xmpp-session"/></iq> :: xmpps_l0328mignyvl
2012-03-20 09:52:01.341 DEBUG [XMPPService-t-28] #XMPP#: (o)<iq from="127.0.0.1" id="blather0004" to="[email protected]/blmbp.home-28910" type="result"/> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.341 DEBUG [XMPPService-t-28] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.345 DEBUG [SocketAcceptorIoProcessor-0.1] #XMPP#: (i)<iq id="blather0006" type="get"><query xmlns="jabber:iq:roster"/></iq> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.346 DEBUG [XMPPService-t-29] #XMPP#: Invoke application:rayo rayo
2012-03-20 09:52:01.346 DEBUG [XMPPService-t-29] #XMPP#: Forwarding Request #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][null]
2012-03-20 09:52:01.347 DEBUG [XMPPService-t-29] <iq from="[email protected]/blmbp.home-28910" id="blather0006" to="127.0.0.1" type="get"><query xmlns="jabber:iq:roster"/></iq> :: xmpps_l0328mignyvl
2012-03-20 09:52:01.348 DEBUG [XMPPService-t-29] #XMPP#: (o)<iq from="127.0.0.1" id="blather0006" to="[email protected]/blmbp.home-28910" type="error"><query xmlns="jabber:iq:roster"/><error type="cancel"><feature-not-implemented xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/><text xml:lang="en" xmlns="urn:ietf:params:xml:ns:xmpp-stanzas">Feature not supported</text></error></iq> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.349 DEBUG [XMPPService-t-29] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.492 DEBUG [SocketAcceptorIoProcessor-0.1] #XMPP#: (i)<presence id="fc313c5f-3534-48e3-9998-ab1ebf73b5af"/> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:01.493 DEBUG [XMPPService-t-30] #XMPP#: Invoke application:rayo rayo
2012-03-20 09:52:01.493 DEBUG [XMPPService-t-30] #XMPP#: Forwarding Request #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][null]
2012-03-20 09:52:01.493 DEBUG [XMPPService-t-30] <presence from="[email protected]/blmbp.home-28910" id="fc313c5f-3534-48e3-9998-ab1ebf73b5af" to="127.0.0.1"/> :: xmpps_l0328mignyvl
2012-03-20 09:52:01.494 WARN [XMPPService-t-30] Ignoring unknown presence message
2012-03-20 09:52:04.501 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: (i)[INVITE sip:[email protected] SIP/2.0\r\nContent-Type: application/sdp\r\nTo: <sip:[email protected]>\r\nVia: SIP/2.0/UDP 192.168.1.72:59615;rport;branch=z9hG4bKPjE.KMjdg80mb40oy1nHXQiQ.unbXxr31K\r\nAllow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER\r\nCSeq: 22123 INVITE\r\nContent-Length: 342\r\nSupported: 100rel, norefersub\r\nCall-ID: T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u\r\nUser-Agent: Blink 0.24.1 (MacOSX)\r\nFrom: "Ben Langfeld" <sip:[email protected]>;tag=c9hgQjuQkAKpYJSoYBa1ZJFVuQq.M-iL\r\nMax-Forwards: 70\r\nContact: <sip:[email protected]:59615>\r\n\r\nv=0\r\no=- 3541225924 3541225924 IN IP4 127.0.0.1\r\ns=Blink 0.24.1 (MacOSX)\r\nc=IN IP4 127.0.0.1\r\nt=0 0\r\nm=audio 50068 RTP/AVP 9 104 103 102 3 101\r\na=rtcp:50069\r\na=rtpmap:9 G722/8000\r\na=rtpmap:104 speex/32000\r\na=rtpmap:103 speex/16000\r\na=rtpmap:102 speex/8000\r\na=rtpmap:3 GSM/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=sendrecv\r\n] #[N/A][N/A][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][N/A][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.502 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: The transaction was created: z9hG4bKPjE.KMjdg80mb40oy1nHXQiQ.unbXxr31K #[N/A][N/A][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][N/A][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.503 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: (o)[SIP/2.0 100 Trying\r\nTo: <sip:[email protected]>\r\nVia: SIP/2.0/UDP 192.168.1.72:59615;rport=59615;branch=z9hG4bKPjE.KMjdg80mb40oy1nHXQiQ.unbXxr31K;received=127.0.0.1\r\nCSeq: 22123 INVITE\r\nContent-Length: 0\r\nCall-ID: T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u\r\nFrom: "Ben Langfeld" <sip:[email protected]>;tag=c9hgQjuQkAKpYJSoYBa1ZJFVuQq.M-iL\r\n\r\n] #[N/A][N/A][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][N/A][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.503 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: Send message to: /127.0.0.1:59615 by udp #[N/A][N/A][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][N/A][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.504 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: Connected to 127.0.0.1:59615/udp #[N/A][N/A][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][N/A][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.504 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: Found [rayo] to handle the request by port mappings: 5060
2012-03-20 09:52:04.504 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: SipApplicationInfo: SipApplicationRouterInfo[ApplicationName=rayo, RouteModifier=NO_ROUTE, RouteRegion=null, SubscriberURI=sip:[email protected], StateInfo=rayo] #[N/A][N/A][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][N/A][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.505 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: Session creating: ss_1hrqgtdr2wdid #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.506 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: Session created:SipSessionImpl[_id=ss_1hrqgtdr2wdid, _parentId=sas_2-15-sm1i1a8cbvif5iarayo, _handler=Controller, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UNKNOW, _method=INVITE, _callId=T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, ] #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.506 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: SessionManagementLayer recv request: INVITE #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.506 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: ApplicationDispatchLayer invoke application: Controller with INVITE #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.507 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: SipServletWrapper[Controller, com.voxeo.moho.sip.SIPController] is forwarding. #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.507 DEBUG [udp/0.0.0.0/5060-t-3] Returning cached instance of singleton bean 'com.voxeo.moho.sip.IncomingCallFactoryImpl#0'
2012-03-20 09:52:04.509 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm1i1a8cbvif5iarayo], invalidateWhenReady: true
2012-03-20 09:52:04.509 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: processInvalidationWhenReady [ss_1hrqgtdr2wdid], current State = INITIAL, Vaild:true, Role:UNKNOW, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.509 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: processInvalidationWhenReady [sas_2-15-sm1i1a8cbvif5iarayo], invalidateWhenReady: true
2012-03-20 09:52:04.510 DEBUG [MOHO-21] Dispatching Event to listener:SIPCallImpl[SipSessionAdaptor[sessionid=ss_1hrqgtdr2wdid, appSessionId=sas_2-15-sm1i1a8cbvif5iarayo, ],INVITING]
2012-03-20 09:52:04.510 DEBUG [MOHO-21] Received incoming call
2012-03-20 09:52:04.510 DEBUG [MOHO-21] Creating CDR for call id [4vg6dkqc-lx7-fxod8zouyy3mb]
2012-03-20 09:52:04.511 INFO [pool-21-thread-2] Message [SIPCallImpl[SipSessionAdaptor[sessionid=ss_1hrqgtdr2wdid, appSessionId=sas_2-15-sm1i1a8cbvif5iarayo, ],INVITING]]
2012-03-20 09:52:04.511 INFO [pool-21-thread-2] Incoming Call [SIPCallImpl[SipSessionAdaptor[sessionid=ss_1hrqgtdr2wdid, appSessionId=sas_2-15-sm1i1a8cbvif5iarayo, ],INVITING]]
2012-03-20 09:52:04.511 DEBUG [pool-21-thread-2] Creating call actor for call [4vg6dkqc-lx7-fxod8zouyy3mb]
2012-03-20 09:52:04.515 DEBUG [pool-21-thread-2] Adding call [4vg6dkqc-lx7-fxod8zouyy3mb] to registry: [com.rayo.server.DefaultCallRegistry@491a97]
2012-03-20 09:52:04.516 INFO [pool-21-thread-3] Message [SIPCallImpl[SipSessionAdaptor[sessionid=ss_1hrqgtdr2wdid, appSessionId=sas_2-15-sm1i1a8cbvif5iarayo, ],INVITING]]
2012-03-20 09:52:04.519 INFO [pool-21-thread-3] Queued Event [OfferEvent[from=sip:[email protected],to=sip:[email protected],headers={Max-Forwards=70, Content-Length=342, Contact=<sip:[email protected]:59615>, Supported=100rel, Allow=SUBSCRIBE, To=<sip:[email protected]>, CSeq=22123 INVITE, User-Agent=Blink 0.24.1 (MacOSX), Via=SIP/2.0/UDP 192.168.1.72:59615;rport=59615;branch=z9hG4bKPjE.KMjdg80mb40oy1nHXQiQ.unbXxr31K;received=127.0.0.1, Call-ID=T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, Content-Type=application/sdp, From="Ben Langfeld" <sip:[email protected]>;tag=c9hgQjuQkAKpYJSoYBa1ZJFVuQq.M-iL}]]
2012-03-20 09:52:04.519 INFO [pool-21-thread-3] Event [OfferEvent[from=sip:[email protected],to=sip:[email protected],headers={Max-Forwards=70, Content-Length=342, Contact=<sip:[email protected]:59615>, Supported=100rel, Allow=SUBSCRIBE, To=<sip:[email protected]>, CSeq=22123 INVITE, User-Agent=Blink 0.24.1 (MacOSX), Via=SIP/2.0/UDP 192.168.1.72:59615;rport=59615;branch=z9hG4bKPjE.KMjdg80mb40oy1nHXQiQ.unbXxr31K;received=127.0.0.1, Call-ID=T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, Content-Type=application/sdp, From="Ben Langfeld" <sip:[email protected]>;tag=c9hgQjuQkAKpYJSoYBa1ZJFVuQq.M-iL}]]
2012-03-20 09:52:04.521 DEBUG [pool-21-thread-3] Found a match for sip:[email protected] : [email protected]
2012-03-20 09:52:04.521 DEBUG [pool-21-thread-3] Received Offer. Offer will be delivered to [[email protected]]
2012-03-20 09:52:04.526 DEBUG [pool-21-thread-3] #XMPP#: (o)<presence from="[email protected]" id="041c9bc9-7e50-4c5e-a36a-4fa666c46c33" to="[email protected]"><offer xmlns="urn:xmpp:rayo:1" from="sip:[email protected]" to="sip:[email protected]"><header name="Max-Forwards" value="70"/><header name="Content-Length" value="342"/><header name="Contact" value="&lt;sip:[email protected]:59615&gt;"/><header name="Supported" value="100rel"/><header name="Allow" value="SUBSCRIBE"/><header name="To" value="&lt;sip:[email protected]&gt;"/><header name="CSeq" value="22123 INVITE"/><header name="User-Agent" value="Blink 0.24.1 (MacOSX)"/><header name="Via" value="SIP/2.0/UDP 192.168.1.72:59615;rport=59615;branch=z9hG4bKPjE.KMjdg80mb40oy1nHXQiQ.unbXxr31K;received=127.0.0.1"/><header name="Call-ID" value="T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u"/><header name="Content-Type" value="application/sdp"/><header name="From" value="&quot;Ben Langfeld&quot; &lt;sip:[email protected]&gt;;tag=c9hgQjuQkAKpYJSoYBa1ZJFVuQq.M-iL"/></offer></presence> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:04.526 DEBUG [pool-21-thread-3] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:04.725 DEBUG [SocketAcceptorIoProcessor-0.1] #XMPP#: (i)<iq id="blather0008" to="[email protected]" type="set"><accept xmlns="urn:xmpp:rayo:1"/></iq> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:04.726 DEBUG [XMPPService-t-31] #XMPP#: Invoke application:rayo rayo
2012-03-20 09:52:04.726 DEBUG [XMPPService-t-31] #XMPP#: Forwarding Request #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][null]
2012-03-20 09:52:04.726 DEBUG [XMPPService-t-31] <iq from="[email protected]/blmbp.home-28910" id="blather0008" to="[email protected]" type="set"><accept xmlns="urn:xmpp:rayo:1"/></iq> :: xmpps_l0328mignyvl
2012-03-20 09:52:04.727 DEBUG [XMPPService-t-31] Looking up call [4vg6dkqc-lx7-fxod8zouyy3mb] in registry: [com.rayo.server.DefaultCallRegistry@491a97]
2012-03-20 09:52:04.728 DEBUG [pool-21-thread-3] [IncomingCallActor[callId=4vg6dkqc-lx7-fxod8zouyy3mb]] : Request [AcceptCommand[callId=4vg6dkqc-lx7-fxod8zouyy3mb,headers={}]]
2012-03-20 09:52:04.728 DEBUG [pool-21-thread-3] #SIP#: SessionManagementLayer send response: INVITE/180 #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.729 DEBUG [pool-21-thread-3] #SIP#: Add Path[ id=T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u-c9hgQjuQkAKpYJSoYBa1ZJFVuQq.M-iL-dhgn9s9mk146, session=SipSessionImpl[_id=ss_1hrqgtdr2wdid, _parentId=sas_2-15-sm1i1a8cbvif5iarayo, _handler=Controller, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=INVITE, _callId=T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, ], party= CALLER] #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.730 DEBUG [pool-21-thread-3] #SIP#: (o)[SIP/2.0 180 Ringing\r\nTo: <sip:[email protected]>;tag=dhgn9s9mk146\r\nVia: SIP/2.0/UDP 192.168.1.72:59615;rport=59615;branch=z9hG4bKPjE.KMjdg80mb40oy1nHXQiQ.unbXxr31K;received=127.0.0.1\r\nCSeq: 22123 INVITE\r\nContent-Length: 0\r\nCall-ID: T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u\r\nFrom: "Ben Langfeld" <sip:[email protected]>;tag=c9hgQjuQkAKpYJSoYBa1ZJFVuQq.M-iL\r\n\r\n] #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.730 DEBUG [pool-21-thread-3] #SIP#: Send message to: /127.0.0.1:59615 by udp #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.730 DEBUG [pool-21-thread-3] #SIP#: Connected to 127.0.0.1:59615/udp #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.730 DEBUG [pool-21-thread-3] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm1i1a8cbvif5iarayo], invalidateWhenReady: true
2012-03-20 09:52:04.731 DEBUG [pool-21-thread-3] #SIP#: processInvalidationWhenReady [ss_1hrqgtdr2wdid], current State = EARLY, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.731 DEBUG [pool-21-thread-3] #SIP#: processInvalidationWhenReady [sas_2-15-sm1i1a8cbvif5iarayo], invalidateWhenReady: true
2012-03-20 09:52:04.731 INFO [pool-21-thread-3] Reply [null]
2012-03-20 09:52:04.732 DEBUG [pool-21-thread-3] #XMPP#: (o)<iq from="[email protected]" id="blather0008" to="[email protected]/blmbp.home-28910" type="result"/> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:04.732 DEBUG [pool-21-thread-3] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:04.825 DEBUG [SocketAcceptorIoProcessor-0.1] #XMPP#: (i)<iq id="blather000a" to="[email protected]" type="set"><answer xmlns="urn:xmpp:rayo:1"/></iq> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:04.826 DEBUG [XMPPService-t-32] #XMPP#: Invoke application:rayo rayo
2012-03-20 09:52:04.826 DEBUG [XMPPService-t-32] #XMPP#: Forwarding Request #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][null]
2012-03-20 09:52:04.827 DEBUG [XMPPService-t-32] <iq from="[email protected]/blmbp.home-28910" id="blather000a" to="[email protected]" type="set"><answer xmlns="urn:xmpp:rayo:1"/></iq> :: xmpps_l0328mignyvl
2012-03-20 09:52:04.827 DEBUG [XMPPService-t-32] Looking up call [4vg6dkqc-lx7-fxod8zouyy3mb] in registry: [com.rayo.server.DefaultCallRegistry@491a97]
2012-03-20 09:52:04.828 DEBUG [pool-21-thread-3] [IncomingCallActor[callId=4vg6dkqc-lx7-fxod8zouyy3mb]] : Request [AnswerCommand[callId=4vg6dkqc-lx7-fxod8zouyy3mb,headers={}]]
2012-03-20 09:52:04.828 DEBUG [pool-21-thread-3] Set ms id with call id :T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u
2012-03-20 09:52:04.828 INFO [pool-21-thread-3] #MSCTRL#: MS[MS-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] updates MEDIAOBJECT_ID, old:"ms2-5", new:"MS-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u"
2012-03-20 09:52:04.828 DEBUG [pool-21-thread-3] Set nc id with call id :T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u
2012-03-20 09:52:04.829 INFO [pool-21-thread-3] #MSCTRL#: MS[NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] updates MEDIAOBJECT_ID, old:"MS-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u", new:"NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u"
2012-03-20 09:52:04.829 INFO [pool-21-thread-3] #MSCTRL#: MS[NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] creates a MediaObject[BASIC, NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, {MEDIAOBJECT_ID=NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u}]
2012-03-20 09:52:04.829 INFO [pool-21-thread-3] #MSCTRL#: SdpPort[IDLE, NC[NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]] processes a SDP offer: v=0\r\no=- 3541225924 3541225924 IN IP4 127.0.0.1\r\ns=Blink 0.24.1 (MacOSX)\r\nc=IN IP4 127.0.0.1\r\nt=0 0\r\nm=audio 50068 RTP/AVP 9 104 103 102 3 101\r\na=rtcp:50069\r\na=rtpmap:9 G722/8000\r\na=rtpmap:104 speex/32000\r\na=rtpmap:103 speex/16000\r\na=rtpmap:102 speex/8000\r\na=rtpmap:3 GSM/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=sendrecv\r\n
2012-03-20 09:52:04.831 DEBUG [pool-21-thread-3] #MSCTRL#: SdpPort[UNDER_PROCESSING, NC[NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]] moves state from [IDLE] to [UNDER_PROCESSING]
2012-03-20 09:52:04.832 INFO [msctrl/2-t-12] #MSCTRL#: No CodecPolicy is installed, just return back the initial offer
2012-03-20 09:52:04.832 DEBUG [msctrl/2-t-12] #MRCP#: load configuration from {maxThreadPool=2147483647, minThreadPool=25, MEDIAOBJECT_ID=NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, com.voxeo.useLocalConfigurationOnGUTFailures=false}
2012-03-20 09:52:04.843 DEBUG [msctrl/2-t-12] #MRCP#: (o)SETUP rtsp://192.168.1.73:10074/recognizer/ RTSP/1.0\r\nCseq: 1\r\nTransport: RTP/AVP;unicast;\r\nContent-Type: application/sdp\r\nContent-Length: 342\r\n\r\nv=0\r\no=- 3541225924 3541225924 IN IP4 127.0.0.1\r\ns=Blink 0.24.1 (MacOSX)\r\nc=IN IP4 127.0.0.1\r\nt=0 0\r\nm=audio 50068 RTP/AVP 9 104 103 102 3 101\r\na=rtcp:50069\r\na=rtpmap:9 G722/8000\r\na=rtpmap:104 speex/32000\r\na=rtpmap:103 speex/16000\r\na=rtpmap:102 speex/8000\r\na=rtpmap:3 GSM/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=sendrecv\r\n #[N/A][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:04.854 DEBUG [mrcp/2-t-13] #MRCP#: (i)RTSP/1.0 200 OK\r\nSession: 797263084-a787590-01b1f470-00000002\r\nTransport: RTP/AVP;unicast;client_port=50068-50069;server_port=65535-65536\r\nCseq: 1\r\nContent-Type: application/sdp\r\nContent-Length: 193\r\n\r\nv=0\r\no=- 1896872 1896872 IN IP4 109.149.163.56\r\ns=voxeo\r\nc=IN IP4 109.149.163.56\r\nt=0 0\r\nm=audio 20002 RTP/AVP 101 103\r\na=rtpmap:101 telephone-event/8000\r\na=rtpmap:103 SPEEX/16000\r\na=ptime:20\r\n #[N/A][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:04.855 DEBUG [msctrl/2-t-12] #MSCTRL#: NC[NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] applies for the recognizer resource. #[797263084-a787590-01b1f470-00000002]
2012-03-20 09:52:04.856 DEBUG [msctrl/2-t-12] #MRCP#: (o)SETUP rtsp://192.168.1.73:10074/synthesizer/ RTSP/1.0\r\nCseq: 2\r\nTransport: RTP/AVP;unicast;\r\nSession: 797263084-a787590-01b1f470-00000002\r\n\r\n #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:04.867 DEBUG [mrcp/2-t-14] #MRCP#: (i)RTSP/1.0 200 OK\r\nSession: 797263084-a787590-01b1f470-00000002\r\nTransport: RTP/AVP;unicast;client_port=50068-50069;server_port=65535-65536\r\nCseq: 2\r\nContent-Type: application/sdp\r\nContent-Length: 183\r\n\r\nv=0\r\no=- 1896883 1896883 IN IP4 127.0.0.1\r\ns=voxeo\r\nc=IN IP4 127.0.0.1\r\nt=0 0\r\nm=audio 20002 RTP/AVP 101 103\r\na=rtpmap:101 telephone-event/8000\r\na=rtpmap:103 SPEEX/16000\r\na=ptime:20\r\n #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:04.867 DEBUG [msctrl/2-t-12] #MSCTRL#: NC[NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] applies for the synthesizer resource. #[797263084-a787590-01b1f470-00000002]
2012-03-20 09:52:04.868 DEBUG [msctrl/2-t-12] #MSCTRL#: SdpPort[SDP_NEGOTIATED, NC[NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]] moves state from [UNDER_PROCESSING] to [SDP_NEGOTIATED]
2012-03-20 09:52:04.869 DEBUG [msctrl/2-t-13] #MSCTRL#: Return SdpPortEvt[SdpPort[SDP_NEGOTIATED, NC[NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]], ANSWER_GENERATED, NO_ERROR, null, NO_QUALIFIER, null, v=0\r\no=- 1896872 1896872 IN IP4 109.149.163.56\r\ns=voxeo\r\nc=IN IP4 109.149.163.56\r\nt=0 0\r\nm=audio 20002 RTP/AVP 101 103\r\na=rtpmap:101 telephone-event/8000\r\na=rtpmap:103 SPEEX/16000\r\na=ptime:20\r\n] to the application
2012-03-20 09:52:04.872 DEBUG [msctrl/2-t-13] #SIP#: SessionManagementLayer send response: INVITE/200 #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.874 DEBUG [msctrl/2-t-13] #SIP#: (o)[SIP/2.0 200 OK\r\nContent-Type: application/sdp\r\nTo: <sip:[email protected]>;tag=dhgn9s9mk146\r\nVia: SIP/2.0/UDP 192.168.1.72:59615;rport=59615;branch=z9hG4bKPjE.KMjdg80mb40oy1nHXQiQ.unbXxr31K;received=127.0.0.1\r\nCSeq: 22123 INVITE\r\nContent-Length: 193\r\nCall-ID: T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u\r\nFrom: "Ben Langfeld" <sip:[email protected]>;tag=c9hgQjuQkAKpYJSoYBa1ZJFVuQq.M-iL\r\nContact: <sip:192.168.1.73:5060;transport=udp>\r\n\r\nv=0\r\no=- 1896872 1896872 IN IP4 109.149.163.56\r\ns=voxeo\r\nc=IN IP4 109.149.163.56\r\nt=0 0\r\nm=audio 20002 RTP/AVP 101 103\r\na=rtpmap:101 telephone-event/8000\r\na=rtpmap:103 SPEEX/16000\r\na=ptime:20\r\n] #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.874 DEBUG [msctrl/2-t-13] #SIP#: Send message to: /127.0.0.1:59615 by udp #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.875 DEBUG [msctrl/2-t-13] #SIP#: Connected to 127.0.0.1:59615/udp #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.875 DEBUG [msctrl/2-t-13] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm1i1a8cbvif5iarayo], invalidateWhenReady: true
2012-03-20 09:52:04.875 DEBUG [msctrl/2-t-13] #SIP#: processInvalidationWhenReady [ss_1hrqgtdr2wdid], current State = CONFIRMED, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.875 DEBUG [msctrl/2-t-13] #SIP#: processInvalidationWhenReady [sas_2-15-sm1i1a8cbvif5iarayo], invalidateWhenReady: true
2012-03-20 09:52:04.903 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: (i)[ACK sip:192.168.1.73:5060;transport=udp SIP/2.0\r\nTo: <sip:[email protected]>;tag=dhgn9s9mk146\r\nVia: SIP/2.0/UDP 192.168.1.72:59615;rport;branch=z9hG4bKPjHhRrlkPgd8Fj8wgaxGEacxiijevp3aRD\r\nCSeq: 22123 ACK\r\nContent-Length: 0\r\nCall-ID: T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u\r\nUser-Agent: Blink 0.24.1 (MacOSX)\r\nFrom: "Ben Langfeld" <sip:[email protected]>;tag=c9hgQjuQkAKpYJSoYBa1ZJFVuQq.M-iL\r\nMax-Forwards: 70\r\n\r\n] #[N/A][N/A][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][N/A][sip:[email protected](192.168.1.73:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.905 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: Find Path[ id=T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u-c9hgQjuQkAKpYJSoYBa1ZJFVuQq.M-iL-dhgn9s9mk146, path=ApplicationPath[_id=T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u-c9hgQjuQkAKpYJSoYBa1ZJFVuQq.M-iL-dhgn9s9mk146, _nodes=ApplicationPathList[_nodes=[ApplicationPathNode[_sipSession=SipSessionAdaptor[sessionid=ss_1hrqgtdr2wdid, appSessionId=sas_2-15-sm1i1a8cbvif5iarayo, ], ]], ], ]] #[N/A][N/A][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][N/A][sip:[email protected](192.168.1.73:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.905 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: SessionManagementLayer recv request: ACK #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](192.168.1.73:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.906 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: ApplicationDispatchLayer invoke application: Controller with ACK #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](192.168.1.73:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.906 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: SipServletWrapper[Controller, com.voxeo.moho.sip.SIPController] is forwarding. #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](192.168.1.73:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.907 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm1i1a8cbvif5iarayo], invalidateWhenReady: true
2012-03-20 09:52:04.908 INFO [pool-21-thread-3] Reply [null]
2012-03-20 09:52:04.908 DEBUG [MOHO-22] Dispatching Event to listener:[Event class=com.voxeo.moho.common.event.MohoJoinCompleteEvent sourceClass=SIPIncomingCall id=24248381]
2012-03-20 09:52:04.908 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: processInvalidationWhenReady [ss_1hrqgtdr2wdid], current State = CONFIRMED, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:04.910 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: processInvalidationWhenReady [sas_2-15-sm1i1a8cbvif5iarayo], invalidateWhenReady: true
2012-03-20 09:52:04.908 DEBUG [pool-21-thread-3] #XMPP#: (o)<iq from="[email protected]" id="blather000a" to="[email protected]/blmbp.home-28910" type="result"/> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:04.915 DEBUG [pool-21-thread-3] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:04.916 DEBUG [pool-21-thread-2] [IncomingCallActor[callId=4vg6dkqc-lx7-fxod8zouyy3mb]] : Request [[Event class=com.voxeo.moho.common.event.MohoJoinCompleteEvent sourceClass=SIPIncomingCall id=24248381]]
2012-03-20 09:52:04.916 DEBUG [pool-21-thread-2] Received Join Complete Event. Is initiator: [true]
2012-03-20 09:52:04.920 DEBUG [pool-21-thread-2] Join Complete Event source: [SIPCallImpl[SipSessionAdaptor[sessionid=ss_1hrqgtdr2wdid, appSessionId=sas_2-15-sm1i1a8cbvif5iarayo, ],ANSWERED]]. Peer: [null]
2012-03-20 09:52:04.922 DEBUG [pool-21-thread-2] Validating media on join
2012-03-20 09:52:04.922 DEBUG [pool-21-thread-2] Joined Event not fired. Join cause [JOINED]. Joinees: [[]]
2012-03-20 09:52:04.922 INFO [pool-21-thread-2] Reply [null]
2012-03-20 09:52:05.159 DEBUG [SocketAcceptorIoProcessor-0.1] #XMPP#: (i)<iq id="blather000c" to="[email protected]" type="set"><output xmlns="urn:xmpp:rayo:output:1">digits/3</output></iq> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:05.160 DEBUG [XMPPService-t-33] #XMPP#: Invoke application:rayo rayo
2012-03-20 09:52:05.160 DEBUG [XMPPService-t-33] #XMPP#: Forwarding Request #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][null]
2012-03-20 09:52:05.161 DEBUG [XMPPService-t-33] <iq from="[email protected]/blmbp.home-28910" id="blather000c" to="[email protected]" type="set"><output xmlns="urn:xmpp:rayo:output:1">digits/3</output></iq> :: xmpps_l0328mignyvl
2012-03-20 09:52:05.161 DEBUG [XMPPService-t-33] Looking up call [4vg6dkqc-lx7-fxod8zouyy3mb] in registry: [com.rayo.server.DefaultCallRegistry@491a97]
2012-03-20 09:52:05.162 DEBUG [pool-21-thread-2] [IncomingCallActor[callId=4vg6dkqc-lx7-fxod8zouyy3mb]] : Request [Output[callId=4vg6dkqc-lx7-fxod8zouyy3mb,verbId=1ef345cc-b9df-455f-bbd5-08ba025de3b2,interrupt-on=<null>,start-offset=<null>,start-paused=<null>,repeatInterval=<null>,repeatTimes=<null>,maxTime=<null>,voice=<null>,prompt=Ssml[ssml=digits/3,voice=<null>,uri=data:application%2Fssml%2Bxml%2C%3Cspeak%3Edigits%2F3%3C%2Fspeak%3E]]]
2012-03-20 09:52:05.162 DEBUG [pool-21-thread-2] Creating instance of bean 'outputHandler'
2012-03-20 09:52:05.164 DEBUG [pool-21-thread-2] Returning cached instance of singleton bean 'ssmlValidator'
2012-03-20 09:52:05.165 DEBUG [pool-21-thread-2] Finished creating instance of bean 'outputHandler'
2012-03-20 09:52:05.166 DEBUG [pool-21-thread-2] Set mg id with call id :T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u
2012-03-20 09:52:05.166 INFO [pool-21-thread-2] #MSCTRL#: MS[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] updates MEDIAOBJECT_ID, old:"NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u", new:"MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u"
2012-03-20 09:52:05.166 INFO [pool-21-thread-2] #MSCTRL#: MS[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] creates a MediaObject[PLAYER_RECORDER_SIGNALDETECTOR, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, {MEDIAOBJECT_ID=MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u}]
2012-03-20 09:52:05.167 INFO [pool-21-thread-2] SIPCallImpl[SipSessionAdaptor[sessionid=ss_1hrqgtdr2wdid, appSessionId=sas_2-15-sm1i1a8cbvif5iarayo, ],ANSWERED] joins to MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] in DUPLEX
2012-03-20 09:52:05.167 INFO [pool-21-thread-2] #MSCTRL#: NC[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] joins to MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] in DUPLEX
2012-03-20 09:52:05.168 DEBUG [pool-21-thread-2] #MSCTRL#: MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] adds JoineeMrcpContext[mscontrol://192.168.1.73:10074/MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u/NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, 797263084-a787590-01b1f470-00000002, 797263084-a787590-01b1f470-00000002] #[797263084-a787590-01b1f470-00000002]
2012-03-20 09:52:05.169 DEBUG [pool-21-thread-2] #MSCTRL#: MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] adds JoinCompleteDector[MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u], NC[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]] #[797263084-a787590-01b1f470-00000002]
2012-03-20 09:52:05.169 DEBUG [pool-21-thread-2] #MSCTRL#: NC[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] adds(MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u], JoineeContext[RESOURCE_CONTAINER, DUPLEX, null])
2012-03-20 09:52:05.169 DEBUG [pool-21-thread-2] #MSCTRL#: MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] adds(NC[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u], JoineeContext[RESOURCE_CONTAINER, DUPLEX, null])
2012-03-20 09:52:05.170 DEBUG [pool-21-thread-2] #MSCTRL#: Add PlayListItem[gi:0, pi:0, ei:0, null, rtcs=null, optargs={PLAYER_MAX_DURATION=-1, PLAYER_START_OFFSET=0, JUMP_PLAYLIST_INCREMENT=1, PLAYER_ENABLED_EVENTS=[Ljavax.media.mscontrol.EventType;@120bd9a, BARGE_IN_ENABLED=false, PLAYER_AUDIO_CODEC=CODEC_INFERRED, VOLUME_CHANGE=3, PLAYER_JUMP_TIME=5000, VOICE_NAME=null, BEHAVIOUR_IF_BUSY=STOP_IF_BUSY, PLAYER_START_PAUSED=false, PLAYER_FILE_FORMAT=FORMAT_INFERRED, TTS_SPEECH_LANGUAGE=null},"<speak>digits/3</speak>"]
2012-03-20 09:52:05.170 DEBUG [pool-21-thread-2] #MSCTRL#: Find PlayListItem[IDLE, gi=0, pi=0, ei=0, null]
2012-03-20 09:52:05.170 DEBUG [pool-21-thread-2] #MSCTRL#: Player[IDLE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]] starts playing PlayListItem[IDLE, gi=0, pi=0, ei=0, null]
2012-03-20 09:52:05.170 DEBUG [pool-21-thread-2] #MSCTRL#: Player[ACTIVE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]] moves state from [IDLE] to [ACTIVE]
2012-03-20 09:52:05.170 DEBUG [pool-21-thread-2] #MSCTRL#: PlayListItem[0, 0, 0] moves state from [IDLE] to [PLAYING]
2012-03-20 09:52:05.171 DEBUG [pool-21-thread-2] #MSCTRL#: MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] added MrcpSpeakListener[Player[ACTIVE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]], ACTIVE] #[797263084-a787590-01b1f470-00000002]
2012-03-20 09:52:05.172 DEBUG [pool-21-thread-2] #MRCP#: (o)ANNOUNCE rtsp://192.168.1.73:10074/synthesizer/ RTSP/1.0\r\nCseq: 3\r\nSession: 797263084-a787590-01b1f470-00000002\r\nContent-Type: application/mrcp\r\nContent-Length: 251\r\n\r\nSPEAK 37000 MRCP/1.0\r\nKill-On-Barge-In: false\r\nSpeech-Language: en-us\r\nVendor-Specific-Parameters: Voxeo-Playback-Mode=JSR309;Voxeo-Speed-Out=100;Voxeo-Gain-Out=0\r\nContent-Type: application/synthesis+ssml\r\nContent-Length: 23\r\n\r\n<speak>digits/3</speak> #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:05.174 DEBUG [mrcp/2-t-15] #MRCP#: (i)RTSP/1.0 200 OK\r\nSession: 797263084-a787590-01b1f470-00000002\r\nCseq: 3\r\nContent-Type: application/mrcp\r\nContent-Length: 34\r\n\r\nMRCP/1.0 37000 200 IN-PROGRESS\r\n\r\n #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:05.175 DEBUG [pool-21-thread-2] #MSCTRL#: PlayListItem[0, 0, 0] added (37000, 797263084-a787590-01b1f470-00000002)
2012-03-20 09:52:05.175 INFO [pool-21-thread-2] Reply [com.rayo.core.verb.VerbRef@1fff962]
2012-03-20 09:52:05.176 DEBUG [pool-21-thread-2] #XMPP#: (o)<iq from="[email protected]" id="blather000c" to="[email protected]/blmbp.home-28910" type="result"><ref id="eb5f6969-d096-4e40-97be-4fbece5c1c43" xmlns="urn:xmpp:rayo:1"/></iq> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:05.176 DEBUG [pool-21-thread-2] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:05.658 DEBUG [Timer-15] #SIP#: InviteServerTransaction[, , _state=ACCEPTED, _id=z9hG4bKPjEo3epd5w.R0rkPDgJJT2579z7lsQqeIJ, ] timerRemoveTransaction is fired. #[rayo][sas_2-14-sm5mhpdz1ouph4rayo][-dv.4n1E0.TiySTTyyv-bY2C.yxUhwF-][ss_1wzw1mez634cw][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:05.658 DEBUG [Timer-15] #SIP#: InviteServerTransaction[, , _state=TERMINATED, _id=z9hG4bKPjEo3epd5w.R0rkPDgJJT2579z7lsQqeIJ, ] is released. #[rayo][sas_2-14-sm5mhpdz1ouph4rayo][-dv.4n1E0.TiySTTyyv-bY2C.yxUhwF-][ss_1wzw1mez634cw][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:06.589 DEBUG [mrcp/2-t-16] #MRCP#: (i)ANNOUNCE rtsp://192.168.1.73:10074/synthesizer/ RTSP/1.0\r\nCseq: 1\r\nSession: 797263084-a787590-01b1f470-00000002\r\nContent-Type: application/mrcp\r\nContent-Length: 72\r\n\r\nSPEAK-COMPLETE 37000 COMPLETE MRCP/1.0\r\ncompletion-cause: 000 normal\r\n\r\n #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:06.589 DEBUG [mrcp/2-t-16] #MRCP#: (o)RTSP/1.0 200 OK\r\nSession: 797263084-a787590-01b1f470-00000002\r\nCseq: 1\r\n\r\n #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:06.590 DEBUG [mrcp/2-t-17] #MRCP#: Handling SPEAK-COMPLETE[37000] #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:06.591 DEBUG [mrcp/2-t-17] #MSCTRL#: Find PlayListItem[PLAYING, gi=0, pi=0, ei=0, null, speakIds=[37000]]
2012-03-20 09:52:06.592 DEBUG [mrcp/2-t-17] #MSCTRL#: MrcpSpeakListener[Player[ACTIVE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]], ACTIVE] handling with MrcpSpeakCompleteEvent[originalId:37000, requestId:37000, rc:0, duration:1421] #[797263084-a787590-01b1f470-00000002]
2012-03-20 09:52:06.592 DEBUG [mrcp/2-t-17] #MSCTRL#: PlayListItem[0, 0, 0] removed (37000, 797263084-a787590-01b1f470-00000002)
2012-03-20 09:52:06.592 DEBUG [mrcp/2-t-17] #MSCTRL#: PlayListItem[0, 0, 0] moves state from [PLAYING] to [IDLE]
2012-03-20 09:52:06.592 DEBUG [mrcp/2-t-17] #MSCTRL#: Find [PlayListItem[IDLE, gi=0, pi=0, ei=0, null]]
2012-03-20 09:52:06.593 DEBUG [mrcp/2-t-17] #MSCTRL#: Player[IDLE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]] moves state from [ACTIVE] to [IDLE]
2012-03-20 09:52:06.593 DEBUG [mrcp/2-t-17] #MSCTRL#: clear up playList=[PlayListItem[IDLE, gi=0, pi=0, ei=0, null]]
2012-03-20 09:52:06.594 DEBUG [msctrl/2-t-14] #MSCTRL#: Return PlayerEvent[Player[IDLE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]], PLAY_COMPLETED, NO_ERROR, null, END_OF_PLAY_LIST, null, null, 0, 1421] to the application
2012-03-20 09:52:06.595 DEBUG [MOHO-24] Dispatching Event to listener:[Event class=com.voxeo.moho.common.event.MohoOutputCompleteEvent sourceClass=SIPIncomingCall id=1057446]
2012-03-20 09:52:06.595 DEBUG [pool-21-thread-2] [IncomingCallActor[callId=4vg6dkqc-lx7-fxod8zouyy3mb]] : Request [[Event class=com.voxeo.moho.common.event.MohoOutputCompleteEvent sourceClass=SIPIncomingCall id=1057446]]
2012-03-20 09:52:06.596 INFO [pool-21-thread-2] Queued Event [OutputCompleteEvent[callId=4vg6dkqc-lx7-fxod8zouyy3mb,verbId=eb5f6969-d096-4e40-97be-4fbece5c1c43,reason=SUCCESS,errorText=<null>]]
2012-03-20 09:52:06.596 INFO [pool-21-thread-2] Reply [null]
2012-03-20 09:52:06.596 INFO [pool-21-thread-2] Event [OutputCompleteEvent[callId=4vg6dkqc-lx7-fxod8zouyy3mb,verbId=eb5f6969-d096-4e40-97be-4fbece5c1c43,reason=SUCCESS,errorText=<null>]]
2012-03-20 09:52:06.599 DEBUG [pool-21-thread-2] #XMPP#: (o)<presence from="[email protected]/eb5f6969-d096-4e40-97be-4fbece5c1c43" id="579ced25-c02c-4e2a-8dae-8ea3b9f13b86" to="[email protected]"><complete xmlns="urn:xmpp:rayo:ext:1"><success xmlns="urn:xmpp:rayo:output:complete:1"/></complete></presence> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:06.599 DEBUG [pool-21-thread-2] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:06.692 DEBUG [SocketAcceptorIoProcessor-0.1] #XMPP#: (i)<iq id="blather000e" to="[email protected]" type="set"><output xmlns="urn:xmpp:rayo:output:1"><speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US"><audio src="http://static1.grsites.com/archive/sounds/aircraft/aircraft001.mp3"/></speak></output></iq> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:06.693 DEBUG [XMPPService-t-34] #XMPP#: Invoke application:rayo rayo
2012-03-20 09:52:06.693 DEBUG [XMPPService-t-34] #XMPP#: Forwarding Request #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][null]
2012-03-20 09:52:06.694 DEBUG [XMPPService-t-34] <iq from="[email protected]/blmbp.home-28910" id="blather000e" to="[email protected]" type="set"><output xmlns="urn:xmpp:rayo:output:1"><speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US"><audio src="http://static1.grsites.com/archive/sounds/aircraft/aircraft001.mp3"/></speak></output></iq> :: xmpps_l0328mignyvl
2012-03-20 09:52:06.695 DEBUG [XMPPService-t-34] Looking up call [4vg6dkqc-lx7-fxod8zouyy3mb] in registry: [com.rayo.server.DefaultCallRegistry@491a97]
2012-03-20 09:52:06.696 DEBUG [pool-21-thread-2] [IncomingCallActor[callId=4vg6dkqc-lx7-fxod8zouyy3mb]] : Request [Output[callId=4vg6dkqc-lx7-fxod8zouyy3mb,verbId=e504c5e2-b230-4f9e-aad2-bbd87f361d7d,interrupt-on=<null>,start-offset=<null>,start-paused=<null>,repeatInterval=<null>,repeatTimes=<null>,maxTime=<null>,voice=<null>,prompt=Ssml[ssml=<speak version="1.0" xmlns:xml="" xml:xml:lang="en-US"><audio src="http://static1.grsites.com/archive/sounds/aircraft/aircraft001.mp3"/></speak>,voice=<null>,uri=data:application%2Fssml%2Bxml%2C%3Cspeak+version%3D%221.0%22+xmlns%3Axml%3D%22%22+xml%3Axml%3Alang%3D%22en-US%22%3E%3Caudio+src%3D%22http%3A%2F%2Fstatic1.grsites.com%2Farchive%2Fsounds%2Faircraft%2Faircraft001.mp3%22%2F%3E%3C%2Fspeak%3E]]]
2012-03-20 09:52:06.696 DEBUG [pool-21-thread-2] Creating instance of bean 'outputHandler'
2012-03-20 09:52:06.696 DEBUG [pool-21-thread-2] Returning cached instance of singleton bean 'ssmlValidator'
2012-03-20 09:52:06.697 DEBUG [pool-21-thread-2] Finished creating instance of bean 'outputHandler'
2012-03-20 09:52:06.698 DEBUG [pool-21-thread-2] #MSCTRL#: Add PlayListItem[gi:0, pi:1, ei:0, null, rtcs=null, optargs={PLAYER_MAX_DURATION=-1, PLAYER_START_OFFSET=0, JUMP_PLAYLIST_INCREMENT=1, PLAYER_ENABLED_EVENTS=[Ljavax.media.mscontrol.EventType;@e134e6, BARGE_IN_ENABLED=false, PLAYER_AUDIO_CODEC=CODEC_INFERRED, VOLUME_CHANGE=3, PLAYER_JUMP_TIME=5000, VOICE_NAME=null, BEHAVIOUR_IF_BUSY=STOP_IF_BUSY, PLAYER_START_PAUSED=false, PLAYER_FILE_FORMAT=FORMAT_INFERRED, TTS_SPEECH_LANGUAGE=null},"<speak version="1.0" xmlns:xml="" xml:xml:lang="en-US"><audio src="http://static1.grsites.com/archive/sounds/aircraft/aircraft001.mp3"/></speak>"]
2012-03-20 09:52:06.698 DEBUG [pool-21-thread-2] #MSCTRL#: Find PlayListItem[IDLE, gi=0, pi=1, ei=0, null]
2012-03-20 09:52:06.698 DEBUG [pool-21-thread-2] #MSCTRL#: Player[IDLE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]] starts playing PlayListItem[IDLE, gi=0, pi=1, ei=0, null]
2012-03-20 09:52:06.698 DEBUG [pool-21-thread-2] #MSCTRL#: Player[ACTIVE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]] moves state from [IDLE] to [ACTIVE]
2012-03-20 09:52:06.698 DEBUG [pool-21-thread-2] #MSCTRL#: PlayListItem[0, 0, 1] moves state from [IDLE] to [PLAYING]
2012-03-20 09:52:06.699 DEBUG [pool-21-thread-2] #MRCP#: (o)ANNOUNCE rtsp://192.168.1.73:10074/synthesizer/ RTSP/1.0\r\nCseq: 4\r\nSession: 797263084-a787590-01b1f470-00000002\r\nContent-Type: application/mrcp\r\nContent-Length: 373\r\n\r\nSPEAK 37001 MRCP/1.0\r\nKill-On-Barge-In: false\r\nSpeech-Language: en-us\r\nVendor-Specific-Parameters: Voxeo-Playback-Mode=JSR309;Voxeo-Speed-Out=100;Voxeo-Gain-Out=0\r\nContent-Type: application/synthesis+ssml\r\nContent-Length: 144\r\n\r\n<speak version="1.0" xmlns:xml="" xml:xml:lang="en-US"><audio src="http://static1.grsites.com/archive/sounds/aircraft/aircraft001.mp3"/></speak> #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:06.701 DEBUG [mrcp/2-t-18] #MRCP#: (i)RTSP/1.0 200 OK\r\nSession: 797263084-a787590-01b1f470-00000002\r\nCseq: 4\r\nContent-Type: application/mrcp\r\nContent-Length: 34\r\n\r\nMRCP/1.0 37001 200 IN-PROGRESS\r\n\r\n #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:06.702 DEBUG [pool-21-thread-2] #MSCTRL#: PlayListItem[0, 0, 1] added (37001, 797263084-a787590-01b1f470-00000002)
2012-03-20 09:52:06.702 INFO [pool-21-thread-2] Reply [com.rayo.core.verb.VerbRef@89178b]
2012-03-20 09:52:06.703 DEBUG [pool-21-thread-2] #XMPP#: (o)<iq from="[email protected]" id="blather000e" to="[email protected]/blmbp.home-28910" type="result"><ref id="92f9a63d-6783-40b8-b076-0a9d44871f91" xmlns="urn:xmpp:rayo:1"/></iq> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:06.703 DEBUG [pool-21-thread-2] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:09.850 DEBUG [Timer-12] #SIP#: NonInviteServerTransaction[, , _state=COMPLETED, _id=z9hG4bKPjx2u1RiCyEK7uQrmRKDBb7.zOmXeO0bMD, ] timerRemoveTransaction is fired. #[rayo][sas_2-14-smpyhzn6od27p5rayo][pYlJZAj4MIMZu1XYAFr9HhXvrzeEzlYv][ss_19egmrp6jom40][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:09.851 DEBUG [Timer-12] #SIP#: NonInviteServerTransaction[, , _state=TERMINATED, _id=z9hG4bKPjx2u1RiCyEK7uQrmRKDBb7.zOmXeO0bMD, ] is released. #[rayo][sas_2-14-smpyhzn6od27p5rayo][pYlJZAj4MIMZu1XYAFr9HhXvrzeEzlYv][ss_19egmrp6jom40][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:09.854 DEBUG [Timer-13] #SIP#: SipSessionImpl[_id=ss_19egmrp6jom40, _parentId=sas_2-14-smpyhzn6od27p5rayo, _handler=Controller, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=REGISTER, _callId=pYlJZAj4MIMZu1XYAFr9HhXvrzeEzlYv, ] is invalidating. (s) #[rayo][sas_2-14-smpyhzn6od27p5rayo][pYlJZAj4MIMZu1XYAFr9HhXvrzeEzlYv][ss_19egmrp6jom40][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:09.855 DEBUG [Timer-13] #SIP#: Remove Path[ id=pYlJZAj4MIMZu1XYAFr9HhXvrzeEzlYv-nesE.K.G.uYf94A3BNn.Q3q2Ld-ljpYZ-1lggtz9ydxcxk, session=SipSessionImpl[_id=ss_19egmrp6jom40, _parentId=sas_2-14-smpyhzn6od27p5rayo, _handler=Controller, _state=INITIAL, _fresh=false, _valid=true, _unavailable=true, _role=UAS, _method=REGISTER, _callId=pYlJZAj4MIMZu1XYAFr9HhXvrzeEzlYv, ]] #[rayo][sas_2-14-smpyhzn6od27p5rayo][pYlJZAj4MIMZu1XYAFr9HhXvrzeEzlYv][ss_19egmrp6jom40][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:09.855 DEBUG [Timer-13] #SIP#: processInvalidationWhenReady [sas_2-14-smpyhzn6od27p5rayo], invalidateWhenReady: true
2012-03-20 09:52:09.855 DEBUG [Timer-13] #SIP#: Container will automatically invalidate SipApplicationSession [sas_2-14-smpyhzn6od27p5rayo]
2012-03-20 09:52:09.856 DEBUG [Timer-13] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-14-smpyhzn6od27p5rayo, ] is invalidating. (as)
2012-03-20 09:52:11.407 DEBUG [mrcp/2-t-19] #MRCP#: (i)ANNOUNCE rtsp://192.168.1.73:10074/synthesizer/ RTSP/1.0\r\nCseq: 2\r\nSession: 797263084-a787590-01b1f470-00000002\r\nContent-Type: application/mrcp\r\nContent-Length: 72\r\n\r\nSPEAK-COMPLETE 37001 COMPLETE MRCP/1.0\r\ncompletion-cause: 000 normal\r\n\r\n #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:11.407 DEBUG [mrcp/2-t-19] #MRCP#: (o)RTSP/1.0 200 OK\r\nSession: 797263084-a787590-01b1f470-00000002\r\nCseq: 2\r\n\r\n #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:11.409 DEBUG [mrcp/2-t-20] #MRCP#: Handling SPEAK-COMPLETE[37001] #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:11.409 DEBUG [mrcp/2-t-20] #MSCTRL#: Find PlayListItem[PLAYING, gi=0, pi=1, ei=0, null, speakIds=[37001]]
2012-03-20 09:52:11.410 DEBUG [mrcp/2-t-20] #MSCTRL#: MrcpSpeakListener[Player[ACTIVE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]], ACTIVE] handling with MrcpSpeakCompleteEvent[originalId:37001, requestId:37001, rc:0, duration:4711] #[797263084-a787590-01b1f470-00000002]
2012-03-20 09:52:11.410 DEBUG [mrcp/2-t-20] #MSCTRL#: PlayListItem[0, 0, 1] removed (37001, 797263084-a787590-01b1f470-00000002)
2012-03-20 09:52:11.410 DEBUG [mrcp/2-t-20] #MSCTRL#: PlayListItem[0, 0, 1] moves state from [PLAYING] to [IDLE]
2012-03-20 09:52:11.410 DEBUG [mrcp/2-t-20] #MSCTRL#: Find [PlayListItem[IDLE, gi=0, pi=1, ei=0, null]]
2012-03-20 09:52:11.410 DEBUG [mrcp/2-t-20] #MSCTRL#: Player[IDLE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]] moves state from [ACTIVE] to [IDLE]
2012-03-20 09:52:11.410 DEBUG [mrcp/2-t-20] #MSCTRL#: clear up playList=[PlayListItem[IDLE, gi=0, pi=1, ei=0, null]]
2012-03-20 09:52:11.411 DEBUG [msctrl/2-t-15] #MSCTRL#: Return PlayerEvent[Player[IDLE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]], PLAY_COMPLETED, NO_ERROR, null, END_OF_PLAY_LIST, null, null, 0, 4711] to the application
2012-03-20 09:52:11.412 DEBUG [MOHO-26] Dispatching Event to listener:[Event class=com.voxeo.moho.common.event.MohoOutputCompleteEvent sourceClass=SIPIncomingCall id=28009984]
2012-03-20 09:52:11.412 DEBUG [pool-21-thread-2] [IncomingCallActor[callId=4vg6dkqc-lx7-fxod8zouyy3mb]] : Request [[Event class=com.voxeo.moho.common.event.MohoOutputCompleteEvent sourceClass=SIPIncomingCall id=28009984]]
2012-03-20 09:52:11.413 INFO [pool-21-thread-2] Queued Event [OutputCompleteEvent[callId=4vg6dkqc-lx7-fxod8zouyy3mb,verbId=92f9a63d-6783-40b8-b076-0a9d44871f91,reason=SUCCESS,errorText=<null>]]
2012-03-20 09:52:11.413 INFO [pool-21-thread-2] Reply [null]
2012-03-20 09:52:11.413 INFO [pool-21-thread-2] Event [OutputCompleteEvent[callId=4vg6dkqc-lx7-fxod8zouyy3mb,verbId=92f9a63d-6783-40b8-b076-0a9d44871f91,reason=SUCCESS,errorText=<null>]]
2012-03-20 09:52:11.415 DEBUG [pool-21-thread-2] #XMPP#: (o)<presence from="[email protected]/92f9a63d-6783-40b8-b076-0a9d44871f91" id="05a322d7-a2ce-4c72-8d76-ed8dad54680f" to="[email protected]"><complete xmlns="urn:xmpp:rayo:ext:1"><success xmlns="urn:xmpp:rayo:output:complete:1"/></complete></presence> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:11.416 DEBUG [pool-21-thread-2] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:11.509 DEBUG [SocketAcceptorIoProcessor-0.1] #XMPP#: (i)<iq id="blather0010" to="[email protected]" type="set"><output xmlns="urn:xmpp:rayo:output:1"><speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US"><audio src="digits/3"/></speak></output></iq> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:11.510 DEBUG [XMPPService-t-35] #XMPP#: Invoke application:rayo rayo
2012-03-20 09:52:11.510 DEBUG [XMPPService-t-35] #XMPP#: Forwarding Request #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][null]
2012-03-20 09:52:11.510 DEBUG [XMPPService-t-35] <iq from="[email protected]/blmbp.home-28910" id="blather0010" to="[email protected]" type="set"><output xmlns="urn:xmpp:rayo:output:1"><speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US"><audio src="digits/3"/></speak></output></iq> :: xmpps_l0328mignyvl
2012-03-20 09:52:11.511 DEBUG [XMPPService-t-35] Looking up call [4vg6dkqc-lx7-fxod8zouyy3mb] in registry: [com.rayo.server.DefaultCallRegistry@491a97]
2012-03-20 09:52:11.512 DEBUG [pool-21-thread-2] [IncomingCallActor[callId=4vg6dkqc-lx7-fxod8zouyy3mb]] : Request [Output[callId=4vg6dkqc-lx7-fxod8zouyy3mb,verbId=8069306f-7b3a-401d-803e-4020adf1862e,interrupt-on=<null>,start-offset=<null>,start-paused=<null>,repeatInterval=<null>,repeatTimes=<null>,maxTime=<null>,voice=<null>,prompt=Ssml[ssml=<speak version="1.0" xmlns:xml="" xml:xml:lang="en-US"><audio src="digits/3"/></speak>,voice=<null>,uri=data:application%2Fssml%2Bxml%2C%3Cspeak+version%3D%221.0%22+xmlns%3Axml%3D%22%22+xml%3Axml%3Alang%3D%22en-US%22%3E%3Caudio+src%3D%22digits%2F3%22%2F%3E%3C%2Fspeak%3E]]]
2012-03-20 09:52:11.512 DEBUG [pool-21-thread-2] Creating instance of bean 'outputHandler'
2012-03-20 09:52:11.513 DEBUG [pool-21-thread-2] Returning cached instance of singleton bean 'ssmlValidator'
2012-03-20 09:52:11.513 DEBUG [pool-21-thread-2] Finished creating instance of bean 'outputHandler'
2012-03-20 09:52:11.514 DEBUG [pool-21-thread-2] #MSCTRL#: Add PlayListItem[gi:0, pi:2, ei:0, null, rtcs=null, optargs={PLAYER_MAX_DURATION=-1, PLAYER_START_OFFSET=0, JUMP_PLAYLIST_INCREMENT=1, PLAYER_ENABLED_EVENTS=[Ljavax.media.mscontrol.EventType;@14ab6b5, BARGE_IN_ENABLED=false, PLAYER_AUDIO_CODEC=CODEC_INFERRED, VOLUME_CHANGE=3, PLAYER_JUMP_TIME=5000, VOICE_NAME=null, BEHAVIOUR_IF_BUSY=STOP_IF_BUSY, PLAYER_START_PAUSED=false, PLAYER_FILE_FORMAT=FORMAT_INFERRED, TTS_SPEECH_LANGUAGE=null},"<speak version="1.0" xmlns:xml="" xml:xml:lang="en-US"><audio src="digits/3"/></speak>"]
2012-03-20 09:52:11.514 DEBUG [pool-21-thread-2] #MSCTRL#: Find PlayListItem[IDLE, gi=0, pi=2, ei=0, null]
2012-03-20 09:52:11.514 DEBUG [pool-21-thread-2] #MSCTRL#: Player[IDLE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]] starts playing PlayListItem[IDLE, gi=0, pi=2, ei=0, null]
2012-03-20 09:52:11.515 DEBUG [pool-21-thread-2] #MSCTRL#: Player[ACTIVE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]] moves state from [IDLE] to [ACTIVE]
2012-03-20 09:52:11.515 DEBUG [pool-21-thread-2] #MSCTRL#: PlayListItem[0, 0, 2] moves state from [IDLE] to [PLAYING]
2012-03-20 09:52:11.516 DEBUG [pool-21-thread-2] #MRCP#: (o)ANNOUNCE rtsp://192.168.1.73:10074/synthesizer/ RTSP/1.0\r\nCseq: 5\r\nSession: 797263084-a787590-01b1f470-00000002\r\nContent-Type: application/mrcp\r\nContent-Length: 314\r\n\r\nSPEAK 37002 MRCP/1.0\r\nKill-On-Barge-In: false\r\nSpeech-Language: en-us\r\nVendor-Specific-Parameters: Voxeo-Playback-Mode=JSR309;Voxeo-Speed-Out=100;Voxeo-Gain-Out=0\r\nContent-Type: application/synthesis+ssml\r\nContent-Length: 86\r\n\r\n<speak version="1.0" xmlns:xml="" xml:xml:lang="en-US"><audio src="digits/3"/></speak> #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:11.517 DEBUG [mrcp/2-t-21] #MRCP#: (i)RTSP/1.0 200 OK\r\nSession: 797263084-a787590-01b1f470-00000002\r\nCseq: 5\r\nContent-Type: application/mrcp\r\nContent-Length: 34\r\n\r\nMRCP/1.0 37002 200 IN-PROGRESS\r\n\r\n #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:11.518 DEBUG [pool-21-thread-2] #MSCTRL#: PlayListItem[0, 0, 2] added (37002, 797263084-a787590-01b1f470-00000002)
2012-03-20 09:52:11.518 DEBUG [mrcp/2-t-21] #MRCP#: (i)ANNOUNCE rtsp://192.168.1.73:10074/synthesizer/ RTSP/1.0\r\nCseq: 3\r\nSession: 797263084-a787590-01b1f470-00000002\r\nContent-Type: application/mrcp\r\nContent-Length: 77\r\n\r\nSPEAK-COMPLETE 37002 COMPLETE MRCP/1.0\r\ncompletion-cause: 003 uri-failure\r\n\r\n #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:11.518 INFO [pool-21-thread-2] Reply [com.rayo.core.verb.VerbRef@1cb9b56]
2012-03-20 09:52:11.519 DEBUG [mrcp/2-t-21] #MRCP#: (o)RTSP/1.0 200 OK\r\nSession: 797263084-a787590-01b1f470-00000002\r\nCseq: 3\r\n\r\n #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:11.519 DEBUG [pool-21-thread-2] #XMPP#: (o)<iq from="[email protected]" id="blather0010" to="[email protected]/blmbp.home-28910" type="result"><ref id="f8440d4f-464b-43d9-b48c-3ec686268457" xmlns="urn:xmpp:rayo:1"/></iq> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:11.519 DEBUG [pool-21-thread-2] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:11.520 DEBUG [mrcp/2-t-22] #MRCP#: Handling SPEAK-COMPLETE[37002] #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:11.521 DEBUG [mrcp/2-t-22] #MSCTRL#: Find PlayListItem[PLAYING, gi=0, pi=2, ei=0, null, speakIds=[37002]]
2012-03-20 09:52:11.521 DEBUG [mrcp/2-t-22] #MSCTRL#: MrcpSpeakListener[Player[ACTIVE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]], ACTIVE] handling with MrcpSpeakCompleteEvent[originalId:37002, requestId:37002, rc:3, duration:6] #[797263084-a787590-01b1f470-00000002]
2012-03-20 09:52:11.521 DEBUG [mrcp/2-t-22] #MSCTRL#: PlayListItem[0, 0, 2] removed (37002, 797263084-a787590-01b1f470-00000002)
2012-03-20 09:52:11.521 DEBUG [mrcp/2-t-22] #MSCTRL#: PlayListItem[0, 0, 2] moves state from [PLAYING] to [IDLE]
2012-03-20 09:52:11.522 ERROR [mrcp/2-t-22] #MSCTRL#: SPEAK[37002] is complete with uri-failure@T: javax.media.mscontrol.MsControlException: SPEAK[37002] is complete with uri-failure\n at com.voxeo.mscontrol.mediagroup.AsyncMrcpPlayer$MrcpSpeakListener.handleEvent(AsyncMrcpPlayer.java:1320)\n at com.voxeo.sipmethod.mrcp.client.impl.MrcpSessionImpl.postMrcpEvent(MrcpSessionImpl.java:261)\n at com.voxeo.sipmethod.mrcp.client.impl.MrcpTtsSessionImpl.handleEvent(MrcpTtsSessionImpl.java:537)\n at com.mot.mrcp.ec.motomrcpv1.MotV1MRCPConnection.postMrcpEvent(MotV1MRCPConnection.java:177)\n at com.mot.mrcp.ec.motomrcpv1.MotV1MRCPTTSConnection.handleSpeakComplete(MotV1MRCPTTSConnection.java:121)\n at com.voxeo.motorola.mrcp.VMotV1MRCPTTSConnection.handleSpeakComplete(VMotV1MRCPTTSConnection.java:54)\n at com.mot.mrcp.ec.motomrcpv1.MotV1MRCPTTSConnection.handleEventMessage(MotV1MRCPTTSConnection.java:61)\n at com.mot.mrcp.ec.motomrcpv1.MotV1MRCPConnection$QueueDispatcher.run(MotV1MRCPConnection.java:92)\n at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)\n at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)\n at java.lang.Thread.run(Thread.java:680)\n
2012-03-20 09:52:11.522 DEBUG [mrcp/2-t-22] #MSCTRL#: Player[IDLE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]] moves state from [ACTIVE] to [IDLE]
2012-03-20 09:52:11.522 DEBUG [mrcp/2-t-22] #MSCTRL#: clear up playList=[PlayListItem[IDLE, gi=0, pi=2, ei=0, null]]
2012-03-20 09:52:11.523 DEBUG [msctrl/2-t-16] #MSCTRL#: Return PlayerEvent[Player[IDLE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]], PLAY_COMPLETED, NOT_FOUND, SPEAK[37002] is complete with uri-failure, NO_QUALIFIER, null, null, 0, -1] to the application
2012-03-20 09:52:11.524 DEBUG [MOHO-28] Dispatching Event to listener:[Event class=com.voxeo.moho.common.event.MohoOutputCompleteEvent sourceClass=SIPIncomingCall id=6992979]
2012-03-20 09:52:11.524 DEBUG [pool-21-thread-2] [IncomingCallActor[callId=4vg6dkqc-lx7-fxod8zouyy3mb]] : Request [[Event class=com.voxeo.moho.common.event.MohoOutputCompleteEvent sourceClass=SIPIncomingCall id=6992979]]
2012-03-20 09:52:11.526 INFO [pool-21-thread-2] Queued Event [OutputCompleteEvent[callId=4vg6dkqc-lx7-fxod8zouyy3mb,verbId=f8440d4f-464b-43d9-b48c-3ec686268457,reason=ERROR,errorText=Invalid SSML: The prefix "xml" cannot be bound to any namespace other than its usual namespace; neither can the namespace for "xml" be bound to any prefix other than "xml".]]
2012-03-20 09:52:11.526 INFO [pool-21-thread-2] Reply [null]
2012-03-20 09:52:11.526 INFO [pool-21-thread-2] Event [OutputCompleteEvent[callId=4vg6dkqc-lx7-fxod8zouyy3mb,verbId=f8440d4f-464b-43d9-b48c-3ec686268457,reason=ERROR,errorText=Invalid SSML: The prefix "xml" cannot be bound to any namespace other than its usual namespace; neither can the namespace for "xml" be bound to any prefix other than "xml".]]
2012-03-20 09:52:11.529 DEBUG [pool-21-thread-2] #XMPP#: (o)<presence from="[email protected]/f8440d4f-464b-43d9-b48c-3ec686268457" id="53797fbe-284b-4138-8f41-7886a7f64b0d" to="[email protected]"><complete xmlns="urn:xmpp:rayo:ext:1"><error xmlns="urn:xmpp:rayo:ext:complete:1">Invalid SSML: The prefix "xml" cannot be bound to any namespace other than its usual namespace; neither can the namespace for "xml" be bound to any prefix other than "xml".</error></complete></presence> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:11.529 DEBUG [pool-21-thread-2] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:11.622 DEBUG [SocketAcceptorIoProcessor-0.1] #XMPP#: (i)<iq id="blather0012" to="[email protected]" type="set"><hangup xmlns="urn:xmpp:rayo:1"/></iq> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:11.623 DEBUG [XMPPService-t-36] #XMPP#: Invoke application:rayo rayo
2012-03-20 09:52:11.624 DEBUG [XMPPService-t-36] #XMPP#: Forwarding Request #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][null]
2012-03-20 09:52:11.624 DEBUG [XMPPService-t-36] <iq from="[email protected]/blmbp.home-28910" id="blather0012" to="[email protected]" type="set"><hangup xmlns="urn:xmpp:rayo:1"/></iq> :: xmpps_l0328mignyvl
2012-03-20 09:52:11.624 DEBUG [XMPPService-t-36] Looking up call [4vg6dkqc-lx7-fxod8zouyy3mb] in registry: [com.rayo.server.DefaultCallRegistry@491a97]
2012-03-20 09:52:11.625 DEBUG [pool-21-thread-2] [IncomingCallActor[callId=4vg6dkqc-lx7-fxod8zouyy3mb]] : Request [HangupCommand[callId=4vg6dkqc-lx7-fxod8zouyy3mb,headers={}]]
2012-03-20 09:52:11.625 DEBUG [pool-21-thread-2] destroyNetworkConnection
2012-03-20 09:52:11.625 DEBUG [pool-21-thread-2] #MSCTRL#: NC[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] moves state from [INITIALIZED] to [RELEASED]
2012-03-20 09:52:11.626 INFO [pool-21-thread-2] #MSCTRL#: MS[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] removes a MediaObject[mscontrol://192.168.1.73:10074/MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u/NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]
2012-03-20 09:52:11.626 DEBUG [pool-21-thread-2] #MSCTRL#: MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] removes JoinCompleteDector[MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u], NC[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]] #[797263084-a787590-01b1f470-00000002]
2012-03-20 09:52:11.626 DEBUG [pool-21-thread-2] #MSCTRL#: MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] removes JoineeMrcpContext[mscontrol://192.168.1.73:10074/MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u/NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, 797263084-a787590-01b1f470-00000002, 797263084-a787590-01b1f470-00000002] #[797263084-a787590-01b1f470-00000002]
2012-03-20 09:52:11.626 DEBUG [pool-21-thread-2] #MSCTRL#: MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] removed MrcpSpeakListener[Player[IDLE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]], ACTIVE] #[797263084-a787590-01b1f470-00000002]
2012-03-20 09:52:11.626 DEBUG [pool-21-thread-2] #MSCTRL#: Remove MrcpSpeakListener[Player[IDLE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]], ACTIVE] #[797263084-a787590-01b1f470-00000002]
2012-03-20 09:52:11.626 DEBUG [pool-21-thread-2] #MSCTRL#: MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] removes(NC[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, NC-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u], JoineeContext[RESOURCE_CONTAINER, DUPLEX, null])
2012-03-20 09:52:11.627 DEBUG [pool-21-thread-2] #MRCP#: (o)TEARDOWN rtsp://192.168.1.73:10074/recognizer/ RTSP/1.0\r\nCseq: 6\r\nSession: 797263084-a787590-01b1f470-00000002\r\n\r\n #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:11.630 DEBUG [mrcp/2-t-23] #MRCP#: (i)RTSP/1.0 200 OK\r\nSession: 797263084-a787590-01b1f470-00000002\r\nCseq: 6\r\n\r\n #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:11.631 DEBUG [pool-21-thread-2] #MRCP#: (o)TEARDOWN rtsp://192.168.1.73:10074/synthesizer/ RTSP/1.0\r\nCseq: 7\r\nSession: 797263084-a787590-01b1f470-00000002\r\n\r\n #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:11.640 DEBUG [mrcp/2-t-24] #MRCP#: (i)RTSP/1.0 200 OK\r\nSession: 797263084-a787590-01b1f470-00000002\r\nCseq: 7\r\n\r\n #[797263084-a787590-01b1f470-00000002][192.168.1.73:10074][192.168.1.73:59747]
2012-03-20 09:52:11.641 DEBUG [pool-21-thread-2] #MSCTRL#: MS[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] moves state from [INITIALIZED] to [RELEASED]
2012-03-20 09:52:11.641 DEBUG [pool-21-thread-2] #MSCTRL#: MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u] moves state from [INITIALIZED] to [RELEASED]
2012-03-20 09:52:11.641 DEBUG [pool-21-thread-2] #MSCTRL#: Stopping Player[IDLE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]], isStopAll:true
2012-03-20 09:52:11.641 DEBUG [pool-21-thread-2] #MSCTRL#: Stopping SigDet[IDLE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]]
2012-03-20 09:52:11.642 DEBUG [pool-21-thread-2] #MSCTRL#: Stopping Recorder[IDLE, MG[MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, MG-T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u]]
2012-03-20 09:52:11.642 DEBUG [pool-21-thread-2] #SIP#: SessionManagementLayer send request: BYE sip:[email protected]:59615 #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected]][sip:[email protected]]
2012-03-20 09:52:11.642 DEBUG [MOHO-29] Dispatching Event to listener:[Event class=com.voxeo.moho.common.event.MohoCallCompleteEvent sourceClass=SIPIncomingCall id=9690828]
2012-03-20 09:52:11.643 DEBUG [pool-21-thread-2] #SIP#: The transaction was created: z9hG4bKycje8bq2eyat #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected]][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:11.643 DEBUG [pool-21-thread-2] #SIP#: (o)[BYE sip:[email protected]:59615 SIP/2.0\r\nTo: "Ben Langfeld" <sip:[email protected]>;tag=c9hgQjuQkAKpYJSoYBa1ZJFVuQq.M-iL\r\nVia: SIP/2.0/UDP 192.168.1.73:5060;branch=z9hG4bKycje8bq2eyat;rport;x-sm-sid=27c0bbf0-53f7-44e4-8635-7062778d5903;x-sm-nid=ss_1hrqgtdr2wdid\r\nCSeq: 1 BYE\r\nContent-Length: 0\r\nCall-ID: T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u\r\nMax-Forwards: 70\r\nFrom: <sip:[email protected]>;tag=dhgn9s9mk146\r\n\r\n] #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected]][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:11.643 DEBUG [pool-21-thread-2] #SIP#: Send message to: /127.0.0.1:59615 by udp #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected]][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:11.644 DEBUG [pool-21-thread-2] #SIP#: Connected to 127.0.0.1:59615/udp #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:11.644 INFO [pool-21-thread-2] Reply [null]
2012-03-20 09:52:11.644 DEBUG [pool-21-thread-2] #XMPP#: (o)<iq from="[email protected]" id="blather0012" to="[email protected]/blmbp.home-28910" type="result"/> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:11.645 DEBUG [pool-21-thread-2] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:11.645 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: (i)[SIP/2.0 200 OK\r\nTo: "Ben Langfeld" <sip:[email protected]>;tag=c9hgQjuQkAKpYJSoYBa1ZJFVuQq.M-iL\r\nVia: SIP/2.0/UDP 192.168.1.73:5060;rport=5060;received=127.0.0.1;branch=z9hG4bKycje8bq2eyat;x-sm-sid=27c0bbf0-53f7-44e4-8635-7062778d5903;x-sm-nid=ss_1hrqgtdr2wdid\r\nCSeq: 1 BYE\r\nContent-Length: 0\r\nCall-ID: T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u\r\nServer: Blink 0.24.1 (MacOSX)\r\nFrom: <sip:[email protected]>;tag=dhgn9s9mk146\r\n\r\n] #[N/A][N/A][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][N/A][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:11.646 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: Receive 200/BYE, branch=z9hG4bKycje8bq2eyat #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:11.648 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: NonInviteClientTransaction[, , _state=COMPLETED, _id=z9hG4bKycje8bq2eyat, ] is ready to release. #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:11.648 DEBUG [pool-21-thread-3] [IncomingCallActor[callId=4vg6dkqc-lx7-fxod8zouyy3mb]] : Request [[Event class=com.voxeo.moho.common.event.MohoCallCompleteEvent sourceClass=SIPIncomingCall id=9690828]]
2012-03-20 09:52:11.648 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: SessionManagementLayer recv response: BYE/200 #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:11.650 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: SipServletWrapper[Controller, com.voxeo.moho.sip.SIPController] is forwarding. #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:11.651 DEBUG [udp/0.0.0.0/5060-t-3] SIPCallImpl[SipSessionAdaptor[sessionid=ss_1hrqgtdr2wdid, appSessionId=sas_2-15-sm1i1a8cbvif5iarayo, ],DISCONNECTED] is already terminated.
2012-03-20 09:52:11.651 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm1i1a8cbvif5iarayo], invalidateWhenReady: true
2012-03-20 09:52:11.652 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: processInvalidationWhenReady [ss_1hrqgtdr2wdid], current State = TERMINATED, Vaild:true, Role:UAS, hasOngoingTransaction: true, OT: 1, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:11.652 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: server will automatically invalidate sipsession [ss_1hrqgtdr2wdid] #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:11.652 INFO [pool-21-thread-3] Queued Event [EndEvent[callId=4vg6dkqc-lx7-fxod8zouyy3mb,reason=HANGUP,errorText=<null>,headers=<null>]]
2012-03-20 09:52:11.654 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: SipSessionImpl[_id=ss_1hrqgtdr2wdid, _parentId=sas_2-15-sm1i1a8cbvif5iarayo, _handler=Controller, _state=TERMINATED, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=INVITE, _callId=T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, ] is invalidating. (s) #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:11.654 INFO [pool-21-thread-3] Call cleanup [call=SIPCallImpl[SipSessionAdaptor[sessionid=ss_1hrqgtdr2wdid, appSessionId=sas_2-15-sm1i1a8cbvif5iarayo, ],DISCONNECTED]]
2012-03-20 09:52:11.655 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: Remove Path[ id=T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u-c9hgQjuQkAKpYJSoYBa1ZJFVuQq.M-iL-dhgn9s9mk146, session=SipSessionImpl[_id=ss_1hrqgtdr2wdid, _parentId=sas_2-15-sm1i1a8cbvif5iarayo, _handler=Controller, _state=TERMINATED, _fresh=false, _valid=true, _unavailable=true, _role=UAS, _method=INVITE, _callId=T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u, ]] #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:11.655 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: processInvalidationWhenReady [sas_2-15-sm1i1a8cbvif5iarayo], invalidateWhenReady: true
2012-03-20 09:52:11.656 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: Container will automatically invalidate SipApplicationSession [sas_2-15-sm1i1a8cbvif5iarayo]
2012-03-20 09:52:11.656 DEBUG [udp/0.0.0.0/5060-t-3] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-15-sm1i1a8cbvif5iarayo, ] is invalidating. (as)
2012-03-20 09:52:11.655 DEBUG [pool-21-thread-3] Removing call [4vg6dkqc-lx7-fxod8zouyy3mb] from registry [com.rayo.server.DefaultCallRegistry@491a97]
2012-03-20 09:52:11.657 DEBUG [pool-21-thread-3] Removing call id 4vg6dkqc-lx7-fxod8zouyy3mb from the JID registry
2012-03-20 09:52:11.660 INFO [pool-21-thread-3] Reply [null]
2012-03-20 09:52:11.661 INFO [pool-21-thread-3] Event [EndEvent[callId=4vg6dkqc-lx7-fxod8zouyy3mb,reason=HANGUP,errorText=<null>,headers=<null>]]
2012-03-20 09:52:11.661 DEBUG [pool-21-thread-3] Storing CDR record for call id [4vg6dkqc-lx7-fxod8zouyy3mb]
2012-03-20 09:52:11.661 DEBUG [pool-21-thread-3] Removing CDR record from memory for call id [4vg6dkqc-lx7-fxod8zouyy3mb]
2012-03-20 09:52:11.665 DEBUG [pool-21-thread-3] #XMPP#: (o)<presence from="[email protected]" id="417b829a-1af7-4de2-94ce-b43134d08e15" to="[email protected]"><end xmlns="urn:xmpp:rayo:1"><hangup/></end></presence> #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:11.665 DEBUG [pool-21-thread-3] #XMPP#: Send message to: 127.0.0.1:59745 by xmpp #[rayo][null][xmpps_l0328mignyvl][CLIENT][[email protected]/blmbp.home-28910, 127.0.0.1][127.0.0.1:59745][127.0.0.1:5222][xmpp][N/A]
2012-03-20 09:52:16.646 DEBUG [Timer-15] #SIP#: NonInviteClientTransaction[, , _state=COMPLETED, _id=z9hG4bKycje8bq2eyat, ] timerRemoveTransaction is fired. #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
2012-03-20 09:52:16.647 DEBUG [Timer-15] #SIP#: NonInviteClientTransaction[, , _state=TERMINATED, _id=z9hG4bKycje8bq2eyat, ] is released. #[rayo][sas_2-15-sm1i1a8cbvif5iarayo][T49vPNRHCy5ZvdAUueM3DJcXR5uU6z-u][ss_1hrqgtdr2wdid][sip:[email protected](127.0.0.1:59615)][sip:[email protected](192.168.1.73:5060)]
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment