README.md

• Adhearsion: develop @ 999001751d069cc6dafe54a22b379a7c886267b
• FreeSWITCH: FreeSWITCH Version 1.4.14~64bit ( 64bit)

Usually this scenario works fine, but sometimes (I can consistently reproduce it) the Join-command never gets a response, and the call.join(other) hangs in Adhearsion until some timeout and both calls are hungup.

The point at which the calls stall is marked by the log line "BUGMIDDLE" in both adhearsion-bad.log and freeswitch-bad.log. I have attached adhearsion-good.log and freeswitch-good.log which contains an example of the same scenario going well.

Files

• config/routes.rb
• adhearsion-good.log
• freeswitch-good.log
• adhearsion-bad.log
• freeswitch-bad.log

adhearsion-bad.log

[2014-11-26 17:09:43.062] INFO  Adhearsion::Console: BUGSTART
[2014-11-26 17:09:43.974] DEBUG Adhearsion::Call: @: Receiving message: #<Punchblock::Event::Offer target_call_id="12583f8c-75d2-11e4-816d-379ee336ca8b", target_mixer_name=nil, component_id=nil, source_uri="xmpp:12583f8c-75d2-11e4-816d-379ee336ca8b@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:09:43 +0000, headers={"from"=>"\"22334455\" <sip:22334455@192.168.90.101>;tag=256386020", "to"=>"<sip:71999917@192.168.90.101>", "via"=>"SIP/2.0/UDP 192.168.90.101:5090;rport=5090;branch=z9hG4bK1806589332", "X-accountcode"=>"3000", "X-Firmafon-Inbound-Provider"=>"telenor_ic"}, to="sip:71999917@192.168.90.101", from="sip:22334455@192.168.90.101">
[2014-11-26 17:09:43.977] INFO  Adhearsion::Router: Call 12583f8c-75d2-11e4-816d-379ee336ca8b selected route "Default" (#<Proc:0x007f40e6d60d20@/srv/switch/adhearsion/config/routes.rb:4>)
[2014-11-26 17:09:44.022] DEBUG Adhearsion::Call: 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: Executing command #<Punchblock::Command::Accept target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Wed, 26 Nov 2014 17:09:43 -0800, request_id="37f9faf6-7df2-48ae-8aff-8d68d4fb0050", headers={}>
[2014-11-26 17:09:44.046] INFO  Adhearsion::Call: 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: Executing controller #<Adhearsion::CallController call=12583f8c-75d2-11e4-816d-379ee336ca8b, metadata={}>
[2014-11-26 17:09:44.049] DEBUG Adhearsion::Call: 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: Receiving message: #<Punchblock::Event::Offer target_call_id="12583f8c-75d2-11e4-816d-379ee336ca8b", target_mixer_name=nil, component_id=nil, source_uri="xmpp:12583f8c-75d2-11e4-816d-379ee336ca8b@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:09:43 +0000, headers={"from"=>"\"22334455\" <sip:22334455@192.168.90.101>;tag=256386020", "to"=>"<sip:71999917@192.168.90.101>", "via"=>"SIP/2.0/UDP 192.168.90.101:5090;rport=5090;branch=z9hG4bK1806589332", "X-accountcode"=>"3000", "X-Firmafon-Inbound-Provider"=>"telenor_ic"}, to="sip:71999917@192.168.90.101", from="sip:22334455@192.168.90.101">
[2014-11-26 17:09:44.054] DEBUG Adhearsion::Call: 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: Executing command #<Punchblock::Command::Answer target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Wed, 26 Nov 2014 17:09:44 -0800, request_id="af2a823a-646a-4ab3-8bae-da2e3b9b654e", headers={}>
[2014-11-26 17:09:44.144] DEBUG Adhearsion::OutboundCall: 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: Executing command #<Punchblock::Command::Dial target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Wed, 26 Nov 2014 17:09:44 -0800, request_id="a35a8c09-6877-45b2-84dd-27c3f6ec31f8", headers={}, to="sofia/gateway/development_mvno_link1/71999917", from=nil, uri="xmpp:3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost", timeout=nil, join=nil>
[2014-11-26 17:09:44.162] DEBUG Adhearsion::Call: 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: Receiving message: #<Punchblock::Event::Answered target_call_id="12583f8c-75d2-11e4-816d-379ee336ca8b", target_mixer_name=nil, component_id=nil, source_uri="xmpp:12583f8c-75d2-11e4-816d-379ee336ca8b@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:09:44 +0000, headers={}>
[2014-11-26 17:09:44.273] INFO  Adhearsion::Call: 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: Waiting for B-leg to answer
[2014-11-26 17:09:44.426] DEBUG Adhearsion::OutboundCall: 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: Receiving message: #<Punchblock::Event::Ringing target_call_id="3afaefc6-e051-4beb-925b-0225ec68d8f2", target_mixer_name=nil, component_id=nil, source_uri="xmpp:3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:09:44 +0000, headers={}>
[2014-11-26 17:09:45.945] DEBUG Adhearsion::OutboundCall: 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: Receiving message: #<Punchblock::Event::Answered target_call_id="3afaefc6-e051-4beb-925b-0225ec68d8f2", target_mixer_name=nil, component_id=nil, source_uri="xmpp:3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:09:45 +0000, headers={}>
[2014-11-26 17:09:45.947] INFO  Adhearsion::Call: 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: B-leg answered
[2014-11-26 17:09:45.954] INFO  Adhearsion::Call: 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: Joining A and B
[2014-11-26 17:09:45.955] DEBUG Adhearsion::Call: 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: Joining to #<Celluloid::ActorProxy:0x007f40e6b784b8>
[2014-11-26 17:09:45.965] DEBUG Adhearsion::Call: 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: Executing command #<Punchblock::Command::Join target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Wed, 26 Nov 2014 17:09:45 -0800, request_id="ab26c60b-1757-4440-a80c-c3b46f30c641", call_uri="xmpp:3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost", mixer_name=nil, direction=nil, media=nil>
[2014-11-26 17:09:53.393] INFO  Adhearsion::Console: BUGMIDDLE
[2014-11-26 17:10:08.619] DEBUG Adhearsion::OutboundCall: 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: Receiving message: #<Punchblock::Event::End target_call_id="3afaefc6-e051-4beb-925b-0225ec68d8f2", target_mixer_name=nil, component_id=nil, source_uri="xmpp:3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:10:08 +0000, headers={}, reason=:error, platform_code="27">
[2014-11-26 17:10:08.620] INFO  Adhearsion::OutboundCall: 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: Call  -> sofia/gateway/development_mvno_link1/71999917 ended due to error (code 27)
[2014-11-26 17:10:08.618] DEBUG Adhearsion::Call: 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: Receiving message: #<Punchblock::Event::End target_call_id="12583f8c-75d2-11e4-816d-379ee336ca8b", target_mixer_name=nil, component_id=nil, source_uri="xmpp:12583f8c-75d2-11e4-816d-379ee336ca8b@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:10:08 +0000, headers={"X-accountcode"=>"3000", "X-Firmafon-Inbound-Provider"=>"telenor_ic"}, reason=:error, platform_code="27">
[2014-11-26 17:10:08.619] INFO  Adhearsion::Call: 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: Call sip:22334455@192.168.90.101 -> sip:71999917@192.168.90.101 ended due to error (code 27)
[2014-11-26 17:10:08.660] DEBUG Celluloid: Celluloid::Condition signaled spuriously
[2014-11-26 17:10:08.681] DEBUG Adhearsion::Call: 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: Finished executing controller #<Adhearsion::CallController call=12583f8c-75d2-11e4-816d-379ee336ca8b, metadata={}>
[2014-11-26 17:10:08.685] INFO  Adhearsion::Router::Route: Call 12583f8c-75d2-11e4-816d-379ee336ca8b routing completed. Call was already hung up.
[2014-11-26 17:10:15.607] INFO  Adhearsion::Console: BUGEND

adhearsion-good.log

[2014-11-26 17:18:37.634] DEBUG Adhearsion::Call: @: Receiving message: #<Punchblock::Event::Offer target_call_id="506a3aea-75d3-11e4-8182-379ee336ca8b", target_mixer_name=nil, component_id=nil, source_uri="xmpp:506a3aea-75d3-11e4-8182-379ee336ca8b@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:18:37 +0000, headers={"from"=>"\"22334455\" <sip:22334455@192.168.90.101>;tag=2061909510", "to"=>"<sip:71999917@192.168.90.101>", "via"=>"SIP/2.0/UDP 192.168.90.101:5090;rport=5090;branch=z9hG4bK1022204622", "X-accountcode"=>"3000", "X-Firmafon-Inbound-Provider"=>"telenor_ic"}, to="sip:71999917@192.168.90.101", from="sip:22334455@192.168.90.101">
[2014-11-26 17:18:37.642] INFO  Adhearsion::Router: Call 506a3aea-75d3-11e4-8182-379ee336ca8b selected route "Default" (#<Proc:0x007f97828a9190@/srv/switch/adhearsion/config/routes.rb:4>)
[2014-11-26 17:18:37.700] DEBUG Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Executing command #<Punchblock::Command::Accept target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Wed, 26 Nov 2014 17:18:37 -0800, request_id="a87a6d0e-7d83-4977-ac0e-8769a9931e6a", headers={}>
[2014-11-26 17:18:37.784] INFO  Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Executing controller #<Adhearsion::CallController call=506a3aea-75d3-11e4-8182-379ee336ca8b, metadata={}>
[2014-11-26 17:18:37.786] DEBUG Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Receiving message: #<Punchblock::Event::Offer target_call_id="506a3aea-75d3-11e4-8182-379ee336ca8b", target_mixer_name=nil, component_id=nil, source_uri="xmpp:506a3aea-75d3-11e4-8182-379ee336ca8b@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:18:37 +0000, headers={"from"=>"\"22334455\" <sip:22334455@192.168.90.101>;tag=2061909510", "to"=>"<sip:71999917@192.168.90.101>", "via"=>"SIP/2.0/UDP 192.168.90.101:5090;rport=5090;branch=z9hG4bK1022204622", "X-accountcode"=>"3000", "X-Firmafon-Inbound-Provider"=>"telenor_ic"}, to="sip:71999917@192.168.90.101", from="sip:22334455@192.168.90.101">
[2014-11-26 17:18:37.803] DEBUG Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Executing command #<Punchblock::Command::Answer target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Wed, 26 Nov 2014 17:18:37 -0800, request_id="05fd4c35-260c-4de1-842c-df22405f06e2", headers={}>
[2014-11-26 17:18:37.917] DEBUG Adhearsion::OutboundCall: 1c905694-1210-4116-b08b-30421af2b195@localhost: Executing command #<Punchblock::Command::Dial target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Wed, 26 Nov 2014 17:18:37 -0800, request_id="39cbd652-d221-4e9f-bade-5e7d49a81c0c", headers={}, to="sofia/gateway/development_mvno_link1/71999917", from=nil, uri="xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost", timeout=nil, join=nil>
[2014-11-26 17:18:37.992] DEBUG Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Receiving message: #<Punchblock::Event::Answered target_call_id="506a3aea-75d3-11e4-8182-379ee336ca8b", target_mixer_name=nil, component_id=nil, source_uri="xmpp:506a3aea-75d3-11e4-8182-379ee336ca8b@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:18:37 +0000, headers={}>
[2014-11-26 17:18:38.115] INFO  Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Waiting for B-leg to answer
[2014-11-26 17:18:38.353] DEBUG Adhearsion::OutboundCall: 1c905694-1210-4116-b08b-30421af2b195@localhost: Receiving message: #<Punchblock::Event::Ringing target_call_id="1c905694-1210-4116-b08b-30421af2b195", target_mixer_name=nil, component_id=nil, source_uri="xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:18:38 +0000, headers={}>
[2014-11-26 17:18:45.500] DEBUG Adhearsion::OutboundCall: 1c905694-1210-4116-b08b-30421af2b195@localhost: Receiving message: #<Punchblock::Event::Answered target_call_id="1c905694-1210-4116-b08b-30421af2b195", target_mixer_name=nil, component_id=nil, source_uri="xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:18:45 +0000, headers={}>
[2014-11-26 17:18:45.503] INFO  Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: B-leg answered
[2014-11-26 17:18:45.505] INFO  Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Joining A and B
[2014-11-26 17:18:45.506] DEBUG Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Joining to #<Celluloid::ActorProxy:0x007f97824dba18>
[2014-11-26 17:18:45.518] DEBUG Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Executing command #<Punchblock::Command::Join target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Wed, 26 Nov 2014 17:18:45 -0800, request_id="82eeed8d-38fb-4591-ba85-8908bb0c6d49", call_uri="xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost", mixer_name=nil, direction=nil, media=nil>
[2014-11-26 17:18:45.654] INFO  Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Joined. Waiting for B-leg to hangup.
[2014-11-26 17:18:45.712] DEBUG Adhearsion::OutboundCall: 1c905694-1210-4116-b08b-30421af2b195@localhost: Receiving message: #<Punchblock::Event::Joined target_call_id="1c905694-1210-4116-b08b-30421af2b195", target_mixer_name=nil, component_id=nil, source_uri="xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:18:45 +0000, call_uri="xmpp:506a3aea-75d3-11e4-8182-379ee336ca8b@localhost", mixer_name=nil>
[2014-11-26 17:18:45.713] INFO  Adhearsion::OutboundCall: 1c905694-1210-4116-b08b-30421af2b195@localhost: Joined to call xmpp:506a3aea-75d3-11e4-8182-379ee336ca8b@localhost
[2014-11-26 17:18:45.737] DEBUG Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Receiving message: #<Punchblock::Event::Joined target_call_id="506a3aea-75d3-11e4-8182-379ee336ca8b", target_mixer_name=nil, component_id=nil, source_uri="xmpp:506a3aea-75d3-11e4-8182-379ee336ca8b@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:18:45 +0000, call_uri="xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost", mixer_name=nil>
[2014-11-26 17:18:45.737] INFO  Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Joined to call xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost
[2014-11-26 17:18:53.190] DEBUG Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Receiving message: #<Punchblock::Event::Unjoined target_call_id="506a3aea-75d3-11e4-8182-379ee336ca8b", target_mixer_name=nil, component_id=nil, source_uri="xmpp:506a3aea-75d3-11e4-8182-379ee336ca8b@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:18:53 +0000, call_uri="xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost", mixer_name=nil>
[2014-11-26 17:18:53.191] INFO  Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Unjoined from call xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost
[2014-11-26 17:18:53.281] DEBUG Adhearsion::OutboundCall: 1c905694-1210-4116-b08b-30421af2b195@localhost: Receiving message: #<Punchblock::Event::Unjoined target_call_id="1c905694-1210-4116-b08b-30421af2b195", target_mixer_name=nil, component_id=nil, source_uri="xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:18:53 +0000, call_uri="xmpp:506a3aea-75d3-11e4-8182-379ee336ca8b@localhost", mixer_name=nil>
[2014-11-26 17:18:53.281] INFO  Adhearsion::OutboundCall: 1c905694-1210-4116-b08b-30421af2b195@localhost: Unjoined from call xmpp:506a3aea-75d3-11e4-8182-379ee336ca8b@localhost
[2014-11-26 17:18:53.285] DEBUG Adhearsion::OutboundCall: 1c905694-1210-4116-b08b-30421af2b195@localhost: Receiving message: #<Punchblock::Event::End target_call_id="1c905694-1210-4116-b08b-30421af2b195", target_mixer_name=nil, component_id=nil, source_uri="xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:18:53 +0000, headers={}, reason=:hungup, platform_code="16">
[2014-11-26 17:18:53.285] INFO  Adhearsion::OutboundCall: 1c905694-1210-4116-b08b-30421af2b195@localhost: Call  -> sofia/gateway/development_mvno_link1/71999917 ended due to hungup (code 16)
[2014-11-26 17:18:53.295] DEBUG Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Finished executing controller #<Adhearsion::CallController call=506a3aea-75d3-11e4-8182-379ee336ca8b, metadata={}>
[2014-11-26 17:18:53.296] INFO  Adhearsion::Router::Route: Call 506a3aea-75d3-11e4-8182-379ee336ca8b routing completed. Hanging up now.
[2014-11-26 17:18:53.297] INFO  Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Hanging up
[2014-11-26 17:18:53.303] DEBUG Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Executing command #<Punchblock::Command::Hangup target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Wed, 26 Nov 2014 17:18:53 -0800, request_id="7cd26c6c-92ed-4038-8cdb-0f9253f2a8a0", headers={}>
[2014-11-26 17:18:53.473] DEBUG Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Receiving message: #<Punchblock::Event::End target_call_id="506a3aea-75d3-11e4-8182-379ee336ca8b", target_mixer_name=nil, component_id=nil, source_uri="xmpp:506a3aea-75d3-11e4-8182-379ee336ca8b@localhost", domain="localhost", transport="xmpp", timestamp=Thu, 27 Nov 2014 01:18:53 +0000, headers={"X-accountcode"=>"3000", "X-Firmafon-Inbound-Provider"=>"telenor_ic"}, reason=:"hangup-command", platform_code=nil>
[2014-11-26 17:18:53.479] INFO  Adhearsion::Call: 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: Call sip:22334455@192.168.90.101 -> sip:71999917@192.168.90.101 ended due to hangup-command

freeswitch-bad.log

2014-11-26 17:09:42.109189 [DEBUG] mod_commands.c:6276 BUGSTART
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [NOTICE] switch_channel.c:1055 New Channel sofia/external/22334455@192.168.90.101 [12583f8c-75d2-11e4-816d-379ee336ca8b]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_NEW
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] sofia.c:8834 sofia/external/22334455@192.168.90.101 receiving invite from 192.168.90.101:5090 version: 1.4.14  64bit
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] sofia.c:6614 Channel sofia/external/22334455@192.168.90.101 entering state [received][100]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] sofia.c:6624 Remote SDP:
12583f8c-75d2-11e4-816d-379ee336ca8b v=0
12583f8c-75d2-11e4-816d-379ee336ca8b o=yate 1417050583 1417050583 IN IP4 192.168.90.101
12583f8c-75d2-11e4-816d-379ee336ca8b s=SIP Call
12583f8c-75d2-11e4-816d-379ee336ca8b c=IN IP4 192.168.90.101
12583f8c-75d2-11e4-816d-379ee336ca8b t=0 0
12583f8c-75d2-11e4-816d-379ee336ca8b m=audio 20206 RTP/AVP 0 8 101
12583f8c-75d2-11e4-816d-379ee336ca8b a=rtpmap:0 PCMU/8000
12583f8c-75d2-11e4-816d-379ee336ca8b a=rtpmap:8 PCMA/8000
12583f8c-75d2-11e4-816d-379ee336ca8b a=rtpmap:101 telephone-event/8000
12583f8c-75d2-11e4-816d-379ee336ca8b 
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_media.c:3670 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_media.c:3531 Set telephone-event payload to 101
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_media.c:2473 Set Codec sofia/external/22334455@192.168.90.101 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_codec.c:111 sofia/external/22334455@192.168.90.101 Original read codec set to PCMA:8
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_media.c:3861 Set 2833 dtmf send/recv payload to 101
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] sofia.c:6910 (sofia/external/22334455@192.168.90.101) State Change CS_NEW -> CS_INIT
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_state_machine.c:491 (sofia/external/22334455@192.168.90.101) State NEW
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_INIT
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_state_machine.c:512 (sofia/external/22334455@192.168.90.101) State INIT
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] mod_sofia.c:87 sofia/external/22334455@192.168.90.101 SOFIA INIT
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_state_machine.c:40 sofia/external/22334455@192.168.90.101 Standard INIT
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_state_machine.c:48 (sofia/external/22334455@192.168.90.101) State Change CS_INIT -> CS_ROUTING
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_state_machine.c:512 (sofia/external/22334455@192.168.90.101) State INIT going to sleep
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_ROUTING
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_channel.c:2184 (sofia/external/22334455@192.168.90.101) Callstate Change DOWN -> RINGING
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_state_machine.c:528 (sofia/external/22334455@192.168.90.101) State ROUTING
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] mod_sofia.c:123 sofia/external/22334455@192.168.90.101 SOFIA ROUTING
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_state_machine.c:166 sofia/external/22334455@192.168.90.101 Standard ROUTING
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [INFO] mod_dialplan_xml.c:635 Processing 22334455 <22334455>->71999917 in context public
12583f8c-75d2-11e4-816d-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 parsing [public->unloop] continue=false
12583f8c-75d2-11e4-816d-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
12583f8c-75d2-11e4-816d-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
12583f8c-75d2-11e4-816d-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 parsing [public->outside_call] continue=true
12583f8c-75d2-11e4-816d-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Absolute Condition [outside_call]
12583f8c-75d2-11e4-816d-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Action set(outside_call=true)
12583f8c-75d2-11e4-816d-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
12583f8c-75d2-11e4-816d-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 parsing [public->rayo] continue=false
12583f8c-75d2-11e4-816d-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Regex (FAIL) [rayo] ${sip_h_X-accountcode}(3000) =~ /^1000$/ break=never
12583f8c-75d2-11e4-816d-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Regex (PASS) [rayo] ${sip_h_X-accountcode}(3000) =~ /^3000$/ break=never
12583f8c-75d2-11e4-816d-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Action set(sip_h_X-Firmafon-Inbound-Provider=telenor_ic)
12583f8c-75d2-11e4-816d-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Absolute Condition [rayo]
12583f8c-75d2-11e4-816d-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Action rayo()
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_state_machine.c:216 (sofia/external/22334455@192.168.90.101) State Change CS_ROUTING -> CS_EXECUTE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_state_machine.c:528 (sofia/external/22334455@192.168.90.101) State ROUTING going to sleep
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_EXECUTE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_state_machine.c:535 (sofia/external/22334455@192.168.90.101) State EXECUTE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] mod_sofia.c:178 sofia/external/22334455@192.168.90.101 SOFIA EXECUTE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] switch_core_state_machine.c:258 sofia/external/22334455@192.168.90.101 Standard EXECUTE
12583f8c-75d2-11e4-816d-379ee336ca8b EXECUTE sofia/external/22334455@192.168.90.101 set(outside_call=true)
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] mod_dptools.c:1435 sofia/external/22334455@192.168.90.101 SET [outside_call]=[true]
12583f8c-75d2-11e4-816d-379ee336ca8b EXECUTE sofia/external/22334455@192.168.90.101 set(RFC2822_DATE=Wed, 26 Nov 2014 17:09:43 -0800)
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] mod_dptools.c:1435 sofia/external/22334455@192.168.90.101 SET [RFC2822_DATE]=[Wed, 26 Nov 2014 17:09:43 -0800]
12583f8c-75d2-11e4-816d-379ee336ca8b EXECUTE sofia/external/22334455@192.168.90.101 set(sip_h_X-Firmafon-Inbound-Provider=telenor_ic)
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] mod_dptools.c:1435 sofia/external/22334455@192.168.90.101 SET [sip_h_X-Firmafon-Inbound-Provider]=[telenor_ic]
12583f8c-75d2-11e4-816d-379ee336ca8b EXECUTE sofia/external/22334455@192.168.90.101 rayo()
2014-11-26 17:09:43.929727 [DEBUG] mod_rayo.c:3825 Init 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] mod_rayo.c:3836 Offering call for Rayo 3PCC
2014-11-26 17:09:43.929727 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:43.929727 [DEBUG] mod_rayo.c:3859 Deliver 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost => usera@localhost/dev01-10266 <presence from='12583f8c-75d2-11e4-816d-379ee336ca8b@localhost' to='usera@localhost/dev01-10266'><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='urn:xmpp:rayo:call:1' ver='L9rOKMEJl9rssEggArljiapRd9k='/><offer xmlns='urn:xmpp:rayo:1' from='sip:22334455@192.168.90.101' to='sip:71999917@192.168.90.101'><header name='from' value='&quot;22334455&quot; &lt;sip:22334455@192.168.90.101&gt;;tag=256386020'/><header name='to' value='&lt;sip:71999917@192.168.90.101&gt;'/><header name='via' value='SIP/2.0/UDP 192.168.90.101:5090;rport=5090;branch=z9hG4bK1806589332'/><header name='X-accountcode' value='3000'/><header name='X-Firmafon-Inbound-Provider' value='telenor_ic'/></offer><delay xmlns='urn:xmpp:delay' stamp='2014-11-27T01:09:43Z'/></presence>
2014-11-26 17:09:43.929727 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10266: ref count = 1
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE_COMPLETE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE_COMPLETE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE_COMPLETE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] mod_rayo.c:3598 got event CHANNEL_PARK
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:43.929727 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10266, 127.0.0.1:36280, c2s_in SEND <presence from=12583f8c-75d2-11e4-816d-379ee336ca8b@localhost to=usera@localhost/dev01-10266><c xmlns=http://jabber.org/protocol/caps hash=sha-1 node=urn:xmpp:rayo:call:1 ver=L9rOKMEJl9rssEggArljiapRd9k=/><offer xmlns=urn:xmpp:rayo:1 from=sip:22334455@192.168.90.101 to=sip:71999917@192.168.90.101><header name=from value=&quot;22334455&quot; &lt;sip:22334455@192.168.90.101&gt;;tag=256386020/><header name=to value=&lt;sip:71999917@192.168.90.101&gt;/><header name=via value=SIP/2.0/UDP 192.168.90.101:5090;rport=5090;branch=z9hG4bK1806589332/><header name=X-accountcode value=3000/><header name=X-Firmafon-Inbound-Provider value=telenor_ic/></offer><delay xmlns=urn:xmpp:delay stamp=2014-11-27T01:09:43Z/></presence>
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:44.014873 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10266, 127.0.0.1:36280, c2s_in RECV <iq type="set" to="12583f8c-75d2-11e4-816d-379ee336ca8b@localhost" id="37f9faf6-7df2-48ae-8aff-8d68d4fb0050"><accept xmlns="urn:xmpp:rayo:1"/></iq>
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:44.014873 [DEBUG] xmpp_streams.c:1058 usera@localhost/dev01-10266, 127.0.0.1:36280, state = READY, node type = NODE_NORMAL
2014-11-26 17:09:44.014873 [DEBUG] mod_rayo.c:3912 Lock usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:44.014873 [DEBUG] mod_rayo.c:3056 usera@localhost/dev01-10266, recv iq, availability = ONLINE
2014-11-26 17:09:44.014873 [DEBUG] mod_rayo.c:3983 Release usera@localhost/dev01-10266: ref count = 1
2014-11-26 17:09:44.014873 [DEBUG] mod_rayo.c:774 Locate (jid) 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: ref count = 2
2014-11-26 17:09:44.014873 [DEBUG] mod_rayo.c:3059 Deliver usera@localhost/dev01-10266 => 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost <iq type='set' to='12583f8c-75d2-11e4-816d-379ee336ca8b@localhost' id='37f9faf6-7df2-48ae-8aff-8d68d4fb0050' from='usera@localhost/dev01-10266'><accept xmlns='urn:xmpp:rayo:1'/></iq>
2014-11-26 17:09:44.014873 [DEBUG] mod_rayo.c:655 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost, looking for CALL::set:urn:xmpp:rayo:1:accept command
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.014873 [INFO] mod_rayo.c:1636 usera@localhost/dev01-10266 has control of call
2014-11-26 17:09:44.014873 [DEBUG] mod_rayo.c:1816 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost, executing command
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.014873 [INFO] mod_rayo.c:1953 Sending early media
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.014873 [DEBUG] switch_core_media.c:5111 AUDIO RTP [sofia/external/22334455@192.168.90.101] 192.168.90.101 port 27454 -> 192.168.90.101 port 20206 codec: 8 ms: 20
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.014873 [DEBUG] switch_rtp.c:3521 Starting timer [soft] 160 bytes per 20ms
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.014873 [DEBUG] switch_core_media.c:5409 Set 2833 dtmf send payload to 101
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.014873 [DEBUG] switch_core_media.c:5415 Set 2833 dtmf receive payload to 101
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.014873 [DEBUG] mod_sofia.c:2247 Ring SDP:
12583f8c-75d2-11e4-816d-379ee336ca8b v=0
12583f8c-75d2-11e4-816d-379ee336ca8b o=FreeSWITCH 1417023130 1417023131 IN IP4 192.168.90.101
12583f8c-75d2-11e4-816d-379ee336ca8b s=FreeSWITCH
12583f8c-75d2-11e4-816d-379ee336ca8b c=IN IP4 192.168.90.101
12583f8c-75d2-11e4-816d-379ee336ca8b t=0 0
12583f8c-75d2-11e4-816d-379ee336ca8b m=audio 27454 RTP/AVP 8 101
12583f8c-75d2-11e4-816d-379ee336ca8b a=rtpmap:8 PCMA/8000
12583f8c-75d2-11e4-816d-379ee336ca8b a=rtpmap:101 telephone-event/8000
12583f8c-75d2-11e4-816d-379ee336ca8b a=fmtp:101 0-16
12583f8c-75d2-11e4-816d-379ee336ca8b a=ptime:20
12583f8c-75d2-11e4-816d-379ee336ca8b a=sendrecv
12583f8c-75d2-11e4-816d-379ee336ca8b 
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.014873 [NOTICE] mod_sofia.c:2250 Pre-Answer sofia/external/22334455@192.168.90.101!
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.014873 [DEBUG] switch_channel.c:3399 (sofia/external/22334455@192.168.90.101) Callstate Change RINGING -> EARLY
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.014873 [DEBUG] switch_core_session.c:908 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
2014-11-26 17:09:44.014873 [DEBUG] mod_rayo.c:1818 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost, done executing command
2014-11-26 17:09:44.014873 [DEBUG] mod_rayo.c:781 Release 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: ref count = 1
2014-11-26 17:09:44.014873 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:44.014873 [DEBUG] mod_rayo.c:1824 Deliver 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost => usera@localhost/dev01-10266 <iq from='12583f8c-75d2-11e4-816d-379ee336ca8b@localhost' to='usera@localhost/dev01-10266' type='result' id='37f9faf6-7df2-48ae-8aff-8d68d4fb0050'/>
2014-11-26 17:09:44.014873 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10266: ref count = 1
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.014873 [DEBUG] mod_rayo.c:3598 got event CHANNEL_PROGRESS_MEDIA
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.014873 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10266 rayo event CHANNEL_PROGRESS_MEDIA
2014-11-26 17:09:44.014873 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:44.014873 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10266: ref count = 1
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:44.057824 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10266, 127.0.0.1:36280, c2s_in SEND <iq from=12583f8c-75d2-11e4-816d-379ee336ca8b@localhost to=usera@localhost/dev01-10266 type=result id=37f9faf6-7df2-48ae-8aff-8d68d4fb0050/>
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.057824 [DEBUG] switch_ivr.c:961 Codec Activated L16@8000hz 1 channels 20ms
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:44.057824 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10266, 127.0.0.1:36280, c2s_in RECV <iq type="set" to="12583f8c-75d2-11e4-816d-379ee336ca8b@localhost" id="af2a823a-646a-4ab3-8bae-da2e3b9b654e"><answer xmlns="urn:xmpp:rayo:1"/></iq>
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:44.057824 [DEBUG] xmpp_streams.c:1058 usera@localhost/dev01-10266, 127.0.0.1:36280, state = READY, node type = NODE_NORMAL
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:3912 Lock usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:3056 usera@localhost/dev01-10266, recv iq, availability = ONLINE
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:3983 Release usera@localhost/dev01-10266: ref count = 1
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:774 Locate (jid) 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: ref count = 2
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:3059 Deliver usera@localhost/dev01-10266 => 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost <iq type='set' to='12583f8c-75d2-11e4-816d-379ee336ca8b@localhost' id='af2a823a-646a-4ab3-8bae-da2e3b9b654e' from='usera@localhost/dev01-10266'><answer xmlns='urn:xmpp:rayo:1'/></iq>
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:655 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost, looking for CALL::set:urn:xmpp:rayo:1:answer command
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:1816 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost, executing command
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.057824 [DEBUG] mod_sofia.c:780 Local SDP sofia/external/22334455@192.168.90.101:
12583f8c-75d2-11e4-816d-379ee336ca8b v=0
12583f8c-75d2-11e4-816d-379ee336ca8b o=FreeSWITCH 1417023130 1417023132 IN IP4 192.168.90.101
12583f8c-75d2-11e4-816d-379ee336ca8b s=FreeSWITCH
12583f8c-75d2-11e4-816d-379ee336ca8b c=IN IP4 192.168.90.101
12583f8c-75d2-11e4-816d-379ee336ca8b t=0 0
12583f8c-75d2-11e4-816d-379ee336ca8b m=audio 27454 RTP/AVP 8 101
12583f8c-75d2-11e4-816d-379ee336ca8b a=rtpmap:8 PCMA/8000
12583f8c-75d2-11e4-816d-379ee336ca8b a=rtpmap:101 telephone-event/8000
12583f8c-75d2-11e4-816d-379ee336ca8b a=fmtp:101 0-16
12583f8c-75d2-11e4-816d-379ee336ca8b a=ptime:20
12583f8c-75d2-11e4-816d-379ee336ca8b a=sendrecv
12583f8c-75d2-11e4-816d-379ee336ca8b 
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.057824 [DEBUG] switch_core_session.c:908 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.057824 [NOTICE] mod_rayo.c:1972 Channel [sofia/external/22334455@192.168.90.101] has been answered
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.057824 [DEBUG] switch_channel.c:3689 (sofia/external/22334455@192.168.90.101) Callstate Change EARLY -> ACTIVE
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:1818 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost, done executing command
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:781 Release 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: ref count = 1
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:1824 Deliver 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost => usera@localhost/dev01-10266 <iq from='12583f8c-75d2-11e4-816d-379ee336ca8b@localhost' to='usera@localhost/dev01-10266' type='result' id='af2a823a-646a-4ab3-8bae-da2e3b9b654e'/>
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10266: ref count = 1
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:3598 got event CHANNEL_ANSWER
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10266 rayo event CHANNEL_ANSWER
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:3380 Locate (id) 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: ref count = 2
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:3386 Release 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: ref count = 1
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10266: ref count = 1
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:3385 Deliver 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost => usera@localhost/dev01-10266 <presence from='12583f8c-75d2-11e4-816d-379ee336ca8b@localhost' to='usera@localhost/dev01-10266'><answered xmlns='urn:xmpp:rayo:1'/><delay xmlns='urn:xmpp:delay' stamp='2014-11-27T01:09:44Z'/></presence>
2014-11-26 17:09:44.057824 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10266: ref count = 1
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:44.150094 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10266, 127.0.0.1:36280, c2s_in SEND <iq from=12583f8c-75d2-11e4-816d-379ee336ca8b@localhost to=usera@localhost/dev01-10266 type=result id=af2a823a-646a-4ab3-8bae-da2e3b9b654e/>
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:44.150094 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10266, 127.0.0.1:36280, c2s_in SEND <presence from=12583f8c-75d2-11e4-816d-379ee336ca8b@localhost to=usera@localhost/dev01-10266><answered xmlns=urn:xmpp:rayo:1/><delay xmlns=urn:xmpp:delay stamp=2014-11-27T01:09:44Z/></presence>
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:44.170368 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10266, 127.0.0.1:36280, c2s_in RECV <iq type="set" to="localhost" id="a35a8c09-6877-45b2-84dd-27c3f6ec31f8"><dial xmlns="urn:xmpp:rayo:1" to="sofia/gateway/development_mvno_link1/71999917" uri="xmpp:3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost"/></iq>
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:44.170368 [DEBUG] xmpp_streams.c:1058 usera@localhost/dev01-10266, 127.0.0.1:36280, state = READY, node type = NODE_NORMAL
2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:3912 Lock usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:3056 usera@localhost/dev01-10266, recv iq, availability = ONLINE
2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:3983 Release usera@localhost/dev01-10266: ref count = 1
2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:774 Locate (jid) localhost: ref count = 2
2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:3059 Deliver usera@localhost/dev01-10266 => localhost <iq type='set' to='localhost' id='a35a8c09-6877-45b2-84dd-27c3f6ec31f8' from='usera@localhost/dev01-10266'><dial xmlns='urn:xmpp:rayo:1' to='sofia/gateway/development_mvno_link1/71999917' uri='xmpp:3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost'/></iq>
2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:655 localhost, looking for SERVER::set:urn:xmpp:rayo:1:dial command
2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:781 Release localhost: ref count = 1
2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:2591 Init 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [INFO] mod_rayo.c:2598 usera@localhost/dev01-10266 has control of call
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:2712 dial: Using dialstring: sofia/gateway/development_mvno_link1/71999917
2014-11-26 17:09:44.170368 [DEBUG] switch_ivr_originate.c:2079 Parsing global variables
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [NOTICE] switch_channel.c:1055 New Channel sofia/external/71999917 [3afaefc6-e051-4beb-925b-0225ec68d8f2]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] mod_sofia.c:4615 (sofia/external/71999917) State Change CS_NEW -> CS_INIT
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] switch_core_session.c:612 sofia/external/71999917 set UUID=3afaefc6-e051-4beb-925b-0225ec68d8f2
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_INIT
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] switch_core_state_machine.c:512 (sofia/external/71999917) State INIT
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] mod_sofia.c:87 sofia/external/71999917 SOFIA INIT
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] sofia_glue.c:1232 sofia/external/71999917 sending invite version: 1.4.14  64bit
3afaefc6-e051-4beb-925b-0225ec68d8f2 Local SDP:
3afaefc6-e051-4beb-925b-0225ec68d8f2 v=0
3afaefc6-e051-4beb-925b-0225ec68d8f2 o=FreeSWITCH 1417019512 1417019513 IN IP4 192.168.90.101
3afaefc6-e051-4beb-925b-0225ec68d8f2 s=FreeSWITCH
3afaefc6-e051-4beb-925b-0225ec68d8f2 c=IN IP4 192.168.90.101
3afaefc6-e051-4beb-925b-0225ec68d8f2 t=0 0
3afaefc6-e051-4beb-925b-0225ec68d8f2 m=audio 31072 RTP/AVP 8 101 13
3afaefc6-e051-4beb-925b-0225ec68d8f2 a=rtpmap:8 PCMA/8000
3afaefc6-e051-4beb-925b-0225ec68d8f2 a=rtpmap:101 telephone-event/8000
3afaefc6-e051-4beb-925b-0225ec68d8f2 a=fmtp:101 0-16
3afaefc6-e051-4beb-925b-0225ec68d8f2 a=ptime:20
3afaefc6-e051-4beb-925b-0225ec68d8f2 a=sendrecv
3afaefc6-e051-4beb-925b-0225ec68d8f2 
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] switch_core_state_machine.c:40 sofia/external/71999917 Standard INIT
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] switch_core_state_machine.c:48 (sofia/external/71999917) State Change CS_INIT -> CS_ROUTING
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] switch_core_state_machine.c:512 (sofia/external/71999917) State INIT going to sleep
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_ROUTING
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] switch_core_state_machine.c:528 (sofia/external/71999917) State ROUTING
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] mod_sofia.c:123 sofia/external/71999917 SOFIA ROUTING
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] switch_ivr_originate.c:67 (sofia/external/71999917) State Change CS_ROUTING -> CS_CONSUME_MEDIA
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] switch_core_state_machine.c:528 (sofia/external/71999917) State ROUTING going to sleep
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_CONSUME_MEDIA
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] switch_core_state_machine.c:547 (sofia/external/71999917) State CONSUME_MEDIA
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] switch_core_state_machine.c:547 (sofia/external/71999917) State CONSUME_MEDIA going to sleep
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:3598 got event CHANNEL_ORIGINATE
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10266 rayo event CHANNEL_ORIGINATE
2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:3317 Locate (id) 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 2
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:3322 Got originate event
2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:3341 Release 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 1
2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10266: ref count = 1
2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:3336 Deliver 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost => usera@localhost/dev01-10266 <iq from='localhost' to='usera@localhost/dev01-10266' id='a35a8c09-6877-45b2-84dd-27c3f6ec31f8' type='result'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost'/></iq>
2014-11-26 17:09:44.170368 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10266: ref count = 1
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.189243 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:44.189243 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10266, 127.0.0.1:36280, c2s_in SEND <iq from=localhost to=usera@localhost/dev01-10266 id=a35a8c09-6877-45b2-84dd-27c3f6ec31f8 type=result><ref xmlns=urn:xmpp:rayo:1 uri=xmpp:3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost/></iq>
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.189243 [DEBUG] sofia.c:6607 Channel sofia/external/22334455@192.168.90.101 skipping state [early][183]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.282158 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.282158 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/71999917 [BREAK]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.282158 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.282158 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.282158 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.282158 [DEBUG] sofia.c:6614 Channel sofia/external/71999917 entering state [calling][0]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.282158 [DEBUG] sofia.c:6614 Channel sofia/external/22334455@192.168.90.101 entering state [completed][200]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.282158 [DEBUG] sofia.c:6614 Channel sofia/external/22334455@192.168.90.101 entering state [ready][200]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:44.282158 [DEBUG] switch_rtp.c:5823 Correct ip/port confirmed.
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.361182 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/71999917 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.361182 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/71999917 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.361182 [DEBUG] sofia.c:6614 Channel sofia/external/71999917 entering state [proceeding][180]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.361182 [NOTICE] sofia.c:6716 Ring-Ready sofia/external/71999917!
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.361182 [DEBUG] switch_channel.c:3277 (sofia/external/71999917) Callstate Change DOWN -> RINGING
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.361182 [DEBUG] mod_rayo.c:3598 got event CHANNEL_PROGRESS
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:44.361182 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10266 rayo event CHANNEL_PROGRESS
2014-11-26 17:09:44.361182 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:44.361182 [DEBUG] mod_rayo.c:3399 Locate (id) 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 2
2014-11-26 17:09:44.390076 [DEBUG] mod_rayo.c:3410 Release 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 1
2014-11-26 17:09:44.390076 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10266: ref count = 1
2014-11-26 17:09:44.390076 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:44.390076 [DEBUG] mod_rayo.c:3407 Deliver 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost => usera@localhost/dev01-10266 <presence from='3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost' to='usera@localhost/dev01-10266'><ringing xmlns='urn:xmpp:rayo:1'/><delay xmlns='urn:xmpp:delay' stamp='2014-11-27T01:09:44Z'/></presence>
2014-11-26 17:09:44.390076 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10266: ref count = 1
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:44.390076 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10266, 127.0.0.1:36280, c2s_in SEND <presence from=3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost to=usera@localhost/dev01-10266><ringing xmlns=urn:xmpp:rayo:1/><delay xmlns=urn:xmpp:delay stamp=2014-11-27T01:09:44Z/></presence>
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/71999917 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/71999917 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] sofia.c:6614 Channel sofia/external/71999917 entering state [completing][200]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] sofia.c:6624 Remote SDP:
3afaefc6-e051-4beb-925b-0225ec68d8f2 v=0
3afaefc6-e051-4beb-925b-0225ec68d8f2 o=yate 1417050585 1417050585 IN IP4 192.168.90.101
3afaefc6-e051-4beb-925b-0225ec68d8f2 s=SIP Call
3afaefc6-e051-4beb-925b-0225ec68d8f2 c=IN IP4 192.168.90.101
3afaefc6-e051-4beb-925b-0225ec68d8f2 t=0 0
3afaefc6-e051-4beb-925b-0225ec68d8f2 m=audio 24662 RTP/AVP 8 101
3afaefc6-e051-4beb-925b-0225ec68d8f2 a=rtpmap:8 PCMA/8000
3afaefc6-e051-4beb-925b-0225ec68d8f2 a=rtpmap:101 telephone-event/8000
3afaefc6-e051-4beb-925b-0225ec68d8f2 
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/71999917 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/71999917 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] sofia.c:6614 Channel sofia/external/71999917 entering state [ready][200]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] sofia.c:6621 Duplicate SDP
3afaefc6-e051-4beb-925b-0225ec68d8f2 v=0
3afaefc6-e051-4beb-925b-0225ec68d8f2 o=yate 1417050585 1417050585 IN IP4 192.168.90.101
3afaefc6-e051-4beb-925b-0225ec68d8f2 s=SIP Call
3afaefc6-e051-4beb-925b-0225ec68d8f2 c=IN IP4 192.168.90.101
3afaefc6-e051-4beb-925b-0225ec68d8f2 t=0 0
3afaefc6-e051-4beb-925b-0225ec68d8f2 m=audio 24662 RTP/AVP 8 101
3afaefc6-e051-4beb-925b-0225ec68d8f2 a=rtpmap:8 PCMA/8000
3afaefc6-e051-4beb-925b-0225ec68d8f2 a=rtpmap:101 telephone-event/8000
3afaefc6-e051-4beb-925b-0225ec68d8f2 
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] switch_core_media.c:3670 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] switch_core_media.c:3531 Set telephone-event payload to 101
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] switch_core_media.c:2473 Set Codec sofia/external/71999917 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] switch_core_codec.c:111 sofia/external/71999917 Original read codec set to PCMA:8
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] switch_core_media.c:3852 Set 2833 dtmf send payload to 101
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] switch_core_media.c:5111 AUDIO RTP [sofia/external/71999917] 192.168.90.101 port 31072 -> 192.168.90.101 port 24662 codec: 8 ms: 20
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] switch_rtp.c:3521 Starting timer [soft] 160 bytes per 20ms
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] switch_core_media.c:5409 Set 2833 dtmf send payload to 101
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] switch_core_media.c:5415 Set 2833 dtmf receive payload to 101
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] mod_rayo.c:3598 got event CHANNEL_ANSWER
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10266 rayo event CHANNEL_ANSWER
2014-11-26 17:09:45.879392 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:45.879392 [DEBUG] mod_rayo.c:3380 Locate (id) 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 2
2014-11-26 17:09:45.879392 [DEBUG] mod_rayo.c:3386 Release 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 1
2014-11-26 17:09:45.879392 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10266: ref count = 1
2014-11-26 17:09:45.879392 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:45.879392 [DEBUG] mod_rayo.c:3385 Deliver 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost => usera@localhost/dev01-10266 <presence from='3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost' to='usera@localhost/dev01-10266'><answered xmlns='urn:xmpp:rayo:1'/><delay xmlns='urn:xmpp:delay' stamp='2014-11-27T01:09:45Z'/></presence>
2014-11-26 17:09:45.879392 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10266: ref count = 1
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.879392 [NOTICE] sofia.c:7475 Channel [sofia/external/71999917] has been answered
2014-11-26 17:09:45.915245 [DEBUG] switch_ivr_originate.c:3552 Originate Resulted in Success: [sofia/external/71999917]
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:45.915245 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10266, 127.0.0.1:36280, c2s_in SEND <presence from=3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost to=usera@localhost/dev01-10266><answered xmlns=urn:xmpp:rayo:1/><delay xmlns=urn:xmpp:delay stamp=2014-11-27T01:09:45Z/></presence>
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10266, 127.0.0.1:36280, c2s_in RECV <iq type="set" to="12583f8c-75d2-11e4-816d-379ee336ca8b@localhost" id="ab26c60b-1757-4440-a80c-c3b46f30c641"><join xmlns="urn:xmpp:rayo:1" call-uri="xmpp:3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost"/></iq>
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] xmpp_streams.c:1058 usera@localhost/dev01-10266, 127.0.0.1:36280, state = READY, node type = NODE_NORMAL
2014-11-26 17:09:45.968985 [DEBUG] mod_rayo.c:3912 Lock usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:45.968985 [DEBUG] mod_rayo.c:3056 usera@localhost/dev01-10266, recv iq, availability = ONLINE
2014-11-26 17:09:45.968985 [DEBUG] mod_rayo.c:3983 Release usera@localhost/dev01-10266: ref count = 1
2014-11-26 17:09:45.968985 [DEBUG] mod_rayo.c:774 Locate (jid) 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: ref count = 2
2014-11-26 17:09:45.968985 [DEBUG] mod_rayo.c:3059 Deliver usera@localhost/dev01-10266 => 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost <iq type='set' to='12583f8c-75d2-11e4-816d-379ee336ca8b@localhost' id='ab26c60b-1757-4440-a80c-c3b46f30c641' from='usera@localhost/dev01-10266'><join xmlns='urn:xmpp:rayo:1' call-uri='xmpp:3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost'/></iq>
2014-11-26 17:09:45.968985 [DEBUG] mod_rayo.c:655 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost, looking for CALL::set:urn:xmpp:rayo:1:join command
2014-11-26 17:09:45.968985 [DEBUG] mod_rayo.c:1816 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost, executing command
2014-11-26 17:09:45.968985 [DEBUG] mod_rayo.c:2082 Locate (jid) 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 2
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] switch_ivr_bridge.c:1873 (sofia/external/22334455@192.168.90.101) State Change CS_EXECUTE -> CS_HIBERNATE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_ivr_bridge.c:1875 (sofia/external/71999917) State Change CS_CONSUME_MEDIA -> CS_HIBERNATE
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
2014-11-26 17:09:45.968985 [DEBUG] mod_rayo.c:2107 Release 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 1
2014-11-26 17:09:45.968985 [DEBUG] mod_rayo.c:1818 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost, done executing command
2014-11-26 17:09:45.968985 [DEBUG] mod_rayo.c:781 Release 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: ref count = 1
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_channel.c:3689 (sofia/external/71999917) Callstate Change RINGING -> ACTIVE
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_HIBERNATE
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:550 (sofia/external/71999917) State HIBERNATE
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] mod_sofia.c:160 sofia/external/71999917 SOFIA HIBERNATE
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_ivr_bridge.c:835 (sofia/external/71999917) State Change CS_HIBERNATE -> CS_RESET
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:550 (sofia/external/71999917) State HIBERNATE going to sleep
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_RESET
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:531 (sofia/external/71999917) State RESET
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] mod_sofia.c:141 sofia/external/71999917 SOFIA RESET
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_ivr_bridge.c:820 sofia/external/71999917 CUSTOM RESET
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:118 sofia/external/71999917 Standard RESET
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:531 (sofia/external/71999917) State RESET going to sleep
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] mod_rayo.c:2719 dial: Call originated
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [INFO] switch_channel.c:3062 sofia/external/71999917 Flipping CID from "22334455" <22334455> to "Outbound Call" <71999917>
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] mod_rayo.c:2726 (sofia/external/71999917) State Change CS_RESET -> CS_EXECUTE
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_EXECUTE
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:535 (sofia/external/71999917) State EXECUTE
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] mod_sofia.c:178 sofia/external/71999917 SOFIA EXECUTE
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:258 sofia/external/71999917 Standard EXECUTE
3afaefc6-e051-4beb-925b-0225ec68d8f2 EXECUTE sofia/external/71999917 rayo()
2014-11-26 17:09:45.968985 [DEBUG] mod_rayo.c:3780 Locate (id) 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 2
2014-11-26 17:09:45.968985 [DEBUG] mod_rayo.c:3786 Release 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 1
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.968985 [DEBUG] switch_ivr.c:961 Codec Activated L16@8000hz 1 channels 20ms
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:535 (sofia/external/22334455@192.168.90.101) State EXECUTE going to sleep
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_HIBERNATE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:550 (sofia/external/22334455@192.168.90.101) State HIBERNATE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] mod_sofia.c:160 sofia/external/22334455@192.168.90.101 SOFIA HIBERNATE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] switch_ivr_bridge.c:835 (sofia/external/22334455@192.168.90.101) State Change CS_HIBERNATE -> CS_RESET
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:550 (sofia/external/22334455@192.168.90.101) State HIBERNATE going to sleep
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_RESET
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:531 (sofia/external/22334455@192.168.90.101) State RESET
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] mod_sofia.c:141 sofia/external/22334455@192.168.90.101 SOFIA RESET
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] switch_ivr_bridge.c:820 sofia/external/22334455@192.168.90.101 CUSTOM RESET
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] switch_ivr_bridge.c:827 (sofia/external/22334455@192.168.90.101) State Change CS_RESET -> CS_SOFT_EXECUTE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:531 (sofia/external/22334455@192.168.90.101) State RESET going to sleep
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_SOFT_EXECUTE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] switch_core_state_machine.c:541 (sofia/external/22334455@192.168.90.101) State SOFT_EXECUTE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] mod_sofia.c:600 SOFIA SOFT_EXECUTE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.968985 [DEBUG] switch_ivr_bridge.c:845 sofia/external/22334455@192.168.90.101 CUSTOM SOFT_EXECUTE
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10266 rayo event CHANNEL_EXECUTE
2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3526 Locate (id) 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 2
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3528 Application rayo execute
2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3529 Release 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 1
2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10266: ref count = 1
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3598 got event CHANNEL_PARK
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10266 rayo event CHANNEL_PARK
2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3487 Locate (id) 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 2
2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3515 Release 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 1
2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10266: ref count = 1
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE_COMPLETE
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10266 rayo event CHANNEL_EXECUTE_COMPLETE
2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3540 Locate (id) 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: ref count = 2
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3543 Application rayo execute complete: _none_
2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3546 Release 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: ref count = 1
2014-11-26 17:09:45.990388 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10266: ref count = 1
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:09:46.008749 [DEBUG] switch_rtp.c:5823 Correct ip/port confirmed.
2014-11-26 17:09:56.368803 [DEBUG] mod_commands.c:6276 BUGMIDDLE
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:58.270199 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10266, 127.0.0.1:36280, c2s_in RECV <iq type="get" to="localhost" id="blather0030"><ping xmlns="urn:xmpp:ping"/></iq>
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:58.270199 [DEBUG] xmpp_streams.c:1058 usera@localhost/dev01-10266, 127.0.0.1:36280, state = READY, node type = NODE_NORMAL
2014-11-26 17:09:58.270199 [DEBUG] mod_rayo.c:3912 Lock usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:58.270199 [DEBUG] mod_rayo.c:3056 usera@localhost/dev01-10266, recv iq, availability = ONLINE
2014-11-26 17:09:58.270199 [DEBUG] mod_rayo.c:3983 Release usera@localhost/dev01-10266: ref count = 1
2014-11-26 17:09:58.270199 [DEBUG] mod_rayo.c:774 Locate (jid) localhost: ref count = 2
2014-11-26 17:09:58.270199 [DEBUG] mod_rayo.c:3059 Deliver usera@localhost/dev01-10266 => localhost <iq type='get' to='localhost' id='blather0030' from='usera@localhost/dev01-10266'><ping xmlns='urn:xmpp:ping'/></iq>
2014-11-26 17:09:58.270199 [DEBUG] mod_rayo.c:655 localhost, looking for SERVER::get:urn:xmpp:ping:ping command
2014-11-26 17:09:58.270199 [DEBUG] mod_rayo.c:781 Release localhost: ref count = 1
2014-11-26 17:09:58.270199 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:09:58.270199 [DEBUG] mod_rayo.c:1754 Deliver localhost => usera@localhost/dev01-10266 <iq type='result' from='localhost' to='usera@localhost/dev01-10266' id='blather0030'/>
2014-11-26 17:09:58.270199 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10266: ref count = 1
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:09:58.270199 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10266, 127.0.0.1:36280, c2s_in SEND <iq type=result from=localhost to=usera@localhost/dev01-10266 id=blather0030/>
2014-11-26 17:10:01.188823 [NOTICE] mod_cdr_csv.c:123 Re-opened CDR logfile /opt/freeswitch/log/cdr-csv/Master.csv
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.350211 [NOTICE] switch_ivr_bridge.c:872 Hangup sofia/external/22334455@192.168.90.101 [CS_SOFT_EXECUTE] [DESTINATION_OUT_OF_ORDER]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.350211 [DEBUG] switch_channel.c:3222 Send signal sofia/external/22334455@192.168.90.101 [KILL]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.350211 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.350211 [NOTICE] switch_ivr_bridge.c:873 Hangup sofia/external/71999917 [CS_EXECUTE] [DESTINATION_OUT_OF_ORDER]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.350211 [DEBUG] switch_channel.c:3222 Send signal sofia/external/71999917 [KILL]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.350211 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.370400 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE_COMPLETE
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.370400 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10266 rayo event CHANNEL_EXECUTE_COMPLETE
2014-11-26 17:10:08.370400 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:10:08.370400 [DEBUG] mod_rayo.c:3540 Locate (id) 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 2
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.370400 [DEBUG] mod_rayo.c:3543 Application rayo execute complete: _none_
2014-11-26 17:10:08.370400 [DEBUG] mod_rayo.c:3546 Release 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 1
2014-11-26 17:10:08.370400 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10266: ref count = 1
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.370400 [DEBUG] switch_core_session.c:2893 sofia/external/71999917 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.370400 [DEBUG] switch_core_state_machine.c:535 (sofia/external/71999917) State EXECUTE going to sleep
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.370400 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_HANGUP
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.370400 [DEBUG] switch_core_state_machine.c:735 (sofia/external/71999917) Callstate Change ACTIVE -> HANGUP
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.370400 [DEBUG] switch_core_state_machine.c:737 (sofia/external/71999917) State HANGUP
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.370400 [DEBUG] mod_sofia.c:413 Channel sofia/external/71999917 hanging up, cause: DESTINATION_OUT_OF_ORDER
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.370400 [DEBUG] mod_sofia.c:465 Sending BYE to sofia/external/71999917
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.370400 [DEBUG] switch_core_state_machine.c:541 (sofia/external/22334455@192.168.90.101) State SOFT_EXECUTE going to sleep
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.370400 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_HANGUP
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:735 (sofia/external/22334455@192.168.90.101) Callstate Change ACTIVE -> HANGUP
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:737 (sofia/external/22334455@192.168.90.101) State HANGUP
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] mod_sofia.c:413 Channel sofia/external/22334455@192.168.90.101 hanging up, cause: DESTINATION_OUT_OF_ORDER
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] mod_sofia.c:465 Sending BYE to sofia/external/22334455@192.168.90.101
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:60 sofia/external/22334455@192.168.90.101 Standard HANGUP, cause: DESTINATION_OUT_OF_ORDER
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:737 (sofia/external/22334455@192.168.90.101) State HANGUP going to sleep
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:504 (sofia/external/22334455@192.168.90.101) State Change CS_HANGUP -> CS_REPORTING
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_REPORTING
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:823 (sofia/external/22334455@192.168.90.101) State REPORTING
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:104 sofia/external/22334455@192.168.90.101 Standard REPORTING, cause: DESTINATION_OUT_OF_ORDER
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:823 (sofia/external/22334455@192.168.90.101) State REPORTING going to sleep
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:498 (sofia/external/22334455@192.168.90.101) State Change CS_REPORTING -> CS_DESTROY
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] switch_core_session.c:1615 Session 49 (sofia/external/22334455@192.168.90.101) Locked, Waiting on external entities
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [NOTICE] switch_core_session.c:1633 Session 49 (sofia/external/22334455@192.168.90.101) Ended
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [NOTICE] switch_core_session.c:1637 Close Channel sofia/external/22334455@192.168.90.101 [CS_DESTROY]
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:626 (sofia/external/22334455@192.168.90.101) Running State Change CS_DESTROY
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:60 sofia/external/71999917 Standard HANGUP, cause: DESTINATION_OUT_OF_ORDER
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] rayo_cpa_component.c:130 Subscriber execute hangup
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] rayo_cpa_component.c:143 No subscribers for hangup
2014-11-26 17:10:08.428209 [DEBUG] mod_rayo.c:3350 Locate (id) 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: ref count = 2
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] mod_rayo.c:3360 Got channel destroy event
2014-11-26 17:10:08.428209 [DEBUG] mod_rayo.c:3365 Destroy 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost requested: ref_count = 2
2014-11-26 17:10:08.428209 [DEBUG] mod_rayo.c:3366 Release 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: ref count = 1
2014-11-26 17:10:08.428209 [DEBUG] mod_rayo.c:3369 Release 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost: ref count = 0
2014-11-26 17:10:08.428209 [DEBUG] mod_rayo.c:3369 Destroying 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] mod_rayo.c:1110 Sending <end> to offered client usera@localhost/dev01-10266
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:737 (sofia/external/71999917) State HANGUP going to sleep
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:504 (sofia/external/71999917) State Change CS_HANGUP -> CS_REPORTING
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_REPORTING
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:823 (sofia/external/71999917) State REPORTING
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:104 sofia/external/71999917 Standard REPORTING, cause: DESTINATION_OUT_OF_ORDER
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:823 (sofia/external/71999917) State REPORTING going to sleep
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:498 (sofia/external/71999917) State Change CS_REPORTING -> CS_DESTROY
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [DEBUG] switch_core_session.c:1615 Session 50 (sofia/external/71999917) Locked, Waiting on external entities
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [NOTICE] switch_core_session.c:1633 Session 50 (sofia/external/71999917) Ended
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [NOTICE] switch_core_session.c:1637 Close Channel sofia/external/71999917 [CS_DESTROY]
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:626 (sofia/external/71999917) Running State Change CS_DESTROY
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:636 (sofia/external/71999917) State DESTROY
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [DEBUG] mod_sofia.c:323 sofia/external/71999917 SOFIA DESTROY
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:111 sofia/external/71999917 Standard DESTROY
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:636 (sofia/external/71999917) State DESTROY going to sleep
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:636 (sofia/external/22334455@192.168.90.101) State DESTROY
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] mod_sofia.c:323 sofia/external/22334455@192.168.90.101 SOFIA DESTROY
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:111 sofia/external/22334455@192.168.90.101 Standard DESTROY
12583f8c-75d2-11e4-816d-379ee336ca8b 2014-11-26 17:10:08.428209 [DEBUG] switch_core_state_machine.c:636 (sofia/external/22334455@192.168.90.101) State DESTROY going to sleep
2014-11-26 17:10:08.475904 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:10:08.475904 [DEBUG] mod_rayo.c:1111 Deliver 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost => usera@localhost/dev01-10266 <presence from='12583f8c-75d2-11e4-816d-379ee336ca8b@localhost' to='usera@localhost/dev01-10266' type='unavailable'><end xmlns='urn:xmpp:rayo:1'><error platform-code='27'/><header name='X-accountcode' value='3000'/><header name='X-Firmafon-Inbound-Provider' value='telenor_ic'/></end><delay xmlns='urn:xmpp:delay' stamp='2014-11-27T01:10:08Z'/></presence>
2014-11-26 17:10:08.475904 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10266: ref count = 1
2014-11-26 17:10:08.475904 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:10:08.475904 [DEBUG] mod_rayo.c:1163 Deliver 12583f8c-75d2-11e4-816d-379ee336ca8b@localhost => usera@localhost/dev01-10266 <iq type='error' to='usera@localhost/dev01-10266' id='ab26c60b-1757-4440-a80c-c3b46f30c641' from='12583f8c-75d2-11e4-816d-379ee336ca8b@localhost'><join xmlns='urn:xmpp:rayo:1' call-uri='xmpp:3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost' direction='duplex' media='bridge' mixer-name=''/><error type='cancel'><item-not-found xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/><text xml:lang='en' xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'>call ended</text></error></iq>
2014-11-26 17:10:08.475904 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10266: ref count = 1
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.475904 [DEBUG] rayo_cpa_component.c:130 Subscriber execute hangup
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.475904 [DEBUG] rayo_cpa_component.c:143 No subscribers for hangup
2014-11-26 17:10:08.475904 [DEBUG] mod_rayo.c:3350 Locate (id) 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 2
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.475904 [DEBUG] mod_rayo.c:3360 Got channel destroy event
2014-11-26 17:10:08.475904 [DEBUG] mod_rayo.c:3365 Destroy 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost requested: ref_count = 2
2014-11-26 17:10:08.475904 [DEBUG] mod_rayo.c:3366 Release 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 1
2014-11-26 17:10:08.475904 [DEBUG] mod_rayo.c:3369 Release 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost: ref count = 0
2014-11-26 17:10:08.475904 [DEBUG] mod_rayo.c:3369 Destroying 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost
3afaefc6-e051-4beb-925b-0225ec68d8f2 2014-11-26 17:10:08.475904 [DEBUG] mod_rayo.c:1117 Sending <end> to DCP usera@localhost/dev01-10266
2014-11-26 17:10:08.475904 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10266: ref count = 2
2014-11-26 17:10:08.475904 [DEBUG] mod_rayo.c:1119 Deliver 3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost => usera@localhost/dev01-10266 <presence from='3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost' to='usera@localhost/dev01-10266' type='unavailable'><end xmlns='urn:xmpp:rayo:1'><error platform-code='27'/></end><delay xmlns='urn:xmpp:delay' stamp='2014-11-27T01:10:08Z'/></presence>
2014-11-26 17:10:08.475904 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10266: ref count = 1
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:10:08.475904 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10266, 127.0.0.1:36280, c2s_in SEND <presence from=12583f8c-75d2-11e4-816d-379ee336ca8b@localhost to=usera@localhost/dev01-10266 type=unavailable><end xmlns=urn:xmpp:rayo:1><error platform-code=27/><header name=X-accountcode value=3000/><header name=X-Firmafon-Inbound-Provider value=telenor_ic/></end><delay xmlns=urn:xmpp:delay stamp=2014-11-27T01:10:08Z/></presence>
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:10:08.475904 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10266, 127.0.0.1:36280, c2s_in SEND <iq type=error to=usera@localhost/dev01-10266 id=ab26c60b-1757-4440-a80c-c3b46f30c641 from=12583f8c-75d2-11e4-816d-379ee336ca8b@localhost><join xmlns=urn:xmpp:rayo:1 call-uri=xmpp:3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost direction=duplex media=bridge mixer-name=/><error type=cancel><item-not-found xmlns=urn:ietf:params:xml:ns:xmpp-stanzas/><text xml:lang=en xmlns=urn:ietf:params:xml:ns:xmpp-stanzas>call ended</text></error></iq>
67d46ba8-75d1-11e4-811e-379ee336ca8b 2014-11-26 17:10:08.475904 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10266, 127.0.0.1:36280, c2s_in SEND <presence from=3afaefc6-e051-4beb-925b-0225ec68d8f2@localhost to=usera@localhost/dev01-10266 type=unavailable><end xmlns=urn:xmpp:rayo:1><error platform-code=27/></end><delay xmlns=urn:xmpp:delay stamp=2014-11-27T01:10:08Z/></presence>
2014-11-26 17:10:18.689442 [DEBUG] mod_commands.c:6276 BUGEND

freeswitch-good.log

2014-11-26 17:18:30.189455 [NOTICE] mod_cdr_csv.c:123 Re-opened CDR logfile /opt/freeswitch/log/cdr-csv/Master.csv
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [NOTICE] switch_channel.c:1055 New Channel sofia/external/22334455@192.168.90.101 [506a3aea-75d3-11e4-8182-379ee336ca8b]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_NEW
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] sofia.c:8834 sofia/external/22334455@192.168.90.101 receiving invite from 192.168.90.101:5090 version: 1.4.14  64bit
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] sofia.c:6614 Channel sofia/external/22334455@192.168.90.101 entering state [received][100]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] sofia.c:6624 Remote SDP:
506a3aea-75d3-11e4-8182-379ee336ca8b v=0
506a3aea-75d3-11e4-8182-379ee336ca8b o=yate 1417051117 1417051117 IN IP4 192.168.90.101
506a3aea-75d3-11e4-8182-379ee336ca8b s=SIP Call
506a3aea-75d3-11e4-8182-379ee336ca8b c=IN IP4 192.168.90.101
506a3aea-75d3-11e4-8182-379ee336ca8b t=0 0
506a3aea-75d3-11e4-8182-379ee336ca8b m=audio 27018 RTP/AVP 0 8 101
506a3aea-75d3-11e4-8182-379ee336ca8b a=rtpmap:0 PCMU/8000
506a3aea-75d3-11e4-8182-379ee336ca8b a=rtpmap:8 PCMA/8000
506a3aea-75d3-11e4-8182-379ee336ca8b a=rtpmap:101 telephone-event/8000
506a3aea-75d3-11e4-8182-379ee336ca8b 
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_media.c:3670 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_media.c:3531 Set telephone-event payload to 101
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_media.c:2473 Set Codec sofia/external/22334455@192.168.90.101 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_codec.c:111 sofia/external/22334455@192.168.90.101 Original read codec set to PCMA:8
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_media.c:3861 Set 2833 dtmf send/recv payload to 101
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] sofia.c:6910 (sofia/external/22334455@192.168.90.101) State Change CS_NEW -> CS_INIT
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_state_machine.c:491 (sofia/external/22334455@192.168.90.101) State NEW
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_INIT
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_state_machine.c:512 (sofia/external/22334455@192.168.90.101) State INIT
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] mod_sofia.c:87 sofia/external/22334455@192.168.90.101 SOFIA INIT
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_state_machine.c:40 sofia/external/22334455@192.168.90.101 Standard INIT
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_state_machine.c:48 (sofia/external/22334455@192.168.90.101) State Change CS_INIT -> CS_ROUTING
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_state_machine.c:512 (sofia/external/22334455@192.168.90.101) State INIT going to sleep
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_ROUTING
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_channel.c:2184 (sofia/external/22334455@192.168.90.101) Callstate Change DOWN -> RINGING
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_state_machine.c:528 (sofia/external/22334455@192.168.90.101) State ROUTING
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] mod_sofia.c:123 sofia/external/22334455@192.168.90.101 SOFIA ROUTING
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_state_machine.c:166 sofia/external/22334455@192.168.90.101 Standard ROUTING
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [INFO] mod_dialplan_xml.c:635 Processing 22334455 <22334455>->71999917 in context public
506a3aea-75d3-11e4-8182-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 parsing [public->unloop] continue=false
506a3aea-75d3-11e4-8182-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
506a3aea-75d3-11e4-8182-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
506a3aea-75d3-11e4-8182-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 parsing [public->outside_call] continue=true
506a3aea-75d3-11e4-8182-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Absolute Condition [outside_call]
506a3aea-75d3-11e4-8182-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Action set(outside_call=true)
506a3aea-75d3-11e4-8182-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
506a3aea-75d3-11e4-8182-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 parsing [public->rayo] continue=false
506a3aea-75d3-11e4-8182-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Regex (FAIL) [rayo] ${sip_h_X-accountcode}(3000) =~ /^1000$/ break=never
506a3aea-75d3-11e4-8182-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Regex (PASS) [rayo] ${sip_h_X-accountcode}(3000) =~ /^3000$/ break=never
506a3aea-75d3-11e4-8182-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Action set(sip_h_X-Firmafon-Inbound-Provider=telenor_ic)
506a3aea-75d3-11e4-8182-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Absolute Condition [rayo]
506a3aea-75d3-11e4-8182-379ee336ca8b Dialplan: sofia/external/22334455@192.168.90.101 Action rayo()
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_state_machine.c:216 (sofia/external/22334455@192.168.90.101) State Change CS_ROUTING -> CS_EXECUTE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_state_machine.c:528 (sofia/external/22334455@192.168.90.101) State ROUTING going to sleep
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_EXECUTE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_state_machine.c:535 (sofia/external/22334455@192.168.90.101) State EXECUTE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] mod_sofia.c:178 sofia/external/22334455@192.168.90.101 SOFIA EXECUTE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] switch_core_state_machine.c:258 sofia/external/22334455@192.168.90.101 Standard EXECUTE
506a3aea-75d3-11e4-8182-379ee336ca8b EXECUTE sofia/external/22334455@192.168.90.101 set(outside_call=true)
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] mod_dptools.c:1435 sofia/external/22334455@192.168.90.101 SET [outside_call]=[true]
506a3aea-75d3-11e4-8182-379ee336ca8b EXECUTE sofia/external/22334455@192.168.90.101 set(RFC2822_DATE=Wed, 26 Nov 2014 17:18:37 -0800)
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] mod_dptools.c:1435 sofia/external/22334455@192.168.90.101 SET [RFC2822_DATE]=[Wed, 26 Nov 2014 17:18:37 -0800]
506a3aea-75d3-11e4-8182-379ee336ca8b EXECUTE sofia/external/22334455@192.168.90.101 set(sip_h_X-Firmafon-Inbound-Provider=telenor_ic)
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.552834 [DEBUG] mod_dptools.c:1435 sofia/external/22334455@192.168.90.101 SET [sip_h_X-Firmafon-Inbound-Provider]=[telenor_ic]
506a3aea-75d3-11e4-8182-379ee336ca8b EXECUTE sofia/external/22334455@192.168.90.101 rayo()
2014-11-26 17:18:37.585985 [DEBUG] mod_rayo.c:3825 Init 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.585985 [DEBUG] mod_rayo.c:3836 Offering call for Rayo 3PCC
2014-11-26 17:18:37.585985 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:37.585985 [DEBUG] mod_rayo.c:3859 Deliver 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost => usera@localhost/dev01-10657 <presence from='506a3aea-75d3-11e4-8182-379ee336ca8b@localhost' to='usera@localhost/dev01-10657'><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='urn:xmpp:rayo:call:1' ver='L9rOKMEJl9rssEggArljiapRd9k='/><offer xmlns='urn:xmpp:rayo:1' from='sip:22334455@192.168.90.101' to='sip:71999917@192.168.90.101'><header name='from' value='&quot;22334455&quot; &lt;sip:22334455@192.168.90.101&gt;;tag=2061909510'/><header name='to' value='&lt;sip:71999917@192.168.90.101&gt;'/><header name='via' value='SIP/2.0/UDP 192.168.90.101:5090;rport=5090;branch=z9hG4bK1022204622'/><header name='X-accountcode' value='3000'/><header name='X-Firmafon-Inbound-Provider' value='telenor_ic'/></offer><delay xmlns='urn:xmpp:delay' stamp='2014-11-27T01:18:37Z'/></presence>
2014-11-26 17:18:37.585985 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10657: ref count = 1
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.585985 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.585985 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE_COMPLETE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.585985 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.585985 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE_COMPLETE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.585985 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.585985 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE_COMPLETE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.585985 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.585985 [DEBUG] mod_rayo.c:3598 got event CHANNEL_PARK
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:37.585985 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in SEND <presence from=506a3aea-75d3-11e4-8182-379ee336ca8b@localhost to=usera@localhost/dev01-10657><c xmlns=http://jabber.org/protocol/caps hash=sha-1 node=urn:xmpp:rayo:call:1 ver=L9rOKMEJl9rssEggArljiapRd9k=/><offer xmlns=urn:xmpp:rayo:1 from=sip:22334455@192.168.90.101 to=sip:71999917@192.168.90.101><header name=from value=&quot;22334455&quot; &lt;sip:22334455@192.168.90.101&gt;;tag=2061909510/><header name=to value=&lt;sip:71999917@192.168.90.101&gt;/><header name=via value=SIP/2.0/UDP 192.168.90.101:5090;rport=5090;branch=z9hG4bK1022204622/><header name=X-accountcode value=3000/><header name=X-Firmafon-Inbound-Provider value=telenor_ic/></offer><delay xmlns=urn:xmpp:delay stamp=2014-11-27T01:18:37Z/></presence>
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:37.730143 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in RECV <iq type="set" to="506a3aea-75d3-11e4-8182-379ee336ca8b@localhost" id="a87a6d0e-7d83-4977-ac0e-8769a9931e6a"><accept xmlns="urn:xmpp:rayo:1"/></iq>
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:37.730143 [DEBUG] xmpp_streams.c:1058 usera@localhost/dev01-10657, 127.0.0.1:36291, state = READY, node type = NODE_NORMAL
2014-11-26 17:18:37.730143 [DEBUG] mod_rayo.c:3912 Lock usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:37.730143 [DEBUG] mod_rayo.c:3056 usera@localhost/dev01-10657, recv iq, availability = ONLINE
2014-11-26 17:18:37.730143 [DEBUG] mod_rayo.c:3983 Release usera@localhost/dev01-10657: ref count = 1
2014-11-26 17:18:37.730143 [DEBUG] mod_rayo.c:774 Locate (jid) 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 2
2014-11-26 17:18:37.730143 [DEBUG] mod_rayo.c:3059 Deliver usera@localhost/dev01-10657 => 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost <iq type='set' to='506a3aea-75d3-11e4-8182-379ee336ca8b@localhost' id='a87a6d0e-7d83-4977-ac0e-8769a9931e6a' from='usera@localhost/dev01-10657'><accept xmlns='urn:xmpp:rayo:1'/></iq>
2014-11-26 17:18:37.730143 [DEBUG] mod_rayo.c:655 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost, looking for CALL::set:urn:xmpp:rayo:1:accept command
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.730143 [INFO] mod_rayo.c:1636 usera@localhost/dev01-10657 has control of call
2014-11-26 17:18:37.730143 [DEBUG] mod_rayo.c:1816 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost, executing command
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.730143 [INFO] mod_rayo.c:1953 Sending early media
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.730143 [DEBUG] switch_core_media.c:5111 AUDIO RTP [sofia/external/22334455@192.168.90.101] 192.168.90.101 port 28972 -> 192.168.90.101 port 27018 codec: 8 ms: 20
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.730143 [DEBUG] switch_rtp.c:3521 Starting timer [soft] 160 bytes per 20ms
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.730143 [DEBUG] switch_core_media.c:5409 Set 2833 dtmf send payload to 101
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.730143 [DEBUG] switch_core_media.c:5415 Set 2833 dtmf receive payload to 101
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.730143 [DEBUG] mod_sofia.c:2247 Ring SDP:
506a3aea-75d3-11e4-8182-379ee336ca8b v=0
506a3aea-75d3-11e4-8182-379ee336ca8b o=FreeSWITCH 1417022145 1417022146 IN IP4 192.168.90.101
506a3aea-75d3-11e4-8182-379ee336ca8b s=FreeSWITCH
506a3aea-75d3-11e4-8182-379ee336ca8b c=IN IP4 192.168.90.101
506a3aea-75d3-11e4-8182-379ee336ca8b t=0 0
506a3aea-75d3-11e4-8182-379ee336ca8b m=audio 28972 RTP/AVP 8 101
506a3aea-75d3-11e4-8182-379ee336ca8b a=rtpmap:8 PCMA/8000
506a3aea-75d3-11e4-8182-379ee336ca8b a=rtpmap:101 telephone-event/8000
506a3aea-75d3-11e4-8182-379ee336ca8b a=fmtp:101 0-16
506a3aea-75d3-11e4-8182-379ee336ca8b a=ptime:20
506a3aea-75d3-11e4-8182-379ee336ca8b a=sendrecv
506a3aea-75d3-11e4-8182-379ee336ca8b 
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.730143 [NOTICE] mod_sofia.c:2250 Pre-Answer sofia/external/22334455@192.168.90.101!
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.730143 [DEBUG] switch_channel.c:3399 (sofia/external/22334455@192.168.90.101) Callstate Change RINGING -> EARLY
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.730143 [DEBUG] switch_core_session.c:908 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
2014-11-26 17:18:37.730143 [DEBUG] mod_rayo.c:1818 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost, done executing command
2014-11-26 17:18:37.730143 [DEBUG] mod_rayo.c:781 Release 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 1
2014-11-26 17:18:37.730143 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:37.730143 [DEBUG] mod_rayo.c:1824 Deliver 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost => usera@localhost/dev01-10657 <iq from='506a3aea-75d3-11e4-8182-379ee336ca8b@localhost' to='usera@localhost/dev01-10657' type='result' id='a87a6d0e-7d83-4977-ac0e-8769a9931e6a'/>
2014-11-26 17:18:37.730143 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10657: ref count = 1
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.730143 [DEBUG] mod_rayo.c:3598 got event CHANNEL_PROGRESS_MEDIA
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.730143 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10657 rayo event CHANNEL_PROGRESS_MEDIA
2014-11-26 17:18:37.730143 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:37.730143 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10657: ref count = 1
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.730143 [DEBUG] switch_ivr.c:961 Codec Activated L16@8000hz 1 channels 20ms
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:37.804370 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in SEND <iq from=506a3aea-75d3-11e4-8182-379ee336ca8b@localhost to=usera@localhost/dev01-10657 type=result id=a87a6d0e-7d83-4977-ac0e-8769a9931e6a/>
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.804370 [DEBUG] switch_rtp.c:5823 Correct ip/port confirmed.
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:37.804370 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in RECV <iq type="set" to="506a3aea-75d3-11e4-8182-379ee336ca8b@localhost" id="05fd4c35-260c-4de1-842c-df22405f06e2"><answer xmlns="urn:xmpp:rayo:1"/></iq>
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:37.804370 [DEBUG] xmpp_streams.c:1058 usera@localhost/dev01-10657, 127.0.0.1:36291, state = READY, node type = NODE_NORMAL
2014-11-26 17:18:37.804370 [DEBUG] mod_rayo.c:3912 Lock usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:37.804370 [DEBUG] mod_rayo.c:3056 usera@localhost/dev01-10657, recv iq, availability = ONLINE
2014-11-26 17:18:37.804370 [DEBUG] mod_rayo.c:3983 Release usera@localhost/dev01-10657: ref count = 1
2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:774 Locate (jid) 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 2
2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:3059 Deliver usera@localhost/dev01-10657 => 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost <iq type='set' to='506a3aea-75d3-11e4-8182-379ee336ca8b@localhost' id='05fd4c35-260c-4de1-842c-df22405f06e2' from='usera@localhost/dev01-10657'><answer xmlns='urn:xmpp:rayo:1'/></iq>
2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:655 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost, looking for CALL::set:urn:xmpp:rayo:1:answer command
2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:1816 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost, executing command
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.841822 [DEBUG] mod_sofia.c:780 Local SDP sofia/external/22334455@192.168.90.101:
506a3aea-75d3-11e4-8182-379ee336ca8b v=0
506a3aea-75d3-11e4-8182-379ee336ca8b o=FreeSWITCH 1417022145 1417022147 IN IP4 192.168.90.101
506a3aea-75d3-11e4-8182-379ee336ca8b s=FreeSWITCH
506a3aea-75d3-11e4-8182-379ee336ca8b c=IN IP4 192.168.90.101
506a3aea-75d3-11e4-8182-379ee336ca8b t=0 0
506a3aea-75d3-11e4-8182-379ee336ca8b m=audio 28972 RTP/AVP 8 101
506a3aea-75d3-11e4-8182-379ee336ca8b a=rtpmap:8 PCMA/8000
506a3aea-75d3-11e4-8182-379ee336ca8b a=rtpmap:101 telephone-event/8000
506a3aea-75d3-11e4-8182-379ee336ca8b a=fmtp:101 0-16
506a3aea-75d3-11e4-8182-379ee336ca8b a=ptime:20
506a3aea-75d3-11e4-8182-379ee336ca8b a=sendrecv
506a3aea-75d3-11e4-8182-379ee336ca8b 
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.841822 [DEBUG] switch_core_session.c:908 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.841822 [NOTICE] mod_rayo.c:1972 Channel [sofia/external/22334455@192.168.90.101] has been answered
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.841822 [DEBUG] switch_channel.c:3689 (sofia/external/22334455@192.168.90.101) Callstate Change EARLY -> ACTIVE
2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:1818 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost, done executing command
2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:781 Release 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 1
2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:1824 Deliver 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost => usera@localhost/dev01-10657 <iq from='506a3aea-75d3-11e4-8182-379ee336ca8b@localhost' to='usera@localhost/dev01-10657' type='result' id='05fd4c35-260c-4de1-842c-df22405f06e2'/>
2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10657: ref count = 1
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:3598 got event CHANNEL_ANSWER
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10657 rayo event CHANNEL_ANSWER
2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:3380 Locate (id) 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 2
2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:3386 Release 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 1
2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10657: ref count = 1
2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:3385 Deliver 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost => usera@localhost/dev01-10657 <presence from='506a3aea-75d3-11e4-8182-379ee336ca8b@localhost' to='usera@localhost/dev01-10657'><answered xmlns='urn:xmpp:rayo:1'/><delay xmlns='urn:xmpp:delay' stamp='2014-11-27T01:18:37Z'/></presence>
2014-11-26 17:18:37.841822 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10657: ref count = 1
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.841822 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.841822 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.841822 [DEBUG] sofia.c:6607 Channel sofia/external/22334455@192.168.90.101 skipping state [early][183]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.841822 [DEBUG] sofia.c:6614 Channel sofia/external/22334455@192.168.90.101 entering state [completed][200]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.841822 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.841822 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.841822 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:37.940032 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in SEND <iq from=506a3aea-75d3-11e4-8182-379ee336ca8b@localhost to=usera@localhost/dev01-10657 type=result id=05fd4c35-260c-4de1-842c-df22405f06e2/>
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:37.990774 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in SEND <presence from=506a3aea-75d3-11e4-8182-379ee336ca8b@localhost to=usera@localhost/dev01-10657><answered xmlns=urn:xmpp:rayo:1/><delay xmlns=urn:xmpp:delay stamp=2014-11-27T01:18:37Z/></presence>
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:37.990774 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in RECV <iq type="set" to="localhost" id="39cbd652-d221-4e9f-bade-5e7d49a81c0c"><dial xmlns="urn:xmpp:rayo:1" to="sofia/gateway/development_mvno_link1/71999917" uri="xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost"/></iq>
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:37.990774 [DEBUG] xmpp_streams.c:1058 usera@localhost/dev01-10657, 127.0.0.1:36291, state = READY, node type = NODE_NORMAL
2014-11-26 17:18:37.990774 [DEBUG] mod_rayo.c:3912 Lock usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:37.990774 [DEBUG] mod_rayo.c:3056 usera@localhost/dev01-10657, recv iq, availability = ONLINE
2014-11-26 17:18:37.990774 [DEBUG] mod_rayo.c:3983 Release usera@localhost/dev01-10657: ref count = 1
2014-11-26 17:18:37.990774 [DEBUG] mod_rayo.c:774 Locate (jid) localhost: ref count = 2
2014-11-26 17:18:37.990774 [DEBUG] mod_rayo.c:3059 Deliver usera@localhost/dev01-10657 => localhost <iq type='set' to='localhost' id='39cbd652-d221-4e9f-bade-5e7d49a81c0c' from='usera@localhost/dev01-10657'><dial xmlns='urn:xmpp:rayo:1' to='sofia/gateway/development_mvno_link1/71999917' uri='xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost'/></iq>
2014-11-26 17:18:37.990774 [DEBUG] mod_rayo.c:655 localhost, looking for SERVER::set:urn:xmpp:rayo:1:dial command
2014-11-26 17:18:37.990774 [DEBUG] mod_rayo.c:781 Release localhost: ref count = 1
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:37.990774 [DEBUG] sofia.c:6614 Channel sofia/external/22334455@192.168.90.101 entering state [ready][200]
2014-11-26 17:18:38.009615 [DEBUG] mod_rayo.c:2591 Init 1c905694-1210-4116-b08b-30421af2b195@localhost
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.009615 [INFO] mod_rayo.c:2598 usera@localhost/dev01-10657 has control of call
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.009615 [DEBUG] mod_rayo.c:2712 dial: Using dialstring: sofia/gateway/development_mvno_link1/71999917
2014-11-26 17:18:38.009615 [DEBUG] switch_ivr_originate.c:2079 Parsing global variables
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.009615 [NOTICE] switch_channel.c:1055 New Channel sofia/external/71999917 [1c905694-1210-4116-b08b-30421af2b195]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.009615 [DEBUG] mod_sofia.c:4615 (sofia/external/71999917) State Change CS_NEW -> CS_INIT
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.009615 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.009615 [DEBUG] switch_core_session.c:612 sofia/external/71999917 set UUID=1c905694-1210-4116-b08b-30421af2b195
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_INIT
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] switch_core_state_machine.c:512 (sofia/external/71999917) State INIT
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] mod_sofia.c:87 sofia/external/71999917 SOFIA INIT
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] sofia_glue.c:1232 sofia/external/71999917 sending invite version: 1.4.14  64bit
1c905694-1210-4116-b08b-30421af2b195 Local SDP:
1c905694-1210-4116-b08b-30421af2b195 v=0
1c905694-1210-4116-b08b-30421af2b195 o=FreeSWITCH 1417028034 1417028035 IN IP4 192.168.90.101
1c905694-1210-4116-b08b-30421af2b195 s=FreeSWITCH
1c905694-1210-4116-b08b-30421af2b195 c=IN IP4 192.168.90.101
1c905694-1210-4116-b08b-30421af2b195 t=0 0
1c905694-1210-4116-b08b-30421af2b195 m=audio 23084 RTP/AVP 8 101 13
1c905694-1210-4116-b08b-30421af2b195 a=rtpmap:8 PCMA/8000
1c905694-1210-4116-b08b-30421af2b195 a=rtpmap:101 telephone-event/8000
1c905694-1210-4116-b08b-30421af2b195 a=fmtp:101 0-16
1c905694-1210-4116-b08b-30421af2b195 a=ptime:20
1c905694-1210-4116-b08b-30421af2b195 a=sendrecv
1c905694-1210-4116-b08b-30421af2b195 
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] switch_core_state_machine.c:40 sofia/external/71999917 Standard INIT
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] switch_core_state_machine.c:48 (sofia/external/71999917) State Change CS_INIT -> CS_ROUTING
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] switch_core_state_machine.c:512 (sofia/external/71999917) State INIT going to sleep
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_ROUTING
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] switch_core_state_machine.c:528 (sofia/external/71999917) State ROUTING
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] mod_sofia.c:123 sofia/external/71999917 SOFIA ROUTING
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] switch_ivr_originate.c:67 (sofia/external/71999917) State Change CS_ROUTING -> CS_CONSUME_MEDIA
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] switch_core_state_machine.c:528 (sofia/external/71999917) State ROUTING going to sleep
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_CONSUME_MEDIA
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] switch_core_state_machine.c:547 (sofia/external/71999917) State CONSUME_MEDIA
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] switch_core_state_machine.c:547 (sofia/external/71999917) State CONSUME_MEDIA going to sleep
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] mod_rayo.c:3598 got event CHANNEL_ORIGINATE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10657 rayo event CHANNEL_ORIGINATE
2014-11-26 17:18:38.069347 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:38.069347 [DEBUG] mod_rayo.c:3317 Locate (id) 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 2
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.069347 [DEBUG] mod_rayo.c:3322 Got originate event
2014-11-26 17:18:38.069347 [DEBUG] mod_rayo.c:3341 Release 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 1
2014-11-26 17:18:38.069347 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10657: ref count = 1
2014-11-26 17:18:38.069347 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:38.069347 [DEBUG] mod_rayo.c:3336 Deliver 1c905694-1210-4116-b08b-30421af2b195@localhost => usera@localhost/dev01-10657 <iq from='localhost' to='usera@localhost/dev01-10657' id='39cbd652-d221-4e9f-bade-5e7d49a81c0c' type='result'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost'/></iq>
2014-11-26 17:18:38.069347 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10657: ref count = 1
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:38.110373 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in SEND <iq from=localhost to=usera@localhost/dev01-10657 id=39cbd652-d221-4e9f-bade-5e7d49a81c0c type=result><ref xmlns=urn:xmpp:rayo:1 uri=xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost/></iq>
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.110373 [DEBUG] sofia.c:6614 Channel sofia/external/71999917 entering state [calling][0]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.218550 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.218550 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.218550 [DEBUG] sofia.c:6614 Channel sofia/external/71999917 entering state [proceeding][180]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.218550 [NOTICE] sofia.c:6716 Ring-Ready sofia/external/71999917!
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.272023 [DEBUG] switch_channel.c:3277 (sofia/external/71999917) Callstate Change DOWN -> RINGING
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.272023 [DEBUG] mod_rayo.c:3598 got event CHANNEL_PROGRESS
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:38.272023 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10657 rayo event CHANNEL_PROGRESS
2014-11-26 17:18:38.272023 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:38.272023 [DEBUG] mod_rayo.c:3399 Locate (id) 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 2
2014-11-26 17:18:38.272023 [DEBUG] mod_rayo.c:3410 Release 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 1
2014-11-26 17:18:38.272023 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10657: ref count = 1
2014-11-26 17:18:38.272023 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:38.272023 [DEBUG] mod_rayo.c:3407 Deliver 1c905694-1210-4116-b08b-30421af2b195@localhost => usera@localhost/dev01-10657 <presence from='1c905694-1210-4116-b08b-30421af2b195@localhost' to='usera@localhost/dev01-10657'><ringing xmlns='urn:xmpp:rayo:1'/><delay xmlns='urn:xmpp:delay' stamp='2014-11-27T01:18:38Z'/></presence>
2014-11-26 17:18:38.272023 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10657: ref count = 1
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:38.295262 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in SEND <presence from=1c905694-1210-4116-b08b-30421af2b195@localhost to=usera@localhost/dev01-10657><ringing xmlns=urn:xmpp:rayo:1/><delay xmlns=urn:xmpp:delay stamp=2014-11-27T01:18:38Z/></presence>
2014-11-26 17:18:43.439876 [DEBUG] mod_commands.c:6276 BUGMIDDLE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] sofia.c:6614 Channel sofia/external/71999917 entering state [completing][200]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] sofia.c:6624 Remote SDP:
1c905694-1210-4116-b08b-30421af2b195 v=0
1c905694-1210-4116-b08b-30421af2b195 o=yate 1417051125 1417051125 IN IP4 192.168.90.101
1c905694-1210-4116-b08b-30421af2b195 s=SIP Call
1c905694-1210-4116-b08b-30421af2b195 c=IN IP4 192.168.90.101
1c905694-1210-4116-b08b-30421af2b195 t=0 0
1c905694-1210-4116-b08b-30421af2b195 m=audio 21896 RTP/AVP 8 101
1c905694-1210-4116-b08b-30421af2b195 a=rtpmap:8 PCMA/8000
1c905694-1210-4116-b08b-30421af2b195 a=rtpmap:101 telephone-event/8000
1c905694-1210-4116-b08b-30421af2b195 
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] sofia.c:6614 Channel sofia/external/71999917 entering state [ready][200]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] sofia.c:6621 Duplicate SDP
1c905694-1210-4116-b08b-30421af2b195 v=0
1c905694-1210-4116-b08b-30421af2b195 o=yate 1417051125 1417051125 IN IP4 192.168.90.101
1c905694-1210-4116-b08b-30421af2b195 s=SIP Call
1c905694-1210-4116-b08b-30421af2b195 c=IN IP4 192.168.90.101
1c905694-1210-4116-b08b-30421af2b195 t=0 0
1c905694-1210-4116-b08b-30421af2b195 m=audio 21896 RTP/AVP 8 101
1c905694-1210-4116-b08b-30421af2b195 a=rtpmap:8 PCMA/8000
1c905694-1210-4116-b08b-30421af2b195 a=rtpmap:101 telephone-event/8000
1c905694-1210-4116-b08b-30421af2b195 
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] switch_core_media.c:3670 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] switch_core_media.c:3531 Set telephone-event payload to 101
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] switch_core_media.c:2473 Set Codec sofia/external/71999917 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] switch_core_codec.c:111 sofia/external/71999917 Original read codec set to PCMA:8
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] switch_core_media.c:3852 Set 2833 dtmf send payload to 101
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] switch_core_media.c:5111 AUDIO RTP [sofia/external/71999917] 192.168.90.101 port 23084 -> 192.168.90.101 port 21896 codec: 8 ms: 20
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] switch_rtp.c:3521 Starting timer [soft] 160 bytes per 20ms
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] switch_core_media.c:5409 Set 2833 dtmf send payload to 101
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.356727 [DEBUG] switch_core_media.c:5415 Set 2833 dtmf receive payload to 101
2014-11-26 17:18:45.356727 [DEBUG] switch_ivr_originate.c:3552 Originate Resulted in Success: [sofia/external/71999917]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3598 got event CHANNEL_ANSWER
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10657 rayo event CHANNEL_ANSWER
2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3380 Locate (id) 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 2
2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3386 Release 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 1
2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10657: ref count = 1
2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3385 Deliver 1c905694-1210-4116-b08b-30421af2b195@localhost => usera@localhost/dev01-10657 <presence from='1c905694-1210-4116-b08b-30421af2b195@localhost' to='usera@localhost/dev01-10657'><answered xmlns='urn:xmpp:rayo:1'/><delay xmlns='urn:xmpp:delay' stamp='2014-11-27T01:18:45Z'/></presence>
2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10657: ref count = 1
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [NOTICE] sofia.c:7475 Channel [sofia/external/71999917] has been answered
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [DEBUG] switch_channel.c:3689 (sofia/external/71999917) Callstate Change RINGING -> ACTIVE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:2719 dial: Call originated
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [INFO] switch_channel.c:3062 sofia/external/71999917 Flipping CID from "" <0000000000> to "Outbound Call" <71999917>
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:2726 (sofia/external/71999917) State Change CS_CONSUME_MEDIA -> CS_EXECUTE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_EXECUTE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [DEBUG] switch_core_state_machine.c:535 (sofia/external/71999917) State EXECUTE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [DEBUG] mod_sofia.c:178 sofia/external/71999917 SOFIA EXECUTE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [DEBUG] switch_core_state_machine.c:258 sofia/external/71999917 Standard EXECUTE
1c905694-1210-4116-b08b-30421af2b195 EXECUTE sofia/external/71999917 rayo()
2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3780 Locate (id) 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 2
2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3786 Release 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 1
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [DEBUG] switch_ivr.c:961 Codec Activated L16@8000hz 1 channels 20ms
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10657 rayo event CHANNEL_EXECUTE
2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3526 Locate (id) 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 2
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3528 Application rayo execute
2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3529 Release 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 1
2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10657: ref count = 1
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3598 got event CHANNEL_PARK
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10657 rayo event CHANNEL_PARK
2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3487 Locate (id) 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 2
2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3515 Release 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 1
2014-11-26 17:18:45.450328 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10657: ref count = 1
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.468644 [DEBUG] switch_rtp.c:5823 Correct ip/port confirmed.
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:45.468644 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in SEND <presence from=1c905694-1210-4116-b08b-30421af2b195@localhost to=usera@localhost/dev01-10657><answered xmlns=urn:xmpp:rayo:1/><delay xmlns=urn:xmpp:delay stamp=2014-11-27T01:18:45Z/></presence>
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:45.496022 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in RECV <iq type="set" to="506a3aea-75d3-11e4-8182-379ee336ca8b@localhost" id="82eeed8d-38fb-4591-ba85-8908bb0c6d49"><join xmlns="urn:xmpp:rayo:1" call-uri="xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost"/></iq>
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:45.496022 [DEBUG] xmpp_streams.c:1058 usera@localhost/dev01-10657, 127.0.0.1:36291, state = READY, node type = NODE_NORMAL
2014-11-26 17:18:45.496022 [DEBUG] mod_rayo.c:3912 Lock usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:45.496022 [DEBUG] mod_rayo.c:3056 usera@localhost/dev01-10657, recv iq, availability = ONLINE
2014-11-26 17:18:45.496022 [DEBUG] mod_rayo.c:3983 Release usera@localhost/dev01-10657: ref count = 1
2014-11-26 17:18:45.496022 [DEBUG] mod_rayo.c:774 Locate (jid) 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 2
2014-11-26 17:18:45.496022 [DEBUG] mod_rayo.c:3059 Deliver usera@localhost/dev01-10657 => 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost <iq type='set' to='506a3aea-75d3-11e4-8182-379ee336ca8b@localhost' id='82eeed8d-38fb-4591-ba85-8908bb0c6d49' from='usera@localhost/dev01-10657'><join xmlns='urn:xmpp:rayo:1' call-uri='xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost'/></iq>
2014-11-26 17:18:45.496022 [DEBUG] mod_rayo.c:655 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost, looking for CALL::set:urn:xmpp:rayo:1:join command
2014-11-26 17:18:45.496022 [DEBUG] mod_rayo.c:1816 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost, executing command
2014-11-26 17:18:45.496022 [DEBUG] mod_rayo.c:2082 Locate (jid) 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 2
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.496022 [DEBUG] switch_ivr_bridge.c:1873 (sofia/external/22334455@192.168.90.101) State Change CS_EXECUTE -> CS_HIBERNATE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.496022 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.496022 [DEBUG] switch_ivr_bridge.c:1875 (sofia/external/71999917) State Change CS_EXECUTE -> CS_HIBERNATE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.496022 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
2014-11-26 17:18:45.496022 [DEBUG] mod_rayo.c:2107 Release 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 1
2014-11-26 17:18:45.496022 [DEBUG] mod_rayo.c:1818 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost, done executing command
2014-11-26 17:18:45.496022 [DEBUG] mod_rayo.c:781 Release 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 1
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:535 (sofia/external/71999917) State EXECUTE going to sleep
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_HIBERNATE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:550 (sofia/external/71999917) State HIBERNATE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] mod_sofia.c:160 sofia/external/71999917 SOFIA HIBERNATE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_ivr_bridge.c:835 (sofia/external/71999917) State Change CS_HIBERNATE -> CS_RESET
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:550 (sofia/external/71999917) State HIBERNATE going to sleep
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_RESET
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:531 (sofia/external/71999917) State RESET
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] mod_sofia.c:141 sofia/external/71999917 SOFIA RESET
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_ivr_bridge.c:820 sofia/external/71999917 CUSTOM RESET
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:118 sofia/external/71999917 Standard RESET
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:531 (sofia/external/71999917) State RESET going to sleep
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE_COMPLETE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10657 rayo event CHANNEL_EXECUTE_COMPLETE
2014-11-26 17:18:45.530354 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:45.530354 [DEBUG] mod_rayo.c:3540 Locate (id) 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 2
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] mod_rayo.c:3543 Application rayo execute complete: _none_
2014-11-26 17:18:45.530354 [DEBUG] mod_rayo.c:3546 Release 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 1
2014-11-26 17:18:45.530354 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10657: ref count = 1
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:535 (sofia/external/22334455@192.168.90.101) State EXECUTE going to sleep
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_HIBERNATE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:550 (sofia/external/22334455@192.168.90.101) State HIBERNATE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] mod_sofia.c:160 sofia/external/22334455@192.168.90.101 SOFIA HIBERNATE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] switch_ivr_bridge.c:835 (sofia/external/22334455@192.168.90.101) State Change CS_HIBERNATE -> CS_RESET
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:550 (sofia/external/22334455@192.168.90.101) State HIBERNATE going to sleep
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_RESET
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:531 (sofia/external/22334455@192.168.90.101) State RESET
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] mod_sofia.c:141 sofia/external/22334455@192.168.90.101 SOFIA RESET
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] switch_ivr_bridge.c:820 sofia/external/22334455@192.168.90.101 CUSTOM RESET
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] switch_ivr_bridge.c:827 (sofia/external/22334455@192.168.90.101) State Change CS_RESET -> CS_SOFT_EXECUTE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:531 (sofia/external/22334455@192.168.90.101) State RESET going to sleep
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_SOFT_EXECUTE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:541 (sofia/external/22334455@192.168.90.101) State SOFT_EXECUTE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] mod_sofia.c:600 SOFIA SOFT_EXECUTE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.530354 [DEBUG] switch_ivr_bridge.c:845 sofia/external/22334455@192.168.90.101 CUSTOM SOFT_EXECUTE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_ivr_bridge.c:877 (sofia/external/71999917) State Change CS_RESET -> CS_SOFT_EXECUTE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_SOFT_EXECUTE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:541 (sofia/external/71999917) State SOFT_EXECUTE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] mod_sofia.c:600 SOFIA SOFT_EXECUTE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_ivr_bridge.c:845 sofia/external/71999917 CUSTOM SOFT_EXECUTE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:330 sofia/external/71999917 Standard SOFT_EXECUTE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.530354 [DEBUG] switch_core_state_machine.c:541 (sofia/external/71999917) State SOFT_EXECUTE going to sleep
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE_COMPLETE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10657 rayo event CHANNEL_EXECUTE_COMPLETE
2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3540 Locate (id) 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 2
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3543 Application rayo execute complete: _none_
2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3546 Release 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 1
2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10657: ref count = 1
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.549543 [DEBUG] switch_ivr_bridge.c:1360 (sofia/external/71999917) State Change CS_SOFT_EXECUTE -> CS_CONSUME_MEDIA
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.549543 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.549543 [DEBUG] switch_core_session.c:908 Send signal sofia/external/71999917 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.549543 [DEBUG] switch_core_session.c:908 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.549543 [DEBUG] switch_ivr_bridge.c:1465 (sofia/external/71999917) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.549543 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.549543 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_EXCHANGE_MEDIA
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.549543 [DEBUG] switch_core_state_machine.c:538 (sofia/external/71999917) State EXCHANGE_MEDIA
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.549543 [DEBUG] mod_sofia.c:594 SOFIA EXCHANGE_MEDIA
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10657 rayo event CHANNEL_EXECUTE
2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3526 Locate (id) 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 2
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3528 Application uuid_bridge execute
2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3529 Release 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 1
2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10657: ref count = 1
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.549543 [DEBUG] switch_core_session.c:970 Send signal sofia/external/71999917 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.549543 [DEBUG] switch_core_session.c:970 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3598 got event CHANNEL_EXECUTE
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10657 rayo event CHANNEL_EXECUTE
2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3526 Locate (id) 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 2
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3528 Application uuid_bridge execute
2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3529 Release 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 1
2014-11-26 17:18:45.549543 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10657: ref count = 1
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.568594 [DEBUG] mod_rayo.c:3598 got event CHANNEL_BRIDGE
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:45.568594 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10657 rayo event CHANNEL_BRIDGE
2014-11-26 17:18:45.568594 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:45.568594 [DEBUG] mod_rayo.c:3424 Locate (id) 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 2
2014-11-26 17:18:45.568594 [DEBUG] mod_rayo.c:3443 Locate (id) 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 2
2014-11-26 17:18:45.568594 [DEBUG] mod_rayo.c:3463 Release 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 1
2014-11-26 17:18:45.568594 [DEBUG] mod_rayo.c:3475 Release 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 1
2014-11-26 17:18:45.568594 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10657: ref count = 1
2014-11-26 17:18:45.568594 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:45.568594 [DEBUG] mod_rayo.c:3439 Deliver 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost => usera@localhost/dev01-10657 <iq from='506a3aea-75d3-11e4-8182-379ee336ca8b@localhost' to='usera@localhost/dev01-10657' type='result' id='82eeed8d-38fb-4591-ba85-8908bb0c6d49'/>
2014-11-26 17:18:45.568594 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10657: ref count = 1
2014-11-26 17:18:45.568594 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:45.568594 [DEBUG] mod_rayo.c:3462 Deliver 1c905694-1210-4116-b08b-30421af2b195@localhost => usera@localhost/dev01-10657 <presence from='1c905694-1210-4116-b08b-30421af2b195@localhost' to='usera@localhost/dev01-10657'><joined xmlns='urn:xmpp:rayo:1' call-uri='xmpp:506a3aea-75d3-11e4-8182-379ee336ca8b@localhost'/><delay xmlns='urn:xmpp:delay' stamp='2014-11-27T01:18:45Z'/></presence>
2014-11-26 17:18:45.568594 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10657: ref count = 1
2014-11-26 17:18:45.568594 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:45.568594 [DEBUG] mod_rayo.c:3473 Deliver 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost => usera@localhost/dev01-10657 <presence from='506a3aea-75d3-11e4-8182-379ee336ca8b@localhost' to='usera@localhost/dev01-10657'><joined xmlns='urn:xmpp:rayo:1' call-uri='xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost'/><delay xmlns='urn:xmpp:delay' stamp='2014-11-27T01:18:45Z'/></presence>
2014-11-26 17:18:45.568594 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10657: ref count = 1
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:45.668808 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in SEND <iq from=506a3aea-75d3-11e4-8182-379ee336ca8b@localhost to=usera@localhost/dev01-10657 type=result id=82eeed8d-38fb-4591-ba85-8908bb0c6d49/>
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:45.713432 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in SEND <presence from=1c905694-1210-4116-b08b-30421af2b195@localhost to=usera@localhost/dev01-10657><joined xmlns=urn:xmpp:rayo:1 call-uri=xmpp:506a3aea-75d3-11e4-8182-379ee336ca8b@localhost/><delay xmlns=urn:xmpp:delay stamp=2014-11-27T01:18:45Z/></presence>
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:45.757977 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in SEND <presence from=506a3aea-75d3-11e4-8182-379ee336ca8b@localhost to=usera@localhost/dev01-10657><joined xmlns=urn:xmpp:rayo:1 call-uri=xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost/><delay xmlns=urn:xmpp:delay stamp=2014-11-27T01:18:45Z/></presence>
2014-11-26 17:18:49.669279 [DEBUG] mod_commands.c:6276 BUGMIDDLE2
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.031893 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [NOTICE] sofia.c:952 Hangup sofia/external/71999917 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_channel.c:3222 Send signal sofia/external/71999917 [KILL]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_ivr_bridge.c:660 BRIDGE THREAD DONE [sofia/external/71999917]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.050556 [DEBUG] switch_ivr_bridge.c:690 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:538 (sofia/external/71999917) State EXCHANGE_MEDIA going to sleep
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_HANGUP
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:735 (sofia/external/71999917) Callstate Change ACTIVE -> HANGUP
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:737 (sofia/external/71999917) State HANGUP
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] mod_sofia.c:413 Channel sofia/external/71999917 hanging up, cause: NORMAL_CLEARING
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:60 sofia/external/71999917 Standard HANGUP, cause: NORMAL_CLEARING
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:737 (sofia/external/71999917) State HANGUP going to sleep
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:504 (sofia/external/71999917) State Change CS_HANGUP -> CS_REPORTING
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:472 (sofia/external/71999917) Running State Change CS_REPORTING
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:823 (sofia/external/71999917) State REPORTING
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:104 sofia/external/71999917 Standard REPORTING, cause: NORMAL_CLEARING
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:823 (sofia/external/71999917) State REPORTING going to sleep
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:498 (sofia/external/71999917) State Change CS_REPORTING -> CS_DESTROY
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/71999917 [BREAK]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_session.c:1615 Session 53 (sofia/external/71999917) Locked, Waiting on external entities
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.050556 [DEBUG] switch_ivr_bridge.c:579 sofia/external/71999917 ending bridge by request from write function
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.050556 [DEBUG] switch_ivr_bridge.c:660 BRIDGE THREAD DONE [sofia/external/22334455@192.168.90.101]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_ivr_bridge.c:690 Send signal sofia/external/71999917 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.050556 [DEBUG] switch_core_session.c:908 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.050556 [DEBUG] switch_ivr.c:2916 (sofia/external/22334455@192.168.90.101) State Change CS_SOFT_EXECUTE -> CS_PARK
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.050556 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:541 (sofia/external/22334455@192.168.90.101) State SOFT_EXECUTE going to sleep
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_PARK
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:544 (sofia/external/22334455@192.168.90.101) State PARK
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:336 sofia/external/22334455@192.168.90.101 Standard PARK
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.050556 [DEBUG] switch_ivr.c:961 Codec Activated L16@8000hz 1 channels 20ms
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [NOTICE] switch_core_session.c:1633 Session 53 (sofia/external/71999917) Ended
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [NOTICE] switch_core_session.c:1637 Close Channel sofia/external/71999917 [CS_DESTROY]
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:626 (sofia/external/71999917) Running State Change CS_DESTROY
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:636 (sofia/external/71999917) State DESTROY
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] mod_sofia.c:323 sofia/external/71999917 SOFIA DESTROY
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:111 sofia/external/71999917 Standard DESTROY
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.050556 [DEBUG] switch_core_state_machine.c:636 (sofia/external/71999917) State DESTROY going to sleep
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.125639 [DEBUG] rayo_cpa_component.c:130 Subscriber execute hangup
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.125639 [DEBUG] rayo_cpa_component.c:143 No subscribers for hangup
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.125639 [DEBUG] mod_rayo.c:3598 got event CHANNEL_PARK
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.125639 [DEBUG] mod_rayo.c:3603 usera@localhost/dev01-10657 rayo event CHANNEL_PARK
2014-11-26 17:18:53.125639 [DEBUG] mod_rayo.c:3605 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:53.125639 [DEBUG] mod_rayo.c:3487 Locate (id) 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 2
2014-11-26 17:18:53.125639 [DEBUG] mod_rayo.c:3515 Release 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 1
2014-11-26 17:18:53.125639 [DEBUG] mod_rayo.c:3613 Release usera@localhost/dev01-10657: ref count = 1
2014-11-26 17:18:53.125639 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:53.125639 [DEBUG] mod_rayo.c:3513 Deliver 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost => usera@localhost/dev01-10657 <presence from='506a3aea-75d3-11e4-8182-379ee336ca8b@localhost' to='usera@localhost/dev01-10657'><unjoined xmlns='urn:xmpp:rayo:1' call-uri='xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost'/><delay xmlns='urn:xmpp:delay' stamp='2014-11-27T01:18:53Z'/></presence>
2014-11-26 17:18:53.125639 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10657: ref count = 1
2014-11-26 17:18:53.125639 [DEBUG] mod_rayo.c:3350 Locate (id) 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 2
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.125639 [DEBUG] mod_rayo.c:3360 Got channel destroy event
2014-11-26 17:18:53.125639 [DEBUG] mod_rayo.c:3365 Destroy 1c905694-1210-4116-b08b-30421af2b195@localhost requested: ref_count = 2
2014-11-26 17:18:53.125639 [DEBUG] mod_rayo.c:3366 Release 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 1
2014-11-26 17:18:53.125639 [DEBUG] mod_rayo.c:3369 Release 1c905694-1210-4116-b08b-30421af2b195@localhost: ref count = 0
2014-11-26 17:18:53.125639 [DEBUG] mod_rayo.c:3369 Destroying 1c905694-1210-4116-b08b-30421af2b195@localhost
1c905694-1210-4116-b08b-30421af2b195 2014-11-26 17:18:53.149149 [DEBUG] mod_rayo.c:1117 Sending <end> to DCP usera@localhost/dev01-10657
2014-11-26 17:18:53.149149 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:53.149149 [DEBUG] mod_rayo.c:1146 Deliver 1c905694-1210-4116-b08b-30421af2b195@localhost => usera@localhost/dev01-10657 <presence from='1c905694-1210-4116-b08b-30421af2b195@localhost' to='usera@localhost/dev01-10657'><unjoined xmlns='urn:xmpp:rayo:1' call-uri='xmpp:506a3aea-75d3-11e4-8182-379ee336ca8b@localhost'/><delay xmlns='urn:xmpp:delay' stamp='2014-11-27T01:18:53Z'/></presence>
2014-11-26 17:18:53.149149 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10657: ref count = 1
2014-11-26 17:18:53.149149 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:53.149149 [DEBUG] mod_rayo.c:1119 Deliver 1c905694-1210-4116-b08b-30421af2b195@localhost => usera@localhost/dev01-10657 <presence from='1c905694-1210-4116-b08b-30421af2b195@localhost' to='usera@localhost/dev01-10657' type='unavailable'><end xmlns='urn:xmpp:rayo:1'><hungup platform-code='16'/></end><delay xmlns='urn:xmpp:delay' stamp='2014-11-27T01:18:53Z'/></presence>
2014-11-26 17:18:53.149149 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10657: ref count = 1
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:53.248801 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in SEND <presence from=506a3aea-75d3-11e4-8182-379ee336ca8b@localhost to=usera@localhost/dev01-10657><unjoined xmlns=urn:xmpp:rayo:1 call-uri=xmpp:1c905694-1210-4116-b08b-30421af2b195@localhost/><delay xmlns=urn:xmpp:delay stamp=2014-11-27T01:18:53Z/></presence>
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:53.248801 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in SEND <presence from=1c905694-1210-4116-b08b-30421af2b195@localhost to=usera@localhost/dev01-10657><unjoined xmlns=urn:xmpp:rayo:1 call-uri=xmpp:506a3aea-75d3-11e4-8182-379ee336ca8b@localhost/><delay xmlns=urn:xmpp:delay stamp=2014-11-27T01:18:53Z/></presence>
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:53.248801 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in SEND <presence from=1c905694-1210-4116-b08b-30421af2b195@localhost to=usera@localhost/dev01-10657 type=unavailable><end xmlns=urn:xmpp:rayo:1><hungup platform-code=16/></end><delay xmlns=urn:xmpp:delay stamp=2014-11-27T01:18:53Z/></presence>
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:53.308875 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in RECV <iq type="set" to="506a3aea-75d3-11e4-8182-379ee336ca8b@localhost" id="7cd26c6c-92ed-4038-8cdb-0f9253f2a8a0"><hangup xmlns="urn:xmpp:rayo:1"/></iq>
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:53.308875 [DEBUG] xmpp_streams.c:1058 usera@localhost/dev01-10657, 127.0.0.1:36291, state = READY, node type = NODE_NORMAL
2014-11-26 17:18:53.308875 [DEBUG] mod_rayo.c:3912 Lock usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:53.308875 [DEBUG] mod_rayo.c:3056 usera@localhost/dev01-10657, recv iq, availability = ONLINE
2014-11-26 17:18:53.308875 [DEBUG] mod_rayo.c:3983 Release usera@localhost/dev01-10657: ref count = 1
2014-11-26 17:18:53.308875 [DEBUG] mod_rayo.c:774 Locate (jid) 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 2
2014-11-26 17:18:53.308875 [DEBUG] mod_rayo.c:3059 Deliver usera@localhost/dev01-10657 => 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost <iq type='set' to='506a3aea-75d3-11e4-8182-379ee336ca8b@localhost' id='7cd26c6c-92ed-4038-8cdb-0f9253f2a8a0' from='usera@localhost/dev01-10657'><hangup xmlns='urn:xmpp:rayo:1'/></iq>
2014-11-26 17:18:53.308875 [DEBUG] mod_rayo.c:655 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost, looking for CALL::set:urn:xmpp:rayo:1:hangup command
2014-11-26 17:18:53.308875 [DEBUG] mod_rayo.c:1816 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost, executing command
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.308875 [NOTICE] switch_ivr.c:3716 Hangup sofia/external/22334455@192.168.90.101 [CS_PARK] [NORMAL_CLEARING]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.308875 [DEBUG] switch_channel.c:3222 Send signal sofia/external/22334455@192.168.90.101 [KILL]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.308875 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
2014-11-26 17:18:53.308875 [DEBUG] mod_rayo.c:1818 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost, done executing command
2014-11-26 17:18:53.308875 [DEBUG] mod_rayo.c:781 Release 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 1
2014-11-26 17:18:53.308875 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:53.308875 [DEBUG] mod_rayo.c:1824 Deliver 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost => usera@localhost/dev01-10657 <iq from='506a3aea-75d3-11e4-8182-379ee336ca8b@localhost' to='usera@localhost/dev01-10657' type='result' id='7cd26c6c-92ed-4038-8cdb-0f9253f2a8a0'/>
2014-11-26 17:18:53.308875 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10657: ref count = 1
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:53.308875 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in SEND <iq from=506a3aea-75d3-11e4-8182-379ee336ca8b@localhost to=usera@localhost/dev01-10657 type=result id=7cd26c6c-92ed-4038-8cdb-0f9253f2a8a0/>
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.308875 [DEBUG] switch_core_state_machine.c:544 (sofia/external/22334455@192.168.90.101) State PARK going to sleep
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.308875 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_HANGUP
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.308875 [DEBUG] switch_core_state_machine.c:735 (sofia/external/22334455@192.168.90.101) Callstate Change ACTIVE -> HANGUP
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.308875 [DEBUG] switch_core_state_machine.c:737 (sofia/external/22334455@192.168.90.101) State HANGUP
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.308875 [DEBUG] mod_sofia.c:407 sofia/external/22334455@192.168.90.101 Overriding SIP cause 480 with 200 from the other leg
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.308875 [DEBUG] mod_sofia.c:413 Channel sofia/external/22334455@192.168.90.101 hanging up, cause: NORMAL_CLEARING
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.308875 [DEBUG] mod_sofia.c:465 Sending BYE to sofia/external/22334455@192.168.90.101
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [DEBUG] switch_core_state_machine.c:60 sofia/external/22334455@192.168.90.101 Standard HANGUP, cause: NORMAL_CLEARING
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [DEBUG] switch_core_state_machine.c:737 (sofia/external/22334455@192.168.90.101) State HANGUP going to sleep
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [DEBUG] switch_core_state_machine.c:504 (sofia/external/22334455@192.168.90.101) State Change CS_HANGUP -> CS_REPORTING
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [DEBUG] switch_core_state_machine.c:472 (sofia/external/22334455@192.168.90.101) Running State Change CS_REPORTING
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [DEBUG] switch_core_state_machine.c:823 (sofia/external/22334455@192.168.90.101) State REPORTING
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [DEBUG] switch_core_state_machine.c:104 sofia/external/22334455@192.168.90.101 Standard REPORTING, cause: NORMAL_CLEARING
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [DEBUG] switch_core_state_machine.c:823 (sofia/external/22334455@192.168.90.101) State REPORTING going to sleep
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [DEBUG] switch_core_state_machine.c:498 (sofia/external/22334455@192.168.90.101) State Change CS_REPORTING -> CS_DESTROY
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/22334455@192.168.90.101 [BREAK]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [DEBUG] switch_core_session.c:1615 Session 52 (sofia/external/22334455@192.168.90.101) Locked, Waiting on external entities
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [NOTICE] switch_core_session.c:1633 Session 52 (sofia/external/22334455@192.168.90.101) Ended
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [NOTICE] switch_core_session.c:1637 Close Channel sofia/external/22334455@192.168.90.101 [CS_DESTROY]
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [DEBUG] switch_core_state_machine.c:626 (sofia/external/22334455@192.168.90.101) Running State Change CS_DESTROY
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [DEBUG] switch_core_state_machine.c:636 (sofia/external/22334455@192.168.90.101) State DESTROY
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [DEBUG] mod_sofia.c:323 sofia/external/22334455@192.168.90.101 SOFIA DESTROY
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [DEBUG] switch_core_state_machine.c:111 sofia/external/22334455@192.168.90.101 Standard DESTROY
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.380025 [DEBUG] switch_core_state_machine.c:636 (sofia/external/22334455@192.168.90.101) State DESTROY going to sleep
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.399417 [DEBUG] rayo_cpa_component.c:130 Subscriber execute hangup
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.399417 [DEBUG] rayo_cpa_component.c:143 No subscribers for hangup
2014-11-26 17:18:53.420034 [DEBUG] mod_rayo.c:3350 Locate (id) 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 2
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.420034 [DEBUG] mod_rayo.c:3360 Got channel destroy event
2014-11-26 17:18:53.420034 [DEBUG] mod_rayo.c:3365 Destroy 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost requested: ref_count = 2
2014-11-26 17:18:53.420034 [DEBUG] mod_rayo.c:3366 Release 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 1
2014-11-26 17:18:53.420034 [DEBUG] mod_rayo.c:3369 Release 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost: ref count = 0
2014-11-26 17:18:53.420034 [DEBUG] mod_rayo.c:3369 Destroying 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost
506a3aea-75d3-11e4-8182-379ee336ca8b 2014-11-26 17:18:53.420034 [DEBUG] mod_rayo.c:1110 Sending <end> to offered client usera@localhost/dev01-10657
2014-11-26 17:18:53.420034 [DEBUG] mod_rayo.c:774 Locate (jid) usera@localhost/dev01-10657: ref count = 2
2014-11-26 17:18:53.420034 [DEBUG] mod_rayo.c:1111 Deliver 506a3aea-75d3-11e4-8182-379ee336ca8b@localhost => usera@localhost/dev01-10657 <presence from='506a3aea-75d3-11e4-8182-379ee336ca8b@localhost' to='usera@localhost/dev01-10657' type='unavailable'><end xmlns='urn:xmpp:rayo:1'><hangup-command/><header name='X-accountcode' value='3000'/><header name='X-Firmafon-Inbound-Provider' value='telenor_ic'/></end><delay xmlns='urn:xmpp:delay' stamp='2014-11-27T01:18:53Z'/></presence>
2014-11-26 17:18:53.420034 [DEBUG] mod_rayo.c:781 Release usera@localhost/dev01-10657: ref count = 1
3ff861e6-75d3-11e4-8181-379ee336ca8b 2014-11-26 17:18:53.472764 [DEBUG] xmpp_streams.c:190 usera@localhost/dev01-10657, 127.0.0.1:36291, c2s_in SEND <presence from=506a3aea-75d3-11e4-8182-379ee336ca8b@localhost to=usera@localhost/dev01-10657 type=unavailable><end xmlns=urn:xmpp:rayo:1><hangup-command/><header name=X-accountcode value=3000/><header name=X-Firmafon-Inbound-Provider value=telenor_ic/></end><delay xmlns=urn:xmpp:delay stamp=2014-11-27T01:18:53Z/></presence>
2014-11-26 17:18:56.711867 [DEBUG] mod_commands.c:6276 BUGEND
 

routes.rb

# encoding: utf-8

Adhearsion.router do
  route 'Default' do
    answer

    answer_blocker = Celluloid::Condition.new
    hangup_blocker = Celluloid::Condition.new

    other = Adhearsion::OutboundCall.new
    other.on_answer do
      logger.info "B-leg answered"
      answer_blocker.signal
    end
    other.on_end do
      hangup_blocker.signal
    end
    other.dial("sofia/gateway/development_mvno_link1/71999917")

    logger.info "Waiting for B-leg to answer"
    answer_blocker.wait

    logger.info "Joining A and B"
    call.join(other)

    logger.info "Joined. Waiting for B-leg to hangup."
    hangup_blocker.wait
  end
end