Skip to content

Instantly share code, notes, and snippets.

@neerajnagi
Created August 30, 2013 00:13
Show Gist options
  • Save neerajnagi/6384920 to your computer and use it in GitHub Desktop.
Save neerajnagi/6384920 to your computer and use it in GitHub Desktop.
fs + ahn
est-2.compute.internal-2670: ref count = 2
2013-08-29 20:00:46.991334 [DEBUG] mod_rayo.c:930 Deliver d752bc87-7cbb-c2d5-df6d-b364079b95f7@54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 <presence from='d752bc87-7cbb-c2d5-df6d-b364079b95f7@54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670' type='unavailable'><end xmlns='urn:xmpp:rayo:1'><hangup-command/></end></presence>
2013-08-29 20:00:46.991334 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 1
2013-08-29 20:00:46.991334 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 SEND <presence from='d752bc87-7cbb-c2d5-df6d-b364079b95f7@54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670' type='unavailable'><end xmlns='urn:xmpp:rayo:1'><hangup-command/></end></presence>
2013-08-29 20:01:22.369197 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 RECV <iq type="get" to="54.213.58.94" id="blather0060"><ping xmlns="urn:xmpp:ping"/></iq>
2013-08-29 20:01:22.369197 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670, state = READY, node type = NODE_NORMAL
2013-08-29 20:01:22.369197 [DEBUG] mod_rayo.c:3010 Lock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 2
2013-08-29 20:01:22.369197 [DEBUG] mod_rayo.c:2365 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670, recv iq, availability = ONLINE
2013-08-29 20:01:22.369197 [DEBUG] mod_rayo.c:3069 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 1
2013-08-29 20:01:22.369197 [DEBUG] mod_rayo.c:624 Locate 54.213.58.94: ref count = 2
2013-08-29 20:01:22.369197 [DEBUG] mod_rayo.c:2368 Deliver 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 => 54.213.58.94 <iq type='get' to='54.213.58.94' id='blather0060' from='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670'><ping xmlns='urn:xmpp:ping'/></iq>
2013-08-29 20:01:22.369197 [DEBUG] mod_rayo.c:505 54.213.58.94, looking for SERVER::get:urn:xmpp:ping:ping command
2013-08-29 20:01:22.369197 [DEBUG] mod_rayo.c:631 Unlock 54.213.58.94: ref count = 1
2013-08-29 20:01:22.369197 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 2
2013-08-29 20:01:22.369197 [DEBUG] mod_rayo.c:1432 Deliver 54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670' id='blather0060'/>
2013-08-29 20:01:22.369197 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 1
2013-08-29 20:01:22.369197 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 SEND <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670' id='blather0060'/>
2013-08-29 20:02:22.372958 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 RECV <iq type="get" to="54.213.58.94" id="blather0062"><ping xmlns="urn:xmpp:ping"/></iq>
2013-08-29 20:02:22.372958 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670, state = READY, node type = NODE_NORMAL
2013-08-29 20:02:22.372958 [DEBUG] mod_rayo.c:3010 Lock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 2
2013-08-29 20:02:22.372958 [DEBUG] mod_rayo.c:2365 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670, recv iq, availability = ONLINE
2013-08-29 20:02:22.372958 [DEBUG] mod_rayo.c:3069 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 1
2013-08-29 20:02:22.372958 [DEBUG] mod_rayo.c:624 Locate 54.213.58.94: ref count = 2
2013-08-29 20:02:22.372958 [DEBUG] mod_rayo.c:2368 Deliver 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 => 54.213.58.94 <iq type='get' to='54.213.58.94' id='blather0062' from='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670'><ping xmlns='urn:xmpp:ping'/></iq>
2013-08-29 20:02:22.372958 [DEBUG] mod_rayo.c:505 54.213.58.94, looking for SERVER::get:urn:xmpp:ping:ping command
2013-08-29 20:02:22.372958 [DEBUG] mod_rayo.c:631 Unlock 54.213.58.94: ref count = 1
2013-08-29 20:02:22.372958 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 2
2013-08-29 20:02:22.372958 [DEBUG] mod_rayo.c:1432 Deliver 54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670' id='blather0062'/>
2013-08-29 20:02:22.372958 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 1
2013-08-29 20:02:22.372958 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 SEND <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670' id='blather0062'/>
2013-08-29 20:03:22.372717 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 RECV <iq type="get" to="54.213.58.94" id="blather0064"><ping xmlns="urn:xmpp:ping"/></iq>
2013-08-29 20:03:22.372717 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670, state = READY, node type = NODE_NORMAL
2013-08-29 20:03:22.372717 [DEBUG] mod_rayo.c:3010 Lock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 2
2013-08-29 20:03:22.372717 [DEBUG] mod_rayo.c:2365 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670, recv iq, availability = ONLINE
2013-08-29 20:03:22.372717 [DEBUG] mod_rayo.c:3069 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 1
2013-08-29 20:03:22.372717 [DEBUG] mod_rayo.c:624 Locate 54.213.58.94: ref count = 2
2013-08-29 20:03:22.372717 [DEBUG] mod_rayo.c:2368 Deliver 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 => 54.213.58.94 <iq type='get' to='54.213.58.94' id='blather0064' from='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670'><ping xmlns='urn:xmpp:ping'/></iq>
2013-08-29 20:03:22.372717 [DEBUG] mod_rayo.c:505 54.213.58.94, looking for SERVER::get:urn:xmpp:ping:ping command
2013-08-29 20:03:22.372717 [DEBUG] mod_rayo.c:631 Unlock 54.213.58.94: ref count = 1
2013-08-29 20:03:22.372717 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 2
2013-08-29 20:03:22.372717 [DEBUG] mod_rayo.c:1432 Deliver 54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670' id='blather0064'/>
2013-08-29 20:03:22.372717 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 1
2013-08-29 20:03:22.372717 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 SEND <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670' id='blather0064'/>
2013-08-29 20:04:22.372475 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 RECV <iq type="get" to="54.213.58.94" id="blather0066"><ping xmlns="urn:xmpp:ping"/></iq>
2013-08-29 20:04:22.372475 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670, state = READY, node type = NODE_NORMAL
2013-08-29 20:04:22.372475 [DEBUG] mod_rayo.c:3010 Lock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 2
2013-08-29 20:04:22.372475 [DEBUG] mod_rayo.c:2365 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670, recv iq, availability = ONLINE
2013-08-29 20:04:22.372475 [DEBUG] mod_rayo.c:3069 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 1
2013-08-29 20:04:22.372475 [DEBUG] mod_rayo.c:624 Locate 54.213.58.94: ref count = 2
2013-08-29 20:04:22.372475 [DEBUG] mod_rayo.c:2368 Deliver 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 => 54.213.58.94 <iq type='get' to='54.213.58.94' id='blather0066' from='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670'><ping xmlns='urn:xmpp:ping'/></iq>
2013-08-29 20:04:22.372475 [DEBUG] mod_rayo.c:505 54.213.58.94, looking for SERVER::get:urn:xmpp:ping:ping command
2013-08-29 20:04:22.372475 [DEBUG] mod_rayo.c:631 Unlock 54.213.58.94: ref count = 1
2013-08-29 20:04:22.372475 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 2
2013-08-29 20:04:22.372475 [DEBUG] mod_rayo.c:1432 Deliver 54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670' id='blather0066'/>
2013-08-29 20:04:22.372475 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 1
2013-08-29 20:04:22.372475 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 SEND <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670' id='blather0066'/>
2013-08-29 20:04:42.437015 [INFO] xmpp_streams.c:1211 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670, iks_recv() error = NET_RWERR, ending session
2013-08-29 20:04:42.437015 [DEBUG] mod_rayo.c:3097 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670: ref count = 0
2013-08-29 20:04:42.437015 [DEBUG] mod_rayo.c:3098 Destroy 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670 requested: ref_count = 0
2013-08-29 20:04:42.437015 [DEBUG] mod_rayo.c:3098 Destroying 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-2670
2013-08-29 20:04:51.180878 [DEBUG] xmpp_streams.c:1189 New c2s_in stream
2013-08-29 20:04:51.180878 [DEBUG] xmpp_streams.c:190 c2s_in (null) RECV <stream:stream to='54.213.58.94' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' xml:lang='en'>
2013-08-29 20:04:51.180878 [DEBUG] xmpp_streams.c:1058 (null), state = CONNECT, node type = NODE_START
2013-08-29 20:04:51.180878 [DEBUG] xmpp_streams.c:190 c2s_in (null) SEND <stream:stream xmlns='jabber:client' xmlns:db='jabber:server:dialback' from='54.213.58.94' id='c9ff1858-1107-11e3-9950-5d997994877d' xml:lang='en' version='1.0' xmlns:stream='http://etherx.jabber.org/streams'><stream:features><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>PLAIN</mechanism></mechanisms></stream:features>
2013-08-29 20:04:51.279561 [DEBUG] xmpp_streams.c:190 c2s_in (null) RECV <auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="PLAIN">MUA1NC4yMTMuNTguOTQAMQAx</auth>
2013-08-29 20:04:51.279561 [DEBUG] xmpp_streams.c:1058 (null), state = SECURE, node type = NODE_NORMAL
2013-08-29 20:04:51.279561 [DEBUG] xmpp_streams.c:471 (null), auth, state = SECURE
2013-08-29 20:04:51.279561 [DEBUG] xmpp_streams.c:505 (null), auth, state = SECURE, SASL/PLAIN decoded authzid = "1@54.213.58.94" authcid = "1"
2013-08-29 20:04:51.304935 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94 SEND <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'/>
2013-08-29 20:04:51.304935 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94 RECV <stream:stream to='54.213.58.94' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' xml:lang='en'>
2013-08-29 20:04:51.304935 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94, state = AUTHENTICATED, node type = NODE_START
2013-08-29 20:04:51.304935 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94 SEND <stream:stream xmlns='jabber:client' xmlns:db='jabber:server:dialback' from='54.213.58.94' id='ca1afe10-1107-11e3-9951-5d997994877d' xml:lang='en' version='1.0' xmlns:stream='http://etherx.jabber.org/streams'><stream:features><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'/><session xmlns='urn:ietf:params:xml:ns:xmpp-session'/></stream:features>
2013-08-29 20:04:51.304935 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94 RECV <iq type="set" id="blather0002"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><resource>ip-172-31-41-127.us-west-2.compute.internal-4766</resource></bind></iq>
2013-08-29 20:04:51.304935 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94, state = AUTHENTICATED, node type = NODE_NORMAL
2013-08-29 20:04:51.304935 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 SEND <iq type='result' id='blather0002'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'><jid>1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766</jid></bind></iq>
2013-08-29 20:04:51.304935 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 RECV <iq type="set" id="blather0004" to="54.213.58.94"><session xmlns="urn:ietf:params:xml:ns:xmpp-session"/></iq>
2013-08-29 20:04:51.304935 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, state = RESOURCE_BOUND, node type = NODE_NORMAL
2013-08-29 20:04:51.304935 [DEBUG] mod_rayo.c:1198 Init 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766
2013-08-29 20:04:51.304935 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 SEND <iq from='54.213.58.94' type='result' id='blather0004'/>
2013-08-29 20:04:51.304935 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 RECV <iq type="get" id="blather0006"><query xmlns="jabber:iq:roster"/></iq>
2013-08-29 20:04:51.304935 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, state = READY, node type = NODE_NORMAL
2013-08-29 20:04:51.304935 [DEBUG] mod_rayo.c:3010 Lock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:04:51.304935 [DEBUG] mod_rayo.c:2365 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, recv iq, availability = OFFLINE
2013-08-29 20:04:51.304935 [DEBUG] mod_rayo.c:624 Locate 54.213.58.94: ref count = 2
2013-08-29 20:04:51.304935 [DEBUG] mod_rayo.c:2368 Deliver 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 => 54.213.58.94 <iq type='get' id='blather0006' to='54.213.58.94' from='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766'><query xmlns='jabber:iq:roster'/></iq>
2013-08-29 20:04:51.304935 [DEBUG] mod_rayo.c:505 54.213.58.94, looking for SERVER::get:jabber:iq:roster:query command
2013-08-29 20:04:51.304935 [DEBUG] mod_rayo.c:1418 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, no handler function for command to 54.213.58.94
2013-08-29 20:04:51.304935 [DEBUG] mod_rayo.c:631 Unlock 54.213.58.94: ref count = 1
2013-08-29 20:04:51.304935 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 3
2013-08-29 20:04:51.304935 [DEBUG] mod_rayo.c:1420 Deliver 54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 <iq type='error' id='blather0006' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' from='54.213.58.94'><query xmlns='jabber:iq:roster'/><error type='modify'><feature-not-implemented xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/></error></iq>
2013-08-29 20:04:51.304935 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:04:51.304935 [DEBUG] mod_rayo.c:3069 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:04:51.304935 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 SEND <iq type='error' id='blather0006' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' from='54.213.58.94'><query xmlns='jabber:iq:roster'/><error type='modify'><feature-not-implemented xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/></error></iq>
2013-08-29 20:04:51.315806 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 RECV <presence/>
2013-08-29 20:04:51.315806 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, state = READY, node type = NODE_NORMAL
2013-08-29 20:04:51.315806 [DEBUG] xmpp_streams.c:287 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, presence, state = READY
2013-08-29 20:04:51.315806 [DEBUG] mod_rayo.c:3010 Lock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:04:51.315806 [DEBUG] mod_rayo.c:2310 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 got empty presence
2013-08-29 20:04:51.315806 [DEBUG] mod_rayo.c:2331 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 is ONLINE
2013-08-29 20:04:51.315806 [DEBUG] mod_rayo.c:3076 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:05:51.310014 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 RECV <iq type="get" to="54.213.58.94" id="blather0008"><ping xmlns="urn:xmpp:ping"/></iq>
2013-08-29 20:05:51.310014 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, state = READY, node type = NODE_NORMAL
2013-08-29 20:05:51.310014 [DEBUG] mod_rayo.c:3010 Lock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:05:51.310014 [DEBUG] mod_rayo.c:2365 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, recv iq, availability = ONLINE
2013-08-29 20:05:51.310014 [DEBUG] mod_rayo.c:3069 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:05:51.310014 [DEBUG] mod_rayo.c:624 Locate 54.213.58.94: ref count = 2
2013-08-29 20:05:51.310014 [DEBUG] mod_rayo.c:2368 Deliver 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 => 54.213.58.94 <iq type='get' to='54.213.58.94' id='blather0008' from='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766'><ping xmlns='urn:xmpp:ping'/></iq>
2013-08-29 20:05:51.310014 [DEBUG] mod_rayo.c:505 54.213.58.94, looking for SERVER::get:urn:xmpp:ping:ping command
2013-08-29 20:05:51.310014 [DEBUG] mod_rayo.c:631 Unlock 54.213.58.94: ref count = 1
2013-08-29 20:05:51.310014 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:05:51.310014 [DEBUG] mod_rayo.c:1432 Deliver 54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' id='blather0008'/>
2013-08-29 20:05:51.310014 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:05:51.310014 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 SEND <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' id='blather0008'/>
2013-08-29 20:06:51.309747 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 RECV <iq type="get" to="54.213.58.94" id="blather000a"><ping xmlns="urn:xmpp:ping"/></iq>
2013-08-29 20:06:51.309747 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, state = READY, node type = NODE_NORMAL
2013-08-29 20:06:51.309747 [DEBUG] mod_rayo.c:3010 Lock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:06:51.309747 [DEBUG] mod_rayo.c:2365 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, recv iq, availability = ONLINE
2013-08-29 20:06:51.309747 [DEBUG] mod_rayo.c:3069 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:06:51.309747 [DEBUG] mod_rayo.c:624 Locate 54.213.58.94: ref count = 2
2013-08-29 20:06:51.309747 [DEBUG] mod_rayo.c:2368 Deliver 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 => 54.213.58.94 <iq type='get' to='54.213.58.94' id='blather000a' from='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766'><ping xmlns='urn:xmpp:ping'/></iq>
2013-08-29 20:06:51.309747 [DEBUG] mod_rayo.c:505 54.213.58.94, looking for SERVER::get:urn:xmpp:ping:ping command
2013-08-29 20:06:51.309747 [DEBUG] mod_rayo.c:631 Unlock 54.213.58.94: ref count = 1
2013-08-29 20:06:51.309747 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:06:51.309747 [DEBUG] mod_rayo.c:1432 Deliver 54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' id='blather000a'/>
2013-08-29 20:06:51.309747 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:06:51.309747 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 SEND <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' id='blather000a'/>
2013-08-29 20:07:27.412024 [NOTICE] switch_channel.c:1030 New Channel sofia/internal/1001@54.213.58.94 [424928b4-bc76-505f-febd-a5febae13aa3]
2013-08-29 20:07:27.412024 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/1001@54.213.58.94 [BREAK]
2013-08-29 20:07:27.412024 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/1001@54.213.58.94 [BREAK]
2013-08-29 20:07:27.412024 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/1001@54.213.58.94) Running State Change CS_NEW
2013-08-29 20:07:27.412024 [DEBUG] switch_core_state_machine.c:434 (sofia/internal/1001@54.213.58.94) State NEW
2013-08-29 20:07:27.432045 [DEBUG] sofia.c:7906 IP 202.157.93.2 Approved by acl "domains[]". Access Granted.
2013-08-29 20:07:27.432045 [DEBUG] sofia.c:8925 Setting NAT mode based on via received
2013-08-29 20:07:27.432045 [DEBUG] sofia.c:5793 Channel sofia/internal/1001@54.213.58.94 entering state [received][100]
2013-08-29 20:07:27.432045 [DEBUG] sofia.c:5802 Remote SDP:
v=0
o=- 417531139091299800 2 IN IP4 127.0.0.1
s=Doubango Telecom - chrome
t=0 0
a=group:BUNDLE audio video
a=msid-semantic: WMS yhhZ3SJtPGPnmHpiROozjtjw4QZ8d7KftE1z
m=audio 62710 RTP/SAVPF 111 103 104 0 8 107 106 105 13 126
c=IN IP4 202.157.93.2
a=rtpmap:111 opus/48000/2
a=fmtp:111 minptime=10
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:107 CN/48000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:126 telephone-event/8000
a=rtcp:62710 IN IP4 202.157.93.2
a=candidate:524234378 1 udp 2113937151 10.100.101.254 62710 typ host generation 0
a=candidate:524234378 2 udp 2113937151 10.100.101.254 62710 typ host generation 0
a=candidate:1371329146 1 tcp 1509957375 10.100.101.254 0 typ host generation 0
a=candidate:1371329146 2 tcp 1509957375 10.100.101.254 0 typ host generation 0
a=candidate:3551662361 1 udp 1845501695 202.157.93.2 62710 typ srflx raddr 10.100.101.254 rport 62710 generation 0
a=candidate:3551662361 2 udp 1845501695 202.157.93.2 62710 typ srflx raddr 10.100.101.254 rport 62710 generation 0
a=ice-ufrag:Wg2KPXu0KeJsEiW0
a=ice-pwd:AEydpu9aYxE309iFeTeJEMOO
a=ice-options:google-ice
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=mid:audio
a=rtcp-mux
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:mOzzWppgFTdvWF0fn9jx9rZ9RR21wJ9yX5weywrC
a=maxptime:60
a=ssrc:169614681 cname:GO5nEQ90ukOmvC1y
a=ssrc:169614681 msid:yhhZ3SJtPGPnmHpiROozjtjw4QZ8d7KftE1z yhhZ3SJtPGPnmHpiROozjtjw4QZ8d7KftE1za0
a=ssrc:169614681 mslabel:yhhZ3SJtPGPnmHpiROozjtjw4QZ8d7KftE1z
a=ssrc:169614681 label:yhhZ3SJtPGPnmHpiROozjtjw4QZ8d7KftE1za0
m=video 62710 RTP/SAVPF 100 116 117
c=IN IP4 202.157.93.2
a=rtpmap:100 VP8/90000
a=rtpmap:116 red/90000
a=rtpmap:117 ulpfec/90000
a=rtcp:62710 IN IP4 202.157.93.2
a=candidate:524234378 1 udp 2113937151 10.100.101.254 62710 typ host generation 0
a=candidate:524234378 2 udp 2113937151 10.100.101.254 62710 typ host generation 0
a=candidate:1371329146 1 tcp 1509957375 10.100.101.254 0 typ host generation 0
a=candidate:1371329146 2 tcp 1509957375 10.100.101.254 0 typ host generation 0
a=candidate:3551662361 1 udp 1845501695 202.157.93.2 62710 typ srflx raddr 10.100.101.254 rport 62710 generation 0
a=candidate:3551662361 2 udp 1845501695 202.157.93.2 62710 typ srflx raddr 10.100.101.254 rport 62710 generation 0
a=ice-ufrag:Wg2KPXu0KeJsEiW0
a=ice-pwd:AEydpu9aYxE309iFeTeJEMOO
a=ice-options:google-ice
a=extmap:2 urn:ietf:params:rtp-hdrext:toffset
a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=mid:video
a=rtcp-mux
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:mOzzWppgFTdvWF0fn9jx9rZ9RR21wJ9yX5weywrC
a=rtcp-fb:100 ccm fir
a=rtcp-fb:100 nack
a=rtcp-fb:100 goog-remb
2013-08-29 20:07:27.432045 [DEBUG] sofia.c:6015 (sofia/internal/1001@54.213.58.94) State Change CS_NEW -> CS_INIT
2013-08-29 20:07:27.432045 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/1001@54.213.58.94 [BREAK]
2013-08-29 20:07:27.432045 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/1001@54.213.58.94) Running State Change CS_INIT
2013-08-29 20:07:27.432045 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/1001@54.213.58.94) State INIT
2013-08-29 20:07:27.432045 [DEBUG] mod_sofia.c:87 sofia/internal/1001@54.213.58.94 SOFIA INIT
2013-08-29 20:07:27.432045 [DEBUG] mod_sofia.c:114 (sofia/internal/1001@54.213.58.94) State Change CS_INIT -> CS_ROUTING
2013-08-29 20:07:27.432045 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/1001@54.213.58.94 [BREAK]
2013-08-29 20:07:27.432045 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/1001@54.213.58.94) State INIT going to sleep
2013-08-29 20:07:27.432045 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/1001@54.213.58.94) Running State Change CS_ROUTING
2013-08-29 20:07:27.432045 [DEBUG] switch_channel.c:2116 (sofia/internal/1001@54.213.58.94) Callstate Change DOWN -> RINGING
2013-08-29 20:07:27.432045 [DEBUG] switch_core_state_machine.c:471 (sofia/internal/1001@54.213.58.94) State ROUTING
2013-08-29 20:07:27.432045 [DEBUG] mod_sofia.c:137 sofia/internal/1001@54.213.58.94 SOFIA ROUTING
2013-08-29 20:07:27.432045 [DEBUG] switch_core_state_machine.c:117 sofia/internal/1001@54.213.58.94 Standard ROUTING
2013-08-29 20:07:27.432045 [INFO] mod_dialplan_xml.c:558 Processing 1001 <1001>->1002 in context public
Dialplan: sofia/internal/1001@54.213.58.94 parsing [public->public_did] continue=false
Dialplan: sofia/internal/1001@54.213.58.94 Regex (FAIL) [public_did] destination_number(1002) =~ /^(5551212)$/ break=on-false
Dialplan: sofia/internal/1001@54.213.58.94 parsing [public->conferences_10000] continue=false
Dialplan: sofia/internal/1001@54.213.58.94 Regex (FAIL) [conferences_10000] destination_number(1002) =~ /^(10000)$/ break=on-false
Dialplan: sofia/internal/1001@54.213.58.94 parsing [public->conferences_123123123123] continue=false
Dialplan: sofia/internal/1001@54.213.58.94 Regex (FAIL) [conferences_123123123123] destination_number(1002) =~ /^(123123123123)$/ break=on-false
Dialplan: sofia/internal/1001@54.213.58.94 parsing [public->conferences_2354] continue=false
Dialplan: sofia/internal/1001@54.213.58.94 Regex (FAIL) [conferences_2354] destination_number(1002) =~ /^(2354)$/ break=on-false
Dialplan: sofia/internal/1001@54.213.58.94 parsing [public->conferences_2355] continue=false
Dialplan: sofia/internal/1001@54.213.58.94 Regex (FAIL) [conferences_2355] destination_number(1002) =~ /^(2355)$/ break=on-false
Dialplan: sofia/internal/1001@54.213.58.94 parsing [public->conferences_2356] continue=false
Dialplan: sofia/internal/1001@54.213.58.94 Regex (FAIL) [conferences_2356] destination_number(1002) =~ /^(2356)$/ break=on-false
Dialplan: sofia/internal/1001@54.213.58.94 parsing [public->conferences_2722249814] continue=false
Dialplan: sofia/internal/1001@54.213.58.94 Regex (FAIL) [conferences_2722249814] destination_number(1002) =~ /^(2722249814)$/ break=on-false
Dialplan: sofia/internal/1001@54.213.58.94 parsing [public->conferences_800] continue=false
Dialplan: sofia/internal/1001@54.213.58.94 Regex (FAIL) [conferences_800] destination_number(1002) =~ /^(800)$/ break=on-false
Dialplan: sofia/internal/1001@54.213.58.94 parsing [public->conferences_800100] continue=false
Dialplan: sofia/internal/1001@54.213.58.94 Regex (FAIL) [conferences_800100] destination_number(1002) =~ /^(800100)$/ break=on-false
Dialplan: sofia/internal/1001@54.213.58.94 parsing [public->conferences_Raj2] continue=false
Dialplan: sofia/internal/1001@54.213.58.94 Regex (FAIL) [conferences_Raj2] destination_number(1002) =~ /^(Raj2)$/ break=on-false
Dialplan: sofia/internal/1001@54.213.58.94 parsing [public->conferences_RajRoom] continue=false
Dialplan: sofia/internal/1001@54.213.58.94 Regex (FAIL) [conferences_RajRoom] destination_number(1002) =~ /^(RajRoom)$/ break=on-false
Dialplan: sofia/internal/1001@54.213.58.94 parsing [public->conferences_monu_ki_conference] continue=false
Dialplan: sofia/internal/1001@54.213.58.94 Regex (FAIL) [conferences_monu_ki_conference] destination_number(1002) =~ /^(conference_monu_ki_conference)$/ break=on-false
Dialplan: sofia/internal/1001@54.213.58.94 parsing [public->sunil_conferences] continue=false
Dialplan: sofia/internal/1001@54.213.58.94 Regex (FAIL) [sunil_conferences] destination_number(1002) =~ /^2353$/ break=on-false
Dialplan: sofia/internal/1001@54.213.58.94 parsing [public->Adhearsion] continue=false
Dialplan: sofia/internal/1001@54.213.58.94 Regex (PASS) [Adhearsion] destination_number(1002) =~ /.*$/ break=on-false
Dialplan: sofia/internal/1001@54.213.58.94 Action info()
Dialplan: sofia/internal/1001@54.213.58.94 Action set(is_parent_leg=yes)
Dialplan: sofia/internal/1001@54.213.58.94 Action set(hangup_after_bridge=false)
Dialplan: sofia/internal/1001@54.213.58.94 Action set(park_after_bridge=false)
Dialplan: sofia/internal/1001@54.213.58.94 Action set(domain_name=54.213.58.94)
Dialplan: sofia/internal/1001@54.213.58.94 Action rayo()
2013-08-29 20:07:27.432045 [DEBUG] switch_core_state_machine.c:167 (sofia/internal/1001@54.213.58.94) State Change CS_ROUTING -> CS_EXECUTE
2013-08-29 20:07:27.432045 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/1001@54.213.58.94 [BREAK]
2013-08-29 20:07:27.432045 [DEBUG] switch_core_state_machine.c:471 (sofia/internal/1001@54.213.58.94) State ROUTING going to sleep
2013-08-29 20:07:27.432045 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/1001@54.213.58.94) Running State Change CS_EXECUTE
2013-08-29 20:07:27.432045 [DEBUG] switch_core_state_machine.c:478 (sofia/internal/1001@54.213.58.94) State EXECUTE
2013-08-29 20:07:27.432045 [DEBUG] mod_sofia.c:230 sofia/internal/1001@54.213.58.94 SOFIA EXECUTE
2013-08-29 20:07:27.432045 [DEBUG] switch_core_state_machine.c:209 sofia/internal/1001@54.213.58.94 Standard EXECUTE
EXECUTE sofia/internal/1001@54.213.58.94 info()
2013-08-29 20:07:27.432045 [INFO] mod_dptools.c:1586 CHANNEL_DATA:
Channel-State: [CS_EXECUTE]
Channel-Call-State: [RINGING]
Channel-State-Number: [4]
Channel-Name: [sofia/internal/1001@54.213.58.94]
Unique-ID: [424928b4-bc76-505f-febd-a5febae13aa3]
Call-Direction: [inbound]
Presence-Call-Direction: [inbound]
Channel-HIT-Dialplan: [true]
Channel-Presence-ID: [1001@54.213.58.94]
Channel-Call-UUID: [424928b4-bc76-505f-febd-a5febae13aa3]
Answer-State: [ringing]
Caller-Direction: [inbound]
Caller-Username: [1001]
Caller-Dialplan: [XML]
Caller-Caller-ID-Name: [1001]
Caller-Caller-ID-Number: [1001]
Caller-Orig-Caller-ID-Name: [1001]
Caller-Orig-Caller-ID-Number: [1001]
Caller-Network-Addr: [202.157.93.2]
Caller-ANI: [1001]
Caller-Destination-Number: [1002]
Caller-Unique-ID: [424928b4-bc76-505f-febd-a5febae13aa3]
Caller-Source: [mod_sofia]
Caller-Context: [public]
Caller-Channel-Name: [sofia/internal/1001@54.213.58.94]
Caller-Profile-Index: [1]
Caller-Profile-Created-Time: [1377821247432045]
Caller-Channel-Created-Time: [1377821247432045]
Caller-Channel-Answered-Time: [0]
Caller-Channel-Progress-Time: [0]
Caller-Channel-Progress-Media-Time: [0]
Caller-Channel-Hangup-Time: [0]
Caller-Channel-Transfer-Time: [0]
Caller-Channel-Resurrect-Time: [0]
Caller-Channel-Bridged-Time: [0]
Caller-Channel-Last-Hold: [0]
Caller-Channel-Hold-Accum: [0]
Caller-Screen-Bit: [true]
Caller-Privacy-Hide-Name: [false]
Caller-Privacy-Hide-Number: [false]
variable_direction: [inbound]
variable_uuid: [424928b4-bc76-505f-febd-a5febae13aa3]
variable_session_id: [25]
variable_sip_from_user: [1001]
variable_sip_from_uri: [1001@54.213.58.94]
variable_sip_from_host: [54.213.58.94]
variable_channel_name: [sofia/internal/1001@54.213.58.94]
variable_sip_call_id: [424928b4-bc76-505f-febd-a5febae13aa3]
variable_sip_local_network_addr: [54.213.58.94]
variable_sip_network_ip: [202.157.93.2]
variable_sip_network_port: [63020]
variable_sip_received_ip: [202.157.93.2]
variable_sip_received_port: [63020]
variable_sip_via_protocol: [ws]
variable_sip_authorized: [true]
variable_sip_acl_authed_by: [domains]
variable_sip_from_user_stripped: [1001]
variable_sip_from_tag: [rUEmLhAqn5JETUNxGUPJ]
variable_sofia_profile_name: [internal]
variable_recovery_profile_name: [internal]
variable_sip_full_via: [SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKFdZVBe8T02PrtL6Q3OiuqruyMMHqROwS;rport=63020;received=202.157.93.2]
variable_sip_full_from: [<sip:1001@54.213.58.94>;tag=rUEmLhAqn5JETUNxGUPJ]
variable_sip_full_to: [<sip:1002@54.213.58.94>]
variable_sip_req_user: [1002]
variable_sip_req_uri: [1002@54.213.58.94]
variable_sip_req_host: [54.213.58.94]
variable_sip_to_user: [1002]
variable_sip_to_uri: [1002@54.213.58.94]
variable_sip_to_host: [54.213.58.94]
variable_sip_contact_params: [rtcweb-breaker=no;click2call=no;transport=ws]
variable_sip_contact_user: [1001]
variable_sip_contact_uri: [1001@df7jal23ls0d.invalid]
variable_sip_contact_host: [df7jal23ls0d.invalid]
variable_rtp_use_codec_string: [G722,PCMU,PCMA,GSM]
variable_sip_user_agent: [IM-client/OMA1.0 sipML5-v1.2013.05.24]
variable_sip_via_host: [df7jal23ls0d.invalid]
variable_sip_via_rport: [63020]
variable_max_forwards: [70]
variable_presence_id: [1001@54.213.58.94]
variable_sip_nat_detected: [true]
variable_switch_r_sdp: [v=0
o=- 417531139091299800 2 IN IP4 127.0.0.1
s=Doubango Telecom - chrome
t=0 0
a=group:BUNDLE audio video
a=msid-semantic: WMS yhhZ3SJtPGPnmHpiROozjtjw4QZ8d7KftE1z
m=audio 62710 RTP/SAVPF 111 103 104 0 8 107 106 105 13 126
c=IN IP4 202.157.93.2
a=rtpmap:111 opus/48000/2
a=fmtp:111 minptime=10
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:107 CN/48000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:126 telephone-event/8000
a=rtcp:62710 IN IP4 202.157.93.2
a=candidate:524234378 1 udp 2113937151 10.100.101.254 62710 typ host generation 0
a=candidate:524234378 2 udp 2113937151 10.100.101.254 62710 typ host generation 0
a=candidate:1371329146 1 tcp 1509957375 10.100.101.254 0 typ host generation 0
a=candidate:1371329146 2 tcp 1509957375 10.100.101.254 0 typ host generation 0
a=candidate:3551662361 1 udp 1845501695 202.157.93.2 62710 typ srflx raddr 10.100.101.254 rport 62710 generation 0
a=candidate:3551662361 2 udp 1845501695 202.157.93.2 62710 typ srflx raddr 10.100.101.254 rport 62710 generation 0
a=ice-ufrag:Wg2KPXu0KeJsEiW0
a=ice-pwd:AEydpu9aYxE309iFeTeJEMOO
a=ice-options:google-ice
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=mid:audio
a=rtcp-mux
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:mOzzWppgFTdvWF0fn9jx9rZ9RR21wJ9yX5weywrC
a=maxptime:60
a=ssrc:169614681 cname:GO5nEQ90ukOmvC1y
a=ssrc:169614681 msid:yhhZ3SJtPGPnmHpiROozjtjw4QZ8d7KftE1z yhhZ3SJtPGPnmHpiROozjtjw4QZ8d7KftE1za0
a=ssrc:169614681 mslabel:yhhZ3SJtPGPnmHpiROozjtjw4QZ8d7KftE1z
a=ssrc:169614681 label:yhhZ3SJtPGPnmHpiROozjtjw4QZ8d7KftE1za0
m=video 62710 RTP/SAVPF 100 116 117
c=IN IP4 202.157.93.2
a=rtpmap:100 VP8/90000
a=rtpmap:116 red/90000
a=rtpmap:117 ulpfec/90000
a=rtcp:62710 IN IP4 202.157.93.2
a=candidate:524234378 1 udp 2113937151 10.100.101.254 62710 typ host generation 0
a=candidate:524234378 2 udp 2113937151 10.100.101.254 62710 typ host generation 0
a=candidate:1371329146 1 tcp 1509957375 10.100.101.254 0 typ host generation 0
a=candidate:1371329146 2 tcp 1509957375 10.100.101.254 0 typ host generation 0
a=candidate:3551662361 1 udp 1845501695 202.157.93.2 62710 typ srflx raddr 10.100.101.254 rport 62710 generation 0
a=candidate:3551662361 2 udp 1845501695 202.157.93.2 62710 typ srflx raddr 10.100.101.254 rport 62710 generation 0
a=ice-ufrag:Wg2KPXu0KeJsEiW0
a=ice-pwd:AEydpu9aYxE309iFeTeJEMOO
a=ice-options:google-ice
a=extmap:2 urn:ietf:params:rtp-hdrext:toffset
a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=mid:video
a=rtcp-mux
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:mOzzWppgFTdvWF0fn9jx9rZ9RR21wJ9yX5weywrC
a=rtcp-fb:100 ccm fir
a=rtcp-fb:100 nack
a=rtcp-fb:100 goog-remb
]
variable_ep_codec_string: [PCMU@8000h@20i@64000b,PCMA@8000h@20i@64000b]
variable_endpoint_disposition: [DELAYED NEGOTIATION]
variable_call_uuid: [424928b4-bc76-505f-febd-a5febae13aa3]
variable_current_application: [info]
EXECUTE sofia/internal/1001@54.213.58.94 set(is_parent_leg=yes)
2013-08-29 20:07:27.432045 [DEBUG] mod_dptools.c:1374 sofia/internal/1001@54.213.58.94 SET [is_parent_leg]=[yes]
EXECUTE sofia/internal/1001@54.213.58.94 set(hangup_after_bridge=false)
2013-08-29 20:07:27.432045 [DEBUG] mod_dptools.c:1374 sofia/internal/1001@54.213.58.94 SET [hangup_after_bridge]=[false]
EXECUTE sofia/internal/1001@54.213.58.94 set(park_after_bridge=false)
2013-08-29 20:07:27.432045 [DEBUG] mod_dptools.c:1374 sofia/internal/1001@54.213.58.94 SET [park_after_bridge]=[false]
EXECUTE sofia/internal/1001@54.213.58.94 set(domain_name=54.213.58.94)
2013-08-29 20:07:27.432045 [DEBUG] mod_dptools.c:1374 sofia/internal/1001@54.213.58.94 SET [domain_name]=[54.213.58.94]
EXECUTE sofia/internal/1001@54.213.58.94 rayo()
2013-08-29 20:07:27.432045 [DEBUG] mod_rayo.c:2938 Init 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94
2013-08-29 20:07:27.432045 [DEBUG] mod_rayo.c:2943 Offering call for Rayo 3PCC
2013-08-29 20:07:27.432045 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:07:27.432045 [DEBUG] mod_rayo.c:2961 Deliver 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 <presence from='424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766'><offer xmlns='urn:xmpp:rayo:1' from='sip:1001@54.213.58.94' to='sip:1002@54.213.58.94'><header name='from' value='&lt;sip:1001@54.213.58.94&gt;;tag=rUEmLhAqn5JETUNxGUPJ'/><header name='to' value='&lt;sip:1002@54.213.58.94&gt;'/><header name='via' value='SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKFdZVBe8T02PrtL6Q3OiuqruyMMHqROwS;rport=63020;received=202.157.93.2'/></offer></presence>
2013-08-29 20:07:27.432045 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:07:27.452119 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 SEND <presence from='424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766'><offer xmlns='urn:xmpp:rayo:1' from='sip:1001@54.213.58.94' to='sip:1002@54.213.58.94'><header name='from' value='&lt;sip:1001@54.213.58.94&gt;;tag=rUEmLhAqn5JETUNxGUPJ'/><header name='to' value='&lt;sip:1002@54.213.58.94&gt;'/><header name='via' value='SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKFdZVBe8T02PrtL6Q3OiuqruyMMHqROwS;rport=63020;received=202.157.93.2'/></offer></presence>
2013-08-29 20:07:27.590981 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 RECV <iq type="set" to="424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94" id="blather000c"><accept xmlns="urn:xmpp:rayo:1"/></iq>
2013-08-29 20:07:27.590981 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, state = READY, node type = NODE_NORMAL
2013-08-29 20:07:27.590981 [DEBUG] mod_rayo.c:3010 Lock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:07:27.590981 [DEBUG] mod_rayo.c:2365 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, recv iq, availability = ONLINE
2013-08-29 20:07:27.590981 [DEBUG] mod_rayo.c:3069 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:07:27.590981 [DEBUG] mod_rayo.c:624 Locate 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: ref count = 2
2013-08-29 20:07:27.590981 [DEBUG] mod_rayo.c:2368 Deliver 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 => 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94 <iq type='set' to='424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94' id='blather000c' from='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766'><accept xmlns='urn:xmpp:rayo:1'/></iq>
2013-08-29 20:07:27.590981 [DEBUG] mod_rayo.c:505 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94, looking for CALL::set:urn:xmpp:rayo:1:accept command
2013-08-29 20:07:27.590981 [INFO] mod_rayo.c:1314 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 has control of call
2013-08-29 20:07:27.590981 [DEBUG] mod_rayo.c:1471 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94, executing command
2013-08-29 20:07:27.590981 [INFO] mod_rayo.c:1609 Sending early media
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:881 Set Remote Key [1 AES_CM_128_HMAC_SHA1_80 inline:mOzzWppgFTdvWF0fn9jx9rZ9RR21wJ9yX5weywrC]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:682 Set Local Key [1 AES_CM_128_HMAC_SHA1_80 inline:o04A9WuX0qSgkP+ctMOcqfIgqMLOPQzsUnEF2nNe]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2787 Audio Codec Compare [opus:111:48000:60:0]/[G722:9:8000:20:64000]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2787 Audio Codec Compare [opus:111:48000:60:0]/[PCMU:0:8000:20:64000]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2787 Audio Codec Compare [opus:111:48000:60:0]/[PCMA:8:8000:20:64000]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2787 Audio Codec Compare [opus:111:48000:60:0]/[GSM:3:8000:20:13200]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2787 Audio Codec Compare [ISAC:103:16000:30:32000]/[G722:9:8000:20:64000]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2787 Audio Codec Compare [ISAC:103:16000:30:32000]/[PCMU:0:8000:20:64000]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2787 Audio Codec Compare [ISAC:103:16000:30:32000]/[PCMA:8:8000:20:64000]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2787 Audio Codec Compare [ISAC:103:16000:30:32000]/[GSM:3:8000:20:13200]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2787 Audio Codec Compare [ISAC:104:32000:30:32000]/[G722:9:8000:20:64000]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2787 Audio Codec Compare [ISAC:104:32000:30:32000]/[PCMU:0:8000:20:64000]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2787 Audio Codec Compare [ISAC:104:32000:30:32000]/[PCMA:8:8000:20:64000]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2787 Audio Codec Compare [ISAC:104:32000:30:32000]/[GSM:3:8000:20:13200]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2787 Audio Codec Compare [PCMU:0:8000:60:64000]/[G722:9:8000:20:64000]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2787 Audio Codec Compare [PCMU:0:8000:60:64000]/[PCMU:0:8000:20:64000]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:1823 Set Codec sofia/internal/1001@54.213.58.94 PCMU/8000 20 ms 160 samples 64000 bits
2013-08-29 20:07:27.590981 [DEBUG] switch_core_codec.c:111 sofia/internal/1001@54.213.58.94 Original read codec set to PCMU:0
2013-08-29 20:07:27.590981 [WARNING] switch_core_media.c:2002 NO candidate ACL defined, Defaulting to wan.auto
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2026 Checking Candidate cid: 1 proto: udp type: host addr: 10.100.101.254:62710
2013-08-29 20:07:27.590981 [NOTICE] switch_core_media.c:2040 Save audio Candidate cid: 1 proto: udp type: host addr: 10.100.101.254:62710
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2026 Checking Candidate cid: 2 proto: udp type: host addr: 10.100.101.254:62710
2013-08-29 20:07:27.590981 [NOTICE] switch_core_media.c:2040 Save audio Candidate cid: 2 proto: udp type: host addr: 10.100.101.254:62710
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2026 Checking Candidate cid: 1 proto: udp type: srflx addr: 202.157.93.2:62710
2013-08-29 20:07:27.590981 [NOTICE] switch_core_media.c:2035 Choose audio Candidate cid: 1 proto: udp type: srflx addr: 202.157.93.2:62710
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2026 Checking Candidate cid: 2 proto: udp type: srflx addr: 202.157.93.2:62710
2013-08-29 20:07:27.590981 [NOTICE] switch_core_media.c:2035 Choose audio Candidate cid: 2 proto: udp type: srflx addr: 202.157.93.2:62710
2013-08-29 20:07:27.590981 [NOTICE] switch_core_media.c:2149 setting remote audio ice addr to 202.157.93.2:62710 based on candidate
2013-08-29 20:07:27.590981 [NOTICE] switch_core_media.c:2167 setting remote rtcp audio addr to 202.157.93.2:62710 based on candidate
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:2958 Set 2833 dtmf send/recv payload to 126
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:881 Set Remote Key [1 AES_CM_128_HMAC_SHA1_80 inline:mOzzWppgFTdvWF0fn9jx9rZ9RR21wJ9yX5weywrC]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:682 Set Local Key [1 AES_CM_128_HMAC_SHA1_80 inline:8keJpJsPDno27YyBMP6Er5cQJquljOrYm2PbT4pG]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:3986 AUDIO RTP [sofia/internal/1001@54.213.58.94] 172.31.41.127 port 31924 -> 202.157.93.2 port 62710 codec: 0 ms: 20
2013-08-29 20:07:27.590981 [DEBUG] switch_rtp.c:2885 Starting timer [soft] 160 bytes per 20ms
2013-08-29 20:07:27.590981 [INFO] switch_core_media.c:4149 Activating Audio ICE
2013-08-29 20:07:27.590981 [NOTICE] switch_rtp.c:3317 Activating RTP audio ICE: Wg2KPXu0KeJsEiW0:OiAKpFdDYT1WvVLA 202.157.93.2:62710
2013-08-29 20:07:27.590981 [INFO] switch_core_media.c:4192 Activating RTCP PORT 62710
2013-08-29 20:07:27.590981 [DEBUG] switch_rtp.c:3222 RTCP send rate is: 10000 and packet rate is: 20000 Remote Port: 62710
2013-08-29 20:07:27.590981 [DEBUG] switch_rtp.c:1858 Setting RTCP remote addr to 202.157.93.2:62710
2013-08-29 20:07:27.590981 [INFO] switch_core_media.c:4200 Skipping RTCP ICE (Same as RTP)
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:4320 Set 2833 dtmf send payload to 126
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:4326 Set 2833 dtmf receive payload to 126
2013-08-29 20:07:27.590981 [DEBUG] switch_core_media.c:4359 Set comfort noise payload to 107
2013-08-29 20:07:27.590981 [INFO] switch_rtp.c:2705 Activating Audio Secure RTP SEND
2013-08-29 20:07:27.590981 [INFO] switch_rtp.c:2683 Activating Audio Secure RTP RECV
2013-08-29 20:07:27.590981 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1001@54.213.58.94!
2013-08-29 20:07:27.590981 [DEBUG] switch_channel.c:3316 (sofia/internal/1001@54.213.58.94) Callstate Change RINGING -> EARLY
2013-08-29 20:07:27.590981 [DEBUG] mod_sofia.c:2105 Ring SDP:
v=0
o=FreeSWITCH 1377789323 1377789324 IN IP4 54.213.58.94
s=FreeSWITCH
c=IN IP4 54.213.58.94
t=0 0
a=msid-semantic: WMS 1EIDro0V8i90FUfnMdi46heCotQx7L4Z
m=audio 31924 RTP/SAVPF 0 126 107
a=rtpmap:0 PCMU/8000
a=rtpmap:126 telephone-event/8000
a=rtpmap:107 CN/8000
a=ptime:20
a=sendrecv
a=rtcp-mux
a=rtcp:31924 IN IP4 54.213.58.94
a=ssrc:1618248726 cname:fDswRjiPriFW2LaF
a=ssrc:1618248726 msid:1EIDro0V8i90FUfnMdi46heCotQx7L4Z a0
a=ssrc:1618248726 mslabel:1EIDro0V8i90FUfnMdi46heCotQx7L4Z
a=ssrc:1618248726 label:1EIDro0V8i90FUfnMdi46heCotQx7L4Za0
a=ice-ufrag:OiAKpFdDYT1WvVLA
a=ice-pwd:o4X6d6Luehh7ShCx
a=candidate:9165585375 1 udp 659136 54.213.58.94 31924 typ host generation 0
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:o04A9WuX0qSgkP+ctMOcqfIgqMLOPQzsUnEF2nNe
2013-08-29 20:07:27.590981 [DEBUG] switch_core_session.c:861 Send signal sofia/internal/1001@54.213.58.94 [BREAK]
2013-08-29 20:07:27.590981 [DEBUG] mod_rayo.c:1473 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94, done executing command
2013-08-29 20:07:27.590981 [DEBUG] mod_rayo.c:631 Unlock 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: ref count = 1
2013-08-29 20:07:27.590981 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:07:27.590981 [DEBUG] mod_rayo.c:1480 Deliver 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 <iq from='424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' type='result' id='blather000c'/>
2013-08-29 20:07:27.590981 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:07:27.590981 [DEBUG] switch_core_sqldb.c:2352 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2013-08-29 20:07:27.590981 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/1001@54.213.58.94 [BREAK]
2013-08-29 20:07:27.590981 [DEBUG] switch_core_sqldb.c:2352 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2013-08-29 20:07:27.590981 [DEBUG] mod_rayo.c:2776 got event CHANNEL_PROGRESS_MEDIA
2013-08-29 20:07:27.590981 [DEBUG] mod_rayo.c:2781 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 rayo event CHANNEL_PROGRESS_MEDIA
2013-08-29 20:07:27.590981 [DEBUG] mod_rayo.c:2783 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:07:27.590981 [DEBUG] mod_rayo.c:2791 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:07:27.590981 [DEBUG] sofia.c:5793 Channel sofia/internal/1001@54.213.58.94 entering state [early][183]
2013-08-29 20:07:27.590981 [DEBUG] switch_ivr.c:951 Codec Activated L16@8000hz 1 channels 20ms
2013-08-29 20:07:27.590981 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 SEND <iq from='424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' type='result' id='blather000c'/>
2013-08-29 20:07:28.056773 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 RECV <iq type="set" to="424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94" id="blather000e"><answer xmlns="urn:xmpp:rayo:1"/></iq>
2013-08-29 20:07:28.056773 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, state = READY, node type = NODE_NORMAL
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:3010 Lock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:2365 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, recv iq, availability = ONLINE
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:3069 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:624 Locate 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: ref count = 2
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:2368 Deliver 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 => 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94 <iq type='set' to='424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94' id='blather000e' from='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766'><answer xmlns='urn:xmpp:rayo:1'/></iq>
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:505 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94, looking for CALL::set:urn:xmpp:rayo:1:answer command
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:1471 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94, executing command
2013-08-29 20:07:28.056773 [DEBUG] mod_sofia.c:822 Local SDP sofia/internal/1001@54.213.58.94:
v=0
o=FreeSWITCH 1377789323 1377789325 IN IP4 54.213.58.94
s=FreeSWITCH
c=IN IP4 54.213.58.94
t=0 0
a=msid-semantic: WMS 1EIDro0V8i90FUfnMdi46heCotQx7L4Z
m=audio 31924 RTP/SAVPF 0 126 107
a=rtpmap:0 PCMU/8000
a=rtpmap:126 telephone-event/8000
a=rtpmap:107 CN/8000
a=ptime:20
a=sendrecv
a=rtcp-mux
a=rtcp:31924 IN IP4 54.213.58.94
a=ssrc:1618248726 cname:fDswRjiPriFW2LaF
a=ssrc:1618248726 msid:1EIDro0V8i90FUfnMdi46heCotQx7L4Z a0
a=ssrc:1618248726 mslabel:1EIDro0V8i90FUfnMdi46heCotQx7L4Z
a=ssrc:1618248726 label:1EIDro0V8i90FUfnMdi46heCotQx7L4Za0
a=ice-ufrag:OiAKpFdDYT1WvVLA
a=ice-pwd:o4X6d6Luehh7ShCx
a=candidate:8637987208 1 udp 659136 54.213.58.94 31924 typ host generation 0
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:o04A9WuX0qSgkP+ctMOcqfIgqMLOPQzsUnEF2nNe
2013-08-29 20:07:28.056773 [DEBUG] switch_core_session.c:861 Send signal sofia/internal/1001@54.213.58.94 [BREAK]
2013-08-29 20:07:28.056773 [NOTICE] mod_rayo.c:1628 Channel [sofia/internal/1001@54.213.58.94] has been answered
2013-08-29 20:07:28.056773 [DEBUG] switch_channel.c:3595 (sofia/internal/1001@54.213.58.94) Callstate Change EARLY -> ACTIVE
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:1473 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94, done executing command
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:631 Unlock 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: ref count = 1
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:1480 Deliver 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 <iq from='424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' type='result' id='blather000e'/>
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:2776 got event CHANNEL_ANSWER
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:2781 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 rayo event CHANNEL_ANSWER
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:2783 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:2616 Locate 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: ref count = 2
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:2622 Unlock 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: ref count = 1
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:2791 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:2621 Deliver 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 <presence from='424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766'><answered xmlns='urn:xmpp:rayo:1'/></presence>
2013-08-29 20:07:28.056773 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:07:28.056773 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/1001@54.213.58.94 [BREAK]
2013-08-29 20:07:28.056773 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 SEND <iq from='424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' type='result' id='blather000e'/>
2013-08-29 20:07:28.056773 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 SEND <presence from='424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766'><answered xmlns='urn:xmpp:rayo:1'/></presence>
2013-08-29 20:07:28.191113 [DEBUG] sofia.c:5793 Channel sofia/internal/1001@54.213.58.94 entering state [completed][200]
2013-08-29 20:07:28.220537 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 RECV <iq type="set" to="424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94" id="blather0010"><output xmlns="urn:xmpp:rayo:output:1" start-paused="false"><document content-type="application/ssml+xml"><![CDATA[<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">
<audio src="/var/punchblock/record/welcome.mp3"/>
</speak>]]></document></output></iq>
2013-08-29 20:07:28.220537 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, state = READY, node type = NODE_NORMAL
2013-08-29 20:07:28.220537 [DEBUG] mod_rayo.c:3010 Lock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:07:28.220537 [DEBUG] mod_rayo.c:2365 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, recv iq, availability = ONLINE
2013-08-29 20:07:28.220537 [DEBUG] mod_rayo.c:3069 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:07:28.220537 [DEBUG] mod_rayo.c:624 Locate 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: ref count = 2
2013-08-29 20:07:28.220537 [DEBUG] mod_rayo.c:2368 Deliver 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 => 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94 <iq type='set' to='424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94' id='blather0010' from='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766'><output xmlns='urn:xmpp:rayo:output:1' start-paused='false'><document content-type='application/ssml+xml'>&lt;speak xmlns=&quot;http://www.w3.org/2001/10/synthesis&quot; version=&quot;1.0&quot; xml:lang=&quot;en-US&quot;&gt;
&lt;audio src=&quot;/var/punchblock/record/welcome.mp3&quot;/&gt;
&lt;/speak&gt;</document></output></iq>
2013-08-29 20:07:28.220537 [DEBUG] mod_rayo.c:505 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94, looking for CALL::set:urn:xmpp:rayo:output:1:output command
2013-08-29 20:07:28.220537 [DEBUG] mod_rayo.c:1471 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94, executing command
2013-08-29 20:07:28.220537 [DEBUG] rayo_output_component.c:67 Init 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94/output-1
2013-08-29 20:07:28.220537 [DEBUG] mod_rayo.c:1151 Lock 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: ref count = 3
2013-08-29 20:07:28.220537 [DEBUG] switch_event.c:1615 Parsing variable [id]=[424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94/output-1]
2013-08-29 20:07:28.220537 [DEBUG] switch_event.c:1615 Parsing variable [session]=[424928b4-bc76-505f-febd-a5febae13aa3]
2013-08-29 20:07:28.220537 [DEBUG] switch_event.c:1615 Parsing variable [pause]=[false]
2013-08-29 20:07:28.220537 [DEBUG] rayo_output_component.c:624 Got path rayo://424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94/output-1
2013-08-29 20:07:28.220537 [DEBUG] rayo_output_component.c:458 Got path 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94/output-1
2013-08-29 20:07:28.220537 [DEBUG] rayo_output_component.c:460 Locate 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94/output-1: ref count = 2
2013-08-29 20:07:28.220537 [DEBUG] mod_ssml.c:793 Open: <speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">
<audio src="/var/punchblock/record/welcome.mp3"/>
</speak>
2013-08-29 20:07:28.220537 [DEBUG] mod_ssml.c:813 Parse error: <speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">
<audio src="/var/punchblock/record/welcome.mp3"/>
</speak>, num_files = 0
2013-08-29 20:07:28.220537 [INFO] rayo_output_component.c:425 Failed to open ssml://<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">
<audio src="/var/punchblock/record/welcome.mp3"/>
</speak>
2013-08-29 20:07:28.220537 [INFO] rayo_output_component.c:386 Done playing
2013-08-29 20:07:28.220537 [INFO] rayo_output_component.c:474 Status = 1
2013-08-29 20:07:28.220537 [DEBUG] rayo_output_component.c:475 Unlock 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94/output-1: ref count = 1
2013-08-29 20:07:28.220537 [DEBUG] rayo_components.c:116 Unlock 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94/output-1: ref count = 0
2013-08-29 20:07:28.220537 [DEBUG] rayo_components.c:117 Destroy 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94/output-1 requested: ref_count = 0
2013-08-29 20:07:28.220537 [DEBUG] rayo_components.c:117 Destroying 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94/output-1
2013-08-29 20:07:28.220537 [DEBUG] mod_rayo.c:1129 Unlock 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: ref count = 2
2013-08-29 20:07:28.220537 [DEBUG] mod_rayo.c:1473 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94, done executing command
2013-08-29 20:07:28.220537 [DEBUG] mod_rayo.c:631 Unlock 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: ref count = 1
2013-08-29 20:07:28.220537 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:07:28.220537 [DEBUG] rayo_components.c:62 Deliver 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94/output-1 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 <iq from='424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' type='result' id='blather0010'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94/output-1'/></iq>
2013-08-29 20:07:28.220537 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:07:28.220537 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:07:28.220537 [DEBUG] rayo_components.c:115 Deliver 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94/output-1 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 <presence from='424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94/output-1' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' type='unavailable'><complete xmlns='urn:xmpp:rayo:ext:1'><error xmlns='urn:xmpp:rayo:ext:complete:1'/></complete></presence>
2013-08-29 20:07:28.220537 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:07:28.220537 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 SEND <iq from='424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' type='result' id='blather0010'><ref xmlns='urn:xmpp:rayo:1' uri='xmpp:424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94/output-1'/></iq>
2013-08-29 20:07:28.220537 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 SEND <presence from='424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94/output-1' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' type='unavailable'><complete xmlns='urn:xmpp:rayo:ext:1'><error xmlns='urn:xmpp:rayo:ext:complete:1'/></complete></presence>
2013-08-29 20:07:28.472357 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/1001@54.213.58.94 [BREAK]
2013-08-29 20:07:28.472357 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/1001@54.213.58.94 [BREAK]
2013-08-29 20:07:28.472357 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/1001@54.213.58.94 [BREAK]
2013-08-29 20:07:28.492199 [DEBUG] sofia.c:5793 Channel sofia/internal/1001@54.213.58.94 entering state [ready][200]
2013-08-29 20:07:51.330449 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 RECV <iq type="get" to="54.213.58.94" id="blather0012"><ping xmlns="urn:xmpp:ping"/></iq>
2013-08-29 20:07:51.330449 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, state = READY, node type = NODE_NORMAL
2013-08-29 20:07:51.330449 [DEBUG] mod_rayo.c:3010 Lock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:07:51.330449 [DEBUG] mod_rayo.c:2365 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, recv iq, availability = ONLINE
2013-08-29 20:07:51.330449 [DEBUG] mod_rayo.c:3069 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:07:51.330449 [DEBUG] mod_rayo.c:624 Locate 54.213.58.94: ref count = 2
2013-08-29 20:07:51.330449 [DEBUG] mod_rayo.c:2368 Deliver 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 => 54.213.58.94 <iq type='get' to='54.213.58.94' id='blather0012' from='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766'><ping xmlns='urn:xmpp:ping'/></iq>
2013-08-29 20:07:51.330449 [DEBUG] mod_rayo.c:505 54.213.58.94, looking for SERVER::get:urn:xmpp:ping:ping command
2013-08-29 20:07:51.330449 [DEBUG] mod_rayo.c:631 Unlock 54.213.58.94: ref count = 1
2013-08-29 20:07:51.330449 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:07:51.330449 [DEBUG] mod_rayo.c:1432 Deliver 54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' id='blather0012'/>
2013-08-29 20:07:51.330449 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:07:51.330449 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 SEND <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' id='blather0012'/>
2013-08-29 20:07:58.229957 [WARNING] mod_rayo.c:2885 Ending abandoned call. idle_duration_ms = 30009 ms
2013-08-29 20:07:58.229957 [NOTICE] mod_rayo.c:2886 Hangup sofia/internal/1001@54.213.58.94 [CS_EXECUTE] [NORMAL_CLEARING]
2013-08-29 20:07:58.229957 [DEBUG] switch_channel.c:3135 Send signal sofia/internal/1001@54.213.58.94 [KILL]
2013-08-29 20:07:58.229957 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/1001@54.213.58.94 [BREAK]
2013-08-29 20:07:58.229957 [DEBUG] switch_core_session.c:2743 sofia/internal/1001@54.213.58.94 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2013-08-29 20:07:58.229957 [DEBUG] switch_core_state_machine.c:478 (sofia/internal/1001@54.213.58.94) State EXECUTE going to sleep
2013-08-29 20:07:58.229957 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/1001@54.213.58.94) Running State Change CS_HANGUP
2013-08-29 20:07:58.229957 [DEBUG] switch_core_state_machine.c:679 (sofia/internal/1001@54.213.58.94) State HANGUP
2013-08-29 20:07:58.229957 [DEBUG] mod_sofia.c:463 Channel sofia/internal/1001@54.213.58.94 hanging up, cause: NORMAL_CLEARING
2013-08-29 20:07:58.229957 [DEBUG] mod_sofia.c:515 Sending BYE to sofia/internal/1001@54.213.58.94
2013-08-29 20:07:58.229957 [DEBUG] switch_core_state_machine.c:48 sofia/internal/1001@54.213.58.94 Standard HANGUP, cause: NORMAL_CLEARING
2013-08-29 20:07:58.229957 [DEBUG] switch_core_state_machine.c:679 (sofia/internal/1001@54.213.58.94) State HANGUP going to sleep
2013-08-29 20:07:58.229957 [DEBUG] switch_core_state_machine.c:692 (sofia/internal/1001@54.213.58.94) Callstate Change ACTIVE -> HANGUP
2013-08-29 20:07:58.229957 [DEBUG] switch_core_state_machine.c:447 (sofia/internal/1001@54.213.58.94) State Change CS_HANGUP -> CS_REPORTING
2013-08-29 20:07:58.229957 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/1001@54.213.58.94 [BREAK]
2013-08-29 20:07:58.229957 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/1001@54.213.58.94) Running State Change CS_REPORTING
2013-08-29 20:07:58.229957 [DEBUG] switch_core_state_machine.c:764 (sofia/internal/1001@54.213.58.94) State REPORTING
2013-08-29 20:07:58.229957 [DEBUG] switch_core_state_machine.c:92 sofia/internal/1001@54.213.58.94 Standard REPORTING, cause: NORMAL_CLEARING
2013-08-29 20:07:58.229957 [DEBUG] switch_core_state_machine.c:764 (sofia/internal/1001@54.213.58.94) State REPORTING going to sleep
2013-08-29 20:07:58.229957 [DEBUG] switch_core_state_machine.c:441 (sofia/internal/1001@54.213.58.94) State Change CS_REPORTING -> CS_DESTROY
2013-08-29 20:07:58.229957 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/1001@54.213.58.94 [BREAK]
2013-08-29 20:07:58.229957 [DEBUG] switch_core_session.c:1549 Session 25 (sofia/internal/1001@54.213.58.94) Locked, Waiting on external entities
2013-08-29 20:07:58.229957 [NOTICE] switch_core_session.c:1567 Session 25 (sofia/internal/1001@54.213.58.94) Ended
2013-08-29 20:07:58.229957 [NOTICE] switch_core_session.c:1571 Close Channel sofia/internal/1001@54.213.58.94 [CS_DESTROY]
2013-08-29 20:07:58.229957 [DEBUG] switch_core_state_machine.c:566 (sofia/internal/1001@54.213.58.94) Callstate Change HANGUP -> DOWN
2013-08-29 20:07:58.229957 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/1001@54.213.58.94) Running State Change CS_DESTROY
2013-08-29 20:07:58.229957 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/1001@54.213.58.94) State DESTROY
2013-08-29 20:07:58.229957 [DEBUG] mod_sofia.c:373 sofia/internal/1001@54.213.58.94 SOFIA DESTROY
2013-08-29 20:07:58.229957 [DEBUG] switch_core_state_machine.c:99 sofia/internal/1001@54.213.58.94 Standard DESTROY
2013-08-29 20:07:58.229957 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/1001@54.213.58.94) State DESTROY going to sleep
2013-08-29 20:07:58.229957 [DEBUG] mod_rayo.c:2592 Locate 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: ref count = 2
2013-08-29 20:07:58.229957 [DEBUG] mod_rayo.c:2603 Unlock 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: ref count = 1
2013-08-29 20:07:58.229957 [DEBUG] mod_rayo.c:2604 Destroy 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94 requested: ref_count = 1
2013-08-29 20:07:58.229957 [DEBUG] mod_rayo.c:2605 Unlock 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: ref count = 0
2013-08-29 20:07:58.229957 [DEBUG] mod_rayo.c:2605 Destroying 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94
2013-08-29 20:07:58.229957 [DEBUG] mod_rayo.c:929 Sending <end> to offered client 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766
2013-08-29 20:07:58.229957 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:07:58.229957 [DEBUG] mod_rayo.c:930 Deliver 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 <presence from='424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' type='unavailable'><end xmlns='urn:xmpp:rayo:1'><hungup/></end></presence>
2013-08-29 20:07:58.229957 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:07:58.229957 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 SEND <presence from='424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' type='unavailable'><end xmlns='urn:xmpp:rayo:1'><hungup/></end></presence>
2013-08-29 20:08:51.329255 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 RECV <iq type="get" to="54.213.58.94" id="blather0014"><ping xmlns="urn:xmpp:ping"/></iq>
2013-08-29 20:08:51.329255 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, state = READY, node type = NODE_NORMAL
2013-08-29 20:08:51.329255 [DEBUG] mod_rayo.c:3010 Lock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:08:51.329255 [DEBUG] mod_rayo.c:2365 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, recv iq, availability = ONLINE
2013-08-29 20:08:51.329255 [DEBUG] mod_rayo.c:3069 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:08:51.329255 [DEBUG] mod_rayo.c:624 Locate 54.213.58.94: ref count = 2
2013-08-29 20:08:51.329255 [DEBUG] mod_rayo.c:2368 Deliver 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 => 54.213.58.94 <iq type='get' to='54.213.58.94' id='blather0014' from='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766'><ping xmlns='urn:xmpp:ping'/></iq>
2013-08-29 20:08:51.329255 [DEBUG] mod_rayo.c:505 54.213.58.94, looking for SERVER::get:urn:xmpp:ping:ping command
2013-08-29 20:08:51.329255 [DEBUG] mod_rayo.c:631 Unlock 54.213.58.94: ref count = 1
2013-08-29 20:08:51.329255 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:08:51.329255 [DEBUG] mod_rayo.c:1432 Deliver 54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' id='blather0014'/>
2013-08-29 20:08:51.329255 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:08:51.329255 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 SEND <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' id='blather0014'/>
2013-08-29 20:09:51.333018 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 RECV <iq type="get" to="54.213.58.94" id="blather0016"><ping xmlns="urn:xmpp:ping"/></iq>
2013-08-29 20:09:51.333018 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, state = READY, node type = NODE_NORMAL
2013-08-29 20:09:51.333018 [DEBUG] mod_rayo.c:3010 Lock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:09:51.333018 [DEBUG] mod_rayo.c:2365 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, recv iq, availability = ONLINE
2013-08-29 20:09:51.333018 [DEBUG] mod_rayo.c:3069 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:09:51.333018 [DEBUG] mod_rayo.c:624 Locate 54.213.58.94: ref count = 2
2013-08-29 20:09:51.333018 [DEBUG] mod_rayo.c:2368 Deliver 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 => 54.213.58.94 <iq type='get' to='54.213.58.94' id='blather0016' from='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766'><ping xmlns='urn:xmpp:ping'/></iq>
2013-08-29 20:09:51.333018 [DEBUG] mod_rayo.c:505 54.213.58.94, looking for SERVER::get:urn:xmpp:ping:ping command
2013-08-29 20:09:51.333018 [DEBUG] mod_rayo.c:631 Unlock 54.213.58.94: ref count = 1
2013-08-29 20:09:51.333018 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:09:51.333018 [DEBUG] mod_rayo.c:1432 Deliver 54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' id='blather0016'/>
2013-08-29 20:09:51.333018 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:09:51.333018 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 SEND <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' id='blather0016'/>
2013-08-29 20:10:51.332757 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 RECV <iq type="get" to="54.213.58.94" id="blather0018"><ping xmlns="urn:xmpp:ping"/></iq>
2013-08-29 20:10:51.332757 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, state = READY, node type = NODE_NORMAL
2013-08-29 20:10:51.332757 [DEBUG] mod_rayo.c:3010 Lock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:10:51.332757 [DEBUG] mod_rayo.c:2365 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, recv iq, availability = ONLINE
2013-08-29 20:10:51.332757 [DEBUG] mod_rayo.c:3069 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:10:51.332757 [DEBUG] mod_rayo.c:624 Locate 54.213.58.94: ref count = 2
2013-08-29 20:10:51.332757 [DEBUG] mod_rayo.c:2368 Deliver 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 => 54.213.58.94 <iq type='get' to='54.213.58.94' id='blather0018' from='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766'><ping xmlns='urn:xmpp:ping'/></iq>
2013-08-29 20:10:51.332757 [DEBUG] mod_rayo.c:505 54.213.58.94, looking for SERVER::get:urn:xmpp:ping:ping command
2013-08-29 20:10:51.332757 [DEBUG] mod_rayo.c:631 Unlock 54.213.58.94: ref count = 1
2013-08-29 20:10:51.332757 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:10:51.332757 [DEBUG] mod_rayo.c:1432 Deliver 54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' id='blather0018'/>
2013-08-29 20:10:51.332757 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:10:51.332757 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 SEND <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' id='blather0018'/>
2013-08-29 20:11:51.332522 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 RECV <iq type="get" to="54.213.58.94" id="blather001a"><ping xmlns="urn:xmpp:ping"/></iq>
2013-08-29 20:11:51.332522 [DEBUG] xmpp_streams.c:1058 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, state = READY, node type = NODE_NORMAL
2013-08-29 20:11:51.332522 [DEBUG] mod_rayo.c:3010 Lock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:11:51.332522 [DEBUG] mod_rayo.c:2365 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766, recv iq, availability = ONLINE
2013-08-29 20:11:51.332522 [DEBUG] mod_rayo.c:3069 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:11:51.332522 [DEBUG] mod_rayo.c:624 Locate 54.213.58.94: ref count = 2
2013-08-29 20:11:51.332522 [DEBUG] mod_rayo.c:2368 Deliver 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 => 54.213.58.94 <iq type='get' to='54.213.58.94' id='blather001a' from='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766'><ping xmlns='urn:xmpp:ping'/></iq>
2013-08-29 20:11:51.332522 [DEBUG] mod_rayo.c:505 54.213.58.94, looking for SERVER::get:urn:xmpp:ping:ping command
2013-08-29 20:11:51.332522 [DEBUG] mod_rayo.c:631 Unlock 54.213.58.94: ref count = 1
2013-08-29 20:11:51.332522 [DEBUG] mod_rayo.c:624 Locate 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 2
2013-08-29 20:11:51.332522 [DEBUG] mod_rayo.c:1432 Deliver 54.213.58.94 => 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' id='blather001a'/>
2013-08-29 20:11:51.332522 [DEBUG] mod_rayo.c:631 Unlock 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766: ref count = 1
2013-08-29 20:11:51.332522 [DEBUG] xmpp_streams.c:190 c2s_in 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766 SEND <iq type='result' from='54.213.58.94' to='1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766' id='blather001a'/>
freeswitch@internal>
resource>
</bind>
</iq>
[2013-08-29 20:04:50] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq type="result" id="blather0002">
<bind xmlns="urn:ietf:params:xml:ns:xmpp-bind">
<jid>1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766</jid>
</bind>
</iq>
[2013-08-29 20:04:50] TRACE Punchblock::Connection::XMPP: USING JID: 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766
[2013-08-29 20:04:50] TRACE Punchblock::Connection::XMPP: SENDING: (/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/stream/features/session.rb:40:in `session') <iq type="set" id="blather0004" to="54.213.58.94">
<session xmlns="urn:ietf:params:xml:ns:xmpp-session"/>
</iq>
[2013-08-29 20:04:50] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq from="54.213.58.94" type="result" id="blather0004"/>
[2013-08-29 20:04:50] TRACE Punchblock::Connection::XMPP: SENDING: (/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:149:in `write') <iq type="get" id="blather0006">
<query xmlns="jabber:iq:roster"/>
</iq>
[2013-08-29 20:04:50] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq type="error" id="blather0006" to="1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766" from="54.213.58.94">
<query xmlns="jabber:iq:roster"/>
<error type="modify">
<feature-not-implemented xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/>
</error>
</iq>
[2013-08-29 20:04:50] TRACE Punchblock::Connection::XMPP: SENDING: (/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:149:in `write') <presence/>
[2013-08-29 20:04:50] INFO Punchblock::Connection::XMPP: Connected to XMPP as 1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766
[2013-08-29 20:04:50] INFO Adhearsion::PunchblockPlugin::Initializer: Connected to Punchblock server
[2013-08-29 20:04:50] INFO Adhearsion::Process: Transitioning from booting to running with 0 active calls due to booted event.
[2013-08-29 20:05:50] TRACE Punchblock::Connection::XMPP: SENDING: (/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:149:in `write') <iq type="get" to="54.213.58.94" id="blather0008">
<ping xmlns="urn:xmpp:ping"/>
</iq>
[2013-08-29 20:05:50] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq type="result" from="54.213.58.94" to="1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766" id="blather0008"/>
[2013-08-29 20:06:50] TRACE Punchblock::Connection::XMPP: SENDING: (/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:149:in `write') <iq type="get" to="54.213.58.94" id="blather000a">
<ping xmlns="urn:xmpp:ping"/>
</iq>
[2013-08-29 20:06:50] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq type="result" from="54.213.58.94" to="1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766" id="blather000a"/>
[2013-08-29 20:07:26] TRACE Punchblock::Connection::XMPP: RECEIVING (presence) <presence from="424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94" to="1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766">
<offer xmlns="urn:xmpp:rayo:1" from="sip:1001@54.213.58.94" to="sip:1002@54.213.58.94">
<header name="from" value="&lt;sip:1001@54.213.58.94&gt;;tag=rUEmLhAqn5JETUNxGUPJ"/>
<header name="to" value="&lt;sip:1002@54.213.58.94&gt;"/>
<header name="via" value="SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKFdZVBe8T02PrtL6Q3OiuqruyMMHqROwS;rport=63020;received=202.157.93.2"/>
</offer>
</presence>
[2013-08-29 20:07:26] DEBUG Adhearsion::Call: @: Receiving message: #<Punchblock::Event::Offer target_call_id="424928b4-bc76-505f-febd-a5febae13aa3", target_mixer_name=nil, component_id=nil, domain="54.213.58.94", transport="xmpp", headers={"from"=>"<sip:1001@54.213.58.94>;tag=rUEmLhAqn5JETUNxGUPJ", "to"=>"<sip:1002@54.213.58.94>", "via"=>"SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKFdZVBe8T02PrtL6Q3OiuqruyMMHqROwS;rport=63020;received=202.157.93.2"}, to="sip:1002@54.213.58.94", from="sip:1001@54.213.58.94">
[2013-08-29 20:07:26] INFO Adhearsion::Router: Call 424928b4-bc76-505f-febd-a5febae13aa3 selected route "default" (Incomming)
[2013-08-29 20:07:26] DEBUG Adhearsion::Call: 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: Executing command #<Punchblock::Command::Accept target_call_id=nil, target_mixer_name=nil, component_id=nil, domain=nil, transport=nil, headers={}>
[2013-08-29 20:07:26] TRACE Punchblock::Connection::XMPP: SENDING: (/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:149:in `write') <iq type="set" to="424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94" id="blather000c">
<accept xmlns="urn:xmpp:rayo:1"/>
</iq>
[2013-08-29 20:07:26] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq from="424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94" to="1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766" type="result" id="blather000c"/>
[2013-08-29 20:07:26] INFO Adhearsion::Call: 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: Executing controller #<Incomming call=424928b4-bc76-505f-febd-a5febae13aa3, metadata={}>
[2013-08-29 20:07:26] DEBUG Adhearsion::Call: 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: Receiving message: #<Punchblock::Event::Offer target_call_id="424928b4-bc76-505f-febd-a5febae13aa3", target_mixer_name=nil, component_id=nil, domain="54.213.58.94", transport="xmpp", headers={"from"=>"<sip:1001@54.213.58.94>;tag=rUEmLhAqn5JETUNxGUPJ", "to"=>"<sip:1002@54.213.58.94>", "via"=>"SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKFdZVBe8T02PrtL6Q3OiuqruyMMHqROwS;rport=63020;received=202.157.93.2"}, to="sip:1002@54.213.58.94", from="sip:1001@54.213.58.94">
[2013-08-29 20:07:26] INFO Adhearsion::Call: 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: incoming call from 1001 --> 1002
[2013-08-29 20:07:26] INFO Adhearsion::Call: 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: #<Adhearsion::Call:424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94 offer=#<Punchblock::Event::Offer target_call_id="424928b4-bc76-505f-febd-a5febae13aa3", target_mixer_name=nil, component_id=nil, domain="54.213.58.94", transport="xmpp", headers={"from"=>"<sip:1001@54.213.58.94>;tag=rUEmLhAqn5JETUNxGUPJ", "to"=>"<sip:1002@54.213.58.94>", "via"=>"SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKFdZVBe8T02PrtL6Q3OiuqruyMMHqROwS;rport=63020;received=202.157.93.2"}, to="sip:1002@54.213.58.94", from="sip:1001@54.213.58.94">, end_reason=nil, commands=[], variables={"from"=>"<sip:1001@54.213.58.94>;tag=rUEmLhAqn5JETUNxGUPJ", "to"=>"<sip:1002@54.213.58.94>", "via"=>"SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKFdZVBe8T02PrtL6Q3OiuqruyMMHqROwS;rport=63020;received=202.157.93.2"}, controllers=[#<Incomming call=424928b4-bc76-505f-febd-a5febae13aa3, metadata={}>], to="sip:1002@54.213.58.94", from="sip:1001@54.213.58.94">
[2013-08-29 20:07:27] DEBUG Adhearsion::Call: 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: Executing command #<Punchblock::Command::Answer target_call_id=nil, target_mixer_name=nil, component_id=nil, domain=nil, transport=nil, headers={}>
[2013-08-29 20:07:27] TRACE Punchblock::Connection::XMPP: SENDING: (/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:149:in `write') <iq type="set" to="424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94" id="blather000e">
<answer xmlns="urn:xmpp:rayo:1"/>
</iq>
[2013-08-29 20:07:27] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq from="424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94" to="1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766" type="result" id="blather000e"/>
[2013-08-29 20:07:27] TRACE Punchblock::Connection::XMPP: RECEIVING (presence) <presence from="424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94" to="1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766">
<answered xmlns="urn:xmpp:rayo:1"/>
</presence>
[2013-08-29 20:07:27] DEBUG Adhearsion::Call: 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: Executing command #<Punchblock::Component::Output target_call_id=nil, target_mixer_name=nil, component_id=nil, domain=nil, transport=nil, voice=nil, interrupt_on=nil, start_offset=nil, start_paused=false, repeat_interval=nil, repeat_times=nil, max_time=nil, renderer=nil, render_documents=[#<Punchblock::Component::Output::Document target_call_id=nil, target_mixer_name=nil, component_id=nil, domain=nil, transport=nil, url=nil, content_type="application/ssml+xml", value=<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">
<audio src="/var/punchblock/record/welcome.mp3"/>
</speak>>]>
[2013-08-29 20:07:27] TRACE Punchblock::Connection::XMPP: SENDING: (/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:149:in `write') <iq type="set" to="424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94" id="blather0010">
<output xmlns="urn:xmpp:rayo:output:1" start-paused="false">
<document content-type="application/ssml+xml"><![CDATA[<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">
<audio src="/var/punchblock/record/welcome.mp3"/>
</speak>]]></document>
</output>
</iq>
[2013-08-29 20:07:27] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq from="424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94" to="1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766" type="result" id="blather0010">
<ref xmlns="urn:xmpp:rayo:1" uri="xmpp:424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94/output-1"/>
</iq>
[2013-08-29 20:07:27] TRACE Punchblock::Connection::XMPP: RECEIVING (presence) <presence from="424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94/output-1" to="1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766" type="unavailable">
<complete xmlns="urn:xmpp:rayo:ext:1">
<error xmlns="urn:xmpp:rayo:ext:complete:1"/>
</complete>
</presence>
Cannot transition state via :complete from :requested
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/state_machine-1.2.0/lib/state_machine/event.rb:252:in `block in add_actions'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/state_machine-1.2.0/lib/state_machine/machine.rb:765:in `call'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/state_machine-1.2.0/lib/state_machine/machine.rb:765:in `block (2 levels) in define_helper'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/punchblock-2.0.0/lib/punchblock/component/component_node.rb:53:in `complete_event='
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/punchblock-2.0.0/lib/punchblock/component/component_node.rb:16:in `block in register_internal_handlers'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/has-guarded-handlers-1.5.0/lib/has_guarded_handlers.rb:105:in `call'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/has-guarded-handlers-1.5.0/lib/has_guarded_handlers.rb:105:in `call_handler'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/has-guarded-handlers-1.5.0/lib/has_guarded_handlers.rb:91:in `block (3 levels) in trigger_handler'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/has-guarded-handlers-1.5.0/lib/has_guarded_handlers.rb:87:in `catch'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/has-guarded-handlers-1.5.0/lib/has_guarded_handlers.rb:87:in `block (2 levels) in trigger_handler'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/has-guarded-handlers-1.5.0/lib/has_guarded_handlers.rb:85:in `each'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/has-guarded-handlers-1.5.0/lib/has_guarded_handlers.rb:85:in `find'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/has-guarded-handlers-1.5.0/lib/has_guarded_handlers.rb:85:in `block in trigger_handler'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/has-guarded-handlers-1.5.0/lib/has_guarded_handlers.rb:84:in `catch'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/has-guarded-handlers-1.5.0/lib/has_guarded_handlers.rb:84:in `trigger_handler'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/punchblock-2.0.0/lib/punchblock/component/component_node.rb:22:in `add_event'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/punchblock-2.0.0/lib/punchblock/client.rb:27:in `handle_event'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/punchblock-2.0.0/lib/punchblock/client.rb:20:in `block in initialize'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/punchblock-2.0.0/lib/punchblock/connection/xmpp.rb:136:in `call'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/punchblock-2.0.0/lib/punchblock/connection/xmpp.rb:136:in `handle_presence'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/punchblock-2.0.0/lib/punchblock/connection/xmpp.rb:165:in `block in register_handlers'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:295:in `call'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:295:in `call_handler'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:286:in `block (2 levels) in call_handler_for'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:286:in `catch'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:286:in `block in call_handler_for'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:285:in `each'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:285:in `find'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:285:in `call_handler_for'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:278:in `block in handle_stanza'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:277:in `each'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:277:in `handle_stanza'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:194:in `block in handle_data'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:192:in `catch'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:192:in `handle_data'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:63:in `block in initialize'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/girl_friday-0.11.2/lib/girl_friday/work_queue.rb:147:in `call'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/girl_friday-0.11.2/lib/girl_friday/work_queue.rb:147:in `block (2 levels) in start'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/girl_friday-0.11.2/lib/girl_friday/actor.rb:86:in `call'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/girl_friday-0.11.2/lib/girl_friday/actor.rb:86:in `block in spawn_link'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/girl_friday-0.11.2/lib/girl_friday/actor.rb:69:in `call'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/girl_friday-0.11.2/lib/girl_friday/actor.rb:69:in `block (2 levels) in spawn'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/girl_friday-0.11.2/lib/girl_friday/actor.rb:212:in `block in initialize'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/girl_friday-0.11.2/lib/girl_friday/actor.rb:377:in `watchdog'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/girl_friday-0.11.2/lib/girl_friday/actor.rb:212:in `initialize'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/girl_friday-0.11.2/lib/girl_friday/actor.rb:66:in `new'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/girl_friday-0.11.2/lib/girl_friday/actor.rb:66:in `block in spawn'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/logging-1.8.1/lib/logging/diagnostic_context.rb:323:in `call'
/usr/local/rvm/gems/ruby-2.0.0-p247/gems/logging-1.8.1/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context'
[2013-08-29 20:07:27] DEBUG Adhearsion::Call: 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: Receiving message: #<Punchblock::Event::Answered target_call_id="424928b4-bc76-505f-febd-a5febae13aa3", target_mixer_name=nil, component_id=nil, domain="54.213.58.94", transport="xmpp", headers={}>
[2013-08-29 20:07:50] TRACE Punchblock::Connection::XMPP: SENDING: (/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:149:in `write') <iq type="get" to="54.213.58.94" id="blather0012">
<ping xmlns="urn:xmpp:ping"/>
</iq>
[2013-08-29 20:07:50] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq type="result" from="54.213.58.94" to="1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766" id="blather0012"/>
[2013-08-29 20:07:57] TRACE Punchblock::Connection::XMPP: RECEIVING (presence) <presence from="424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94" to="1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766" type="unavailable">
<end xmlns="urn:xmpp:rayo:1">
<hungup/>
</end>
</presence>
[2013-08-29 20:07:57] DEBUG Adhearsion::Call: 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: Receiving message: #<Punchblock::Event::End target_call_id="424928b4-bc76-505f-febd-a5febae13aa3", target_mixer_name=nil, component_id=nil, domain="54.213.58.94", transport="xmpp", headers={}, reason=:hungup, platform_code=nil>
[2013-08-29 20:07:57] INFO Adhearsion::Call: 424928b4-bc76-505f-febd-a5febae13aa3@54.213.58.94: Call ended due to hungup
[2013-08-29 20:08:50] TRACE Punchblock::Connection::XMPP: SENDING: (/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:149:in `write') <iq type="get" to="54.213.58.94" id="blather0014">
<ping xmlns="urn:xmpp:ping"/>
</iq>
[2013-08-29 20:08:50] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq type="result" from="54.213.58.94" to="1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766" id="blather0014"/>
[2013-08-29 20:09:50] TRACE Punchblock::Connection::XMPP: SENDING: (/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:149:in `write') <iq type="get" to="54.213.58.94" id="blather0016">
<ping xmlns="urn:xmpp:ping"/>
</iq>
[2013-08-29 20:09:50] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq type="result" from="54.213.58.94" to="1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766" id="blather0016"/>
[2013-08-29 20:10:50] TRACE Punchblock::Connection::XMPP: SENDING: (/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:149:in `write') <iq type="get" to="54.213.58.94" id="blather0018">
<ping xmlns="urn:xmpp:ping"/>
</iq>
[2013-08-29 20:10:50] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq type="result" from="54.213.58.94" to="1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766" id="blather0018"/>
[2013-08-29 20:11:50] TRACE Punchblock::Connection::XMPP: SENDING: (/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:149:in `write') <iq type="get" to="54.213.58.94" id="blather001a">
<ping xmlns="urn:xmpp:ping"/>
</iq>
[2013-08-29 20:11:50] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq type="result" from="54.213.58.94" to="1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766" id="blather001a"/>
[2013-08-29 20:12:50] TRACE Punchblock::Connection::XMPP: SENDING: (/usr/local/rvm/gems/ruby-2.0.0-p247/gems/blather-0.8.7/lib/blather/client/client.rb:149:in `write') <iq type="get" to="54.213.58.94" id="blather001c">
<ping xmlns="urn:xmpp:ping"/>
</iq>
[2013-08-29 20:12:50] TRACE Punchblock::Connection::XMPP: RECEIVING (iq) <iq type="result" from="54.213.58.94" to="1@54.213.58.94/ip-172-31-41-127.us-west-2.compute.internal-4766" id="blather001c"/>
@EpicVoyage
Copy link

EpicVoyage commented Aug 7, 2017

I don't know the original reason for this log dump but I am also seeing the "NET_RWERR" error. It seems to indicate that FreeSwitch is unable to reply to Adhearsion:

https://freeswitch.org/stash/projects/FS/repos/freeswitch/browse/src/mod/event_handlers/mod_rayo/iks_helpers.c?at=96eba0d6a8e7bbb202e8928c3b18918eeacb4f1c&raw

meduketto/iksemel@8f79792

Recommendation: check firewalls and load balancers.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment