Skip to content

Instantly share code, notes, and snippets.

@zlu

zlu/sipmethod.log

Created July 12, 2011 11:11
Show Gist options
  • Save zlu/1077781 to your computer and use it in GitHub Desktop.
Save zlu/1077781 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
sipmethod.log
2011-07-12 12:10:28.746 DEBUG [SocketAcceptorIoProcessor-0.2] #XMPP#: Creating xmpp session with app: ApplicationImpl[_symbolicName=tropo2-0, _state=STARTED] #[N/A][N/A][N/A][?, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.747 DEBUG [SocketAcceptorIoProcessor-0.2] #XMPP#: Created session: XMPPSessionImpl: _id=xmpps_au2xtk4a13mq, _direction=RECEIVEStream, _sessionType=CLIENT, _remotJID=null, _state=INITIAL, _remoteAddr=/127.0.0.1, _remotePort=51528, _localPort=5222, _localJID=127.0.0.1, _application=ApplicationImpl[_symbolicName=tropo2-0, _state=STARTED] #[N/A][N/A][N/A][?, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.747 DEBUG [SocketAcceptorIoProcessor-0.2] #XMPP#: (i)<stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" to="127.0.0.1" version="1.0" xml:lang="en"> #[tropo2][null][xmpps_au2xtk4a13mq][?, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.748 DEBUG [XMPPService-t-23] #XMPP#: (o)<stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" xmlns:db="jabber:server:dialback" version="1.0" from="127.0.0.1" id="xmpps_au2xtk4a13mq" xml:lang="en"> #[tropo2][null][xmpps_au2xtk4a13mq][?, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.749 DEBUG [XMPPService-t-23] #XMPP#: Send message to: 127.0.0.1:51528 by xmpp #[tropo2][null][xmpps_au2xtk4a13mq][?, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.749 DEBUG [XMPPService-t-23] #XMPP#: (o)<stream:features><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>PLAIN</mechanism></mechanisms></stream:features> #[tropo2][null][xmpps_au2xtk4a13mq][?, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.751 DEBUG [XMPPService-t-23] #XMPP#: Send message to: 127.0.0.1:51528 by xmpp #[tropo2][null][xmpps_au2xtk4a13mq][?, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.752 DEBUG [SocketAcceptorIoProcessor-0.2] #XMPP#: (i)<auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="PLAIN">dXNlcmFAMTI3LjAuMC4xAHVzZXJhADE=</auth> #[tropo2][null][xmpps_au2xtk4a13mq][?, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.753 DEBUG [XMPPService-t-24] #XMPP#: (o)<success xmlns="urn:ietf:params:xml:ns:xmpp-sasl"/> #[tropo2][null][xmpps_au2xtk4a13mq][?, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.754 DEBUG [XMPPService-t-24] #XMPP#: Send message to: 127.0.0.1:51528 by xmpp #[tropo2][null][xmpps_au2xtk4a13mq][?, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.756 DEBUG [SocketAcceptorIoProcessor-0.2] #XMPP#: (i)<stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" to="127.0.0.1" version="1.0" xml:lang="en"> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.757 DEBUG [XMPPService-t-25] #XMPP#: Invoke application:tropo2 ozone
2011-07-12 12:10:28.757 DEBUG [XMPPService-t-25] #XMPP#: Forwarding Request #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][null]
2011-07-12 12:10:28.757 DEBUG [XMPPService-t-25] #XMPP#: (o)<stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" xmlns:db="jabber:server:dialback" version="1.0" from="127.0.0.1" id="xmpps_au2xtk4a13mq" xml:lang="en"> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.757 DEBUG [XMPPService-t-25] #XMPP#: Send message to: 127.0.0.1:51528 by xmpp #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.758 DEBUG [XMPPService-t-25] #XMPP#: (o)<stream:features><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"/><session xmlns="urn:ietf:params:xml:ns:xmpp-session"/></stream:features> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.759 DEBUG [XMPPService-t-25] #XMPP#: Send message to: 127.0.0.1:51528 by xmpp #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.761 DEBUG [SocketAcceptorIoProcessor-0.2] #XMPP#: (i)<iq type="set" id="blather0002"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"/></iq> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.762 DEBUG [XMPPService-t-26] #XMPP#: Invoke application:tropo2 ozone
2011-07-12 12:10:28.762 DEBUG [XMPPService-t-26] #XMPP#: Forwarding Request #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][null]
2011-07-12 12:10:28.762 DEBUG [XMPPService-t-26] <iq type="set" id="blather0002" to="127.0.0.1" from="usera@127.0.0.1"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"/></iq> :: xmpps_au2xtk4a13mq
2011-07-12 12:10:28.763 DEBUG [XMPPService-t-26] #XMPP#: Intercept iq bind result, set full jid usera@127.0.0.1/voxeo to session XMPPSessionImpl: _id=xmpps_au2xtk4a13mq, _direction=RECEIVEStream, _sessionType=CLIENT, _remotJID=usera@127.0.0.1/voxeo, _state=CONFIRMED, _remoteAddr=/127.0.0.1, _remotePort=51528, _localPort=5222, _localJID=127.0.0.1, _application=ApplicationImpl[_symbolicName=tropo2-0, _state=STARTED] #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.763 DEBUG [XMPPService-t-26] #XMPP#: (o)<iq type="result" id="blather0002" from="127.0.0.1" to="usera@127.0.0.1"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><jid>usera@127.0.0.1/voxeo</jid></bind></iq> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.764 DEBUG [XMPPService-t-26] #XMPP#: Send message to: 127.0.0.1:51528 by xmpp #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.764 INFO [XMPPService-t-26] Bound client resource [jid=usera@127.0.0.1/voxeo]
2011-07-12 12:10:28.766 DEBUG [SocketAcceptorIoProcessor-0.2] #XMPP#: (i)<iq type="set" id="blather0004" to="127.0.0.1"><session xmlns="urn:ietf:params:xml:ns:xmpp-session"/></iq> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.766 DEBUG [XMPPService-t-27] #XMPP#: Invoke application:tropo2 ozone
2011-07-12 12:10:28.766 DEBUG [XMPPService-t-27] #XMPP#: Forwarding Request #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][null]
2011-07-12 12:10:28.767 DEBUG [XMPPService-t-27] <iq type="set" id="blather0004" to="127.0.0.1" from="usera@127.0.0.1/voxeo"><session xmlns="urn:ietf:params:xml:ns:xmpp-session"/></iq> :: xmpps_au2xtk4a13mq
2011-07-12 12:10:28.767 DEBUG [XMPPService-t-27] #XMPP#: (o)<iq type="result" id="blather0004" from="127.0.0.1" to="usera@127.0.0.1/voxeo"><session xmlns="urn:ietf:params:xml:ns:xmpp-session"/></iq> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.767 DEBUG [XMPPService-t-27] #XMPP#: Send message to: 127.0.0.1:51528 by xmpp #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.768 DEBUG [SocketAcceptorIoProcessor-0.2] #XMPP#: (i)<iq type="get" id="blather0006"><query xmlns="jabber:iq:roster"/></iq> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.769 DEBUG [XMPPService-t-28] #XMPP#: Invoke application:tropo2 ozone
2011-07-12 12:10:28.769 DEBUG [XMPPService-t-28] #XMPP#: Forwarding Request #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][null]
2011-07-12 12:10:28.769 DEBUG [XMPPService-t-28] <iq type="get" id="blather0006" to="127.0.0.1" from="usera@127.0.0.1/voxeo"><query xmlns="jabber:iq:roster"/></iq> :: xmpps_au2xtk4a13mq
2011-07-12 12:10:28.769 DEBUG [XMPPService-t-28] #XMPP#: (o)<iq type="error" id="blather0006" to="usera@127.0.0.1/voxeo" from="127.0.0.1"><query xmlns="jabber:iq:roster"/><error type="cancel"><feature-not-implemented xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.770 DEBUG [XMPPService-t-28] #XMPP#: Send message to: 127.0.0.1:51528 by xmpp #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.773 DEBUG [SocketAcceptorIoProcessor-0.2] #XMPP#: (i)<presence/> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:28.773 DEBUG [XMPPService-t-29] #XMPP#: Invoke application:tropo2 ozone
2011-07-12 12:10:28.773 DEBUG [XMPPService-t-29] #XMPP#: Forwarding Request #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][null]
2011-07-12 12:10:32.085 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (i)[INVITE sip:usera@127.0.0.1 SIP/2.0\r\nContent-Type: application/sdp\r\nTo: <sip:usera@127.0.0.1>\r\nVia: SIP/2.0/UDP 192.168.1.11:64541;rport;branch=z9hG4bKPjg3ZN5YCl-9Bq6w2PNbzSwocDRZccxLQS\r\nAllow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER\r\nCSeq: 24110 INVITE\r\nContent-Length: 371\r\nSupported: 100rel, norefersub\r\nCall-ID: ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH\r\nUser-Agent: Blink Lite 1.1.1 (MacOSX)\r\nFrom: "zhao lu" <sip:zlu@sip2sip.info>;tag=Z1aFKM6AH3LEBgr5q9FLxuMRq4l9qa3-\r\nMax-Forwards: 70\r\nContact: <sip:aconrulk@127.0.0.1:64541>\r\n\r\nv=0\r\no=- 3519457832 3519457832 IN IP4 127.0.0.1\r\ns=Blink Lite 1.1.1 (MacOSX)\r\nc=IN IP4 127.0.0.1\r\nt=0 0\r\nm=audio 50006 RTP/AVP 9 104 103 102 0 8 101\r\na=rtcp:50007\r\na=rtpmap:9 G722/8000\r\na=rtpmap:104 speex/32000\r\na=rtpmap:103 speex/16000\r\na=rtpmap:102 speex/8000\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=sendrecv\r\n] #[N/A][N/A][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][N/A][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.086 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: The transaction was created: z9hG4bKPjg3ZN5YCl-9Bq6w2PNbzSwocDRZccxLQS #[N/A][N/A][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][N/A][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.086 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (o)[SIP/2.0 100 Trying\r\nTo: <sip:usera@127.0.0.1>\r\nVia: SIP/2.0/UDP 192.168.1.11:64541;rport=64541;branch=z9hG4bKPjg3ZN5YCl-9Bq6w2PNbzSwocDRZccxLQS;received=127.0.0.1\r\nCSeq: 24110 INVITE\r\nContent-Length: 0\r\nCall-ID: ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH\r\nFrom: "zhao lu" <sip:zlu@sip2sip.info>;tag=Z1aFKM6AH3LEBgr5q9FLxuMRq4l9qa3-\r\n\r\n] #[N/A][N/A][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][N/A][sip:usera@127.0.0.1(127.0.0.1:64541)][sip:zlu@sip2sip.info(192.168.1.11:5060)]
2011-07-12 12:10:32.086 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Send message to: /127.0.0.1:64541 by udp #[N/A][N/A][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][N/A][sip:usera@127.0.0.1(127.0.0.1:64541)][sip:zlu@sip2sip.info(192.168.1.11:5060)]
2011-07-12 12:10:32.087 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Connected to 127.0.0.1:64541/udp #[N/A][N/A][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][N/A][sip:usera@127.0.0.1(127.0.0.1:64541)][sip:zlu@sip2sip.info(192.168.1.11:5060)]
2011-07-12 12:10:32.087 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Found [tropo2] to handle the request by alphabet.
2011-07-12 12:10:32.087 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationInfo: SipApplicationRouterInfo[ApplicationName=tropo2, RouteModifier=NO_ROUTE, RouteRegion=null, SubscriberURI=sip:usera@127.0.0.1, StateInfo=tropo2] #[N/A][N/A][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][N/A][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.087 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session creating: ss_10pk46a9gj2zx #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.091 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session created:SipSessionImpl[_id=ss_10pk46a9gj2zx, _parentId=sas_2-14-smm9fk22e0gfeutropo2, _handler=Controller, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UNKNOW, _method=INVITE, _callId=ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.091 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer recv request: INVITE #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.092 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ApplicationDispatchLayer invoke application: Controller with INVITE #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.092 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipServletWrapper[Controller, com.voxeo.moho.sip.SIPController] is forwarding. #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.093 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-smm9fk22e0gfeutropo2], invalidateWhenReady: true
2011-07-12 12:10:32.093 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_10pk46a9gj2zx], current State = INITIAL, Vaild:true, Role:UNKNOW, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.093 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-smm9fk22e0gfeutropo2], invalidateWhenReady: true
2011-07-12 12:10:32.093 DEBUG [MOHO-12] Received incoming call
2011-07-12 12:10:32.095 INFO [pool-16-thread-6] Message [SIPCallImpl[SipSessionAdaptor[sessionid=ss_10pk46a9gj2zx, appSessionId=sas_2-14-smm9fk22e0gfeutropo2],INVITING]]
2011-07-12 12:10:32.095 INFO [pool-16-thread-6] Incoming Call [SIPCallImpl[SipSessionAdaptor[sessionid=ss_10pk46a9gj2zx, appSessionId=sas_2-14-smm9fk22e0gfeutropo2],INVITING]]
2011-07-12 12:10:32.098 INFO [pool-16-thread-7] Message [SIPCallImpl[SipSessionAdaptor[sessionid=ss_10pk46a9gj2zx, appSessionId=sas_2-14-smm9fk22e0gfeutropo2],INVITING]]
2011-07-12 12:10:32.101 INFO [pool-16-thread-7] Queued Event [OfferEvent[from=sip:zlu@sip2sip.info,to=sip:usera@127.0.0.1,headers={Max-Forwards=70, Content-Length=371, Contact=<sip:aconrulk@127.0.0.1:64541>, Supported=100rel, Allow=SUBSCRIBE, To=<sip:usera@127.0.0.1>, CSeq=24110 INVITE, User-Agent=Blink Lite 1.1.1 (MacOSX), Via=SIP/2.0/UDP 192.168.1.11:64541;rport=64541;branch=z9hG4bKPjg3ZN5YCl-9Bq6w2PNbzSwocDRZccxLQS;received=127.0.0.1, Call-ID=ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, Content-Type=application/sdp, From="zhao lu" <sip:zlu@sip2sip.info>;tag=Z1aFKM6AH3LEBgr5q9FLxuMRq4l9qa3-}]]
2011-07-12 12:10:32.102 INFO [pool-16-thread-7] Event [OfferEvent[from=sip:zlu@sip2sip.info,to=sip:usera@127.0.0.1,headers={Max-Forwards=70, Content-Length=371, Contact=<sip:aconrulk@127.0.0.1:64541>, Supported=100rel, Allow=SUBSCRIBE, To=<sip:usera@127.0.0.1>, CSeq=24110 INVITE, User-Agent=Blink Lite 1.1.1 (MacOSX), Via=SIP/2.0/UDP 192.168.1.11:64541;rport=64541;branch=z9hG4bKPjg3ZN5YCl-9Bq6w2PNbzSwocDRZccxLQS;received=127.0.0.1, Call-ID=ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, Content-Type=application/sdp, From="zhao lu" <sip:zlu@sip2sip.info>;tag=Z1aFKM6AH3LEBgr5q9FLxuMRq4l9qa3-}]]
2011-07-12 12:10:32.103 DEBUG [pool-16-thread-7] #XMPP#: (o)<presence from="836b02be-9578-4a53-b813-7d1862b2c0b4@127.0.0.1" to="usera@127.0.0.1/voxeo"><offer xmlns="urn:xmpp:ozone:1" to="sip:usera@127.0.0.1" from="sip:zlu@sip2sip.info"><header name="Max-Forwards" value="70"/><header name="Content-Length" value="371"/><header name="Contact" value="&lt;sip:aconrulk@127.0.0.1:64541&gt;"/><header name="Supported" value="100rel"/><header name="Allow" value="SUBSCRIBE"/><header name="To" value="&lt;sip:usera@127.0.0.1&gt;"/><header name="CSeq" value="24110 INVITE"/><header name="User-Agent" value="Blink Lite 1.1.1 (MacOSX)"/><header name="Via" value="SIP/2.0/UDP 192.168.1.11:64541;rport=64541;branch=z9hG4bKPjg3ZN5YCl-9Bq6w2PNbzSwocDRZccxLQS;received=127.0.0.1"/><header name="Call-ID" value="ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH"/><header name="Content-Type" value="application/sdp"/><header name="From" value="&quot;zhao lu&quot; &lt;sip:zlu@sip2sip.info&gt;;tag=Z1aFKM6AH3LEBgr5q9FLxuMRq4l9qa3-"/></offer></presence> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:32.103 DEBUG [pool-16-thread-7] #XMPP#: Send message to: 127.0.0.1:51528 by xmpp #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:32.107 DEBUG [SocketAcceptorIoProcessor-0.2] #XMPP#: (i)<iq type="set" to="836b02be-9578-4a53-b813-7d1862b2c0b4@127.0.0.1" id="blather0008" from="usera@127.0.0.1/voxeo"><answer xmlns="urn:xmpp:ozone:1"/></iq> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:32.107 DEBUG [XMPPService-t-30] #XMPP#: Invoke application:tropo2 ozone
2011-07-12 12:10:32.107 DEBUG [XMPPService-t-30] #XMPP#: Forwarding Request #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][null]
2011-07-12 12:10:32.108 DEBUG [XMPPService-t-30] <iq type="set" to="836b02be-9578-4a53-b813-7d1862b2c0b4@127.0.0.1" id="blather0008" from="usera@127.0.0.1/voxeo"><answer xmlns="urn:xmpp:ozone:1"/></iq> :: xmpps_au2xtk4a13mq
2011-07-12 12:10:32.108 INFO [pool-16-thread-7] Request [AnswerCommand[callId=836b02be-9578-4a53-b813-7d1862b2c0b4,headers={}]]
2011-07-12 12:10:32.108 DEBUG [pool-16-thread-7] #SIP#: SessionManagementLayer send response: INVITE/180 #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.109 DEBUG [pool-16-thread-7] #SIP#: Add Path[ id=ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH-Z1aFKM6AH3LEBgr5q9FLxuMRq4l9qa3--19gw3squ26tpn, session=SipSessionImpl[_id=ss_10pk46a9gj2zx, _parentId=sas_2-14-smm9fk22e0gfeutropo2, _handler=Controller, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=INVITE, _callId=ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH], party= CALLER] #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.110 DEBUG [pool-16-thread-7] #SIP#: (o)[SIP/2.0 180 Ringing\r\nTo: <sip:usera@127.0.0.1>;tag=19gw3squ26tpn\r\nVia: SIP/2.0/UDP 192.168.1.11:64541;rport=64541;branch=z9hG4bKPjg3ZN5YCl-9Bq6w2PNbzSwocDRZccxLQS;received=127.0.0.1\r\nCSeq: 24110 INVITE\r\nContent-Length: 0\r\nCall-ID: ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH\r\nFrom: "zhao lu" <sip:zlu@sip2sip.info>;tag=Z1aFKM6AH3LEBgr5q9FLxuMRq4l9qa3-\r\n\r\n] #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.110 DEBUG [pool-16-thread-7] #SIP#: Send message to: /127.0.0.1:64541 by udp #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.111 DEBUG [pool-16-thread-7] #SIP#: Connected to 127.0.0.1:64541/udp #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.113 DEBUG [pool-16-thread-7] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-smm9fk22e0gfeutropo2], invalidateWhenReady: true
2011-07-12 12:10:32.114 DEBUG [pool-16-thread-7] #SIP#: processInvalidationWhenReady [ss_10pk46a9gj2zx], current State = EARLY, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.115 DEBUG [pool-16-thread-7] #SIP#: processInvalidationWhenReady [sas_2-14-smm9fk22e0gfeutropo2], invalidateWhenReady: true
2011-07-12 12:10:32.117 DEBUG [MOHO-13] Set ms id with call id :ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH
2011-07-12 12:10:32.117 INFO [MOHO-13] #MSCTRL#: MS[MS-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] updates MEDIAOBJECT_ID, old:"ms2-3", new:"MS-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH"
2011-07-12 12:10:32.117 DEBUG [MOHO-13] Set nc id with call id :ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH
2011-07-12 12:10:32.117 INFO [MOHO-13] #MSCTRL#: MS[NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] updates MEDIAOBJECT_ID, old:"MS-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH", new:"NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH"
2011-07-12 12:10:32.117 INFO [MOHO-13] #MSCTRL#: MS[NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] creates a MediaObject[BASIC, NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, {MEDIAOBJECT_ID=NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH}]
2011-07-12 12:10:32.127 INFO [MOHO-13] #MSCTRL#: SdpPort[IDLE, NC[NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] processes a SDP offer \nv=0\r\no=- 3519457832 3519457832 IN IP4 127.0.0.1\r\ns=Blink Lite 1.1.1 (MacOSX)\r\nc=IN IP4 127.0.0.1\r\nt=0 0\r\nm=audio 50006 RTP/AVP 9 104 103 102 0 8 101\r\na=rtcp:50007\r\na=rtpmap:9 G722/8000\r\na=rtpmap:104 speex/32000\r\na=rtpmap:103 speex/16000\r\na=rtpmap:102 speex/8000\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=sendrecv\r\n
2011-07-12 12:10:32.129 DEBUG [MOHO-13] #MSCTRL#: SdpPort[UNDER_PROCESSING, NC[NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] moves state from [IDLE] to [UNDER_PROCESSING]
2011-07-12 12:10:32.129 DEBUG [MOHO-13] Start wait joinDelegate. CallID:ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH
2011-07-12 12:10:32.129 INFO [msctrl/2-t-7] #MSCTRL#: No CodecPolicy is installed, just return back the initial offer
2011-07-12 12:10:32.129 DEBUG [msctrl/2-t-7] #MRCP#: load configuration from {maxThreadPool=2147483647, minThreadPool=25, MEDIAOBJECT_ID=NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, com.voxeo.useLocalConfigurationOnGUTFailures=false}
2011-07-12 12:10:32.141 DEBUG [msctrl/2-t-7] #MRCP#: (o)SETUP rtsp://192.168.1.11:10074/recognizer/ RTSP/1.0\r\nCseq: 1\r\nTransport: RTP/AVP;unicast;\r\nContent-Type: application/sdp\r\nContent-Length: 371\r\n\r\nv=0\r\no=- 3519457832 3519457832 IN IP4 127.0.0.1\r\ns=Blink Lite 1.1.1 (MacOSX)\r\nc=IN IP4 127.0.0.1\r\nt=0 0\r\nm=audio 50006 RTP/AVP 9 104 103 102 0 8 101\r\na=rtcp:50007\r\na=rtpmap:9 G722/8000\r\na=rtpmap:104 speex/32000\r\na=rtpmap:103 speex/16000\r\na=rtpmap:102 speex/8000\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=sendrecv\r\n #[N/A][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:32.152 DEBUG [mrcp/2-t-25] #MRCP#: (i)RTSP/1.0 200 OK\r\nSession: 504006850-2819200-0b166fb0-00000003\r\nTransport: RTP/AVP;unicast;client_port=50006-50007;server_port=20004-20005\r\nCseq: 1\r\nContent-Type: application/sdp\r\nContent-Length: 167\r\n\r\nv=0\r\no=- 14 14 IN IP4 127.0.0.1\r\ns=voxeo\r\nc=IN IP4 127.0.0.1\r\nt=0 0\r\nm=audio 20004 RTP/AVP 0 101\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=ptime:20\r\n #[N/A][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:32.152 DEBUG [msctrl/2-t-7] #MSCTRL#: NC[NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] initializes the ASR session. #[504006850-2819200-0b166fb0-00000003]
2011-07-12 12:10:32.153 DEBUG [msctrl/2-t-7] #MRCP#: (o)SETUP rtsp://192.168.1.11:10074/synthesizer/ RTSP/1.0\r\nCseq: 2\r\nTransport: RTP/AVP;unicast;\r\nSession: 504006850-2819200-0b166fb0-00000003\r\n\r\n #[504006850-2819200-0b166fb0-00000003][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:32.163 DEBUG [mrcp/2-t-25] #MRCP#: (i)RTSP/1.0 200 OK\r\nSession: 504006850-2819200-0b166fb0-00000003\r\nTransport: RTP/AVP;unicast;client_port=50006-50007;server_port=20004-20005\r\nCseq: 2\r\n\r\n #[504006850-2819200-0b166fb0-00000003][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:32.163 DEBUG [msctrl/2-t-7] #MSCTRL#: NC[NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] initializes the TTS session. #[504006850-2819200-0b166fb0-00000003]
2011-07-12 12:10:32.164 DEBUG [msctrl/2-t-7] #MSCTRL#: SdpPort[SDP_NEGOTIATED, NC[NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] moves state from [UNDER_PROCESSING] to [SDP_NEGOTIATED]
2011-07-12 12:10:32.164 DEBUG [msctrl/2-t-7] #MSCTRL#: Return SdpPortEvt[SdpPort[SDP_NEGOTIATED, NC[NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]], ANSWER_GENERATED, NO_ERROR, null, NO_QUALIFIER, null, v=0\r\no=- 14 14 IN IP4 127.0.0.1\r\ns=voxeo\r\nc=IN IP4 127.0.0.1\r\nt=0 0\r\nm=audio 20004 RTP/AVP 0 101\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=ptime:20\r\n] to the application
2011-07-12 12:10:32.164 DEBUG [msctrl/2-t-7] #SIP#: SessionManagementLayer send response: INVITE/200 #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.165 DEBUG [msctrl/2-t-7] #SIP#: (o)[SIP/2.0 200 OK\r\nContent-Type: application/sdp\r\nTo: <sip:usera@127.0.0.1>;tag=19gw3squ26tpn\r\nVia: SIP/2.0/UDP 192.168.1.11:64541;rport=64541;branch=z9hG4bKPjg3ZN5YCl-9Bq6w2PNbzSwocDRZccxLQS;received=127.0.0.1\r\nCSeq: 24110 INVITE\r\nContent-Length: 167\r\nCall-ID: ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH\r\nFrom: "zhao lu" <sip:zlu@sip2sip.info>;tag=Z1aFKM6AH3LEBgr5q9FLxuMRq4l9qa3-\r\nContact: <sip:192.168.1.11:5060;transport=udp>\r\n\r\nv=0\r\no=- 14 14 IN IP4 127.0.0.1\r\ns=voxeo\r\nc=IN IP4 127.0.0.1\r\nt=0 0\r\nm=audio 20004 RTP/AVP 0 101\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=ptime:20\r\n] #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.166 DEBUG [msctrl/2-t-7] #SIP#: Send message to: /127.0.0.1:64541 by udp #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.166 DEBUG [msctrl/2-t-7] #SIP#: Connected to 127.0.0.1:64541/udp #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.166 DEBUG [msctrl/2-t-7] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-smm9fk22e0gfeutropo2], invalidateWhenReady: true
2011-07-12 12:10:32.166 DEBUG [msctrl/2-t-7] #SIP#: processInvalidationWhenReady [ss_10pk46a9gj2zx], current State = CONFIRMED, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.167 DEBUG [msctrl/2-t-7] #SIP#: processInvalidationWhenReady [sas_2-14-smm9fk22e0gfeutropo2], invalidateWhenReady: true
2011-07-12 12:10:32.168 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (i)[ACK sip:192.168.1.11:5060;transport=udp SIP/2.0\r\nTo: <sip:usera@127.0.0.1>;tag=19gw3squ26tpn\r\nVia: SIP/2.0/UDP 192.168.1.11:64541;rport;branch=z9hG4bKPjm91Sok7UgknwMO06DtfPFIdc11VCDdwE\r\nCSeq: 24110 ACK\r\nContent-Length: 0\r\nCall-ID: ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH\r\nUser-Agent: Blink Lite 1.1.1 (MacOSX)\r\nFrom: "zhao lu" <sip:zlu@sip2sip.info>;tag=Z1aFKM6AH3LEBgr5q9FLxuMRq4l9qa3-\r\nMax-Forwards: 70\r\n\r\n] #[N/A][N/A][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][N/A][sip:zlu@sip2sip.info(192.168.1.11:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.171 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Find Path[ id=ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH-Z1aFKM6AH3LEBgr5q9FLxuMRq4l9qa3--19gw3squ26tpn, path=ApplicationPath[_id=ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH-Z1aFKM6AH3LEBgr5q9FLxuMRq4l9qa3--19gw3squ26tpn, _nodes=ApplicationPathList[_nodes=[ApplicationPathNode[_sipSession=SipSessionAdaptor[sessionid=ss_10pk46a9gj2zx, appSessionId=sas_2-14-smm9fk22e0gfeutropo2]]]]]] #[N/A][N/A][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][N/A][sip:zlu@sip2sip.info(192.168.1.11:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.173 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer recv request: ACK #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(192.168.1.11:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.173 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ApplicationDispatchLayer invoke application: Controller with ACK #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(192.168.1.11:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.174 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipServletWrapper[Controller, com.voxeo.moho.sip.SIPController] is forwarding. #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(192.168.1.11:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.174 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-smm9fk22e0gfeutropo2], invalidateWhenReady: true
2011-07-12 12:10:32.174 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_10pk46a9gj2zx], current State = CONFIRMED, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:32.175 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-smm9fk22e0gfeutropo2], invalidateWhenReady: true
2011-07-12 12:10:32.177 INFO [pool-16-thread-7] Reply [null]
2011-07-12 12:10:32.178 DEBUG [pool-16-thread-7] #XMPP#: (o)<iq type="result" id="blather0008" from="836b02be-9578-4a53-b813-7d1862b2c0b4@127.0.0.1" to="usera@127.0.0.1/voxeo"/> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:32.178 DEBUG [pool-16-thread-7] #XMPP#: Send message to: 127.0.0.1:51528 by xmpp #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:32.182 INFO [pool-16-thread-6] Message [[Event class=com.voxeo.moho.event.JoinCompleteEvent sourceClass=SIPIncomingCall]]
2011-07-12 12:10:32.189 DEBUG [SocketAcceptorIoProcessor-0.2] #XMPP#: (i)<iq type="set" to="836b02be-9578-4a53-b813-7d1862b2c0b4@127.0.0.1" id="blather000a" from="usera@127.0.0.1/voxeo"><record xmlns="urn:xmpp:ozone:record:1" start-beep="true" to="file:///tmp/recording.mp3"/></iq> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:32.190 DEBUG [XMPPService-t-31] #XMPP#: Invoke application:tropo2 ozone
2011-07-12 12:10:32.190 DEBUG [XMPPService-t-31] #XMPP#: Forwarding Request #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][null]
2011-07-12 12:10:32.190 DEBUG [XMPPService-t-31] <iq type="set" to="836b02be-9578-4a53-b813-7d1862b2c0b4@127.0.0.1" id="blather000a" from="usera@127.0.0.1/voxeo"><record xmlns="urn:xmpp:ozone:record:1" start-beep="true" to="file:///tmp/recording.mp3"/></iq> :: xmpps_au2xtk4a13mq
2011-07-12 12:10:32.191 INFO [pool-16-thread-6] Request [Record[callId=836b02be-9578-4a53-b813-7d1862b2c0b4,verbId=c3c8d80c-c73f-4e6c-aad7-d56d2bdd9747,to=file:///tmp/recording.mp3,append=<null>,codec=<null>,codec-params=<null>,dtmf-truncate=<null>,final-timeout=<null>,format=<null>,initial-timeout=<null>,max-duration=<null>,min-duration=<null>,sample-rate=<null>,silence-terminate=<null>,start-beep=true,start-pause-mode=<null>]]
2011-07-12 12:10:32.191 DEBUG [pool-16-thread-6] Creating instance of bean 'recordHandler'
2011-07-12 12:10:32.191 DEBUG [pool-16-thread-6] Returning cached instance of singleton bean 'storageServices'
2011-07-12 12:10:32.191 DEBUG [pool-16-thread-6] Finished creating instance of bean 'recordHandler'
2011-07-12 12:10:32.192 DEBUG [pool-16-thread-6] Set mg id with call id :ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH
2011-07-12 12:10:32.192 INFO [pool-16-thread-6] #MSCTRL#: MS[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] updates MEDIAOBJECT_ID, old:"NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH", new:"MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH"
2011-07-12 12:10:32.193 INFO [pool-16-thread-6] #MSCTRL#: MS[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] creates a MediaObject[PLAYER_RECORDER_SIGNALDETECTOR, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, {MEDIAOBJECT_ID=MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH}]
2011-07-12 12:10:32.193 INFO [pool-16-thread-6] #MSCTRL#: MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] joins to NC[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] in DUPLEX
2011-07-12 12:10:32.193 DEBUG [pool-16-thread-6] #MSCTRL#: MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] adds JoineeMrcpContext[mscontrol://192.168.1.11:10074/MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH/NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, 504006850-2819200-0b166fb0-00000003, 504006850-2819200-0b166fb0-00000003] #[504006850-2819200-0b166fb0-00000003]
2011-07-12 12:10:32.193 DEBUG [pool-16-thread-6] #MSCTRL#: NC[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] adds(MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH], JoineeContext[RESOURCE_CONTAINER, DUPLEX, null])
2011-07-12 12:10:32.194 DEBUG [pool-16-thread-6] #MSCTRL#: MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] adds(NC[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH], JoineeContext[RESOURCE_CONTAINER, DUPLEX, null])
2011-07-12 12:10:32.195 DEBUG [pool-16-thread-6] #MSCTRL#: MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] added MrcpRecordListener[Recorder[IDLE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]], ACTIVE] #[504006850-2819200-0b166fb0-00000003]
2011-07-12 12:10:32.196 DEBUG [pool-16-thread-6] #MSCTRL#: Generate beep sound(frequency:-1, length:-1)
2011-07-12 12:10:32.196 INFO [pool-16-thread-6] #MSCTRL#: beepURI:http://192.168.1.11:8080/com.voxeo.prism.msctrl/beep.wav
2011-07-12 12:10:32.196 DEBUG [pool-16-thread-6] #MSCTRL#: Recorder[IDLE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] starts recording with PROMPT{1}
2011-07-12 12:10:32.196 DEBUG [pool-16-thread-6] #MSCTRL#: rtcs=null, recordRTCs=null, promptRTCs={(PLAY_COMPLETION-RECORDER_RESUME)}
2011-07-12 12:10:32.196 DEBUG [pool-16-thread-6] #MSCTRL#: RecordItem[IDLE, RecordItemIdx_0, file:///tmp/recording.mp3, rtcs=null, optargs={START_BEEP=true}]
2011-07-12 12:10:32.196 DEBUG [pool-16-thread-6] #MSCTRL#: Playing prompt on Player[IDLE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]]
2011-07-12 12:10:32.196 DEBUG [pool-16-thread-6] #MSCTRL#: Add PlayListItem[0, 0, true, rtcs={(PLAY_COMPLETION-RECORDER_RESUME)}, optargs={PROMPT_BARGE_IN=false, PROMPT_FOR_RECORDER=true, PROMPT_FOR_SIGDET=false},"<?xml version="1.0"?><speak><audio src="http://192.168.1.11:8080/com.voxeo.prism.msctrl/beep.wav"/></speak>"]
2011-07-12 12:10:32.197 DEBUG [pool-16-thread-6] #MSCTRL#: Find PlayListItem[IDLE, 0, 0, true]
2011-07-12 12:10:32.197 DEBUG [pool-16-thread-6] #MSCTRL#: Player[IDLE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] starts playing PlayListItem[IDLE, 0, 0, true]
2011-07-12 12:10:32.197 DEBUG [pool-16-thread-6] #MSCTRL#: Player[ACTIVE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] moves state from [IDLE] to [ACTIVE]
2011-07-12 12:10:32.197 DEBUG [pool-16-thread-6] #MSCTRL#: PlayListItem[0, 0] moves state from [IDLE] to [PLAYING]
2011-07-12 12:10:32.197 DEBUG [pool-16-thread-6] #MSCTRL#: RTCHandler[MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] installs RTC(s) for the IVR procedure[PlayListItemIdx_0]
2011-07-12 12:10:32.197 DEBUG [pool-16-thread-6] #MSCTRL#: Added RTCItem[PlayListItemIdx_0, (PLAY_COMPLETION, RECORDER_RESUME), false, false]
2011-07-12 12:10:32.197 DEBUG [pool-16-thread-6] #MSCTRL#: MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] added MrcpSpeakListener[Player[ACTIVE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]], ACTIVE] #[504006850-2819200-0b166fb0-00000003]
2011-07-12 12:10:32.200 DEBUG [pool-16-thread-6] #MRCP#: (o)ANNOUNCE rtsp://192.168.1.11:10074/synthesizer/ RTSP/1.0\r\nCseq: 3\r\nSession: 504006850-2819200-0b166fb0-00000003\r\nContent-Type: application/mrcp\r\nContent-Length: 299\r\n\r\nSPEAK 32000 MRCP/1.0\r\nKill-On-Barge-In: false\r\nSpeech-Language: en-US\r\nVendor-Specific-Parameters: Voxeo-Playback-Mode=JSR309\r\nContent-Type: application/synthesis+ssml\r\nContent-Length: 107\r\n\r\n<?xml version="1.0"?><speak><audio src="http://192.168.1.11:8080/com.voxeo.prism.msctrl/beep.wav"/></speak> #[504006850-2819200-0b166fb0-00000003][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:32.203 DEBUG [mrcp/2-t-25] #MRCP#: (i)RTSP/1.0 200 OK\r\nSession: 504006850-2819200-0b166fb0-00000003\r\nCseq: 3\r\nContent-Type: application/mrcp\r\nContent-Length: 34\r\n\r\nMRCP/1.0 32000 200 IN-PROGRESS\r\n\r\n #[504006850-2819200-0b166fb0-00000003][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:32.203 DEBUG [pool-16-thread-6] #MSCTRL#: PlayListItem[0, 0] added (32000, 504006850-2819200-0b166fb0-00000003)
2011-07-12 12:10:32.204 DEBUG [pool-16-thread-6] #MSCTRL#: Recorder[PAUSED, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] moves state from [IDLE] to [PAUSED]
2011-07-12 12:10:32.205 INFO [pool-16-thread-6] Reply [com.tropo.core.verb.VerbRef@23d1e7]
2011-07-12 12:10:32.205 DEBUG [pool-16-thread-6] #XMPP#: (o)<iq type="result" id="blather000a" from="836b02be-9578-4a53-b813-7d1862b2c0b4@127.0.0.1" to="usera@127.0.0.1/voxeo"><ref xmlns="urn:xmpp:ozone:1" id="fa1137e9-4579-4595-8ac1-ea80d185d276"/></iq> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:32.205 DEBUG [pool-16-thread-6] #XMPP#: Send message to: 127.0.0.1:51528 by xmpp #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:32.209 DEBUG [http-0.0.0.0-8080-exec-3] #HTTP#: (i)GET /com.voxeo.prism.msctrl/beep.wav HTTP/1.1\r\nUser-agent: Voxeo-VCS/10.1\r\nHost: 192.168.1.11:8080\r\nAccept: */*\r\n
2011-07-12 12:10:32.209 DEBUG [http-0.0.0.0-8080-exec-3] #HTTP#: Ignore interceptor request: /com.voxeo.prism.msctrl<->/com.voxeo.prism.msctrl
2011-07-12 12:10:32.210 DEBUG [http-0.0.0.0-8080-exec-3] #HTTP#: Mapping HTTP Request(/com.voxeo.prism.msctrl/beep.wav) to ApplicationImpl[_symbolicName=com.voxeo.prism.msctrl-0, _state=STARTED] and HttpServletWrapper[default, org.apache.catalina.servlets.DefaultServlet]
2011-07-12 12:10:32.210 DEBUG [http-0.0.0.0-8080-exec-3] #HTTP#: The Request will ignore interceptor: GET /com.voxeo.prism.msctrl/beep.wav HTTP/1.1\r\nUser-agent: Voxeo-VCS/10.1\r\nHost: 192.168.1.11:8080\r\nAccept: */*\r\n
2011-07-12 12:10:32.210 DEBUG [http-0.0.0.0-8080-exec-3] #HTTP#: Invoke HttpServletWrapper[default, org.apache.catalina.servlets.DefaultServlet] for HTTP Request(/com.voxeo.prism.msctrl/beep.wav)
2011-07-12 12:10:32.211 DEBUG [http-0.0.0.0-8080-exec-3] #HTTP#: Invoke org.apache.catalina.servlets.DefaultServlet@1a4e6f3 for HTTP Request(/com.voxeo.prism.msctrl/beep.wav:com.voxeo.prism.msctrl)
2011-07-12 12:10:32.211 DEBUG [http-0.0.0.0-8080-exec-3] #HTTP#: (o)HTTP/1.1 200\r\nETag: W/"2722-1271323056000"\r\nLast-Modified: Thu, 15 Apr 2010 09:17:36 GMT\r\nContent-Type: audio/x-wav\r\nContent-Length: 2722\r\nDate: Tue, 12 Jul 2011 11:10:32 GMT\r\n\r\n
2011-07-12 12:10:32.389 DEBUG [mrcp/2-t-25] #MRCP#: (i)ANNOUNCE rtsp://192.168.1.11:10074/synthesizer/ RTSP/1.0\r\nCseq: 1\r\nSession: 504006850-2819200-0b166fb0-00000003\r\nContent-Type: application/mrcp\r\nContent-Length: 72\r\n\r\nSPEAK-COMPLETE 32000 COMPLETE MRCP/1.0\r\ncompletion-cause: 000 normal\r\n\r\n #[504006850-2819200-0b166fb0-00000003][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:32.390 DEBUG [mrcp/2-t-25] #MRCP#: (o)RTSP/1.0 200 OK\r\nSession: 504006850-2819200-0b166fb0-00000003\r\nCseq: 1\r\n\r\n #[504006850-2819200-0b166fb0-00000003][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:32.390 DEBUG [mrcp/2-t-24] #MRCP#: Handling SPEAK-COMPLETE[32000] #[504006850-2819200-0b166fb0-00000003][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:32.391 DEBUG [mrcp/2-t-24] #MSCTRL#: Find PlayListItem[PLAYING, 0, 0, true, speakIds=[32000]]
2011-07-12 12:10:32.391 DEBUG [mrcp/2-t-24] #MSCTRL#: MrcpSpeakListener[Player[ACTIVE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]], ACTIVE] handling with MrcpSpeakCompleteEvent[originalId:32000, requestId:32000, rc:0, duration:193] #[504006850-2819200-0b166fb0-00000003]
2011-07-12 12:10:32.391 DEBUG [mrcp/2-t-24] #MSCTRL#: PlayListItem[0, 0] removed (32000, 504006850-2819200-0b166fb0-00000003)
2011-07-12 12:10:32.391 DEBUG [mrcp/2-t-24] #MSCTRL#: PlayListItem[0, 0] moves state from [PLAYING] to [IDLE]
2011-07-12 12:10:32.391 DEBUG [mrcp/2-t-24] #MSCTRL#: RTCHandler[MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] uninstalls RTC(s) because the IVR procedure[PlayListItemIdx_0] is complete.
2011-07-12 12:10:32.392 DEBUG [mrcp/2-t-24] #MSCTRL#: Removed RTCItem[PlayListItemIdx_0, (PLAY_COMPLETION, RECORDER_RESUME), false, false]
2011-07-12 12:10:32.392 DEBUG [mrcp/2-t-24] #MSCTRL#: Player[IDLE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] moves state from [ACTIVE] to [IDLE]
2011-07-12 12:10:32.392 DEBUG [mrcp/2-t-24] #MSCTRL#: clear up playList=[PlayListItem[IDLE, 0, 0, true]]
2011-07-12 12:10:32.392 DEBUG [mrcp/2-t-24] #MSCTRL#: RTCHandler[MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] invokes RTC(PLAY_COMPLETION, RECORDER_RESUME)
2011-07-12 12:10:32.393 DEBUG [msctrl/2-t-8] #MSCTRL#: Recorder[PAUSED, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] triggers action(PLAY_COMPLETION, RECORDER_RESUME)
2011-07-12 12:10:32.393 DEBUG [msctrl/2-t-8] #MSCTRL#: Recorder[ACTIVE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] moves state from [PAUSED] to [ACTIVE]
2011-07-12 12:10:32.394 DEBUG [msctrl/2-t-8] #MRCP#: (o)ANNOUNCE rtsp://192.168.1.11:10074/recognizer/ RTSP/1.0\r\nCseq: 4\r\nSession: 504006850-2819200-0b166fb0-00000003\r\nContent-Type: application/mrcp\r\nContent-Length: 265\r\n\r\nRECORD 32001 MRCP/1.0\r\nRecord-URI: file:///tmp/recording.mp3\r\nNo-Input-Timeout: 7000\r\nStart-Input-Timers: true\r\nVendor-Specific-Parameters: Voxeo-Record-Uri-Method=PUT;Voxeo-Record-Action=start\r\nMedia-Type: audio/mpeg\r\nFinal-Silence: 0\r\nCapture-On-Speech: false\r\n\r\n #[504006850-2819200-0b166fb0-00000003][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:32.395 DEBUG [msctrl/2-t-9] #MSCTRL#: Prompt for Recorder[ACTIVE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] is complete.
2011-07-12 12:10:32.400 DEBUG [mrcp/2-t-24] #MRCP#: (i)RTSP/1.0 200 OK\r\nSession: 504006850-2819200-0b166fb0-00000003\r\nCseq: 4\r\nContent-Type: application/mrcp\r\nContent-Length: 34\r\n\r\nMRCP/1.0 32001 200 IN-PROGRESS\r\n\r\n #[504006850-2819200-0b166fb0-00000003][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:32.402 DEBUG [msctrl/2-t-8] #MSCTRL#: RecordItem[IDLE, RecordItemIdx_0, file:///tmp/recording.mp3, 32001] #[504006850-2819200-0b166fb0-00000003]
2011-07-12 12:10:37.210 DEBUG [SocketAcceptorIoProcessor-0.2] #XMPP#: (i)<iq type="set" to="836b02be-9578-4a53-b813-7d1862b2c0b4@127.0.0.1/fa1137e9-4579-4595-8ac1-ea80d185d276" id="blather000c" from="usera@127.0.0.1/voxeo"><stop xmlns="urn:xmpp:ozone:ext:1"/></iq> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:37.211 DEBUG [XMPPService-t-32] #XMPP#: Invoke application:tropo2 ozone
2011-07-12 12:10:37.211 DEBUG [XMPPService-t-32] #XMPP#: Forwarding Request #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][null]
2011-07-12 12:10:37.211 DEBUG [XMPPService-t-32] <iq type="set" to="836b02be-9578-4a53-b813-7d1862b2c0b4@127.0.0.1/fa1137e9-4579-4595-8ac1-ea80d185d276" id="blather000c" from="usera@127.0.0.1/voxeo"><stop xmlns="urn:xmpp:ozone:ext:1"/></iq> :: xmpps_au2xtk4a13mq
2011-07-12 12:10:37.211 INFO [pool-16-thread-6] Request [StopCommand[callId=836b02be-9578-4a53-b813-7d1862b2c0b4,verbId=fa1137e9-4579-4595-8ac1-ea80d185d276]]
2011-07-12 12:10:37.212 DEBUG [pool-16-thread-6] #MSCTRL#: Recorder[ACTIVE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] triggers action(MANUAL_TRIGGER, RECORDER_STOP)
2011-07-12 12:10:37.212 DEBUG [pool-16-thread-6] #MSCTRL#: Recorder[ACTIVE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] is stopping. #[504006850-2819200-0b166fb0-00000003]
2011-07-12 12:10:37.212 DEBUG [pool-16-thread-6] #MRCP#: (o)ANNOUNCE rtsp://192.168.1.11:10074/recognizer/ RTSP/1.0\r\nCseq: 5\r\nSession: 504006850-2819200-0b166fb0-00000003\r\nContent-Type: application/mrcp\r\nContent-Length: 84\r\n\r\nSTOP-RECORD 32002 MRCP/1.0\r\nVendor-Specific-Parameters: Voxeo-Record-Action=stop\r\n\r\n #[504006850-2819200-0b166fb0-00000003][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:37.215 DEBUG [mrcp/2-t-24] #MRCP#: (i)RTSP/1.0 200 OK\r\nSession: 504006850-2819200-0b166fb0-00000003\r\nCseq: 5\r\nContent-Type: application/mrcp\r\nContent-Length: 132\r\n\r\nMRCP/1.0 32002 200 COMPLETE\r\nactive-request-id-list: 32001\r\nrecord-uri: file:///tmp/recording.mp3\r\nx-voxeo-record-duration: 4050\r\n\r\n #[504006850-2819200-0b166fb0-00000003][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:37.218 DEBUG [pool-16-thread-6] #MSCTRL#: Recorder[STOPPED[MANUAL_TRIGGER], MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] moves state from [ACTIVE] to [STOPPED[MANUAL_TRIGGER]]
2011-07-12 12:10:37.218 DEBUG [mrcp/2-t-24] #MRCP#: Handling RECORD-COMPLETE[32001] #[504006850-2819200-0b166fb0-00000003][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:37.219 DEBUG [mrcp/2-t-24] #MSCTRL#: MrcpRecordListener[Recorder[STOPPED[MANUAL_TRIGGER], MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]], ACTIVE] handling with MrcpRecordCompleteEvent[requestId:32001] #[504006850-2819200-0b166fb0-00000003]
2011-07-12 12:10:37.219 DEBUG [mrcp/2-t-24] #MSCTRL#: MrcpAsrResult{type:SILENCE, "file:///tmp/recording.mp3", 4050} #[504006850-2819200-0b166fb0-00000003]
2011-07-12 12:10:37.219 DEBUG [mrcp/2-t-24] #MSCTRL#: Recorder[IDLE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] moves state from [STOPPED[MANUAL_TRIGGER]] to [IDLE]
2011-07-12 12:10:37.219 DEBUG [mrcp/2-t-24] #MSCTRL#: Return RecorderEvent[Recorder[IDLE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]], RECORD_COMPLETED, NO_ERROR, null, RTC_TRIGGERED, MANUAL_TRIGGER, 4050] to the application
2011-07-12 12:10:37.220 INFO [pool-16-thread-6] Reply [null]
2011-07-12 12:10:37.220 DEBUG [pool-16-thread-6] #XMPP#: (o)<iq type="result" id="blather000c" from="836b02be-9578-4a53-b813-7d1862b2c0b4@127.0.0.1/fa1137e9-4579-4595-8ac1-ea80d185d276" to="usera@127.0.0.1/voxeo"/> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:37.220 DEBUG [pool-16-thread-6] #XMPP#: Send message to: 127.0.0.1:51528 by xmpp #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:37.221 INFO [pool-16-thread-7] Message [[Event class=com.voxeo.moho.event.RecordCompleteEvent sourceClass=SIPIncomingCall]]
2011-07-12 12:10:37.221 ERROR [pool-16-thread-7]
java.lang.reflect.InvocationTargetException
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.voxeo.moho.event.AutowiredEventTarget.invoke(AutowiredEventTarget.java:110)
at com.voxeo.moho.event.AutowiredEventListener.onEvent(AutowiredEventListener.java:117)
at com.tropo.server.AbstractActor.onMohoEvent(AbstractActor.java:186)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.tropo.server.ReflectiveActor.onMessage(ReflectiveActor.java:92)
at org.jetlang.channels.ChannelSubscription$1.run(ChannelSubscription.java:31)
at org.jetlang.core.BatchExecutorImpl.execute(BatchExecutorImpl.java:11)
at org.jetlang.fibers.PoolFiber.flush(PoolFiber.java:63)
at org.jetlang.fibers.PoolFiber.access$000(PoolFiber.java:19)
at org.jetlang.fibers.PoolFiber$1.run(PoolFiber.java:36)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:680)
Caused by: java.lang.NullPointerException
at com.tropo.server.recording.DefaultStorageService.store(DefaultStorageService.java:20)
at com.tropo.server.verb.RecordHandler.complete(RecordHandler.java:151)
at com.tropo.server.verb.RecordHandler.onRecordComplete(RecordHandler.java:138)
... 20 more
2011-07-12 12:10:37.222 ERROR [pool-16-thread-7] Exception while processing command
java.lang.reflect.InvocationTargetException
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.tropo.server.ReflectiveActor.onMessage(ReflectiveActor.java:92)
at org.jetlang.channels.ChannelSubscription$1.run(ChannelSubscription.java:31)
at org.jetlang.core.BatchExecutorImpl.execute(BatchExecutorImpl.java:11)
at org.jetlang.fibers.PoolFiber.flush(PoolFiber.java:63)
at org.jetlang.fibers.PoolFiber.access$000(PoolFiber.java:19)
at org.jetlang.fibers.PoolFiber$1.run(PoolFiber.java:36)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:680)
Caused by: java.lang.NullPointerException
at com.tropo.server.recording.DefaultStorageService.store(DefaultStorageService.java:20)
at com.tropo.server.verb.RecordHandler.complete(RecordHandler.java:151)
at com.tropo.server.verb.RecordHandler.onRecordComplete(RecordHandler.java:138)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.voxeo.moho.event.AutowiredEventTarget.invoke(AutowiredEventTarget.java:110)
at com.voxeo.moho.event.AutowiredEventListener.onEvent(AutowiredEventListener.java:117)
at com.tropo.server.AbstractActor.onMohoEvent(AbstractActor.java:186)
... 13 more
2011-07-12 12:10:37.223 INFO [pool-16-thread-7] Queued Event [EndEvent[callId=836b02be-9578-4a53-b813-7d1862b2c0b4,reason=ERROR,errorText=<null>,headers=<null>]]
2011-07-12 12:10:37.224 INFO [pool-16-thread-7] Call cleanup [call=SIPCallImpl[SipSessionAdaptor[sessionid=ss_10pk46a9gj2zx, appSessionId=sas_2-14-smm9fk22e0gfeutropo2],ANSWERED]]
2011-07-12 12:10:37.224 DEBUG [pool-16-thread-7] destroyNetworkConnection
2011-07-12 12:10:37.224 DEBUG [pool-16-thread-7] #MSCTRL#: NC[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] moves state from [INITIALIZED] to [RELEASED]
2011-07-12 12:10:37.224 INFO [pool-16-thread-7] #MSCTRL#: MS[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] removes a MediaObject[mscontrol://192.168.1.11:10074/MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH/NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]
2011-07-12 12:10:37.224 DEBUG [pool-16-thread-7] #MSCTRL#: MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] removes JoineeMrcpContext[mscontrol://192.168.1.11:10074/MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH/NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, 504006850-2819200-0b166fb0-00000003, 504006850-2819200-0b166fb0-00000003] #[504006850-2819200-0b166fb0-00000003]
2011-07-12 12:10:37.224 DEBUG [pool-16-thread-7] #MSCTRL#: MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] removed MrcpSpeakListener[Player[IDLE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]], ACTIVE] #[504006850-2819200-0b166fb0-00000003]
2011-07-12 12:10:37.225 DEBUG [pool-16-thread-7] #MSCTRL#: Remove MrcpSpeakListener[Player[IDLE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]], ACTIVE] #[504006850-2819200-0b166fb0-00000003]
2011-07-12 12:10:37.225 DEBUG [pool-16-thread-7] #MSCTRL#: MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] removed MrcpRecordListener[Recorder[IDLE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]], ACTIVE] #[504006850-2819200-0b166fb0-00000003]
2011-07-12 12:10:37.225 DEBUG [pool-16-thread-7] #MSCTRL#: Remove MrcpRecordListener[Recorder[IDLE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]], ACTIVE] #[504006850-2819200-0b166fb0-00000003]
2011-07-12 12:10:37.225 DEBUG [pool-16-thread-7] #MSCTRL#: MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] removes(NC[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, NC-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH], JoineeContext[RESOURCE_CONTAINER, DUPLEX, null])
2011-07-12 12:10:37.225 DEBUG [pool-16-thread-7] #MRCP#: (o)TEARDOWN rtsp://192.168.1.11:10074/recognizer/ RTSP/1.0\r\nCseq: 6\r\nSession: 504006850-2819200-0b166fb0-00000003\r\n\r\n #[504006850-2819200-0b166fb0-00000003][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:37.236 DEBUG [mrcp/2-t-24] #MRCP#: (i)RTSP/1.0 200 OK\r\nSession: 504006850-2819200-0b166fb0-00000003\r\nCseq: 6\r\n\r\n #[504006850-2819200-0b166fb0-00000003][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:37.237 DEBUG [pool-16-thread-7] #MRCP#: (o)TEARDOWN rtsp://192.168.1.11:10074/synthesizer/ RTSP/1.0\r\nCseq: 7\r\nSession: 504006850-2819200-0b166fb0-00000003\r\n\r\n #[504006850-2819200-0b166fb0-00000003][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:37.247 DEBUG [mrcp/2-t-24] #MRCP#: (i)RTSP/1.0 200 OK\r\nSession: 504006850-2819200-0b166fb0-00000003\r\nCseq: 7\r\n\r\n #[504006850-2819200-0b166fb0-00000003][192.168.1.11:10074][192.168.1.11:51529]
2011-07-12 12:10:37.248 DEBUG [pool-16-thread-7] #MSCTRL#: MS[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] moves state from [INITIALIZED] to [RELEASED]
2011-07-12 12:10:37.248 DEBUG [pool-16-thread-7] #MSCTRL#: MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] moves state from [INITIALIZED] to [RELEASED]
2011-07-12 12:10:37.248 DEBUG [pool-16-thread-7] #MSCTRL#: Stopping Player[IDLE, MG[MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH, MG-ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]], isStopAll:true
2011-07-12 12:10:37.248 DEBUG [pool-16-thread-7] terminating call. Notifying this. callID:ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH
2011-07-12 12:10:37.249 DEBUG [pool-16-thread-7] #SIP#: SessionManagementLayer send request: BYE sip:aconrulk@127.0.0.1:64541 #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info][sip:usera@127.0.0.1]
2011-07-12 12:10:37.249 INFO [MOHO-16] Actor CallActor is disposed. Ignoring message. [[Event class=com.voxeo.moho.event.CallCompleteEvent sourceClass=SIPIncomingCall]]
2011-07-12 12:10:37.249 DEBUG [pool-16-thread-7] #SIP#: The transaction was created: z9hG4bK1tzoz706qsrys #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:37.249 DEBUG [pool-16-thread-7] #SIP#: (o)[BYE sip:aconrulk@127.0.0.1:64541 SIP/2.0\r\nTo: "zhao lu" <sip:zlu@sip2sip.info>;tag=Z1aFKM6AH3LEBgr5q9FLxuMRq4l9qa3-\r\nVia: SIP/2.0/UDP 192.168.1.11:5060;branch=z9hG4bK1tzoz706qsrys;rport;x-sm-sid=fac65aa5-89df-4429-a807-39b37393d07c;x-sm-nid=ss_10pk46a9gj2zx\r\nCSeq: 1 BYE\r\nContent-Length: 0\r\nCall-ID: ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH\r\nMax-Forwards: 70\r\nFrom: <sip:usera@127.0.0.1>;tag=19gw3squ26tpn\r\n\r\n] #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:37.250 DEBUG [pool-16-thread-7] #SIP#: Send message to: /127.0.0.1:64541 by udp #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:37.250 DEBUG [pool-16-thread-7] #SIP#: Connected to 127.0.0.1:64541/udp #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:37.250 INFO [pool-16-thread-7] Event [EndEvent[callId=836b02be-9578-4a53-b813-7d1862b2c0b4,reason=ERROR,errorText=<null>,headers=<null>]]
2011-07-12 12:10:37.253 DEBUG [pool-16-thread-7] #XMPP#: (o)<presence from="836b02be-9578-4a53-b813-7d1862b2c0b4@127.0.0.1" to="usera@127.0.0.1/voxeo"><end xmlns="urn:xmpp:ozone:1"><error/></end></presence> #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:37.254 DEBUG [pool-16-thread-7] #XMPP#: Send message to: 127.0.0.1:51528 by xmpp #[tropo2][null][xmpps_au2xtk4a13mq][usera@127.0.0.1/voxeo, 127.0.0.1][127.0.0.1:51528][127.0.0.1:5222][xmpp][N/A]
2011-07-12 12:10:37.258 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (i)[SIP/2.0 200 OK\r\nTo: "zhao lu" <sip:zlu@sip2sip.info>;tag=Z1aFKM6AH3LEBgr5q9FLxuMRq4l9qa3-\r\nVia: SIP/2.0/UDP 192.168.1.11:5060;rport=5060;received=127.0.0.1;branch=z9hG4bK1tzoz706qsrys;x-sm-sid=fac65aa5-89df-4429-a807-39b37393d07c;x-sm-nid=ss_10pk46a9gj2zx\r\nCSeq: 1 BYE\r\nContent-Length: 0\r\nCall-ID: ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH\r\nServer: Blink Lite 1.1.1 (MacOSX)\r\nFrom: <sip:usera@127.0.0.1>;tag=19gw3squ26tpn\r\n\r\n] #[N/A][N/A][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][N/A][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:37.262 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Receive 200/BYE, branch=z9hG4bK1tzoz706qsrys #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:37.262 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: NonInviteClientTransaction[_state=COMPLETED, _id=z9hG4bK1tzoz706qsrys] is ready to release. #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:37.262 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer recv response: BYE/200 #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:37.263 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipServletWrapper[Controller, com.voxeo.moho.sip.SIPController] is forwarding. #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:37.266 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-smm9fk22e0gfeutropo2], invalidateWhenReady: true
2011-07-12 12:10:37.267 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_10pk46a9gj2zx], current State = TERMINATED, Vaild:true, Role:UAS, hasOngoingTransaction: true, OT: 1, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:37.267 INFO [MOHO-17] Actor CallActor is disposed. Ignoring message. [[Event class=com.voxeo.moho.sip.SIPSuccessEventImpl sourceClass=SIPIncomingCall]]
2011-07-12 12:10:37.269 DEBUG [MOHO-17] SIPCallImpl[SipSessionAdaptor[sessionid=ss_10pk46a9gj2zx, appSessionId=sas_2-14-smm9fk22e0gfeutropo2],DISCONNECTED] is already terminated.
2011-07-12 12:10:37.268 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: server will automatically invalidate sipsession [ss_10pk46a9gj2zx] #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:37.273 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipSessionImpl[_id=ss_10pk46a9gj2zx, _parentId=sas_2-14-smm9fk22e0gfeutropo2, _handler=Controller, _state=TERMINATED, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=INVITE, _callId=ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH] is invalidating. (s) #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:37.274 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Remove Path[ id=ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH-Z1aFKM6AH3LEBgr5q9FLxuMRq4l9qa3--19gw3squ26tpn, session=SipSessionImpl[_id=ss_10pk46a9gj2zx, _parentId=sas_2-14-smm9fk22e0gfeutropo2, _handler=Controller, _state=TERMINATED, _fresh=false, _valid=true, _unavailable=true, _role=UAS, _method=INVITE, _callId=ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH]] #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:37.274 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-smm9fk22e0gfeutropo2], invalidateWhenReady: true
2011-07-12 12:10:37.275 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Container will automatically invalidate SipApplicationSession [sas_2-14-smm9fk22e0gfeutropo2]
2011-07-12 12:10:37.276 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-14-smm9fk22e0gfeutropo2] is invalidating. (as)
2011-07-12 12:10:42.263 DEBUG [Timer-8] #SIP#: NonInviteClientTransaction[_state=COMPLETED, _id=z9hG4bK1tzoz706qsrys] timerRemoveTransaction is fired. #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
2011-07-12 12:10:42.265 DEBUG [Timer-8] #SIP#: NonInviteClientTransaction[_state=TERMINATED, _id=z9hG4bK1tzoz706qsrys] is released. #[tropo2][sas_2-14-smm9fk22e0gfeutropo2][ZfgIWEvsYUfoBw58IKdYpLu8YN6-MpuH][ss_10pk46a9gj2zx][sip:zlu@sip2sip.info(127.0.0.1:64541)][sip:usera@127.0.0.1(192.168.1.11:5060)]
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment