Skip to content

Instantly share code, notes, and snippets.

@juandebravo
Created July 14, 2011 17:24
Show Gist options
  • Save juandebravo/1082939 to your computer and use it in GitHub Desktop.
Save juandebravo/1082939 to your computer and use it in GitHub Desktop.
trazas_webapi
2011-07-14 17:16:53.714 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (i)[INVITE sip:index.json@tropo-dev90.tropo-dev90 SIP/2.0\r\nContent-Type: application/sdp\r\nTo: <sip:index.json@tropo-dev90.tropo-dev90>\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport;branch=z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7Bh\r\nAllow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER\r\nCSeq: 32187 INVITE\r\nContent-Length: 365\r\nSupported: 100rel, norefersub\r\nCall-ID: TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy\r\nUser-Agent: Blink 0.24.0 (MacOSX)\r\nFrom: "usera" <sip:usera@tropo-dev90>;tag=0C53ZuMSLfhNJgJI5W7FnQGftDs4UEDW\r\nMax-Forwards: 70\r\nContact: <sip:zsudcpij@3.3.3.11:59832>\r\n\r\nv=0\r\no=- 3519652669 3519652669 IN IP4 3.3.3.11\r\ns=Blink 0.24.0 (MacOSX)\r\nc=IN IP4 3.3.3.11\r\nt=0 0\r\nm=audio 50054 RTP/AVP 9 104 103 102 0 8 101\r\na=rtcp:50055\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][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.714 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: The transaction was created: z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7Bh #[N/A][N/A][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.715 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (o)[SIP/2.0 100 Trying\r\nTo: <sip:index.json@tropo-dev90.tropo-dev90>\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7Bh;received=3.3.3.11\r\nCSeq: 32187 INVITE\r\nContent-Length: 0\r\nCall-ID: TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy\r\nFrom: usera <sip:usera@tropo-dev90>;tag=0C53ZuMSLfhNJgJI5W7FnQGftDs4UEDW\r\n\r\n] #[N/A][N/A][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][N/A][sip:index.json@tropo-dev90.tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.715 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Send message to: /3.3.3.11:59832 by udp #[N/A][N/A][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][N/A][sip:index.json@tropo-dev90.tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.715 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Connected to 3.3.3.11:59832/udp #[N/A][N/A][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][N/A][sip:index.json@tropo-dev90.tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.715 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Found [tropo] to handle the request by port mappings: 5060
2011-07-14 17:16:53.716 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationInfo: SipApplicationRouterInfo[ApplicationName=tropo, RouteModifier=NO_ROUTE, RouteRegion=null, SubscriberURI=sip:index.json@tropo-dev90.tropo-dev90, StateInfo=tropo] #[N/A][N/A][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.716 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-14-smlza5kmis8ff6tropo] will expired after 7200000
2011-07-14 17:16:53.716 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session creating: ss_105g7dwsgh69g #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.717 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session created:SipSessionImpl[_id=ss_105g7dwsgh69g, _parentId=sas_2-14-smlza5kmis8ff6tropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UNKNOW, _method=INVITE, _callId=TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy] #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.717 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer recv request: INVITE #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.717 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ApplicationDispatchLayer invoke application: tropo with INVITE #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.717 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipServletWrapper[tropo, com.voxeo.tropo.SIPDriver] is forwarding. #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.718 DEBUG [udp/0.0.0.0/5060-t-4] doInvite: [INVITE sip:index.json@tropo-dev90.tropo-dev90 SIP/2.0
Content-Type: application/sdp
To: <sip:index.json@tropo-dev90.tropo-dev90>
Via: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7Bh;received=3.3.3.11
Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER
CSeq: 32187 INVITE
Content-Length: 365
Supported: 100rel, norefersub
Call-ID: TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy
User-Agent: Blink 0.24.0 (MacOSX)
From: usera <sip:usera@tropo-dev90>;tag=0C53ZuMSLfhNJgJI5W7FnQGftDs4UEDW
Max-Forwards: 70
Contact: <sip:zsudcpij@3.3.3.11:59832>
v=0
o=- 3519652669 3519652669 IN IP4 3.3.3.11
s=Blink 0.24.0 (MacOSX)
c=IN IP4 3.3.3.11
t=0 0
m=audio 50054 RTP/AVP 9 104 103 102 0 8 101
a=rtcp:50055
a=rtpmap:9 G722/8000
a=rtpmap:104 speex/32000
a=rtpmap:103 speex/16000
a=rtpmap:102 speex/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
]
2011-07-14 17:16:53.718 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer send response: INVITE/100 #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.718 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (o)[SIP/2.0 100 Trying\r\nTo: <sip:index.json@tropo-dev90.tropo-dev90>\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7Bh;received=3.3.3.11\r\nCSeq: 32187 INVITE\r\nContent-Length: 0\r\nCall-ID: TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy\r\nFrom: usera <sip:usera@tropo-dev90>;tag=0C53ZuMSLfhNJgJI5W7FnQGftDs4UEDW\r\n\r\n] #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.718 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Send message to: /3.3.3.11:59832 by udp #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.719 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Connected to 3.3.3.11:59832/udp #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.719 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-smlza5kmis8ff6tropo], invalidateWhenReady: true
2011-07-14 17:16:53.719 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_105g7dwsgh69g], current State = EARLY, Vaild:true, Role:UNKNOW, hasOngoingTransaction: false, OT: 0, ProcessingByApp: true, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.719 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-smlza5kmis8ff6tropo], invalidateWhenReady: true
2011-07-14 17:16:53.719 INFO [udp/0.0.0.0/5060-t-4] A new call is coming from sip:usera@tropo-dev90 to sip:index.json@tropo-dev90.tropo-dev90
2011-07-14 17:16:53.720 DEBUG [udp/0.0.0.0/5060-t-4] Tropo PRISM Hosting Edition found app=null for url=sip:index.json@tropo-dev90.tropo-dev90,_cache.size=0
2011-07-14 17:16:53.720 INFO [udp/0.0.0.0/5060-t-4] Set logging context for udp/0.0.0.0/5060-t-4 to accountID=0 host=tropo-dev90.jajah.dublin sessionGUID=-1 sessionNumber=-1 callID=-1
2011-07-14 17:16:53.744 DEBUG [udp/0.0.0.0/5060-t-4] Determined type=tropo-web from HTTP Content-Type header
2011-07-14 17:16:53.745 DEBUG [udp/0.0.0.0/5060-t-4] Trying to create application for URL=http://212.179.159.107/proxy/index.json and type=tropo-web
2011-07-14 17:16:53.745 INFO [udp/0.0.0.0/5060-t-4] Tropo app dir is /tmp/tropo3660655868735791086appHome
2011-07-14 17:16:53.745 INFO [udp/0.0.0.0/5060-t-4] Set logging context for udp/0.0.0.0/5060-t-4 to accountID=0 host=tropo-dev90.jajah.dublin sessionGUID=-1 sessionNumber=-1 callID=-1
2011-07-14 17:16:53.746 INFO [udp/0.0.0.0/5060-t-4] Application[http://212.179.159.107/proxy/index.json:null] ver(development.50674) has been created.
2011-07-14 17:16:53.746 DEBUG [udp/0.0.0.0/5060-t-4] Tropo PRISM Hosting Edition cached app=Application[http://212.179.159.107/proxy/index.json:null] ver(development.50674) for url=sip:index.json@tropo-dev90.tropo-dev90,_cache.size=1
2011-07-14 17:16:53.746 INFO [udp/0.0.0.0/5060-t-4] Set logging context for udp/0.0.0.0/5060-t-4 to accountID=0 host=tropo-dev90.jajah.dublin sessionGUID=-1 sessionNumber=9c221bf4ccb979d32f9b6226b7aeb421 callID=TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy
2011-07-14 17:16:53.746 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer send response: INVITE/180 #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.747 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Add Path[ id=TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy-0C53ZuMSLfhNJgJI5W7FnQGftDs4UEDW-1k0an0d1ovqsn, session=SipSessionImpl[_id=ss_105g7dwsgh69g, _parentId=sas_2-14-smlza5kmis8ff6tropo, _handler=tropo, _state=EARLY, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=INVITE, _callId=TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy], party= CALLER] #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.747 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (o)[SIP/2.0 180 Ringing\r\nTo: <sip:index.json@tropo-dev90.tropo-dev90>;tag=1k0an0d1ovqsn\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7Bh;received=3.3.3.11\r\nCSeq: 32187 INVITE\r\nContent-Length: 0\r\nCall-ID: TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy\r\nFrom: usera <sip:usera@tropo-dev90>;tag=0C53ZuMSLfhNJgJI5W7FnQGftDs4UEDW\r\n\r\n] #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.748 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Send message to: /3.3.3.11:59832 by udp #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.748 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Connected to 3.3.3.11:59832/udp #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.748 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-smlza5kmis8ff6tropo], invalidateWhenReady: true
2011-07-14 17:16:53.748 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_105g7dwsgh69g], current State = EARLY, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: true, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.748 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-smlza5kmis8ff6tropo], invalidateWhenReady: true
2011-07-14 17:16:53.749 INFO [udp/0.0.0.0/5060-t-4] Set logging context for udp/0.0.0.0/5060-t-4 to accountID=0 host=tropo-dev90.jajah.dublin sessionGUID=-1 sessionNumber=9c221bf4ccb979d32f9b6226b7aeb421 callID=TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy
2011-07-14 17:16:53.749 DEBUG [udp/0.0.0.0/5060-t-4] Thread udp/0.0.0.0/5060-t-4 acquired engine of type tropo-web, activeEngines = 1
2011-07-14 17:16:53.749 DEBUG [udp/0.0.0.0/5060-t-4] Thread udp/0.0.0.0/5060-t-4 got engine to compile script
2011-07-14 17:16:53.749 DEBUG [udp/0.0.0.0/5060-t-4] Thread udp/0.0.0.0/5060-t-4 returning engine after compiling script
2011-07-14 17:16:53.749 DEBUG [udp/0.0.0.0/5060-t-4] Thread udp/0.0.0.0/5060-t-4 returned engine of type tropo-web, activeEngines = 0
2011-07-14 17:16:53.749 DEBUG [udp/0.0.0.0/5060-t-4] SipApplicationSession sas_2-14-smlza5kmis8ff6tropo associated with Tropo session 9c221bf4ccb979d32f9b6226b7aeb421
2011-07-14 17:16:53.749 INFO [udp/0.0.0.0/5060-t-4] ApplicationInstance[http://212.179.159.107/proxy/index.json, sas_2-14-smlza5kmis8ff6tropo] has been created.
2011-07-14 17:16:53.749 DEBUG [udp/0.0.0.0/5060-t-4] com.voxeo.tropo.core.SimpleCallFactory@4838670 is added into the context of app instance : ApplicationInstance[http://212.179.159.107/proxy/index.json, sas_2-14-smlza5kmis8ff6tropo]
2011-07-14 17:16:53.750 INFO [udp/0.0.0.0/5060-t-4] Clearing logging context for udp/0.0.0.0/5060-t-4
2011-07-14 17:16:53.750 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-smlza5kmis8ff6tropo], invalidateWhenReady: false
2011-07-14 17:16:53.750 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_105g7dwsgh69g], current State = EARLY, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:16:53.750 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-smlza5kmis8ff6tropo], invalidateWhenReady: false
2011-07-14 17:16:53.751 INFO [Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421] Set logging context for Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421 to accountID=0 host=tropo-dev90.jajah.dublin sessionGUID=-1 sessionNumber=9c221bf4ccb979d32f9b6226b7aeb421 callID=TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy
2011-07-14 17:16:53.753 WARN [Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421] Attribute com.voxeo.tropo.core.call.inst added to Sip Session ss_105g7dwsgh69g in state EARLY
2011-07-14 17:16:53.753 DEBUG [Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421] SipSession ss_105g7dwsgh69g - TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy associated with Tropo call a8abed480c18f4b6dbb319ff3ea557c1
2011-07-14 17:16:53.754 DEBUG [Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421] SimpleIncomingCall[usera/usera->index.json/null] state is changed: NEW->RINGING
2011-07-14 17:16:53.754 DEBUG [Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421] Call a8abed480c18f4b6dbb319ff3ea557c1 state changed from NEW to RINGING on thread Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421
2011-07-14 17:16:53.754 DEBUG [Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421] SimpleIncomingCall[usera/usera->index.json/null]->got INVITE:
[INVITE sip:index.json@tropo-dev90.tropo-dev90 SIP/2.0
Content-Type: application/sdp
To: <sip:index.json@tropo-dev90.tropo-dev90>
Via: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7Bh;received=3.3.3.11
Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER
CSeq: 32187 INVITE
Content-Length: 365
Supported: 100rel, norefersub
Call-ID: TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy
User-Agent: Blink 0.24.0 (MacOSX)
From: usera <sip:usera@tropo-dev90>;tag=0C53ZuMSLfhNJgJI5W7FnQGftDs4UEDW
Max-Forwards: 70
Contact: <sip:zsudcpij@3.3.3.11:59832>
v=0
o=- 3519652669 3519652669 IN IP4 3.3.3.11
s=Blink 0.24.0 (MacOSX)
c=IN IP4 3.3.3.11
t=0 0
m=audio 50054 RTP/AVP 9 104 103 102 0 8 101
a=rtcp:50055
a=rtpmap:9 G722/8000
a=rtpmap:104 speex/32000
a=rtpmap:103 speex/16000
a=rtpmap:102 speex/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
]
2011-07-14 17:16:53.755 INFO [Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421] SimpleIncomingCall[usera/usera->index.json/null] is received.
2011-07-14 17:16:53.755 DEBUG [Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421] SimpleIncomingCall[usera/usera->index.json/null] is added into the context
2011-07-14 17:16:53.755 DEBUG [Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421] ApplicationInstance[http://212.179.159.107/proxy/index.json, sas_2-14-smlza5kmis8ff6tropo] starts execution on Thread Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421
2011-07-14 17:16:53.755 DEBUG [Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421] Thread Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421 acquired engine of type tropo-web, activeEngines = 1
2011-07-14 17:16:53.761 INFO [Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421] Sending TropoML Payload on Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421 [url=http://212.179.159.107/proxy/index.json]: {"session":{"id":"9c221bf4ccb979d32f9b6226b7aeb421","accountId":"0","timestamp":"2011-07-14T17:16:53.758Z","userType":"HUMAN","initialText":null,"callId":"a8abed480c18f4b6dbb319ff3ea557c1","to":{"id":"index.json","name":null,"channel":"VOICE","network":"SIP"},"from":{"id":"usera","name":"usera","channel":"VOICE","network":"SIP"},"headers":{"Max-Forwards":"70","Content-Length":"365","Contact":"<sip:zsudcpij@3.3.3.11:59832>","Supported":"100rel","Allow":"SUBSCRIBE","To":"<sip:index.json@tropo-dev90.tropo-dev90>","CSeq":"32187 INVITE","User-Agent":"Blink 0.24.0 (MacOSX)","Via":"SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7Bh;received=3.3.3.11","Call-ID":"TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy","Content-Type":"application/sdp","From":"usera <sip:usera@tropo-dev90>;tag=0C53ZuMSLfhNJgJI5W7FnQGftDs4UEDW"}}}
2011-07-14 17:17:02.641 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (i)[SUBSCRIBE sip:usera@tropo-dev90 SIP/2.0\r\nTo: <sip:usera@tropo-dev90>\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport;branch=z9hG4bKPj0iBwTTnHcrMcYUwk5SrZBScFdXmMps9Z\r\nAccept: application/simple-message-summary\r\nCall-ID: k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6\r\nUser-Agent: Blink 0.24.0 (MacOSX)\r\nMax-Forwards: 70\r\nFrom: "usera" <sip:usera@tropo-dev90>;tag=r9jJziCFKY0C2rLVq7bulGIuQKnM-8vC\r\nContact: <sip:zsudcpij@3.3.3.11:59832>\r\nExpires: 3600\r\nCSeq: 29068 SUBSCRIBE\r\nEvent: message-summary\r\nContent-Length: 0\r\nAllow-Events: conference, message-summary, presence, presence.winfo, xcap-diff, refer\r\n\r\n] #[N/A][N/A][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.644 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: The transaction was created: z9hG4bKPj0iBwTTnHcrMcYUwk5SrZBScFdXmMps9Z #[N/A][N/A][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.644 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Found [tropo] to handle the request by port mappings: 5060
2011-07-14 17:17:02.644 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationInfo: SipApplicationRouterInfo[ApplicationName=tropo, RouteModifier=NO_ROUTE, RouteRegion=null, SubscriberURI=sip:usera@tropo-dev90, StateInfo=tropo] #[N/A][N/A][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.645 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-14-smfmr0wkvhf386tropo] will expired after 7200000
2011-07-14 17:17:02.645 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session creating: ss_uztb9r75t28c #[tropo][sas_2-14-smfmr0wkvhf386tropo][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][ss_uztb9r75t28c][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.646 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session created:SipSessionImpl[_id=ss_uztb9r75t28c, _parentId=sas_2-14-smfmr0wkvhf386tropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UNKNOW, _method=SUBSCRIBE, _callId=k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6] #[tropo][sas_2-14-smfmr0wkvhf386tropo][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][ss_uztb9r75t28c][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.646 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer recv request: SUBSCRIBE #[tropo][sas_2-14-smfmr0wkvhf386tropo][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][ss_uztb9r75t28c][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.646 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ApplicationDispatchLayer invoke application: tropo with SUBSCRIBE #[tropo][sas_2-14-smfmr0wkvhf386tropo][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][ss_uztb9r75t28c][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.646 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipServletWrapper[tropo, com.voxeo.tropo.SIPDriver] is forwarding. #[tropo][sas_2-14-smfmr0wkvhf386tropo][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][ss_uztb9r75t28c][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.647 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer send response: SUBSCRIBE/500 #[tropo][sas_2-14-smfmr0wkvhf386tropo][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][ss_uztb9r75t28c][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.647 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Add Path[ id=k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6-r9jJziCFKY0C2rLVq7bulGIuQKnM-8vC-tfi070tzcaq9, session=SipSessionImpl[_id=ss_uztb9r75t28c, _parentId=sas_2-14-smfmr0wkvhf386tropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=SUBSCRIBE, _callId=k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6], party= CALLER] #[tropo][sas_2-14-smfmr0wkvhf386tropo][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][ss_uztb9r75t28c][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.648 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (o)[SIP/2.0 500 Request not handled by app\r\nTo: <sip:usera@tropo-dev90>;tag=tfi070tzcaq9\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPj0iBwTTnHcrMcYUwk5SrZBScFdXmMps9Z;received=3.3.3.11\r\nCSeq: 29068 SUBSCRIBE\r\nContent-Length: 0\r\nCall-ID: k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6\r\nFrom: usera <sip:usera@tropo-dev90>;tag=r9jJziCFKY0C2rLVq7bulGIuQKnM-8vC\r\n\r\n] #[tropo][sas_2-14-smfmr0wkvhf386tropo][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][ss_uztb9r75t28c][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.648 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Send message to: /3.3.3.11:59832 by udp #[tropo][sas_2-14-smfmr0wkvhf386tropo][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][ss_uztb9r75t28c][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.648 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Connected to 3.3.3.11:59832/udp #[tropo][sas_2-14-smfmr0wkvhf386tropo][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][ss_uztb9r75t28c][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.649 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-smfmr0wkvhf386tropo], invalidateWhenReady: true
2011-07-14 17:17:02.649 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_uztb9r75t28c], current State = TERMINATED, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: true, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-14-smfmr0wkvhf386tropo][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][ss_uztb9r75t28c][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.649 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-smfmr0wkvhf386tropo], invalidateWhenReady: true
2011-07-14 17:17:02.649 INFO [udp/0.0.0.0/5060-t-4] Clearing logging context for udp/0.0.0.0/5060-t-4
2011-07-14 17:17:02.649 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-smfmr0wkvhf386tropo], invalidateWhenReady: true
2011-07-14 17:17:02.649 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_uztb9r75t28c], current State = TERMINATED, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-14-smfmr0wkvhf386tropo][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][ss_uztb9r75t28c][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.650 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: server will automatically invalidate sipsession [ss_uztb9r75t28c] #[tropo][sas_2-14-smfmr0wkvhf386tropo][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][ss_uztb9r75t28c][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.650 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipSessionImpl[_id=ss_uztb9r75t28c, _parentId=sas_2-14-smfmr0wkvhf386tropo, _handler=tropo, _state=TERMINATED, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=SUBSCRIBE, _callId=k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6] is invalidating. (s) #[tropo][sas_2-14-smfmr0wkvhf386tropo][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][ss_uztb9r75t28c][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.651 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Remove Path[ id=k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6-r9jJziCFKY0C2rLVq7bulGIuQKnM-8vC-tfi070tzcaq9, session=SipSessionImpl[_id=ss_uztb9r75t28c, _parentId=sas_2-14-smfmr0wkvhf386tropo, _handler=tropo, _state=TERMINATED, _fresh=false, _valid=true, _unavailable=true, _role=UAS, _method=SUBSCRIBE, _callId=k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6]] #[tropo][sas_2-14-smfmr0wkvhf386tropo][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][ss_uztb9r75t28c][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:02.651 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-smfmr0wkvhf386tropo], invalidateWhenReady: true
2011-07-14 17:17:02.651 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Container will automatically invalidate SipApplicationSession [sas_2-14-smfmr0wkvhf386tropo]
2011-07-14 17:17:02.652 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-14-smfmr0wkvhf386tropo] is invalidating. (as)
2011-07-14 17:17:05.813 DEBUG [Timer-12] #SIP#: NonInviteServerTransaction[_state=COMPLETED, _id=z9hG4bKPjDIt8r8kkdqAexX9Sw2k-WnSEZcaXx.VA] timerRemoveTransaction is fired. #[tropo][sas_2-14-sm817ri08utmmxtropo][oJBUb8zQtxKrNBgwMNgZhJ51ajhSM-EV][ss_khz6zcnwz9di][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:05.818 DEBUG [Timer-12] #SIP#: NonInviteServerTransaction[_state=TERMINATED, _id=z9hG4bKPjDIt8r8kkdqAexX9Sw2k-WnSEZcaXx.VA] is released. #[tropo][sas_2-14-sm817ri08utmmxtropo][oJBUb8zQtxKrNBgwMNgZhJ51ajhSM-EV][ss_khz6zcnwz9di][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:05.813 DEBUG [Timer-13] #SIP#: SipSessionImpl[_id=ss_khz6zcnwz9di, _parentId=sas_2-14-sm817ri08utmmxtropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=REGISTER, _callId=oJBUb8zQtxKrNBgwMNgZhJ51ajhSM-EV] is invalidating. (s) #[tropo][sas_2-14-sm817ri08utmmxtropo][oJBUb8zQtxKrNBgwMNgZhJ51ajhSM-EV][ss_khz6zcnwz9di][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:05.818 DEBUG [Timer-13] #SIP#: Remove Path[ id=oJBUb8zQtxKrNBgwMNgZhJ51ajhSM-EV-u.DiUg7uB5w6j0pGAi8ZfajSLriNTvud-b3abruwzolq4, session=SipSessionImpl[_id=ss_khz6zcnwz9di, _parentId=sas_2-14-sm817ri08utmmxtropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=true, _role=UAS, _method=REGISTER, _callId=oJBUb8zQtxKrNBgwMNgZhJ51ajhSM-EV]] #[tropo][sas_2-14-sm817ri08utmmxtropo][oJBUb8zQtxKrNBgwMNgZhJ51ajhSM-EV][ss_khz6zcnwz9di][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:05.819 DEBUG [Timer-13] #SIP#: processInvalidationWhenReady [sas_2-14-sm817ri08utmmxtropo], invalidateWhenReady: true
2011-07-14 17:17:05.819 DEBUG [Timer-13] #SIP#: Container will automatically invalidate SipApplicationSession [sas_2-14-sm817ri08utmmxtropo]
2011-07-14 17:17:05.820 DEBUG [Timer-13] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-14-sm817ri08utmmxtropo] is invalidating. (as)
2011-07-14 17:17:08.643 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (i)[REGISTER sip:tropo-dev90 SIP/2.0\r\nTo: "usera" <sip:usera@tropo-dev90>\r\nExpires: 600\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport;branch=z9hG4bKPjxMaTJDGIBjYz3Degx6wDpZ3hGfgb0rBL\r\nCSeq: 1 REGISTER\r\nContent-Length: 0\r\nCall-ID: Of125BkyFSNm.lhnB9bJf1pk5KrI6osb\r\nUser-Agent: Blink 0.24.0 (MacOSX)\r\nFrom: "usera" <sip:usera@tropo-dev90>;tag=8dfZ9G6OnI5bmS-SxmhIVU2Lpb30Onyg\r\nMax-Forwards: 70\r\nContact: <sip:zsudcpij@3.3.3.11:59832>\r\n\r\n] #[N/A][N/A][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:08.646 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: The transaction was created: z9hG4bKPjxMaTJDGIBjYz3Degx6wDpZ3hGfgb0rBL #[N/A][N/A][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:08.646 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Found [tropo] to handle the request by port mappings: 5060
2011-07-14 17:17:08.646 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationInfo: SipApplicationRouterInfo[ApplicationName=tropo, RouteModifier=NO_ROUTE, RouteRegion=null, SubscriberURI=sip:tropo-dev90, StateInfo=tropo] #[N/A][N/A][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:08.647 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-15-sm15unddnz5uzr0tropo] will expired after 7200000
2011-07-14 17:17:08.647 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session creating: ss_1m3yf5hd7v6fr #[tropo][sas_2-15-sm15unddnz5uzr0tropo][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][ss_1m3yf5hd7v6fr][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:08.648 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session created:SipSessionImpl[_id=ss_1m3yf5hd7v6fr, _parentId=sas_2-15-sm15unddnz5uzr0tropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UNKNOW, _method=REGISTER, _callId=Of125BkyFSNm.lhnB9bJf1pk5KrI6osb] #[tropo][sas_2-15-sm15unddnz5uzr0tropo][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][ss_1m3yf5hd7v6fr][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:08.648 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer recv request: REGISTER #[tropo][sas_2-15-sm15unddnz5uzr0tropo][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][ss_1m3yf5hd7v6fr][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:08.648 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ApplicationDispatchLayer invoke application: tropo with REGISTER #[tropo][sas_2-15-sm15unddnz5uzr0tropo][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][ss_1m3yf5hd7v6fr][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:08.648 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipServletWrapper[tropo, com.voxeo.tropo.SIPDriver] is forwarding. #[tropo][sas_2-15-sm15unddnz5uzr0tropo][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][ss_1m3yf5hd7v6fr][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:08.649 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer send response: REGISTER/500 #[tropo][sas_2-15-sm15unddnz5uzr0tropo][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][ss_1m3yf5hd7v6fr][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:08.649 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Add Path[ id=Of125BkyFSNm.lhnB9bJf1pk5KrI6osb-8dfZ9G6OnI5bmS-SxmhIVU2Lpb30Onyg-1igr7ga8f05d0, session=SipSessionImpl[_id=ss_1m3yf5hd7v6fr, _parentId=sas_2-15-sm15unddnz5uzr0tropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=REGISTER, _callId=Of125BkyFSNm.lhnB9bJf1pk5KrI6osb], party= CALLER] #[tropo][sas_2-15-sm15unddnz5uzr0tropo][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][ss_1m3yf5hd7v6fr][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:08.650 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (o)[SIP/2.0 500 Request not handled by app\r\nTo: usera <sip:usera@tropo-dev90>;tag=1igr7ga8f05d0\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPjxMaTJDGIBjYz3Degx6wDpZ3hGfgb0rBL;received=3.3.3.11\r\nCSeq: 1 REGISTER\r\nContent-Length: 0\r\nCall-ID: Of125BkyFSNm.lhnB9bJf1pk5KrI6osb\r\nFrom: usera <sip:usera@tropo-dev90>;tag=8dfZ9G6OnI5bmS-SxmhIVU2Lpb30Onyg\r\n\r\n] #[tropo][sas_2-15-sm15unddnz5uzr0tropo][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][ss_1m3yf5hd7v6fr][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:08.650 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Send message to: /3.3.3.11:59832 by udp #[tropo][sas_2-15-sm15unddnz5uzr0tropo][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][ss_1m3yf5hd7v6fr][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:08.650 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Connected to 3.3.3.11:59832/udp #[tropo][sas_2-15-sm15unddnz5uzr0tropo][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][ss_1m3yf5hd7v6fr][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:08.651 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm15unddnz5uzr0tropo], invalidateWhenReady: true
2011-07-14 17:17:08.651 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_1m3yf5hd7v6fr], current State = INITIAL, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: true, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-15-sm15unddnz5uzr0tropo][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][ss_1m3yf5hd7v6fr][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:08.651 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-15-sm15unddnz5uzr0tropo], invalidateWhenReady: true
2011-07-14 17:17:08.651 INFO [udp/0.0.0.0/5060-t-4] Clearing logging context for udp/0.0.0.0/5060-t-4
2011-07-14 17:17:08.651 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm15unddnz5uzr0tropo], invalidateWhenReady: true
2011-07-14 17:17:08.651 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_1m3yf5hd7v6fr], current State = INITIAL, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-15-sm15unddnz5uzr0tropo][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][ss_1m3yf5hd7v6fr][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:08.651 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-15-sm15unddnz5uzr0tropo], invalidateWhenReady: true
2011-07-14 17:17:34.650 DEBUG [Timer-8] #SIP#: NonInviteServerTransaction[_state=COMPLETED, _id=z9hG4bKPj0iBwTTnHcrMcYUwk5SrZBScFdXmMps9Z] timerRemoveTransaction is fired. #[tropo][sas_2-14-smfmr0wkvhf386tropo][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][ss_uztb9r75t28c][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:34.653 DEBUG [Timer-8] #SIP#: NonInviteServerTransaction[_state=TERMINATED, _id=z9hG4bKPj0iBwTTnHcrMcYUwk5SrZBScFdXmMps9Z] is released. #[tropo][sas_2-14-smfmr0wkvhf386tropo][k3gbaUDL147tFYR1c2w4S.aZrrxSbsB6][ss_uztb9r75t28c][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:40.753 DEBUG [Timer-9] #SIP#: NonInviteServerTransaction[_state=COMPLETED, _id=z9hG4bKPjxMaTJDGIBjYz3Degx6wDpZ3hGfgb0rBL] timerRemoveTransaction is fired. #[tropo][sas_2-15-sm15unddnz5uzr0tropo][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][ss_1m3yf5hd7v6fr][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:40.754 DEBUG [Timer-10] #SIP#: SipSessionImpl[_id=ss_1m3yf5hd7v6fr, _parentId=sas_2-15-sm15unddnz5uzr0tropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=REGISTER, _callId=Of125BkyFSNm.lhnB9bJf1pk5KrI6osb] is invalidating. (s) #[tropo][sas_2-15-sm15unddnz5uzr0tropo][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][ss_1m3yf5hd7v6fr][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:40.754 DEBUG [Timer-9] #SIP#: NonInviteServerTransaction[_state=TERMINATED, _id=z9hG4bKPjxMaTJDGIBjYz3Degx6wDpZ3hGfgb0rBL] is released. #[tropo][sas_2-15-sm15unddnz5uzr0tropo][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][ss_1m3yf5hd7v6fr][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:40.755 DEBUG [Timer-10] #SIP#: Remove Path[ id=Of125BkyFSNm.lhnB9bJf1pk5KrI6osb-8dfZ9G6OnI5bmS-SxmhIVU2Lpb30Onyg-1igr7ga8f05d0, session=SipSessionImpl[_id=ss_1m3yf5hd7v6fr, _parentId=sas_2-15-sm15unddnz5uzr0tropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=true, _role=UAS, _method=REGISTER, _callId=Of125BkyFSNm.lhnB9bJf1pk5KrI6osb]] #[tropo][sas_2-15-sm15unddnz5uzr0tropo][Of125BkyFSNm.lhnB9bJf1pk5KrI6osb][ss_1m3yf5hd7v6fr][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:40.757 DEBUG [Timer-10] #SIP#: processInvalidationWhenReady [sas_2-15-sm15unddnz5uzr0tropo], invalidateWhenReady: true
2011-07-14 17:17:40.757 DEBUG [Timer-10] #SIP#: Container will automatically invalidate SipApplicationSession [sas_2-15-sm15unddnz5uzr0tropo]
2011-07-14 17:17:40.758 DEBUG [Timer-10] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-15-sm15unddnz5uzr0tropo] is invalidating. (as)
2011-07-14 17:17:46.989 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (i)[REGISTER sip:tropo-dev90 SIP/2.0\r\nTo: "usera" <sip:usera@tropo-dev90>\r\nExpires: 600\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport;branch=z9hG4bKPjXbwhkoKM.RPaPuaKQyyF-pCCU7KK5af-\r\nCSeq: 1 REGISTER\r\nContent-Length: 0\r\nCall-ID: tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j\r\nUser-Agent: Blink 0.24.0 (MacOSX)\r\nFrom: "usera" <sip:usera@tropo-dev90>;tag=OCczRS25eH1voiExjdhVqf3iEsf4A8GH\r\nMax-Forwards: 70\r\nContact: <sip:zsudcpij@3.3.3.11:59832>\r\n\r\n] #[N/A][N/A][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:46.991 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: The transaction was created: z9hG4bKPjXbwhkoKM.RPaPuaKQyyF-pCCU7KK5af- #[N/A][N/A][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:46.991 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Found [tropo] to handle the request by port mappings: 5060
2011-07-14 17:17:46.991 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationInfo: SipApplicationRouterInfo[ApplicationName=tropo, RouteModifier=NO_ROUTE, RouteRegion=null, SubscriberURI=sip:tropo-dev90, StateInfo=tropo] #[N/A][N/A][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:46.992 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-14-sm1sh6ms0kk6o3tropo] will expired after 7200000
2011-07-14 17:17:46.992 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session creating: ss_v7shtnldgguz #[tropo][sas_2-14-sm1sh6ms0kk6o3tropo][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][ss_v7shtnldgguz][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:46.993 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session created:SipSessionImpl[_id=ss_v7shtnldgguz, _parentId=sas_2-14-sm1sh6ms0kk6o3tropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UNKNOW, _method=REGISTER, _callId=tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j] #[tropo][sas_2-14-sm1sh6ms0kk6o3tropo][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][ss_v7shtnldgguz][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:46.993 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer recv request: REGISTER #[tropo][sas_2-14-sm1sh6ms0kk6o3tropo][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][ss_v7shtnldgguz][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:46.993 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ApplicationDispatchLayer invoke application: tropo with REGISTER #[tropo][sas_2-14-sm1sh6ms0kk6o3tropo][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][ss_v7shtnldgguz][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:46.993 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipServletWrapper[tropo, com.voxeo.tropo.SIPDriver] is forwarding. #[tropo][sas_2-14-sm1sh6ms0kk6o3tropo][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][ss_v7shtnldgguz][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:46.993 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer send response: REGISTER/500 #[tropo][sas_2-14-sm1sh6ms0kk6o3tropo][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][ss_v7shtnldgguz][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:46.994 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Add Path[ id=tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j-OCczRS25eH1voiExjdhVqf3iEsf4A8GH-vfvrsedco1u5, session=SipSessionImpl[_id=ss_v7shtnldgguz, _parentId=sas_2-14-sm1sh6ms0kk6o3tropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=REGISTER, _callId=tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j], party= CALLER] #[tropo][sas_2-14-sm1sh6ms0kk6o3tropo][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][ss_v7shtnldgguz][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:46.994 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (o)[SIP/2.0 500 Request not handled by app\r\nTo: usera <sip:usera@tropo-dev90>;tag=vfvrsedco1u5\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPjXbwhkoKM.RPaPuaKQyyF-pCCU7KK5af-;received=3.3.3.11\r\nCSeq: 1 REGISTER\r\nContent-Length: 0\r\nCall-ID: tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j\r\nFrom: usera <sip:usera@tropo-dev90>;tag=OCczRS25eH1voiExjdhVqf3iEsf4A8GH\r\n\r\n] #[tropo][sas_2-14-sm1sh6ms0kk6o3tropo][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][ss_v7shtnldgguz][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:46.995 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Send message to: /3.3.3.11:59832 by udp #[tropo][sas_2-14-sm1sh6ms0kk6o3tropo][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][ss_v7shtnldgguz][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:46.995 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Connected to 3.3.3.11:59832/udp #[tropo][sas_2-14-sm1sh6ms0kk6o3tropo][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][ss_v7shtnldgguz][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:46.995 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-sm1sh6ms0kk6o3tropo], invalidateWhenReady: true
2011-07-14 17:17:46.995 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_v7shtnldgguz], current State = INITIAL, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: true, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-14-sm1sh6ms0kk6o3tropo][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][ss_v7shtnldgguz][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:46.995 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-sm1sh6ms0kk6o3tropo], invalidateWhenReady: true
2011-07-14 17:17:46.996 INFO [udp/0.0.0.0/5060-t-4] Clearing logging context for udp/0.0.0.0/5060-t-4
2011-07-14 17:17:46.996 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-sm1sh6ms0kk6o3tropo], invalidateWhenReady: true
2011-07-14 17:17:46.996 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_v7shtnldgguz], current State = INITIAL, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-14-sm1sh6ms0kk6o3tropo][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][ss_v7shtnldgguz][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:17:46.996 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-sm1sh6ms0kk6o3tropo], invalidateWhenReady: true
2011-07-14 17:18:09.518 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (i)[SUBSCRIBE sip:usera@tropo-dev90 SIP/2.0\r\nTo: <sip:usera@tropo-dev90>\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport;branch=z9hG4bKPjXKDb8B90ayHe83wccEyFUX15ROPZ1T2K\r\nAccept: application/simple-message-summary\r\nCall-ID: JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H\r\nUser-Agent: Blink 0.24.0 (MacOSX)\r\nMax-Forwards: 70\r\nFrom: "usera" <sip:usera@tropo-dev90>;tag=Wb6NtbL2zRmfDA6U8JCDNleBsXGsYt4k\r\nContact: <sip:zsudcpij@3.3.3.11:59832>\r\nExpires: 3600\r\nCSeq: 13340 SUBSCRIBE\r\nEvent: message-summary\r\nContent-Length: 0\r\nAllow-Events: conference, message-summary, presence, presence.winfo, xcap-diff, refer\r\n\r\n] #[N/A][N/A][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.519 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: The transaction was created: z9hG4bKPjXKDb8B90ayHe83wccEyFUX15ROPZ1T2K #[N/A][N/A][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.519 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Found [tropo] to handle the request by port mappings: 5060
2011-07-14 17:18:09.519 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationInfo: SipApplicationRouterInfo[ApplicationName=tropo, RouteModifier=NO_ROUTE, RouteRegion=null, SubscriberURI=sip:usera@tropo-dev90, StateInfo=tropo] #[N/A][N/A][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.520 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-15-sm1nz6hlok7hsbatropo] will expired after 7200000
2011-07-14 17:18:09.520 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session creating: ss_6n7hiyu0oc11 #[tropo][sas_2-15-sm1nz6hlok7hsbatropo][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][ss_6n7hiyu0oc11][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.521 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session created:SipSessionImpl[_id=ss_6n7hiyu0oc11, _parentId=sas_2-15-sm1nz6hlok7hsbatropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UNKNOW, _method=SUBSCRIBE, _callId=JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H] #[tropo][sas_2-15-sm1nz6hlok7hsbatropo][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][ss_6n7hiyu0oc11][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.521 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer recv request: SUBSCRIBE #[tropo][sas_2-15-sm1nz6hlok7hsbatropo][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][ss_6n7hiyu0oc11][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.521 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ApplicationDispatchLayer invoke application: tropo with SUBSCRIBE #[tropo][sas_2-15-sm1nz6hlok7hsbatropo][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][ss_6n7hiyu0oc11][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.521 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipServletWrapper[tropo, com.voxeo.tropo.SIPDriver] is forwarding. #[tropo][sas_2-15-sm1nz6hlok7hsbatropo][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][ss_6n7hiyu0oc11][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.522 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer send response: SUBSCRIBE/500 #[tropo][sas_2-15-sm1nz6hlok7hsbatropo][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][ss_6n7hiyu0oc11][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.522 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Add Path[ id=JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H-Wb6NtbL2zRmfDA6U8JCDNleBsXGsYt4k-mrf6rjqwow6l, session=SipSessionImpl[_id=ss_6n7hiyu0oc11, _parentId=sas_2-15-sm1nz6hlok7hsbatropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=SUBSCRIBE, _callId=JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H], party= CALLER] #[tropo][sas_2-15-sm1nz6hlok7hsbatropo][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][ss_6n7hiyu0oc11][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.523 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (o)[SIP/2.0 500 Request not handled by app\r\nTo: <sip:usera@tropo-dev90>;tag=mrf6rjqwow6l\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPjXKDb8B90ayHe83wccEyFUX15ROPZ1T2K;received=3.3.3.11\r\nCSeq: 13340 SUBSCRIBE\r\nContent-Length: 0\r\nCall-ID: JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H\r\nFrom: usera <sip:usera@tropo-dev90>;tag=Wb6NtbL2zRmfDA6U8JCDNleBsXGsYt4k\r\n\r\n] #[tropo][sas_2-15-sm1nz6hlok7hsbatropo][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][ss_6n7hiyu0oc11][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.523 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Send message to: /3.3.3.11:59832 by udp #[tropo][sas_2-15-sm1nz6hlok7hsbatropo][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][ss_6n7hiyu0oc11][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.523 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Connected to 3.3.3.11:59832/udp #[tropo][sas_2-15-sm1nz6hlok7hsbatropo][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][ss_6n7hiyu0oc11][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.523 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm1nz6hlok7hsbatropo], invalidateWhenReady: true
2011-07-14 17:18:09.523 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_6n7hiyu0oc11], current State = TERMINATED, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: true, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-15-sm1nz6hlok7hsbatropo][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][ss_6n7hiyu0oc11][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.524 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-15-sm1nz6hlok7hsbatropo], invalidateWhenReady: true
2011-07-14 17:18:09.524 INFO [udp/0.0.0.0/5060-t-4] Clearing logging context for udp/0.0.0.0/5060-t-4
2011-07-14 17:18:09.524 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm1nz6hlok7hsbatropo], invalidateWhenReady: true
2011-07-14 17:18:09.524 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_6n7hiyu0oc11], current State = TERMINATED, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-15-sm1nz6hlok7hsbatropo][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][ss_6n7hiyu0oc11][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.524 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: server will automatically invalidate sipsession [ss_6n7hiyu0oc11] #[tropo][sas_2-15-sm1nz6hlok7hsbatropo][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][ss_6n7hiyu0oc11][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.525 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipSessionImpl[_id=ss_6n7hiyu0oc11, _parentId=sas_2-15-sm1nz6hlok7hsbatropo, _handler=tropo, _state=TERMINATED, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=SUBSCRIBE, _callId=JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H] is invalidating. (s) #[tropo][sas_2-15-sm1nz6hlok7hsbatropo][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][ss_6n7hiyu0oc11][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.525 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Remove Path[ id=JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H-Wb6NtbL2zRmfDA6U8JCDNleBsXGsYt4k-mrf6rjqwow6l, session=SipSessionImpl[_id=ss_6n7hiyu0oc11, _parentId=sas_2-15-sm1nz6hlok7hsbatropo, _handler=tropo, _state=TERMINATED, _fresh=false, _valid=true, _unavailable=true, _role=UAS, _method=SUBSCRIBE, _callId=JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H]] #[tropo][sas_2-15-sm1nz6hlok7hsbatropo][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][ss_6n7hiyu0oc11][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:09.526 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-15-sm1nz6hlok7hsbatropo], invalidateWhenReady: true
2011-07-14 17:18:09.526 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Container will automatically invalidate SipApplicationSession [sas_2-15-sm1nz6hlok7hsbatropo]
2011-07-14 17:18:09.526 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-15-sm1nz6hlok7hsbatropo] is invalidating. (as)
2011-07-14 17:18:18.996 DEBUG [Timer-12] #SIP#: SipSessionImpl[_id=ss_v7shtnldgguz, _parentId=sas_2-14-sm1sh6ms0kk6o3tropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=REGISTER, _callId=tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j] is invalidating. (s) #[tropo][sas_2-14-sm1sh6ms0kk6o3tropo][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][ss_v7shtnldgguz][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:18.996 DEBUG [Timer-11] #SIP#: NonInviteServerTransaction[_state=COMPLETED, _id=z9hG4bKPjXbwhkoKM.RPaPuaKQyyF-pCCU7KK5af-] timerRemoveTransaction is fired. #[tropo][sas_2-14-sm1sh6ms0kk6o3tropo][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][ss_v7shtnldgguz][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:19.001 DEBUG [Timer-11] #SIP#: NonInviteServerTransaction[_state=TERMINATED, _id=z9hG4bKPjXbwhkoKM.RPaPuaKQyyF-pCCU7KK5af-] is released. #[tropo][sas_2-14-sm1sh6ms0kk6o3tropo][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][ss_v7shtnldgguz][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:19.002 DEBUG [Timer-12] #SIP#: Remove Path[ id=tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j-OCczRS25eH1voiExjdhVqf3iEsf4A8GH-vfvrsedco1u5, session=SipSessionImpl[_id=ss_v7shtnldgguz, _parentId=sas_2-14-sm1sh6ms0kk6o3tropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=true, _role=UAS, _method=REGISTER, _callId=tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j]] #[tropo][sas_2-14-sm1sh6ms0kk6o3tropo][tdBqt5o54CHoPk3vNbJ2RZqKOyS2ob.j][ss_v7shtnldgguz][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:19.003 DEBUG [Timer-12] #SIP#: processInvalidationWhenReady [sas_2-14-sm1sh6ms0kk6o3tropo], invalidateWhenReady: true
2011-07-14 17:18:19.004 DEBUG [Timer-12] #SIP#: Container will automatically invalidate SipApplicationSession [sas_2-14-sm1sh6ms0kk6o3tropo]
2011-07-14 17:18:19.004 DEBUG [Timer-12] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-14-sm1sh6ms0kk6o3tropo] is invalidating. (as)
2011-07-14 17:18:23.693 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (i)[CANCEL sip:index.json@tropo-dev90.tropo-dev90 SIP/2.0\r\nTo: <sip:index.json@tropo-dev90.tropo-dev90>\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport;branch=z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7Bh\r\nCSeq: 32187 CANCEL\r\nContent-Length: 0\r\nCall-ID: TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy\r\nUser-Agent: Blink 0.24.0 (MacOSX)\r\nFrom: "usera" <sip:usera@tropo-dev90>;tag=0C53ZuMSLfhNJgJI5W7FnQGftDs4UEDW\r\nMax-Forwards: 70\r\n\r\n] #[N/A][N/A][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:23.695 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: The transaction was created: z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7BhCANCEL #[N/A][N/A][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:23.696 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (o)[SIP/2.0 200 OK\r\nTo: <sip:index.json@tropo-dev90.tropo-dev90>;tag=1k0an0d1ovqsn\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7Bh;received=3.3.3.11\r\nCSeq: 32187 CANCEL\r\nContent-Length: 0\r\nCall-ID: TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy\r\nFrom: usera <sip:usera@tropo-dev90>;tag=0C53ZuMSLfhNJgJI5W7FnQGftDs4UEDW\r\n\r\n] #[N/A][N/A][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][N/A][sip:index.json@tropo-dev90.tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:23.696 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Send message to: /3.3.3.11:59832 by udp #[N/A][N/A][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][N/A][sip:index.json@tropo-dev90.tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:23.696 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Connected to 3.3.3.11:59832/udp #[N/A][N/A][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][N/A][sip:index.json@tropo-dev90.tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:23.700 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer recv request: CANCEL #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:23.700 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer send response: INVITE/487 #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:23.701 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (o)[SIP/2.0 487 Request Terminated\r\nTo: <sip:index.json@tropo-dev90.tropo-dev90>;tag=1k0an0d1ovqsn\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7Bh;received=3.3.3.11\r\nCSeq: 32187 INVITE\r\nContent-Length: 0\r\nCall-ID: TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy\r\nFrom: usera <sip:usera@tropo-dev90>;tag=0C53ZuMSLfhNJgJI5W7FnQGftDs4UEDW\r\n\r\n] #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:23.701 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Send message to: /3.3.3.11:59832 by udp #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:23.701 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Connected to 3.3.3.11:59832/udp #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:23.702 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ApplicationDispatchLayer invoke application: tropo with CANCEL #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:23.702 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipServletWrapper[tropo, com.voxeo.tropo.SIPDriver] is forwarding. #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:23.702 DEBUG [udp/0.0.0.0/5060-t-4] doCancel: [CANCEL sip:index.json@tropo-dev90.tropo-dev90 SIP/2.0
To: <sip:index.json@tropo-dev90.tropo-dev90>
Via: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7Bh;received=3.3.3.11
CSeq: 32187 CANCEL
Content-Length: 0
Call-ID: TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy
User-Agent: Blink 0.24.0 (MacOSX)
From: usera <sip:usera@tropo-dev90>;tag=0C53ZuMSLfhNJgJI5W7FnQGftDs4UEDW
Max-Forwards: 70
]
2011-07-14 17:18:23.702 DEBUG [udp/0.0.0.0/5060-t-4] >>findCall() on ss_105g7dwsgh69g - TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy
2011-07-14 17:18:23.702 DEBUG [udp/0.0.0.0/5060-t-4] Found call a8abed480c18f4b6dbb319ff3ea557c1 from session 9c221bf4ccb979d32f9b6226b7aeb421
2011-07-14 17:18:23.702 DEBUG [udp/0.0.0.0/5060-t-4] SipApplicationSession sas_2-14-smlza5kmis8ff6tropo has Tropo session 9c221bf4ccb979d32f9b6226b7aeb421
2011-07-14 17:18:23.703 INFO [udp/0.0.0.0/5060-t-4] Set logging context for udp/0.0.0.0/5060-t-4 to accountID=0 host=tropo-dev90.jajah.dublin sessionGUID=-1 sessionNumber=9c221bf4ccb979d32f9b6226b7aeb421 callID=a8abed480c18f4b6dbb319ff3ea557c1
2011-07-14 17:18:23.703 DEBUG [udp/0.0.0.0/5060-t-4] doCANCEL find call: SimpleIncomingCall[usera/usera->index.json/null]
2011-07-14 17:18:23.703 DEBUG [udp/0.0.0.0/5060-t-4] SimpleIncomingCall[usera/usera->index.json/null] state is changed: RINGING->DISCONNECTED
2011-07-14 17:18:23.703 DEBUG [udp/0.0.0.0/5060-t-4] Call a8abed480c18f4b6dbb319ff3ea557c1 state changed from RINGING to DISCONNECTED on thread udp/0.0.0.0/5060-t-4
2011-07-14 17:18:23.703 DEBUG [udp/0.0.0.0/5060-t-4] Stopping MRCP
2011-07-14 17:18:23.703 DEBUG [udp/0.0.0.0/5060-t-4] MRCP stopped
2011-07-14 17:18:23.703 DEBUG [udp/0.0.0.0/5060-t-4] Disconnect processed
2011-07-14 17:18:23.703 INFO [udp/0.0.0.0/5060-t-4] Clearing logging context for udp/0.0.0.0/5060-t-4
2011-07-14 17:18:23.703 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-smlza5kmis8ff6tropo], invalidateWhenReady: false
2011-07-14 17:18:23.704 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_105g7dwsgh69g], current State = TERMINATED, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:23.704 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: server will automatically invalidate sipsession [ss_105g7dwsgh69g] #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:23.704 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipSessionImpl[_id=ss_105g7dwsgh69g, _parentId=sas_2-14-smlza5kmis8ff6tropo, _handler=tropo, _state=TERMINATED, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=INVITE, _callId=TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy] is invalidating. (s) #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:23.704 WARN [udp/0.0.0.0/5060-t-4] Attribute com.voxeo.tropo.core.call.inst removed from Sip Session ss_105g7dwsgh69g in state TERMINATED
2011-07-14 17:18:23.705 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Remove Path[ id=TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy-0C53ZuMSLfhNJgJI5W7FnQGftDs4UEDW-1k0an0d1ovqsn, session=SipSessionImpl[_id=ss_105g7dwsgh69g, _parentId=sas_2-14-smlza5kmis8ff6tropo, _handler=tropo, _state=TERMINATED, _fresh=false, _valid=true, _unavailable=true, _role=UAS, _method=INVITE, _callId=TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy]] #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:23.706 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-smlza5kmis8ff6tropo], invalidateWhenReady: false
2011-07-14 17:18:23.735 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (i)[ACK sip:index.json@tropo-dev90.tropo-dev90 SIP/2.0\r\nTo: <sip:index.json@tropo-dev90.tropo-dev90>;tag=1k0an0d1ovqsn\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport;branch=z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7Bh\r\nCSeq: 32187 ACK\r\nContent-Length: 0\r\nCall-ID: TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy\r\nUser-Agent: Blink 0.24.0 (MacOSX)\r\nFrom: "usera" <sip:usera@tropo-dev90>;tag=0C53ZuMSLfhNJgJI5W7FnQGftDs4UEDW\r\nMax-Forwards: 70\r\n\r\n] #[N/A][N/A][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:26.088 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (i)[REGISTER sip:tropo-dev90 SIP/2.0\r\nTo: "usera" <sip:usera@tropo-dev90>\r\nExpires: 600\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport;branch=z9hG4bKPj-2X9nWdQ-VY7dut.bG4obfgP.EfMcimJ\r\nCSeq: 1 REGISTER\r\nContent-Length: 0\r\nCall-ID: c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b\r\nUser-Agent: Blink 0.24.0 (MacOSX)\r\nFrom: "usera" <sip:usera@tropo-dev90>;tag=xeHWfSa4BccXYN8bItkMm6EagbrCsrD1\r\nMax-Forwards: 70\r\nContact: <sip:zsudcpij@3.3.3.11:59832>\r\n\r\n] #[N/A][N/A][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:26.089 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: The transaction was created: z9hG4bKPj-2X9nWdQ-VY7dut.bG4obfgP.EfMcimJ #[N/A][N/A][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:26.089 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Found [tropo] to handle the request by port mappings: 5060
2011-07-14 17:18:26.089 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationInfo: SipApplicationRouterInfo[ApplicationName=tropo, RouteModifier=NO_ROUTE, RouteRegion=null, SubscriberURI=sip:tropo-dev90, StateInfo=tropo] #[N/A][N/A][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:26.089 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-15-sm16iwpqvcku5zptropo] will expired after 7200000
2011-07-14 17:18:26.090 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session creating: ss_s1rancjzncqf #[tropo][sas_2-15-sm16iwpqvcku5zptropo][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][ss_s1rancjzncqf][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:26.090 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session created:SipSessionImpl[_id=ss_s1rancjzncqf, _parentId=sas_2-15-sm16iwpqvcku5zptropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UNKNOW, _method=REGISTER, _callId=c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b] #[tropo][sas_2-15-sm16iwpqvcku5zptropo][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][ss_s1rancjzncqf][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:26.090 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer recv request: REGISTER #[tropo][sas_2-15-sm16iwpqvcku5zptropo][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][ss_s1rancjzncqf][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:26.091 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ApplicationDispatchLayer invoke application: tropo with REGISTER #[tropo][sas_2-15-sm16iwpqvcku5zptropo][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][ss_s1rancjzncqf][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:26.091 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipServletWrapper[tropo, com.voxeo.tropo.SIPDriver] is forwarding. #[tropo][sas_2-15-sm16iwpqvcku5zptropo][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][ss_s1rancjzncqf][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:26.091 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer send response: REGISTER/500 #[tropo][sas_2-15-sm16iwpqvcku5zptropo][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][ss_s1rancjzncqf][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:26.092 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Add Path[ id=c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b-xeHWfSa4BccXYN8bItkMm6EagbrCsrD1-bcco6g4nh527, session=SipSessionImpl[_id=ss_s1rancjzncqf, _parentId=sas_2-15-sm16iwpqvcku5zptropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=REGISTER, _callId=c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b], party= CALLER] #[tropo][sas_2-15-sm16iwpqvcku5zptropo][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][ss_s1rancjzncqf][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:26.092 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (o)[SIP/2.0 500 Request not handled by app\r\nTo: usera <sip:usera@tropo-dev90>;tag=bcco6g4nh527\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPj-2X9nWdQ-VY7dut.bG4obfgP.EfMcimJ;received=3.3.3.11\r\nCSeq: 1 REGISTER\r\nContent-Length: 0\r\nCall-ID: c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b\r\nFrom: usera <sip:usera@tropo-dev90>;tag=xeHWfSa4BccXYN8bItkMm6EagbrCsrD1\r\n\r\n] #[tropo][sas_2-15-sm16iwpqvcku5zptropo][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][ss_s1rancjzncqf][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:26.092 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Send message to: /3.3.3.11:59832 by udp #[tropo][sas_2-15-sm16iwpqvcku5zptropo][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][ss_s1rancjzncqf][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:26.093 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Connected to 3.3.3.11:59832/udp #[tropo][sas_2-15-sm16iwpqvcku5zptropo][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][ss_s1rancjzncqf][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:26.093 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm16iwpqvcku5zptropo], invalidateWhenReady: true
2011-07-14 17:18:26.093 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_s1rancjzncqf], current State = INITIAL, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: true, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-15-sm16iwpqvcku5zptropo][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][ss_s1rancjzncqf][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:26.093 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-15-sm16iwpqvcku5zptropo], invalidateWhenReady: true
2011-07-14 17:18:26.093 INFO [udp/0.0.0.0/5060-t-4] Clearing logging context for udp/0.0.0.0/5060-t-4
2011-07-14 17:18:26.093 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm16iwpqvcku5zptropo], invalidateWhenReady: true
2011-07-14 17:18:26.093 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_s1rancjzncqf], current State = INITIAL, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-15-sm16iwpqvcku5zptropo][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][ss_s1rancjzncqf][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:26.094 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-15-sm16iwpqvcku5zptropo], invalidateWhenReady: true
2011-07-14 17:18:28.737 DEBUG [Timer-11] #SIP#: InviteServerTransaction[_state=CONFIRMED, _id=z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7Bh] timerRemoveTransaction is fired. #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:28.738 DEBUG [Timer-11] #SIP#: InviteServerTransaction[_state=TERMINATED, _id=z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7Bh] is released. #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:37.701 INFO [ApplicationMonitor] Starts loop detection.
2011-07-14 17:18:37.703 INFO [ApplicationMonitor] Ends loop detection.
2011-07-14 17:18:41.524 DEBUG [Timer-13] #SIP#: NonInviteServerTransaction[_state=COMPLETED, _id=z9hG4bKPjXKDb8B90ayHe83wccEyFUX15ROPZ1T2K] timerRemoveTransaction is fired. #[tropo][sas_2-15-sm1nz6hlok7hsbatropo][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][ss_6n7hiyu0oc11][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:41.525 DEBUG [Timer-13] #SIP#: NonInviteServerTransaction[_state=TERMINATED, _id=z9hG4bKPjXKDb8B90ayHe83wccEyFUX15ROPZ1T2K] is released. #[tropo][sas_2-15-sm1nz6hlok7hsbatropo][JF0DQpyAHTTWPY6HfROhxuKPwZwLqr2H][ss_6n7hiyu0oc11][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:55.698 DEBUG [Timer-8] #SIP#: NonInviteServerTransaction[_state=COMPLETED, _id=z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7BhCANCEL] timerRemoveTransaction is fired. #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:55.698 DEBUG [Timer-8] #SIP#: NonInviteServerTransaction[_state=TERMINATED, _id=z9hG4bKPjQPJYgGNYZRrsn0zowshB6.reEGvej7BhCANCEL] is released. #[tropo][sas_2-14-smlza5kmis8ff6tropo][TuKcF7lHPjTeOF5EGFCcd6LRj6qx6Mxy][ss_105g7dwsgh69g][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:index.json@tropo-dev90.tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:58.095 DEBUG [Timer-13] #SIP#: SipSessionImpl[_id=ss_s1rancjzncqf, _parentId=sas_2-15-sm16iwpqvcku5zptropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=REGISTER, _callId=c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b] is invalidating. (s) #[tropo][sas_2-15-sm16iwpqvcku5zptropo][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][ss_s1rancjzncqf][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:58.096 DEBUG [Timer-13] #SIP#: Remove Path[ id=c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b-xeHWfSa4BccXYN8bItkMm6EagbrCsrD1-bcco6g4nh527, session=SipSessionImpl[_id=ss_s1rancjzncqf, _parentId=sas_2-15-sm16iwpqvcku5zptropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=true, _role=UAS, _method=REGISTER, _callId=c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b]] #[tropo][sas_2-15-sm16iwpqvcku5zptropo][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][ss_s1rancjzncqf][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:58.098 DEBUG [Timer-13] #SIP#: processInvalidationWhenReady [sas_2-15-sm16iwpqvcku5zptropo], invalidateWhenReady: true
2011-07-14 17:18:58.098 DEBUG [Timer-13] #SIP#: Container will automatically invalidate SipApplicationSession [sas_2-15-sm16iwpqvcku5zptropo]
2011-07-14 17:18:58.099 DEBUG [Timer-12] #SIP#: NonInviteServerTransaction[_state=COMPLETED, _id=z9hG4bKPj-2X9nWdQ-VY7dut.bG4obfgP.EfMcimJ] timerRemoveTransaction is fired. #[tropo][sas_2-15-sm16iwpqvcku5zptropo][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][ss_s1rancjzncqf][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:18:58.099 DEBUG [Timer-13] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-15-sm16iwpqvcku5zptropo] is invalidating. (as)
2011-07-14 17:18:58.100 DEBUG [Timer-12] #SIP#: NonInviteServerTransaction[_state=TERMINATED, _id=z9hG4bKPj-2X9nWdQ-VY7dut.bG4obfgP.EfMcimJ] is released. #[tropo][sas_2-15-sm16iwpqvcku5zptropo][c03AeOyuIxBIm4uaiN.7S4Zeo.NBaU2b][ss_s1rancjzncqf][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:24.043 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (i)[REGISTER sip:tropo-dev90 SIP/2.0\r\nTo: "usera" <sip:usera@tropo-dev90>\r\nExpires: 600\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport;branch=z9hG4bKPj5USIS5y4csy5dQ2N-.dvsCwrWyB8ZBUx\r\nCSeq: 1 REGISTER\r\nContent-Length: 0\r\nCall-ID: wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR\r\nUser-Agent: Blink 0.24.0 (MacOSX)\r\nFrom: "usera" <sip:usera@tropo-dev90>;tag=E855TU3d40A2MuqDUJmVGk9Qq5EK16Ue\r\nMax-Forwards: 70\r\nContact: <sip:zsudcpij@3.3.3.11:59832>\r\n\r\n] #[N/A][N/A][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:24.044 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: The transaction was created: z9hG4bKPj5USIS5y4csy5dQ2N-.dvsCwrWyB8ZBUx #[N/A][N/A][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:24.044 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Found [tropo] to handle the request by port mappings: 5060
2011-07-14 17:19:24.044 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationInfo: SipApplicationRouterInfo[ApplicationName=tropo, RouteModifier=NO_ROUTE, RouteRegion=null, SubscriberURI=sip:tropo-dev90, StateInfo=tropo] #[N/A][N/A][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:24.044 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-15-sm15f3la17511detropo] will expired after 7200000
2011-07-14 17:19:24.045 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session creating: ss_1t7kh5j27jfxd #[tropo][sas_2-15-sm15f3la17511detropo][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][ss_1t7kh5j27jfxd][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:24.045 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session created:SipSessionImpl[_id=ss_1t7kh5j27jfxd, _parentId=sas_2-15-sm15f3la17511detropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UNKNOW, _method=REGISTER, _callId=wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR] #[tropo][sas_2-15-sm15f3la17511detropo][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][ss_1t7kh5j27jfxd][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:24.045 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer recv request: REGISTER #[tropo][sas_2-15-sm15f3la17511detropo][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][ss_1t7kh5j27jfxd][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:24.046 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ApplicationDispatchLayer invoke application: tropo with REGISTER #[tropo][sas_2-15-sm15f3la17511detropo][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][ss_1t7kh5j27jfxd][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:24.046 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipServletWrapper[tropo, com.voxeo.tropo.SIPDriver] is forwarding. #[tropo][sas_2-15-sm15f3la17511detropo][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][ss_1t7kh5j27jfxd][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:24.046 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer send response: REGISTER/500 #[tropo][sas_2-15-sm15f3la17511detropo][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][ss_1t7kh5j27jfxd][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:24.047 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Add Path[ id=wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR-E855TU3d40A2MuqDUJmVGk9Qq5EK16Ue-1dln8yrj1u0cv, session=SipSessionImpl[_id=ss_1t7kh5j27jfxd, _parentId=sas_2-15-sm15f3la17511detropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=REGISTER, _callId=wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR], party= CALLER] #[tropo][sas_2-15-sm15f3la17511detropo][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][ss_1t7kh5j27jfxd][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:24.047 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (o)[SIP/2.0 500 Request not handled by app\r\nTo: usera <sip:usera@tropo-dev90>;tag=1dln8yrj1u0cv\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPj5USIS5y4csy5dQ2N-.dvsCwrWyB8ZBUx;received=3.3.3.11\r\nCSeq: 1 REGISTER\r\nContent-Length: 0\r\nCall-ID: wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR\r\nFrom: usera <sip:usera@tropo-dev90>;tag=E855TU3d40A2MuqDUJmVGk9Qq5EK16Ue\r\n\r\n] #[tropo][sas_2-15-sm15f3la17511detropo][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][ss_1t7kh5j27jfxd][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:24.047 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Send message to: /3.3.3.11:59832 by udp #[tropo][sas_2-15-sm15f3la17511detropo][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][ss_1t7kh5j27jfxd][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:24.047 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Connected to 3.3.3.11:59832/udp #[tropo][sas_2-15-sm15f3la17511detropo][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][ss_1t7kh5j27jfxd][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:24.048 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm15f3la17511detropo], invalidateWhenReady: true
2011-07-14 17:19:24.048 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_1t7kh5j27jfxd], current State = INITIAL, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: true, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-15-sm15f3la17511detropo][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][ss_1t7kh5j27jfxd][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:24.048 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-15-sm15f3la17511detropo], invalidateWhenReady: true
2011-07-14 17:19:24.048 INFO [udp/0.0.0.0/5060-t-4] Clearing logging context for udp/0.0.0.0/5060-t-4
2011-07-14 17:19:24.048 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm15f3la17511detropo], invalidateWhenReady: true
2011-07-14 17:19:24.048 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_1t7kh5j27jfxd], current State = INITIAL, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-15-sm15f3la17511detropo][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][ss_1t7kh5j27jfxd][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:24.048 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-15-sm15f3la17511detropo], invalidateWhenReady: true
2011-07-14 17:19:56.049 DEBUG [Timer-8] #SIP#: NonInviteServerTransaction[_state=COMPLETED, _id=z9hG4bKPj5USIS5y4csy5dQ2N-.dvsCwrWyB8ZBUx] timerRemoveTransaction is fired. #[tropo][sas_2-15-sm15f3la17511detropo][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][ss_1t7kh5j27jfxd][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:56.051 DEBUG [Timer-9] #SIP#: SipSessionImpl[_id=ss_1t7kh5j27jfxd, _parentId=sas_2-15-sm15f3la17511detropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=REGISTER, _callId=wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR] is invalidating. (s) #[tropo][sas_2-15-sm15f3la17511detropo][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][ss_1t7kh5j27jfxd][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:56.052 DEBUG [Timer-8] #SIP#: NonInviteServerTransaction[_state=TERMINATED, _id=z9hG4bKPj5USIS5y4csy5dQ2N-.dvsCwrWyB8ZBUx] is released. #[tropo][sas_2-15-sm15f3la17511detropo][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][ss_1t7kh5j27jfxd][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:56.052 DEBUG [Timer-9] #SIP#: Remove Path[ id=wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR-E855TU3d40A2MuqDUJmVGk9Qq5EK16Ue-1dln8yrj1u0cv, session=SipSessionImpl[_id=ss_1t7kh5j27jfxd, _parentId=sas_2-15-sm15f3la17511detropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=true, _role=UAS, _method=REGISTER, _callId=wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR]] #[tropo][sas_2-15-sm15f3la17511detropo][wbKO8OLfWMkhn266Up3rmLM7jNo3EaZR][ss_1t7kh5j27jfxd][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:19:56.170 DEBUG [Timer-9] #SIP#: processInvalidationWhenReady [sas_2-15-sm15f3la17511detropo], invalidateWhenReady: true
2011-07-14 17:19:56.170 DEBUG [Timer-9] #SIP#: Container will automatically invalidate SipApplicationSession [sas_2-15-sm15f3la17511detropo]
2011-07-14 17:19:56.170 DEBUG [Timer-9] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-15-sm15f3la17511detropo] is invalidating. (as)
2011-07-14 17:20:02.734 DEBUG [Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421] Thread Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421 returned engine of type tropo-web, activeEngines = 0
2011-07-14 17:20:02.736 ERROR [Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421] ApplicationInstance[http://212.179.159.107/proxy/index.json, sas_2-14-smlza5kmis8ff6tropo] has unknown errors: Connection to http://212.179.159.107 refused
org.apache.http.conn.HttpHostConnectException: Connection to http://212.179.159.107 refused
at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:127)
at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:147)
at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:101)
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:381)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:641)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:576)
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 org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite$PojoCachedMethodSiteNoUnwrapNoCoerce.invoke(PojoMetaMethodSite.java:229)
at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite.call(PojoMetaMethodSite.java:52)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:129)
at com.tropo.rest.SimpleFetcher.fetch(SimpleFetcher.groovy:69)
at com.tropo.rest.Fetcher$fetch$0.callCurrent(Unknown Source)
at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallCurrent(CallSiteArray.java:44)
at com.tropo.rest.Fetcher$fetch$0.callCurrent(Unknown Source)
at com.tropo.rest.SimpleFetcher.fetch(SimpleFetcher.groovy:50)
at com.tropo.rest.Fetcher$fetch.call(Unknown Source)
at com.tropo.rest.Dialog.process(Dialog.groovy:45)
at com.tropo.rest.engine.TropoScriptEngine.eval(TropoScriptEngine.java:55)
at com.voxeo.tropo.app.SimulatedCompiledScript.eval(SimulatedCompiledScript.java:59)
at com.voxeo.tropo.app.SimpleInstance.evaluateScript(SimpleInstance.java:243)
at com.voxeo.tropo.app.SimpleInstance.run(SimpleInstance.java:219)
at com.voxeo.tropo.app.AbstractLocalApplicationManager$1.run(AbstractLocalApplicationManager.java:179)
at java.lang.Thread.run(Thread.java:619)
Caused by: java.net.ConnectException: Connection timed out
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333)
at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195)
at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
at java.net.Socket.connect(Socket.java:525)
at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:123)
at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:123)
... 25 more
2011-07-14 17:20:02.859 DEBUG [Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-14-smlza5kmis8ff6tropo] is invalidating. (as)
2011-07-14 17:20:02.860 WARN [Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421] Instance 9c221bf4ccb979d32f9b6226b7aeb421 removed
2011-07-14 17:20:02.861 INFO [Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421] Clearing logging context for Tropo-Thread-9c221bf4ccb979d32f9b6226b7aeb421
2011-07-14 17:20:20.960 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (i)[REGISTER sip:tropo-dev90 SIP/2.0\r\nTo: "usera" <sip:usera@tropo-dev90>\r\nExpires: 600\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport;branch=z9hG4bKPjjB-QfUGIMVnKWS7K2c1xQ-oPvcc2TKgD\r\nCSeq: 1 REGISTER\r\nContent-Length: 0\r\nCall-ID: 10npBLU6ROlQfsbBaZQspEUxzpuuO7mA\r\nUser-Agent: Blink 0.24.0 (MacOSX)\r\nFrom: "usera" <sip:usera@tropo-dev90>;tag=yHJyW65-eohxc5c6zmkkIVEX-9mFPryI\r\nMax-Forwards: 70\r\nContact: <sip:zsudcpij@3.3.3.11:59832>\r\n\r\n] #[N/A][N/A][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:20.960 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: The transaction was created: z9hG4bKPjjB-QfUGIMVnKWS7K2c1xQ-oPvcc2TKgD #[N/A][N/A][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:20.961 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Found [tropo] to handle the request by port mappings: 5060
2011-07-14 17:20:20.961 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationInfo: SipApplicationRouterInfo[ApplicationName=tropo, RouteModifier=NO_ROUTE, RouteRegion=null, SubscriberURI=sip:tropo-dev90, StateInfo=tropo] #[N/A][N/A][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:20.961 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-14-sm365xr6cesi98tropo] will expired after 7200000
2011-07-14 17:20:20.961 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session creating: ss_3s3gjoy2w7wo #[tropo][sas_2-14-sm365xr6cesi98tropo][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][ss_3s3gjoy2w7wo][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:20.962 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session created:SipSessionImpl[_id=ss_3s3gjoy2w7wo, _parentId=sas_2-14-sm365xr6cesi98tropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UNKNOW, _method=REGISTER, _callId=10npBLU6ROlQfsbBaZQspEUxzpuuO7mA] #[tropo][sas_2-14-sm365xr6cesi98tropo][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][ss_3s3gjoy2w7wo][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:20.962 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer recv request: REGISTER #[tropo][sas_2-14-sm365xr6cesi98tropo][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][ss_3s3gjoy2w7wo][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:20.962 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ApplicationDispatchLayer invoke application: tropo with REGISTER #[tropo][sas_2-14-sm365xr6cesi98tropo][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][ss_3s3gjoy2w7wo][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:20.962 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipServletWrapper[tropo, com.voxeo.tropo.SIPDriver] is forwarding. #[tropo][sas_2-14-sm365xr6cesi98tropo][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][ss_3s3gjoy2w7wo][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:20.963 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer send response: REGISTER/500 #[tropo][sas_2-14-sm365xr6cesi98tropo][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][ss_3s3gjoy2w7wo][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:20.963 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Add Path[ id=10npBLU6ROlQfsbBaZQspEUxzpuuO7mA-yHJyW65-eohxc5c6zmkkIVEX-9mFPryI-ezsj3j7m1wod, session=SipSessionImpl[_id=ss_3s3gjoy2w7wo, _parentId=sas_2-14-sm365xr6cesi98tropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=REGISTER, _callId=10npBLU6ROlQfsbBaZQspEUxzpuuO7mA], party= CALLER] #[tropo][sas_2-14-sm365xr6cesi98tropo][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][ss_3s3gjoy2w7wo][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:20.964 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (o)[SIP/2.0 500 Request not handled by app\r\nTo: usera <sip:usera@tropo-dev90>;tag=ezsj3j7m1wod\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPjjB-QfUGIMVnKWS7K2c1xQ-oPvcc2TKgD;received=3.3.3.11\r\nCSeq: 1 REGISTER\r\nContent-Length: 0\r\nCall-ID: 10npBLU6ROlQfsbBaZQspEUxzpuuO7mA\r\nFrom: usera <sip:usera@tropo-dev90>;tag=yHJyW65-eohxc5c6zmkkIVEX-9mFPryI\r\n\r\n] #[tropo][sas_2-14-sm365xr6cesi98tropo][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][ss_3s3gjoy2w7wo][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:20.964 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Send message to: /3.3.3.11:59832 by udp #[tropo][sas_2-14-sm365xr6cesi98tropo][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][ss_3s3gjoy2w7wo][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:20.964 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Connected to 3.3.3.11:59832/udp #[tropo][sas_2-14-sm365xr6cesi98tropo][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][ss_3s3gjoy2w7wo][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:20.964 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-sm365xr6cesi98tropo], invalidateWhenReady: true
2011-07-14 17:20:20.965 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_3s3gjoy2w7wo], current State = INITIAL, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: true, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-14-sm365xr6cesi98tropo][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][ss_3s3gjoy2w7wo][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:20.965 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-sm365xr6cesi98tropo], invalidateWhenReady: true
2011-07-14 17:20:20.965 INFO [udp/0.0.0.0/5060-t-4] Clearing logging context for udp/0.0.0.0/5060-t-4
2011-07-14 17:20:20.965 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-sm365xr6cesi98tropo], invalidateWhenReady: true
2011-07-14 17:20:20.965 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_3s3gjoy2w7wo], current State = INITIAL, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-14-sm365xr6cesi98tropo][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][ss_3s3gjoy2w7wo][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:20.965 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-sm365xr6cesi98tropo], invalidateWhenReady: true
2011-07-14 17:20:37.707 INFO [ApplicationMonitor] Starts loop detection.
2011-07-14 17:20:37.710 INFO [ApplicationMonitor] Ends loop detection.
2011-07-14 17:20:50.968 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (i)[SUBSCRIBE sip:usera@tropo-dev90 SIP/2.0\r\nTo: <sip:usera@tropo-dev90>\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport;branch=z9hG4bKPjQ2S2ZMhSbBZ0TCB56vD4OAqdPhb0Ilr8\r\nAccept: application/simple-message-summary\r\nCall-ID: 2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb\r\nUser-Agent: Blink 0.24.0 (MacOSX)\r\nMax-Forwards: 70\r\nFrom: "usera" <sip:usera@tropo-dev90>;tag=-9347ogSPF8xkUjWWiCltvhMU463mGUj\r\nContact: <sip:zsudcpij@3.3.3.11:59832>\r\nExpires: 3600\r\nCSeq: 21888 SUBSCRIBE\r\nEvent: message-summary\r\nContent-Length: 0\r\nAllow-Events: conference, message-summary, presence, presence.winfo, xcap-diff, refer\r\n\r\n] #[N/A][N/A][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.969 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: The transaction was created: z9hG4bKPjQ2S2ZMhSbBZ0TCB56vD4OAqdPhb0Ilr8 #[N/A][N/A][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.969 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Found [tropo] to handle the request by port mappings: 5060
2011-07-14 17:20:50.969 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationInfo: SipApplicationRouterInfo[ApplicationName=tropo, RouteModifier=NO_ROUTE, RouteRegion=null, SubscriberURI=sip:usera@tropo-dev90, StateInfo=tropo] #[N/A][N/A][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.970 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-14-sm5qpnn4s1p4rptropo] will expired after 7200000
2011-07-14 17:20:50.970 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session creating: ss_n2u0hw8pvmc8 #[tropo][sas_2-14-sm5qpnn4s1p4rptropo][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][ss_n2u0hw8pvmc8][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.970 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session created:SipSessionImpl[_id=ss_n2u0hw8pvmc8, _parentId=sas_2-14-sm5qpnn4s1p4rptropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UNKNOW, _method=SUBSCRIBE, _callId=2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb] #[tropo][sas_2-14-sm5qpnn4s1p4rptropo][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][ss_n2u0hw8pvmc8][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.971 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer recv request: SUBSCRIBE #[tropo][sas_2-14-sm5qpnn4s1p4rptropo][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][ss_n2u0hw8pvmc8][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.971 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ApplicationDispatchLayer invoke application: tropo with SUBSCRIBE #[tropo][sas_2-14-sm5qpnn4s1p4rptropo][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][ss_n2u0hw8pvmc8][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.971 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipServletWrapper[tropo, com.voxeo.tropo.SIPDriver] is forwarding. #[tropo][sas_2-14-sm5qpnn4s1p4rptropo][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][ss_n2u0hw8pvmc8][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.971 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer send response: SUBSCRIBE/500 #[tropo][sas_2-14-sm5qpnn4s1p4rptropo][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][ss_n2u0hw8pvmc8][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.972 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Add Path[ id=2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb--9347ogSPF8xkUjWWiCltvhMU463mGUj-1dwszxpwatuw8, session=SipSessionImpl[_id=ss_n2u0hw8pvmc8, _parentId=sas_2-14-sm5qpnn4s1p4rptropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=SUBSCRIBE, _callId=2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb], party= CALLER] #[tropo][sas_2-14-sm5qpnn4s1p4rptropo][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][ss_n2u0hw8pvmc8][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.972 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (o)[SIP/2.0 500 Request not handled by app\r\nTo: <sip:usera@tropo-dev90>;tag=1dwszxpwatuw8\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPjQ2S2ZMhSbBZ0TCB56vD4OAqdPhb0Ilr8;received=3.3.3.11\r\nCSeq: 21888 SUBSCRIBE\r\nContent-Length: 0\r\nCall-ID: 2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb\r\nFrom: usera <sip:usera@tropo-dev90>;tag=-9347ogSPF8xkUjWWiCltvhMU463mGUj\r\n\r\n] #[tropo][sas_2-14-sm5qpnn4s1p4rptropo][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][ss_n2u0hw8pvmc8][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.972 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Send message to: /3.3.3.11:59832 by udp #[tropo][sas_2-14-sm5qpnn4s1p4rptropo][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][ss_n2u0hw8pvmc8][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.973 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Connected to 3.3.3.11:59832/udp #[tropo][sas_2-14-sm5qpnn4s1p4rptropo][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][ss_n2u0hw8pvmc8][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.973 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-sm5qpnn4s1p4rptropo], invalidateWhenReady: true
2011-07-14 17:20:50.973 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_n2u0hw8pvmc8], current State = TERMINATED, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: true, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-14-sm5qpnn4s1p4rptropo][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][ss_n2u0hw8pvmc8][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.973 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-sm5qpnn4s1p4rptropo], invalidateWhenReady: true
2011-07-14 17:20:50.973 INFO [udp/0.0.0.0/5060-t-4] Clearing logging context for udp/0.0.0.0/5060-t-4
2011-07-14 17:20:50.973 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-sm5qpnn4s1p4rptropo], invalidateWhenReady: true
2011-07-14 17:20:50.973 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_n2u0hw8pvmc8], current State = TERMINATED, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-14-sm5qpnn4s1p4rptropo][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][ss_n2u0hw8pvmc8][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.974 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: server will automatically invalidate sipsession [ss_n2u0hw8pvmc8] #[tropo][sas_2-14-sm5qpnn4s1p4rptropo][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][ss_n2u0hw8pvmc8][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.974 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipSessionImpl[_id=ss_n2u0hw8pvmc8, _parentId=sas_2-14-sm5qpnn4s1p4rptropo, _handler=tropo, _state=TERMINATED, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=SUBSCRIBE, _callId=2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb] is invalidating. (s) #[tropo][sas_2-14-sm5qpnn4s1p4rptropo][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][ss_n2u0hw8pvmc8][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.975 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Remove Path[ id=2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb--9347ogSPF8xkUjWWiCltvhMU463mGUj-1dwszxpwatuw8, session=SipSessionImpl[_id=ss_n2u0hw8pvmc8, _parentId=sas_2-14-sm5qpnn4s1p4rptropo, _handler=tropo, _state=TERMINATED, _fresh=false, _valid=true, _unavailable=true, _role=UAS, _method=SUBSCRIBE, _callId=2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb]] #[tropo][sas_2-14-sm5qpnn4s1p4rptropo][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][ss_n2u0hw8pvmc8][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:50.975 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-sm5qpnn4s1p4rptropo], invalidateWhenReady: true
2011-07-14 17:20:50.975 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Container will automatically invalidate SipApplicationSession [sas_2-14-sm5qpnn4s1p4rptropo]
2011-07-14 17:20:50.975 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-14-sm5qpnn4s1p4rptropo] is invalidating. (as)
2011-07-14 17:20:52.967 DEBUG [Timer-11] #SIP#: SipSessionImpl[_id=ss_3s3gjoy2w7wo, _parentId=sas_2-14-sm365xr6cesi98tropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=REGISTER, _callId=10npBLU6ROlQfsbBaZQspEUxzpuuO7mA] is invalidating. (s) #[tropo][sas_2-14-sm365xr6cesi98tropo][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][ss_3s3gjoy2w7wo][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:52.969 DEBUG [Timer-10] #SIP#: NonInviteServerTransaction[_state=COMPLETED, _id=z9hG4bKPjjB-QfUGIMVnKWS7K2c1xQ-oPvcc2TKgD] timerRemoveTransaction is fired. #[tropo][sas_2-14-sm365xr6cesi98tropo][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][ss_3s3gjoy2w7wo][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:52.969 DEBUG [Timer-11] #SIP#: Remove Path[ id=10npBLU6ROlQfsbBaZQspEUxzpuuO7mA-yHJyW65-eohxc5c6zmkkIVEX-9mFPryI-ezsj3j7m1wod, session=SipSessionImpl[_id=ss_3s3gjoy2w7wo, _parentId=sas_2-14-sm365xr6cesi98tropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=true, _role=UAS, _method=REGISTER, _callId=10npBLU6ROlQfsbBaZQspEUxzpuuO7mA]] #[tropo][sas_2-14-sm365xr6cesi98tropo][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][ss_3s3gjoy2w7wo][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:52.970 DEBUG [Timer-10] #SIP#: NonInviteServerTransaction[_state=TERMINATED, _id=z9hG4bKPjjB-QfUGIMVnKWS7K2c1xQ-oPvcc2TKgD] is released. #[tropo][sas_2-14-sm365xr6cesi98tropo][10npBLU6ROlQfsbBaZQspEUxzpuuO7mA][ss_3s3gjoy2w7wo][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:20:52.970 DEBUG [Timer-11] #SIP#: processInvalidationWhenReady [sas_2-14-sm365xr6cesi98tropo], invalidateWhenReady: true
2011-07-14 17:20:52.971 DEBUG [Timer-11] #SIP#: Container will automatically invalidate SipApplicationSession [sas_2-14-sm365xr6cesi98tropo]
2011-07-14 17:20:52.972 DEBUG [Timer-11] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-14-sm365xr6cesi98tropo] is invalidating. (as)
2011-07-14 17:21:01.747 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (i)[REGISTER sip:tropo-dev90 SIP/2.0\r\nTo: "usera" <sip:usera@tropo-dev90>\r\nExpires: 600\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport;branch=z9hG4bKPjCLWjPDyhdsdBXO1hnPoJInrL3sNtq0Gd\r\nCSeq: 1 REGISTER\r\nContent-Length: 0\r\nCall-ID: iwwDmH7As1CITblySwg7rMB.V7io9v8C\r\nUser-Agent: Blink 0.24.0 (MacOSX)\r\nFrom: "usera" <sip:usera@tropo-dev90>;tag=TGGOvFcL5VF3EN1RfEzU6rKqd6ai.lT7\r\nMax-Forwards: 70\r\nContact: <sip:zsudcpij@3.3.3.11:59832>\r\n\r\n] #[N/A][N/A][iwwDmH7As1CITblySwg7rMB.V7io9v8C][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:01.748 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: The transaction was created: z9hG4bKPjCLWjPDyhdsdBXO1hnPoJInrL3sNtq0Gd #[N/A][N/A][iwwDmH7As1CITblySwg7rMB.V7io9v8C][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:01.748 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Found [tropo] to handle the request by port mappings: 5060
2011-07-14 17:21:01.748 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationInfo: SipApplicationRouterInfo[ApplicationName=tropo, RouteModifier=NO_ROUTE, RouteRegion=null, SubscriberURI=sip:tropo-dev90, StateInfo=tropo] #[N/A][N/A][iwwDmH7As1CITblySwg7rMB.V7io9v8C][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:01.749 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-14-smhs0pfphe78rstropo] will expired after 7200000
2011-07-14 17:21:01.749 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session creating: ss_8umlourc38wb #[tropo][sas_2-14-smhs0pfphe78rstropo][iwwDmH7As1CITblySwg7rMB.V7io9v8C][ss_8umlourc38wb][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:01.750 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session created:SipSessionImpl[_id=ss_8umlourc38wb, _parentId=sas_2-14-smhs0pfphe78rstropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UNKNOW, _method=REGISTER, _callId=iwwDmH7As1CITblySwg7rMB.V7io9v8C] #[tropo][sas_2-14-smhs0pfphe78rstropo][iwwDmH7As1CITblySwg7rMB.V7io9v8C][ss_8umlourc38wb][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:01.750 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer recv request: REGISTER #[tropo][sas_2-14-smhs0pfphe78rstropo][iwwDmH7As1CITblySwg7rMB.V7io9v8C][ss_8umlourc38wb][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:01.750 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ApplicationDispatchLayer invoke application: tropo with REGISTER #[tropo][sas_2-14-smhs0pfphe78rstropo][iwwDmH7As1CITblySwg7rMB.V7io9v8C][ss_8umlourc38wb][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:01.750 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipServletWrapper[tropo, com.voxeo.tropo.SIPDriver] is forwarding. #[tropo][sas_2-14-smhs0pfphe78rstropo][iwwDmH7As1CITblySwg7rMB.V7io9v8C][ss_8umlourc38wb][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:01.751 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer send response: REGISTER/500 #[tropo][sas_2-14-smhs0pfphe78rstropo][iwwDmH7As1CITblySwg7rMB.V7io9v8C][ss_8umlourc38wb][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:01.751 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Add Path[ id=iwwDmH7As1CITblySwg7rMB.V7io9v8C-TGGOvFcL5VF3EN1RfEzU6rKqd6ai.lT7-6zfd2vovxxsr, session=SipSessionImpl[_id=ss_8umlourc38wb, _parentId=sas_2-14-smhs0pfphe78rstropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=REGISTER, _callId=iwwDmH7As1CITblySwg7rMB.V7io9v8C], party= CALLER] #[tropo][sas_2-14-smhs0pfphe78rstropo][iwwDmH7As1CITblySwg7rMB.V7io9v8C][ss_8umlourc38wb][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:01.752 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (o)[SIP/2.0 500 Request not handled by app\r\nTo: usera <sip:usera@tropo-dev90>;tag=6zfd2vovxxsr\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPjCLWjPDyhdsdBXO1hnPoJInrL3sNtq0Gd;received=3.3.3.11\r\nCSeq: 1 REGISTER\r\nContent-Length: 0\r\nCall-ID: iwwDmH7As1CITblySwg7rMB.V7io9v8C\r\nFrom: usera <sip:usera@tropo-dev90>;tag=TGGOvFcL5VF3EN1RfEzU6rKqd6ai.lT7\r\n\r\n] #[tropo][sas_2-14-smhs0pfphe78rstropo][iwwDmH7As1CITblySwg7rMB.V7io9v8C][ss_8umlourc38wb][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:01.752 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Send message to: /3.3.3.11:59832 by udp #[tropo][sas_2-14-smhs0pfphe78rstropo][iwwDmH7As1CITblySwg7rMB.V7io9v8C][ss_8umlourc38wb][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:01.752 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Connected to 3.3.3.11:59832/udp #[tropo][sas_2-14-smhs0pfphe78rstropo][iwwDmH7As1CITblySwg7rMB.V7io9v8C][ss_8umlourc38wb][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:01.753 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-smhs0pfphe78rstropo], invalidateWhenReady: true
2011-07-14 17:21:01.753 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_8umlourc38wb], current State = INITIAL, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: true, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-14-smhs0pfphe78rstropo][iwwDmH7As1CITblySwg7rMB.V7io9v8C][ss_8umlourc38wb][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:01.753 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-smhs0pfphe78rstropo], invalidateWhenReady: true
2011-07-14 17:21:01.753 INFO [udp/0.0.0.0/5060-t-4] Clearing logging context for udp/0.0.0.0/5060-t-4
2011-07-14 17:21:01.753 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-smhs0pfphe78rstropo], invalidateWhenReady: true
2011-07-14 17:21:01.753 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_8umlourc38wb], current State = INITIAL, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-14-smhs0pfphe78rstropo][iwwDmH7As1CITblySwg7rMB.V7io9v8C][ss_8umlourc38wb][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:01.753 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-smhs0pfphe78rstropo], invalidateWhenReady: true
2011-07-14 17:21:22.975 DEBUG [Timer-12] #SIP#: NonInviteServerTransaction[_state=COMPLETED, _id=z9hG4bKPjQ2S2ZMhSbBZ0TCB56vD4OAqdPhb0Ilr8] timerRemoveTransaction is fired. #[tropo][sas_2-14-sm5qpnn4s1p4rptropo][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][ss_n2u0hw8pvmc8][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:22.977 DEBUG [Timer-12] #SIP#: NonInviteServerTransaction[_state=TERMINATED, _id=z9hG4bKPjQ2S2ZMhSbBZ0TCB56vD4OAqdPhb0Ilr8] is released. #[tropo][sas_2-14-sm5qpnn4s1p4rptropo][2KO3BZKgIH9rH0GZGXEWFDuRyIqnBEkb][ss_n2u0hw8pvmc8][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:33.755 DEBUG [Timer-13] #SIP#: NonInviteServerTransaction[_state=COMPLETED, _id=z9hG4bKPjCLWjPDyhdsdBXO1hnPoJInrL3sNtq0Gd] timerRemoveTransaction is fired. #[tropo][sas_2-14-smhs0pfphe78rstropo][iwwDmH7As1CITblySwg7rMB.V7io9v8C][ss_8umlourc38wb][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:33.755 DEBUG [Timer-13] #SIP#: NonInviteServerTransaction[_state=TERMINATED, _id=z9hG4bKPjCLWjPDyhdsdBXO1hnPoJInrL3sNtq0Gd] is released. #[tropo][sas_2-14-smhs0pfphe78rstropo][iwwDmH7As1CITblySwg7rMB.V7io9v8C][ss_8umlourc38wb][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:33.756 DEBUG [Timer-8] #SIP#: SipSessionImpl[_id=ss_8umlourc38wb, _parentId=sas_2-14-smhs0pfphe78rstropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=REGISTER, _callId=iwwDmH7As1CITblySwg7rMB.V7io9v8C] is invalidating. (s) #[tropo][sas_2-14-smhs0pfphe78rstropo][iwwDmH7As1CITblySwg7rMB.V7io9v8C][ss_8umlourc38wb][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:33.756 DEBUG [Timer-8] #SIP#: Remove Path[ id=iwwDmH7As1CITblySwg7rMB.V7io9v8C-TGGOvFcL5VF3EN1RfEzU6rKqd6ai.lT7-6zfd2vovxxsr, session=SipSessionImpl[_id=ss_8umlourc38wb, _parentId=sas_2-14-smhs0pfphe78rstropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=true, _role=UAS, _method=REGISTER, _callId=iwwDmH7As1CITblySwg7rMB.V7io9v8C]] #[tropo][sas_2-14-smhs0pfphe78rstropo][iwwDmH7As1CITblySwg7rMB.V7io9v8C][ss_8umlourc38wb][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:33.758 DEBUG [Timer-8] #SIP#: processInvalidationWhenReady [sas_2-14-smhs0pfphe78rstropo], invalidateWhenReady: true
2011-07-14 17:21:33.758 DEBUG [Timer-8] #SIP#: Container will automatically invalidate SipApplicationSession [sas_2-14-smhs0pfphe78rstropo]
2011-07-14 17:21:33.759 DEBUG [Timer-8] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-14-smhs0pfphe78rstropo] is invalidating. (as)
2011-07-14 17:21:52.652 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (i)[REGISTER sip:tropo-dev90 SIP/2.0\r\nTo: "usera" <sip:usera@tropo-dev90>\r\nExpires: 600\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport;branch=z9hG4bKPjvFDoKrpo4TRdli9vkoIi9U-q-mjaWtvt\r\nCSeq: 1 REGISTER\r\nContent-Length: 0\r\nCall-ID: bcEQVXpzirptNjVPFgvpg846KPw07SI1\r\nUser-Agent: Blink 0.24.0 (MacOSX)\r\nFrom: "usera" <sip:usera@tropo-dev90>;tag=RPBU1CWoHMh40kKft5rc2QztO-WbMdm0\r\nMax-Forwards: 70\r\nContact: <sip:zsudcpij@3.3.3.11:59832>\r\n\r\n] #[N/A][N/A][bcEQVXpzirptNjVPFgvpg846KPw07SI1][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:52.656 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: The transaction was created: z9hG4bKPjvFDoKrpo4TRdli9vkoIi9U-q-mjaWtvt #[N/A][N/A][bcEQVXpzirptNjVPFgvpg846KPw07SI1][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:52.656 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Found [tropo] to handle the request by port mappings: 5060
2011-07-14 17:21:52.656 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationInfo: SipApplicationRouterInfo[ApplicationName=tropo, RouteModifier=NO_ROUTE, RouteRegion=null, SubscriberURI=sip:tropo-dev90, StateInfo=tropo] #[N/A][N/A][bcEQVXpzirptNjVPFgvpg846KPw07SI1][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:52.657 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-14-smvug0uhecdfpltropo] will expired after 7200000
2011-07-14 17:21:52.657 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session creating: ss_1kn3jw81x5k8l #[tropo][sas_2-14-smvug0uhecdfpltropo][bcEQVXpzirptNjVPFgvpg846KPw07SI1][ss_1kn3jw81x5k8l][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:52.658 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session created:SipSessionImpl[_id=ss_1kn3jw81x5k8l, _parentId=sas_2-14-smvug0uhecdfpltropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UNKNOW, _method=REGISTER, _callId=bcEQVXpzirptNjVPFgvpg846KPw07SI1] #[tropo][sas_2-14-smvug0uhecdfpltropo][bcEQVXpzirptNjVPFgvpg846KPw07SI1][ss_1kn3jw81x5k8l][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:52.658 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer recv request: REGISTER #[tropo][sas_2-14-smvug0uhecdfpltropo][bcEQVXpzirptNjVPFgvpg846KPw07SI1][ss_1kn3jw81x5k8l][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:52.658 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ApplicationDispatchLayer invoke application: tropo with REGISTER #[tropo][sas_2-14-smvug0uhecdfpltropo][bcEQVXpzirptNjVPFgvpg846KPw07SI1][ss_1kn3jw81x5k8l][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:52.658 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipServletWrapper[tropo, com.voxeo.tropo.SIPDriver] is forwarding. #[tropo][sas_2-14-smvug0uhecdfpltropo][bcEQVXpzirptNjVPFgvpg846KPw07SI1][ss_1kn3jw81x5k8l][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:52.659 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer send response: REGISTER/500 #[tropo][sas_2-14-smvug0uhecdfpltropo][bcEQVXpzirptNjVPFgvpg846KPw07SI1][ss_1kn3jw81x5k8l][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:52.659 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Add Path[ id=bcEQVXpzirptNjVPFgvpg846KPw07SI1-RPBU1CWoHMh40kKft5rc2QztO-WbMdm0-1i4qauabhpt6j, session=SipSessionImpl[_id=ss_1kn3jw81x5k8l, _parentId=sas_2-14-smvug0uhecdfpltropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=REGISTER, _callId=bcEQVXpzirptNjVPFgvpg846KPw07SI1], party= CALLER] #[tropo][sas_2-14-smvug0uhecdfpltropo][bcEQVXpzirptNjVPFgvpg846KPw07SI1][ss_1kn3jw81x5k8l][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:52.660 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (o)[SIP/2.0 500 Request not handled by app\r\nTo: usera <sip:usera@tropo-dev90>;tag=1i4qauabhpt6j\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPjvFDoKrpo4TRdli9vkoIi9U-q-mjaWtvt;received=3.3.3.11\r\nCSeq: 1 REGISTER\r\nContent-Length: 0\r\nCall-ID: bcEQVXpzirptNjVPFgvpg846KPw07SI1\r\nFrom: usera <sip:usera@tropo-dev90>;tag=RPBU1CWoHMh40kKft5rc2QztO-WbMdm0\r\n\r\n] #[tropo][sas_2-14-smvug0uhecdfpltropo][bcEQVXpzirptNjVPFgvpg846KPw07SI1][ss_1kn3jw81x5k8l][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:52.660 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Send message to: /3.3.3.11:59832 by udp #[tropo][sas_2-14-smvug0uhecdfpltropo][bcEQVXpzirptNjVPFgvpg846KPw07SI1][ss_1kn3jw81x5k8l][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:52.660 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Connected to 3.3.3.11:59832/udp #[tropo][sas_2-14-smvug0uhecdfpltropo][bcEQVXpzirptNjVPFgvpg846KPw07SI1][ss_1kn3jw81x5k8l][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:52.660 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-smvug0uhecdfpltropo], invalidateWhenReady: true
2011-07-14 17:21:52.661 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_1kn3jw81x5k8l], current State = INITIAL, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: true, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-14-smvug0uhecdfpltropo][bcEQVXpzirptNjVPFgvpg846KPw07SI1][ss_1kn3jw81x5k8l][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:52.661 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-smvug0uhecdfpltropo], invalidateWhenReady: true
2011-07-14 17:21:52.661 INFO [udp/0.0.0.0/5060-t-4] Clearing logging context for udp/0.0.0.0/5060-t-4
2011-07-14 17:21:52.661 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-14-smvug0uhecdfpltropo], invalidateWhenReady: true
2011-07-14 17:21:52.661 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_1kn3jw81x5k8l], current State = INITIAL, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-14-smvug0uhecdfpltropo][bcEQVXpzirptNjVPFgvpg846KPw07SI1][ss_1kn3jw81x5k8l][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:21:52.661 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-14-smvug0uhecdfpltropo], invalidateWhenReady: true
2011-07-14 17:22:24.663 DEBUG [Timer-9] #SIP#: NonInviteServerTransaction[_state=COMPLETED, _id=z9hG4bKPjvFDoKrpo4TRdli9vkoIi9U-q-mjaWtvt] timerRemoveTransaction is fired. #[tropo][sas_2-14-smvug0uhecdfpltropo][bcEQVXpzirptNjVPFgvpg846KPw07SI1][ss_1kn3jw81x5k8l][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:24.665 DEBUG [Timer-9] #SIP#: NonInviteServerTransaction[_state=TERMINATED, _id=z9hG4bKPjvFDoKrpo4TRdli9vkoIi9U-q-mjaWtvt] is released. #[tropo][sas_2-14-smvug0uhecdfpltropo][bcEQVXpzirptNjVPFgvpg846KPw07SI1][ss_1kn3jw81x5k8l][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:24.665 DEBUG [Timer-10] #SIP#: SipSessionImpl[_id=ss_1kn3jw81x5k8l, _parentId=sas_2-14-smvug0uhecdfpltropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=REGISTER, _callId=bcEQVXpzirptNjVPFgvpg846KPw07SI1] is invalidating. (s) #[tropo][sas_2-14-smvug0uhecdfpltropo][bcEQVXpzirptNjVPFgvpg846KPw07SI1][ss_1kn3jw81x5k8l][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:24.666 DEBUG [Timer-10] #SIP#: Remove Path[ id=bcEQVXpzirptNjVPFgvpg846KPw07SI1-RPBU1CWoHMh40kKft5rc2QztO-WbMdm0-1i4qauabhpt6j, session=SipSessionImpl[_id=ss_1kn3jw81x5k8l, _parentId=sas_2-14-smvug0uhecdfpltropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=true, _role=UAS, _method=REGISTER, _callId=bcEQVXpzirptNjVPFgvpg846KPw07SI1]] #[tropo][sas_2-14-smvug0uhecdfpltropo][bcEQVXpzirptNjVPFgvpg846KPw07SI1][ss_1kn3jw81x5k8l][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:24.670 DEBUG [Timer-10] #SIP#: processInvalidationWhenReady [sas_2-14-smvug0uhecdfpltropo], invalidateWhenReady: true
2011-07-14 17:22:24.671 DEBUG [Timer-10] #SIP#: Container will automatically invalidate SipApplicationSession [sas_2-14-smvug0uhecdfpltropo]
2011-07-14 17:22:24.671 DEBUG [Timer-10] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-14-smvug0uhecdfpltropo] is invalidating. (as)
2011-07-14 17:22:30.455 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (i)[REGISTER sip:tropo-dev90 SIP/2.0\r\nTo: "usera" <sip:usera@tropo-dev90>\r\nExpires: 600\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport;branch=z9hG4bKPjPZXdjsd4sszyXO916d22K7PX8k.qU6xR\r\nCSeq: 1 REGISTER\r\nContent-Length: 0\r\nCall-ID: nww-Ramx.7d95N58VjPTcepjtno1X6RY\r\nUser-Agent: Blink 0.24.0 (MacOSX)\r\nFrom: "usera" <sip:usera@tropo-dev90>;tag=Vl7OaWU3fbOnpdCTXDw6cc6d3jLFO5VU\r\nMax-Forwards: 70\r\nContact: <sip:zsudcpij@3.3.3.11:59832>\r\n\r\n] #[N/A][N/A][nww-Ramx.7d95N58VjPTcepjtno1X6RY][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:30.500 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: The transaction was created: z9hG4bKPjPZXdjsd4sszyXO916d22K7PX8k.qU6xR #[N/A][N/A][nww-Ramx.7d95N58VjPTcepjtno1X6RY][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:30.500 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Found [tropo] to handle the request by port mappings: 5060
2011-07-14 17:22:30.500 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationInfo: SipApplicationRouterInfo[ApplicationName=tropo, RouteModifier=NO_ROUTE, RouteRegion=null, SubscriberURI=sip:tropo-dev90, StateInfo=tropo] #[N/A][N/A][nww-Ramx.7d95N58VjPTcepjtno1X6RY][N/A][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:30.501 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-15-sm1cso752rl77fotropo] will expired after 7200000
2011-07-14 17:22:30.501 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session creating: ss_1qethgpubzz60 #[tropo][sas_2-15-sm1cso752rl77fotropo][nww-Ramx.7d95N58VjPTcepjtno1X6RY][ss_1qethgpubzz60][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:30.502 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Session created:SipSessionImpl[_id=ss_1qethgpubzz60, _parentId=sas_2-15-sm1cso752rl77fotropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UNKNOW, _method=REGISTER, _callId=nww-Ramx.7d95N58VjPTcepjtno1X6RY] #[tropo][sas_2-15-sm1cso752rl77fotropo][nww-Ramx.7d95N58VjPTcepjtno1X6RY][ss_1qethgpubzz60][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:30.502 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer recv request: REGISTER #[tropo][sas_2-15-sm1cso752rl77fotropo][nww-Ramx.7d95N58VjPTcepjtno1X6RY][ss_1qethgpubzz60][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:30.502 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ApplicationDispatchLayer invoke application: tropo with REGISTER #[tropo][sas_2-15-sm1cso752rl77fotropo][nww-Ramx.7d95N58VjPTcepjtno1X6RY][ss_1qethgpubzz60][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:30.502 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SipServletWrapper[tropo, com.voxeo.tropo.SIPDriver] is forwarding. #[tropo][sas_2-15-sm1cso752rl77fotropo][nww-Ramx.7d95N58VjPTcepjtno1X6RY][ss_1qethgpubzz60][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:30.502 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: SessionManagementLayer send response: REGISTER/500 #[tropo][sas_2-15-sm1cso752rl77fotropo][nww-Ramx.7d95N58VjPTcepjtno1X6RY][ss_1qethgpubzz60][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:30.503 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Add Path[ id=nww-Ramx.7d95N58VjPTcepjtno1X6RY-Vl7OaWU3fbOnpdCTXDw6cc6d3jLFO5VU-rc9x1wfo3f22, session=SipSessionImpl[_id=ss_1qethgpubzz60, _parentId=sas_2-15-sm1cso752rl77fotropo, _handler=tropo, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAS, _method=REGISTER, _callId=nww-Ramx.7d95N58VjPTcepjtno1X6RY], party= CALLER] #[tropo][sas_2-15-sm1cso752rl77fotropo][nww-Ramx.7d95N58VjPTcepjtno1X6RY][ss_1qethgpubzz60][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:30.503 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: (o)[SIP/2.0 500 Request not handled by app\r\nTo: usera <sip:usera@tropo-dev90>;tag=rc9x1wfo3f22\r\nVia: SIP/2.0/UDP 192.168.1.116:59832;rport=59832;branch=z9hG4bKPjPZXdjsd4sszyXO916d22K7PX8k.qU6xR;received=3.3.3.11\r\nCSeq: 1 REGISTER\r\nContent-Length: 0\r\nCall-ID: nww-Ramx.7d95N58VjPTcepjtno1X6RY\r\nFrom: usera <sip:usera@tropo-dev90>;tag=Vl7OaWU3fbOnpdCTXDw6cc6d3jLFO5VU\r\n\r\n] #[tropo][sas_2-15-sm1cso752rl77fotropo][nww-Ramx.7d95N58VjPTcepjtno1X6RY][ss_1qethgpubzz60][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:30.503 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Send message to: /3.3.3.11:59832 by udp #[tropo][sas_2-15-sm1cso752rl77fotropo][nww-Ramx.7d95N58VjPTcepjtno1X6RY][ss_1qethgpubzz60][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:30.504 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: Connected to 3.3.3.11:59832/udp #[tropo][sas_2-15-sm1cso752rl77fotropo][nww-Ramx.7d95N58VjPTcepjtno1X6RY][ss_1qethgpubzz60][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:30.504 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm1cso752rl77fotropo], invalidateWhenReady: true
2011-07-14 17:22:30.504 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_1qethgpubzz60], current State = INITIAL, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: true, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-15-sm1cso752rl77fotropo][nww-Ramx.7d95N58VjPTcepjtno1X6RY][ss_1qethgpubzz60][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:30.504 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-15-sm1cso752rl77fotropo], invalidateWhenReady: true
2011-07-14 17:22:30.504 INFO [udp/0.0.0.0/5060-t-4] Clearing logging context for udp/0.0.0.0/5060-t-4
2011-07-14 17:22:30.504 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm1cso752rl77fotropo], invalidateWhenReady: true
2011-07-14 17:22:30.504 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [ss_1qethgpubzz60], current State = INITIAL, Vaild:true, Role:UAS, hasOngoingTransaction: false, OT: 0, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[tropo][sas_2-15-sm1cso752rl77fotropo][nww-Ramx.7d95N58VjPTcepjtno1X6RY][ss_1qethgpubzz60][sip:usera@tropo-dev90(3.3.3.11:59832)][sip:usera@tropo-dev90(172.16.12.118:5060)]
2011-07-14 17:22:30.505 DEBUG [udp/0.0.0.0/5060-t-4] #SIP#: processInvalidationWhenReady [sas_2-15-sm1cso752rl77fotropo], invalidateWhenReady: true
2011-07-14 17:22:37.711 INFO [ApplicationMonitor] Starts loop detection.
2011-07-14 17:22:37.757 INFO [ApplicationMonitor] Ends loop detection.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment