Hi Paul, What are you running your all-in-one node on? If you're using an all-in-one image on VirtualBox then one of the clients must be Zoiper - (https://github.com/Metaswitch/clearwater-docs/wiki/Making-your-first-call), due to the NAT setup.
Can you get logs from your XLite? Ellie -----Original Message----- From: Paul Sun [mailto:[email protected]] Sent: 05 June 2014 02:21 To: Eleanor Merry; [email protected] Subject: RE: [Clearwater] Question on creating SIP call Hi Ellie I tried to use Zopier instead of X-Lite, and the problem is not presented. Do you know why? - PS -----Original Message----- From: PS Sent: Thursday, June 05, 2014 8:54 AM To: 'Eleanor Merry'; '[email protected]' Subject: RE: [Clearwater] Question on creating SIP call Hello Ellie Do you have any idea? - PS -----Original Message----- From: PS Sent: Wednesday, June 04, 2014 6:42 PM To: 'Eleanor Merry'; [email protected] Subject: RE: [Clearwater] Question on creating SIP call This is the log I had 04-06-2014 10:38:09.235 Verbose pjsip: tcplis:5054 TCP listener 192.168.206.112:5054: got incoming TCP connection from 192.168.206.112:42498, sock=107 04-06-2014 10:38:09.235 Verbose pjsip: tcps0x7fcacc0c TCP server transport created 04-06-2014 10:38:09.235 Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=2929 (rdata0x7fcacc0c0de8) 04-06-2014 10:38:09.235 Verbose stack.cpp:226: RX 358 bytes Request msg OPTIONS/cseq=2929 (rdata0x7fcacc0c0de8) from TCP 192.168.206.112:42498: --start msg-- OPTIONS sip:[email protected]:5054 SIP/2.0 Via: SIP/2.0/TCP 192.168.206.112;rport;branch=z9hG4bK-2929 Max-Forwards: 2 To: <sip:[email protected]:5054> From: poll-sip <sip:[email protected]>;tag=2929 Call-ID: poll-sip-2929 CSeq: 2929 OPTIONS Contact: <sip:192.168.206.112> Accept: application/sdp Content-Length: 0 User-Agent: poll-sip --end msg-- 04-06-2014 10:38:09.235 Debug statistic.cpp:103: Send new value for statistic incoming_requests, size 1 04-06-2014 10:38:09.235 Debug zmq_lvc.cpp:167: Update to incoming_requests statistic 04-06-2014 10:38:09.235 Debug zmq_lvc.cpp:250: Clearing message cache for 0x7fcb1002a170 04-06-2014 10:38:09.235 Debug stack.cpp:410: Queuing cloned received message 0x7fcacc13c378 for worker threads 04-06-2014 10:38:09.235 Debug statistic.cpp:103: Send new value for statistic queue_size, size 5 04-06-2014 10:38:09.236 Debug zmq_lvc.cpp:167: Update to queue_size statistic 04-06-2014 10:38:09.236 Debug zmq_lvc.cpp:250: Clearing message cache for 0x7fcb100334b0 04-06-2014 10:38:09.236 Debug stack.cpp:189: Worker thread dequeue message 0x7fcacc13c378 04-06-2014 10:38:09.236 Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=2929 (rdata0x7fcacc13c378) 04-06-2014 10:38:09.236 Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=2929 (tdta0x7fcaa00008c0) created 04-06-2014 10:38:09.236 Verbose stack.cpp:242: TX 284 bytes Response msg 200/OPTIONS/cseq=2929 (tdta0x7fcaa00008c0) to TCP 192.168.206.112:42498: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP 192.168.206.112;rport=42498;received=192.168.206.112;branch=z9hG4bK-2929 Call-ID: poll-sip-2929 From: "poll-sip" <sip:[email protected]>;tag=2929 To: <sip:[email protected]>;tag=z9hG4bK-2929 CSeq: 2929 OPTIONS Content-Length: 0 --end msg-- 04-06-2014 10:38:09.236 Debug pjsip: tdta0x7fcaa000 Destroying txdata Response msg 200/OPTIONS/cseq=2929 (tdta0x7fcaa00008c0) 04-06-2014 10:38:09.236 Debug stack.cpp:191: Worker thread completed processing message 0x7fcacc13c378 04-06-2014 10:38:09.236 Debug stack.cpp:197: Request latency = 303us 04-06-2014 10:38:09.236 Debug statistic.cpp:103: Send new value for statistic latency_us, size 5 04-06-2014 10:38:09.236 Debug zmq_lvc.cpp:167: Update to latency_us statistic 04-06-2014 10:38:09.236 Debug zmq_lvc.cpp:250: Clearing message cache for 0x7fcb10013100 04-06-2014 10:38:10.239 Verbose pjsip: tcps0x7fcacc0c TCP connection closed 04-06-2014 10:38:10.240 Debug connection_tracker.cpp:91: Connection 0x7fcacc0c0af8 has been destroyed 04-06-2014 10:38:10.240 Verbose pjsip: tcps0x7fcacc0c TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 04-06-2014 10:38:14.928 Debug pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=1 (rdata0x7fcacc026928) 04-06-2014 10:38:14.929 Verbose stack.cpp:226: RX 1295 bytes Request msg INVITE/cseq=1 (rdata0x7fcacc026928) from TCP 192.168.206.112:33070: --start msg-- INVITE sip:[email protected];transport=tcp SIP/2.0 Record-Route: <sip:192.168.206.112:5058;transport=TCP;lr> Record-Route: <sip:[email protected]:5060;transport=TCP;lr> Via: SIP/2.0/TCP 192.168.206.112:33070;rport;branch=z9hG4bKPjrCrWt6rvZ37QxAdh5x0y-vaCx.y1HGpr Via: SIP/2.0/TCP 192.168.206.159:43498;rport=59677;received=192.168.206.159;branch=z9hG4bK-d8754z-884c23056ad58d7b-1---d8754z- Max-Forwards: 69 Contact: <sip:[email protected]:59677;transport=tcp> To: <sip:[email protected]> From: <sip:[email protected]>;tag=1114ab1f Call-ID: MzhlMDdjNjQ3MzdhNTRiZmNiZTlhNDJjMWIwNGQ1OGU CSeq: 1 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Supported: replaces User-Agent: X-Lite release 4.5.5 stamp 71236 P-Asserted-Identity: <sip:[email protected]> Session-Expires: 600 Route: <sip:192.168.206.112:5054;transport=TCP;lr;orig> Content-Type: application/sdp Content-Length: 310 v=0 o=- 13046351975734667 1 IN IP4 192.168.206.159 s=X-Lite 4 release 4.5.5 stamp 71236 c=IN IP4 192.168.206.159 t=0 0 m=audio 49776 RTP/AVP 125 9 0 8 100 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:100 speex/16000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv --end msg-- 04-06-2014 10:38:14.929 Debug statistic.cpp:103: Send new value for statistic incoming_requests, size 1 04-06-2014 10:38:14.929 Debug zmq_lvc.cpp:167: Update to incoming_requests statistic 04-06-2014 10:38:14.929 Debug zmq_lvc.cpp:250: Clearing message cache for 0x7fcb1002a170 04-06-2014 10:38:14.929 Debug stack.cpp:410: Queuing cloned received message 0x7fcacc0c0af8 for worker threads 04-06-2014 10:38:14.930 Debug statistic.cpp:103: Send new value for statistic queue_size, size 5 04-06-2014 10:38:14.930 Debug zmq_lvc.cpp:167: Update to queue_size statistic 04-06-2014 10:38:14.930 Debug zmq_lvc.cpp:250: Clearing message cache for 0x7fcb100334b0 04-06-2014 10:38:14.930 Debug stack.cpp:189: Worker thread dequeue message 0x7fcacc0c0af8 04-06-2014 10:38:14.930 Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=1 (rdata0x7fcacc0c0af8) 04-06-2014 10:38:14.930 Debug stateful_proxy.cpp:257: Proxy RX request 04-06-2014 10:38:14.930 Debug stateful_proxy.cpp:486: Got our Route header, session case orig, OD=None 04-06-2014 10:38:14.931 Debug pjutils.cpp:481: Found Route header, URI = sip:192.168.206.112:5054;transport=TCP;lr;orig 04-06-2014 10:38:14.931 Debug pjutils.cpp:484: Route header is local 04-06-2014 10:38:14.931 Debug stateful_proxy.cpp:1493: Top Route header is local - erasing 04-06-2014 10:38:14.931 Debug stateful_proxy.cpp:515: Create new ACR for this transaction 04-06-2014 10:38:14.931 Debug acr.cpp:48: Created ACR (0x7fcaac005b20) 04-06-2014 10:38:14.931 Debug stateful_proxy.cpp:525: Trust mode TRUSTED(,,), serving state orig (new) 04-06-2014 10:38:14.931 Debug pjsip: tsx0x7fcaac006 Transaction created for Request msg INVITE/cseq=1 (rdata0x7fcacc0c0af8) 04-06-2014 10:38:14.931 Debug stateful_proxy.cpp:2018: UASTransaction constructor (0x7fcaac0067e0) 04-06-2014 10:38:14.931 Debug stateful_proxy.cpp:2019: ACR (0x7fcaac005b20) 04-06-2014 10:38:14.931 Debug pjsip: tsx0x7fcaac006 Incoming Request msg INVITE/cseq=1 (rdata0x7fcacc0c0af8) in state Null 04-06-2014 10:38:14.932 Debug pjsip: tsx0x7fcaac006 State changed from Null to Trying, event=RX_MSG 04-06-2014 10:38:14.932 Debug stateful_proxy.cpp:365: tsx0x7fcaac006078 - tu_on_tsx_state UAS, TSX_STATE RX_MSG state=Trying 04-06-2014 10:38:14.932 Debug pjsip: endpoint Response msg 408/INVITE/cseq=1 (tdta0x7fcaac006990) created 04-06-2014 10:38:14.932 Debug stateful_proxy.cpp:3352: Report SAS start marker - trail (25) 04-06-2014 10:38:14.932 Debug pjsip: endpoint Response msg 100/INVITE/cseq=1 (tdta0x7fcaac008b60) created 04-06-2014 10:38:14.932 Debug pjsip: tsx0x7fcaac006 Sending Response msg 100/INVITE/cseq=1 (tdta0x7fcaac008b60) in state Trying 04-06-2014 10:38:14.932 Verbose stack.cpp:242: TX 580 bytes Response msg 100/INVITE/cseq=1 (tdta0x7fcaac008b60) to TCP 192.168.206.112:33070: --start msg-- SIP/2.0 100 Trying Via: SIP/2.0/TCP 192.168.206.112:33070;rport=33070;received=192.168.206.112;branch=z9hG4bKPjrCrWt6rvZ37QxAdh5x0y-vaCx.y1HGpr Via: SIP/2.0/TCP 192.168.206.159:43498;rport=59677;received=192.168.206.159;branch=z9hG4bK-d8754z-884c23056ad58d7b-1---d8754z- Record-Route: <sip:192.168.206.112:5058;transport=TCP;lr> Record-Route: <sip:[email protected]:5060;transport=TCP;lr> Call-ID: MzhlMDdjNjQ3MzdhNTRiZmNiZTlhNDJjMWIwNGQ1OGU From: <sip:[email protected]>;tag=1114ab1f To: <sip:[email protected]> CSeq: 1 INVITE Content-Length: 0 --end msg-- 04-06-2014 10:38:14.933 Debug pjsip: tsx0x7fcaac006 State changed from Trying to Proceeding, event=TX_MSG 04-06-2014 10:38:14.933 Debug stateful_proxy.cpp:365: tsx0x7fcaac006078 - tu_on_tsx_state UAS, TSX_STATE TX_MSG state=Proceeding 04-06-2014 10:38:14.933 Debug stateful_proxy.cpp:2563: Looking for AS chain for incoming transaction request, serving state = orig (new) 04-06-2014 10:38:14.933 Debug pjutils.cpp:337: Served user from P-Asserted-Identity header 04-06-2014 10:38:14.933 Debug pjutils.cpp:219: aor_from_uri converted sip:[email protected] to sip:[email protected] 04-06-2014 10:38:14.933 Debug stateful_proxy.cpp:2621: Looking up iFCs for sip:[email protected] for new AS chain 04-06-2014 10:38:14.933 Debug hssconnection.cpp:397: Making Homestead request for /impu/sip%3A85229613675%40example.com/reg-data 04-06-2014 10:38:14.935 Debug httpconnection.cpp:159: Allocated CURL handle 0x7fcaac00daf0 04-06-2014 10:38:14.937 Debug httpconnection.cpp:466: Sending HTTP request : http://192.168.206.112:8888/impu/sip%3A85229613675%40example.com/reg-data (try 0) on new connection 04-06-2014 10:38:14.942 Debug httpconnection.cpp:746: Received header http/1.1200ok with value 04-06-2014 10:38:14.942 Debug httpconnection.cpp:746: Received header content-length with value 2700 04-06-2014 10:38:14.942 Debug httpconnection.cpp:746: Received header content-type with value text/plain 04-06-2014 10:38:14.942 Debug httpconnection.cpp:746: Received header with value 04-06-2014 10:38:14.943 Debug httpconnection.cpp:477: Received HTTP response : <ClearwaterRegData> <RegistrationState>REGISTERED</RegistrationState> <IMSSubscription> <PrivateID>[email protected]</PrivateID> <ServiceProfile> <PublicIdentity> <Identity>sip:[email protected]</Identity> <Extension> <IdentityType>0</IdentityType> </Extension> </PublicIdentity> <InitialFilterCriteria> <Priority>0</Priority> <TriggerPoint> <ConditionTypeCNF>0</ConditionTypeCNF> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <Method>PUBLISH</Method> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <SIPHeader> <Header>Event</Header> <Content>.*presence.*</Content> </SIPHeader> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <SessionCase>0</SessionCase> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>1</Group> <Method>PUBLISH</Method> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>1</Group> <SIPHeader> <Header>Event</Header> <Content>.*presence.*</Content> </SIPHeader> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>1</Group> <SessionCase>3</SessionCase> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>2</Group> <Method>SUBSCRIBE</Method> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>2</Group> <SIPHeader> <Header>Event</Header> <Content>.*presence.*</Content> </SIPHeader> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>2</Group> <SessionCase>1</SessionCase> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>3</Group> <Method>SUBSCRIBE</Method> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>3</Group> <SIPHeader> <Header>Event</Header> <Content>.*presence.*</Content> </SIPHeader> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>3</Group> <SessionCase>2</SessionCase> <Extension/> </SPT> </TriggerPoint> <ApplicationServer> <ServerName>sip:127.0.0.1:5065</ServerName> <DefaultHandling>0</DefaultHandling> </ApplicationServer> </InitialFilterCriteria> </ServiceProfile> </IMSSubscription> </ClearwaterRegData> 04-06-2014 10:38:14.943 Debug hssconnection.cpp:323: Processing Identity node from HSS XML - sip:[email protected] 04-06-2014 10:38:14.943 Debug stateful_proxy.cpp:2625: Successfully looked up iFCs 04-06-2014 10:38:14.943 Debug aschain.cpp:73: Creating AsChain 0x7fcaac046750 with 1 IFC and adding to map 04-06-2014 10:38:14.943 Debug aschain.cpp:75: Attached ACR (0x7fcaac005b20) to chain 04-06-2014 10:38:14.943 Debug stateful_proxy.cpp:4714: UASTransaction 0x7fcaac0067e0 linked to AsChain AsChain-orig[0x7fcaac046750]:1/1 04-06-2014 10:38:14.943 Debug stateful_proxy.cpp:2638: Single Record-Route - initiation of originating handling 04-06-2014 10:38:14.943 Debug stateful_proxy.cpp:2292: Performing originating call processing 04-06-2014 10:38:14.943 Debug stateful_proxy.cpp:2687: Applying originating services 04-06-2014 10:38:14.943 Debug ifchandler.cpp:476: SPT class Method: result false 04-06-2014 10:38:14.943 Debug ifchandler.cpp:583: Add to group 0 val false 04-06-2014 10:38:14.943 Debug ifchandler.cpp:476: SPT class SIPHeader: result false 04-06-2014 10:38:14.943 Debug ifchandler.cpp:583: Add to group 0 val false 04-06-2014 10:38:14.943 Debug ifchandler.cpp:476: SPT class SessionCase: result true 04-06-2014 10:38:14.943 Debug ifchandler.cpp:583: Add to group 0 val true 04-06-2014 10:38:14.943 Debug ifchandler.cpp:476: SPT class Method: result false 04-06-2014 10:38:14.943 Debug ifchandler.cpp:583: Add to group 1 val false 04-06-2014 10:38:14.943 Debug ifchandler.cpp:476: SPT class SIPHeader: result false 04-06-2014 10:38:14.943 Debug ifchandler.cpp:583: Add to group 1 val false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:476: SPT class SessionCase: result false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:583: Add to group 1 val false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:476: SPT class Method: result false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:583: Add to group 2 val false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:476: SPT class SIPHeader: result false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:583: Add to group 2 val false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:476: SPT class SessionCase: result false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:583: Add to group 2 val false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:476: SPT class Method: result false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:583: Add to group 3 val false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:476: SPT class SIPHeader: result false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:583: Add to group 3 val false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:476: SPT class SessionCase: result false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:583: Add to group 3 val false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:601: Result group 0 val false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:601: Result group 1 val false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:601: Result group 2 val false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:601: Result group 3 val false 04-06-2014 10:38:14.944 Debug ifchandler.cpp:605: iFC does not match 04-06-2014 10:38:14.944 Debug aschain.cpp:232: No match for AsChain-orig[0x7fcaac046750]:1/1 04-06-2014 10:38:14.944 Debug stateful_proxy.cpp:2696: Done internal step - advance link to AsChain-orig[0x7fcaac046750]:2/1 and go around again 04-06-2014 10:38:14.944 Debug aschain.cpp:221: No ASs left in chain 04-06-2014 10:38:14.944 Info stateful_proxy.cpp:2704: Originating services disposition 2 04-06-2014 10:38:14.944 Debug stateful_proxy.cpp:2510: Originating AS chain complete, move to terminating chain 04-06-2014 10:38:14.944 Debug aschain.h:130: AsChain dec ref 0x7fcaac046750 -> 1 04-06-2014 10:38:14.944 Debug pjutils.cpp:219: aor_from_uri converted sip:[email protected] to sip:[email protected] 04-06-2014 10:38:14.944 Debug stateful_proxy.cpp:2727: Looking up iFCs for served user sip:[email protected] 04-06-2014 10:38:14.944 Debug hssconnection.cpp:397: Making Homestead request for /impu/sip%3A85290000000%40example.com/reg-data 04-06-2014 10:38:14.944 Debug httpconnection.cpp:466: Sending HTTP request : http://192.168.206.112:8888/impu/sip%3A85290000000%40example.com/reg-data (try 0) 04-06-2014 10:38:14.945 Debug statistic.cpp:103: Send new value for statistic connected_homesteads, size 2 04-06-2014 10:38:14.945 Debug statistic.cpp:103: Send new value for statistic hss_subscription_latency_us, size 5 04-06-2014 10:38:14.945 Debug statistic.cpp:103: Send new value for statistic hss_latency_us, size 5 04-06-2014 10:38:14.946 Debug zmq_lvc.cpp:167: Update to connected_homesteads statistic 04-06-2014 10:38:14.946 Debug zmq_lvc.cpp:250: Clearing message cache for 0x7fcb10009dc0 04-06-2014 10:38:14.946 Debug zmq_lvc.cpp:167: Update to hss_latency_us statistic 04-06-2014 10:38:14.946 Debug zmq_lvc.cpp:250: Clearing message cache for 0x7fcb10017a90 04-06-2014 10:38:14.947 Debug zmq_lvc.cpp:167: Update to hss_subscription_latency_us statistic 04-06-2014 10:38:14.947 Debug zmq_lvc.cpp:250: Clearing message cache for 0x7fcb10020df0 04-06-2014 10:38:14.948 Debug httpconnection.cpp:746: Received header http/1.1200ok with value 04-06-2014 10:38:14.948 Debug httpconnection.cpp:746: Received header content-length with value 2700 04-06-2014 10:38:14.948 Debug httpconnection.cpp:746: Received header content-type with value text/plain 04-06-2014 10:38:14.948 Debug httpconnection.cpp:746: Received header with value 04-06-2014 10:38:14.948 Debug httpconnection.cpp:477: Received HTTP response : <ClearwaterRegData> <RegistrationState>REGISTERED</RegistrationState> <IMSSubscription> <PrivateID>[email protected]</PrivateID> <ServiceProfile> <PublicIdentity> <Identity>sip:[email protected]</Identity> <Extension> <IdentityType>0</IdentityType> </Extension> </PublicIdentity> <InitialFilterCriteria> <Priority>0</Priority> <TriggerPoint> <ConditionTypeCNF>0</ConditionTypeCNF> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <Method>PUBLISH</Method> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <SIPHeader> <Header>Event</Header> <Content>.*presence.*</Content> </SIPHeader> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <SessionCase>0</SessionCase> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>1</Group> <Method>PUBLISH</Method> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>1</Group> <SIPHeader> <Header>Event</Header> <Content>.*presence.*</Content> </SIPHeader> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>1</Group> <SessionCase>3</SessionCase> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>2</Group> <Method>SUBSCRIBE</Method> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>2</Group> <SIPHeader> <Header>Event</Header> <Content>.*presence.*</Content> </SIPHeader> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>2</Group> <SessionCase>1</SessionCase> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>3</Group> <Method>SUBSCRIBE</Method> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>3</Group> <SIPHeader> <Header>Event</Header> <Content>.*presence.*</Content> </SIPHeader> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>3</Group> <SessionCase>2</SessionCase> <Extension/> </SPT> </TriggerPoint> <ApplicationServer> <ServerName>sip:127.0.0.1:5065</ServerName> <DefaultHandling>0</DefaultHandling> </ApplicationServer> </InitialFilterCriteria> </ServiceProfile> </IMSSubscription> </ClearwaterRegData> 04-06-2014 10:38:14.948 Debug hssconnection.cpp:323: Processing Identity node from HSS XML - sip:[email protected] 04-06-2014 10:38:14.948 Debug acr.cpp:48: Created ACR (0x7fcaac00dad0) 04-06-2014 10:38:14.948 Debug aschain.cpp:73: Creating AsChain 0x7fcaac0461e0 with 1 IFC and adding to map 04-06-2014 10:38:14.948 Debug aschain.cpp:75: Attached ACR (0x7fcaac00dad0) to chain 04-06-2014 10:38:14.948 Debug stateful_proxy.cpp:4714: UASTransaction 0x7fcaac0067e0 linked to AsChain AsChain-term[0x7fcaac0461e0]:1/1 04-06-2014 10:38:14.948 Debug stateful_proxy.cpp:2534: Terminating half 04-06-2014 10:38:14.948 Debug stateful_proxy.cpp:2797: Apply terminating services 04-06-2014 10:38:14.948 Debug ifchandler.cpp:476: SPT class Method: result false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:583: Add to group 0 val false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:476: SPT class SIPHeader: result false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:583: Add to group 0 val false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:476: SPT class SessionCase: result false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:583: Add to group 0 val false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:476: SPT class Method: result false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:583: Add to group 1 val false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:476: SPT class SIPHeader: result false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:583: Add to group 1 val false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:476: SPT class SessionCase: result false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:583: Add to group 1 val false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:476: SPT class Method: result false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:583: Add to group 2 val false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:476: SPT class SIPHeader: result false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:583: Add to group 2 val false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:476: SPT class SessionCase: result true 04-06-2014 10:38:14.948 Debug ifchandler.cpp:583: Add to group 2 val true 04-06-2014 10:38:14.948 Debug ifchandler.cpp:476: SPT class Method: result false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:583: Add to group 3 val false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:476: SPT class SIPHeader: result false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:583: Add to group 3 val false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:476: SPT class SessionCase: result false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:583: Add to group 3 val false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:601: Result group 0 val false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:601: Result group 1 val false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:601: Result group 2 val false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:601: Result group 3 val false 04-06-2014 10:38:14.948 Debug ifchandler.cpp:605: iFC does not match 04-06-2014 10:38:14.949 Debug aschain.cpp:232: No match for AsChain-term[0x7fcaac0461e0]:1/1 04-06-2014 10:38:14.949 Debug stateful_proxy.cpp:2808: Done internal step - advance link to AsChain-term[0x7fcaac0461e0]:2/1 and go around again 04-06-2014 10:38:14.949 Debug aschain.cpp:221: No ASs left in chain 04-06-2014 10:38:14.949 Info stateful_proxy.cpp:2816: Terminating services disposition 2 04-06-2014 10:38:14.949 Debug stateful_proxy.cpp:2544: Single Record-Route - end of terminating handling 04-06-2014 10:38:14.949 Debug pjutils.cpp:219: aor_from_uri converted sip:[email protected] to sip:[email protected] 04-06-2014 10:38:14.949 Info stateful_proxy.cpp:1742: Look up targets in registration store: sip:[email protected] 04-06-2014 10:38:14.949 Debug regstore.cpp:102: Get AoR data for sip:[email protected] 04-06-2014 10:38:14.949 Debug memcachedstore.cpp:175: Set up new view 1 for thread 04-06-2014 10:38:14.949 Debug memcachedstore.cpp:184: Setting up server 0 for connection 0x7fcaac047130 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS) 04-06-2014 10:38:14.949 Debug memcachedstore.cpp:186: Set up connection 0x7fcaac046aa0 to server 192.168.206.112:11211 04-06-2014 10:38:14.949 Debug memcachedstore.cpp:228: Setting server to IP address 192.168.206.112 port 11211 04-06-2014 10:38:14.949 Debug memcachedstore.cpp:260: Key reg\\sip:[email protected] hashes to vbucket 42 via hash 0x361d152a 04-06-2014 10:38:14.949 Debug memcachedstore.cpp:304: 1 read replicas for key reg\\sip:[email protected] 04-06-2014 10:38:14.949 Debug memcachedstore.cpp:337: Attempt to read from replica 0 (connection 0x7fcaac046aa0) 04-06-2014 10:38:14.949 Debug memcachedstore.cpp:343: Fetch result 04-06-2014 10:38:14.949 Debug memcachedstore.cpp:351: Found record on replica 0 04-06-2014 10:38:14.949 Debug memcachedstore.cpp:400: Read 353 bytes from table reg key sip:[email protected], CAS = 86 04-06-2014 10:38:14.949 Debug regstore.cpp:455: Deserialize 1 bindings 04-06-2014 10:38:14.949 Debug regstore.cpp:462: Binding sip:[email protected]:50030;transport=tcp;rinstance=215393d055505407 04-06-2014 10:38:14.949 Debug regstore.cpp:488: Deserialize 1 path headers 04-06-2014 10:38:14.949 Debug regstore.cpp:494: Deserialized path header sip:CpSQZ/[email protected]:5058;transport=TCP;lr;ob 04-06-2014 10:38:14.950 Debug regstore.cpp:503: Deserialize 0 subscriptions 04-06-2014 10:38:14.950 Debug regstore.cpp:114: Data store returned a record, CAS = 86 04-06-2014 10:38:14.950 Debug stateful_proxy.cpp:1799: Target = <sip:[email protected]:50030;transport=tcp;rinstance=215393d055505407> 04-06-2014 10:38:14.950 Debug stateful_proxy.cpp:3444: Allocating transaction and data for target 0 04-06-2014 10:38:14.950 Debug pjsip: sip_endpoint.c Processing incoming message: Request msg CANCEL/cseq=1 (rdata0x7fcacc026928) 04-06-2014 10:38:14.950 Verbose stack.cpp:226: RX 405 bytes Request msg CANCEL/cseq=1 (rdata0x7fcacc026928) from TCP 192.168.206.112:33070: --start msg-- CANCEL sip:[email protected];transport=tcp SIP/2.0 Via: SIP/2.0/TCP 192.168.206.112:33070;rport;branch=z9hG4bKPjrCrWt6rvZ37QxAdh5x0y-vaCx.y1HGpr Max-Forwards: 70 From: <sip:[email protected]>;tag=1114ab1f To: <sip:[email protected]> Call-ID: MzhlMDdjNjQ3MzdhNTRiZmNiZTlhNDJjMWIwNGQ1OGU CSeq: 1 CANCEL Route: <sip:192.168.206.112:5054;transport=TCP;lr;orig> Content-Length: 0 --end msg-- 04-06-2014 10:38:14.950 Debug pjsip: tsx0x7fcaac072 Transaction created for Request msg INVITE/cseq=1 (tdta0x7fcaac06f350) 04-06-2014 10:38:14.950 Debug stateful_proxy.cpp:3464: Adding trail identifier 37 to UAC transaction 04-06-2014 10:38:14.950 Debug stateful_proxy.cpp:3483: Updating request URI and route for target 0 04-06-2014 10:38:14.950 Debug pjutils.cpp:219: aor_from_uri converted sip:[email protected] to sip:[email protected] 04-06-2014 10:38:14.950 Debug stateful_proxy.cpp:3877: Adding a Route header to sip:CpSQZ/[email protected]:5058;transport=TCP 04-06-2014 10:38:14.950 Debug stateful_proxy.cpp:3887: Target came from store, storing AoR = sip:[email protected], binding_id = sip:[email protected]:50030;transport=tcp;rinstance=215393d055505407 04-06-2014 10:38:14.950 Debug stateful_proxy.cpp:3915: Resolve next hop destination 04-06-2014 10:38:14.950 Debug pjutils.cpp:463: Next hop node is encoded in top route header 04-06-2014 10:38:14.950 Debug sipresolver.cpp:85: SIPResolver::resolve for name 192.168.206.112, port 5058, transport 6, family 2 04-06-2014 10:38:14.950 Debug baseresolver.cpp:480: Attempt to parse 192.168.206.112 as IP address 04-06-2014 10:38:14.950 Debug sipresolver.cpp:102: Target is an IP address - default port/transport if required 04-06-2014 10:38:14.950 Info pjutils.cpp:734: Resolved destination URI sip:CpSQZ/[email protected]:5058;transport=TCP;lr;ob to 1 servers 04-06-2014 10:38:14.950 Debug stateful_proxy.cpp:3953: Sending request for sip:[email protected]:50030;transport=tcp;rinstance=215393d055505407 04-06-2014 10:38:14.950 Debug pjsip: tsx0x7fcaac072 Sending Request msg INVITE/cseq=1 (tdta0x7fcaac06f350) in state Null 04-06-2014 10:38:14.950 Debug pjsip: endpoint Request msg INVITE/cseq=1 (tdta0x7fcaac06f350): skipping target resolution because address is already set 04-06-2014 10:38:14.950 Verbose pjsip: tcpc0x7fcaac07 TCP client transport created 04-06-2014 10:38:14.950 Verbose pjsip: tcpc0x7fcaac07 TCP transport 192.168.206.112:36494 is connecting to 192.168.206.112:5058... 04-06-2014 10:38:14.950 Verbose stack.cpp:242: TX 1576 bytes Request msg INVITE/cseq=1 (tdta0x7fcaac06f350) to TCP 192.168.206.112:5058: --start msg-- INVITE sip:[email protected]:50030;transport=tcp;rinstance=215393d055505407 SIP/2.0 Record-Route: <sip:192.168.206.112:5054;transport=TCP;lr> Record-Route: <sip:192.168.206.112:5058;transport=TCP;lr> Record-Route: <sip:[email protected]:5060;transport=TCP;lr> Via: SIP/2.0/TCP 192.168.206.112:36494;rport;branch=z9hG4bKPjSVMVYWOim2pe.3ly3eSAkpDmC4hJm2ZV Via: SIP/2.0/TCP 192.168.206.112:33070;rport=33070;received=192.168.206.112;branch=z9hG4bKPjrCrWt6rvZ37QxAdh5x0y-vaCx.y1HGpr Via: SIP/2.0/TCP 192.168.206.159:43498;rport=59677;received=192.168.206.159;branch=z9hG4bK-d8754z-884c23056ad58d7b-1---d8754z- Max-Forwards: 68 Contact: <sip:[email protected]:59677;transport=tcp> To: <sip:[email protected]> From: <sip:[email protected]>;tag=1114ab1f Call-ID: MzhlMDdjNjQ3MzdhNTRiZmNiZTlhNDJjMWIwNGQ1OGU CSeq: 1 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Supported: replaces User-Agent: X-Lite release 4.5.5 stamp 71236 P-Asserted-Identity: <sip:[email protected]> Session-Expires: 600 P-Called-Party-ID: <sip:[email protected]> Route: <sip:CpSQZ/[email protected]:5058;transport=TCP;lr;ob> Content-Type: application/sdp Content-Length: 310 v=0 o=- 13046351975734667 1 IN IP4 192.168.206.159 s=X-Lite 4 release 4.5.5 stamp 71236 c=IN IP4 192.168.206.159 t=0 0 m=audio 49776 RTP/AVP 125 9 0 8 100 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:100 speex/16000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv --end msg-- 04-06-2014 10:38:14.950 Debug pjsip: tsx0x7fcaac072 State changed from Null to Calling, event=TX_MSG 04-06-2014 10:38:14.951 Debug stateful_proxy.cpp:365: tsx0x7fcaac072368 - tu_on_tsx_state UAC, TSX_STATE TX_MSG state=Calling 04-06-2014 10:38:14.951 Debug stateful_proxy.cpp:4055: tsx0x7fcaac072368 - uac_data = 0x7fcaac06f1b0, uas_data = 0x7fcaac0067e0 04-06-2014 10:38:14.951 Debug stack.cpp:410: Queuing cloned received message 0x7fcacc13d388 for worker threads 04-06-2014 10:38:14.951 Verbose pjsip: tcpc0x7fcaac07 TCP transport 192.168.206.112:36494 is connected to 192.168.206.112:5058 04-06-2014 10:38:14.951 Debug stack.cpp:189: Worker thread dequeue message 0x7fcacc13d388 04-06-2014 10:38:14.951 Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg CANCEL/cseq=1 (rdata0x7fcacc13d388) 04-06-2014 10:38:14.951 Debug stateful_proxy.cpp:257: Proxy RX request 04-06-2014 10:38:14.951 Debug pjsip: tsx0x7fcaa8000 Transaction created for Request msg CANCEL/cseq=1 (rdata0x7fcacc13d388) 04-06-2014 10:38:14.951 Debug pjsip: tsx0x7fcaa8000 Incoming Request msg CANCEL/cseq=1 (rdata0x7fcacc13d388) in state Null 04-06-2014 10:38:14.951 Debug pjsip: tsx0x7fcaa8000 State changed from Null to Trying, event=RX_MSG 04-06-2014 10:38:14.952 Debug pjsip: endpoint Response msg 200/CANCEL/cseq=1 (tdta0x7fcaa80015b0) created 04-06-2014 10:38:14.952 Debug pjsip: tsx0x7fcaa8000 Sending Response msg 200/CANCEL/cseq=1 (tdta0x7fcaa80015b0) in state Trying 04-06-2014 10:38:14.952 Verbose stack.cpp:242: TX 365 bytes Response msg 200/CANCEL/cseq=1 (tdta0x7fcaa80015b0) to TCP 192.168.206.112:33070: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP 192.168.206.112:33070;rport=33070;received=192.168.206.112;branch=z9hG4bKPjrCrWt6rvZ37QxAdh5x0y-vaCx.y1HGpr Call-ID: MzhlMDdjNjQ3MzdhNTRiZmNiZTlhNDJjMWIwNGQ1OGU From: <sip:[email protected]>;tag=1114ab1f To: <sip:[email protected]>;tag=z9hG4bKPjrCrWt6rvZ37QxAdh5x0y-vaCx.y1HGpr CSeq: 1 CANCEL Content-Length: 0 --end msg-- 04-06-2014 10:38:14.952 Debug pjsip: tsx0x7fcaa8000 State changed from Trying to Completed, event=TX_MSG 04-06-2014 10:38:14.952 Debug stateful_proxy.cpp:656: tsx0x7fcaac006078 - Cancel for UAS transaction 04-06-2014 10:38:14.952 Debug stateful_proxy.cpp:3536: tsx0x7fcaac006078 - Cancel 1 pending UAC transactions 04-06-2014 10:38:14.952 Debug stateful_proxy.cpp:3545: tsx0x7fcaac006078 - Check target 0, UAC data = 0x7fcaac06f1b0, UAC tsx = 0x7fcaac072368 04-06-2014 10:38:14.952 Debug stateful_proxy.cpp:3996: Found transaction tsx0x7fcaac072368 status=0 04-06-2014 10:38:14.952 Debug pjsip: endpoint Request msg CANCEL/cseq=1 (tdta0x7fcaa80025c0) created. 04-06-2014 10:38:14.952 Debug stateful_proxy.cpp:4026: Sending CANCEL request 04-06-2014 10:38:14.952 Debug pjutils.cpp:947: Sending standalone request statefully 04-06-2014 10:38:14.953 Debug pjsip: tsx0x7fcaa8007 Transaction created for Request msg CANCEL/cseq=1 (tdta0x7fcaa80025c0) 04-06-2014 10:38:14.953 Debug pjutils.cpp:992: Transport already determined 04-06-2014 10:38:14.953 Debug pjutils.cpp:1001: Sending request 04-06-2014 10:38:14.953 Debug pjsip: tsx0x7fcaa8007 Sending Request msg CANCEL/cseq=1 (tdta0x7fcaa80025c0) in state Null 04-06-2014 10:38:14.953 Debug pjsip: endpoint Request msg CANCEL/cseq=1 (tdta0x7fcaa80025c0): skipping target resolution because address is already set 04-06-2014 10:38:14.953 Verbose stack.cpp:242: TX 451 bytes Request msg CANCEL/cseq=1 (tdta0x7fcaa80025c0) to TCP 192.168.206.112:5058: --start msg-- CANCEL sip:[email protected]:50030;transport=tcp;rinstance=215393d055505407 SIP/2.0 Via: SIP/2.0/TCP 192.168.206.112:36494;rport;branch=z9hG4bKPjSVMVYWOim2pe.3ly3eSAkpDmC4hJm2ZV Max-Forwards: 70 From: <sip:[email protected]>;tag=1114ab1f To: <sip:[email protected]> Call-ID: MzhlMDdjNjQ3MzdhNTRiZmNiZTlhNDJjMWIwNGQ1OGU CSeq: 1 CANCEL Route: <sip:CpSQZ/[email protected]:5058;transport=TCP;lr;ob> Content-Length: 0 --end msg-- 04-06-2014 10:38:14.953 Debug pjsip: tsx0x7fcaa8007 State changed from Null to Calling, event=TX_MSG 04-06-2014 10:38:14.953 Debug acr.cpp:48: Created ACR (0x7fcaa8000900) 04-06-2014 10:38:14.953 Debug acr.cpp:82: Sending Null ACR (0x7fcaa8000900) 04-06-2014 10:38:14.953 Debug acr.cpp:53: Destroyed ACR (0x7fcaa8000900) 04-06-2014 10:38:14.953 Debug stack.cpp:191: Worker thread completed processing message 0x7fcacc13d388 04-06-2014 10:38:14.953 Debug stack.cpp:197: Request latency = 2236us 04-06-2014 10:38:14.953 Debug statistic.cpp:103: Send new value for statistic latency_us, size 5 04-06-2014 10:38:14.953 Debug zmq_lvc.cpp:167: Update to latency_us statistic 04-06-2014 10:38:14.953 Debug zmq_lvc.cpp:250: Clearing message cache for 0x7fcb10013100 04-06-2014 10:38:14.953 Debug stack.cpp:191: Worker thread completed processing message 0x7fcacc0c0af8 04-06-2014 10:38:14.954 Debug pjsip: sip_endpoint.c Processing incoming message: Response msg 200/CANCEL/cseq=1 (rdata0x7fcaac072ff8) 04-06-2014 10:38:14.954 Verbose stack.cpp:226: RX 365 bytes Response msg 200/CANCEL/cseq=1 (rdata0x7fcaac072ff8) from TCP 192.168.206.112:5058: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP 192.168.206.112:36494;rport=36494;received=192.168.206.112;branch=z9hG4bKPjSVMVYWOim2pe.3ly3eSAkpDmC4hJm2ZV Call-ID: MzhlMDdjNjQ3MzdhNTRiZmNiZTlhNDJjMWIwNGQ1OGU From: <sip:[email protected]>;tag=1114ab1f To: <sip:[email protected]>;tag=z9hG4bKPjSVMVYWOim2pe.3ly3eSAkpDmC4hJm2ZV CSeq: 1 CANCEL Content-Length: 0 --end msg-- 04-06-2014 10:38:14.954 Debug stack.cpp:410: Queuing cloned received message 0x7fcacc13d388 for worker threads 04-06-2014 10:38:14.954 Debug pjsip: tsx0x7fcaa8000 Timeout timer event 04-06-2014 10:38:14.954 Debug pjsip: tsx0x7fcaa8000 State changed from Completed to Terminated, event=TIMER 04-06-2014 10:38:14.954 Debug pjsip: tsx0x7fcaa8000 Timeout timer event 04-06-2014 10:38:14.954 Debug pjsip: tsx0x7fcaa8000 State changed from Terminated to Destroyed, event=TIMER 04-06-2014 10:38:14.954 Debug pjsip: tdta0x7fcaa800 Destroying txdata Response msg 200/CANCEL/cseq=1 (tdta0x7fcaa80015b0) 04-06-2014 10:38:14.954 Debug pjsip: tsx0x7fcaa8000 Transaction destroyed! 04-06-2014 10:38:14.954 Debug stack.cpp:189: Worker thread dequeue message 0x7fcacc13d388 04-06-2014 10:38:14.954 Debug pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/CANCEL/cseq=1 (rdata0x7fcacc13d388) 04-06-2014 10:38:14.954 Debug pjsip: tsx0x7fcaa8007 Incoming Response msg 200/CANCEL/cseq=1 (rdata0x7fcacc13d388) in state Calling 04-06-2014 10:38:14.954 Debug pjsip: tsx0x7fcaa8007 State changed from Calling to Completed, event=RX_MSG 04-06-2014 10:38:14.954 Debug pjutils.cpp:921: Request transaction completed, status code = 200 04-06-2014 10:38:14.954 Debug stack.cpp:191: Worker thread completed processing message 0x7fcacc13d388 04-06-2014 10:38:14.954 Debug stack.cpp:197: Request latency = 338us 04-06-2014 10:38:14.954 Debug stack.cpp:197: Request latency = 24881us 04-06-2014 10:38:14.964 Debug pjsip: tsx0x7fcaa8007 Timeout timer event 04-06-2014 10:38:14.964 Debug pjsip: tsx0x7fcaa8007 State changed from Completed to Terminated, event=TIMER 04-06-2014 10:38:14.964 Debug pjsip: tsx0x7fcaa8007 Timeout timer event 04-06-2014 10:38:14.964 Debug pjsip: tsx0x7fcaa8007 State changed from Terminated to Destroyed, event=TIMER 04-06-2014 10:38:14.964 Debug pjsip: tdta0x7fcaa800 Destroying txdata Request msg CANCEL/cseq=1 (tdta0x7fcaa80025c0) 04-06-2014 10:38:14.964 Debug pjsip: tsx0x7fcaa8007 Transaction destroyed! 04-06-2014 10:38:14.971 Debug pjsip: sip_endpoint.c Processing incoming message: Response msg 487/INVITE/cseq=1 (rdata0x7fcaac072ff8) 04-06-2014 10:38:14.971 Verbose stack.cpp:226: RX 649 bytes Response msg 487/INVITE/cseq=1 (rdata0x7fcaac072ff8) from TCP 192.168.206.112:5058: --start msg-- SIP/2.0 487 Request Terminated Via: SIP/2.0/TCP 192.168.206.112:36494;rport=36494;received=192.168.206.112;branch=z9hG4bKPjSVMVYWOim2pe.3ly3eSAkpDmC4hJm2ZV Via: SIP/2.0/TCP 192.168.206.112:33070;rport=33070;received=192.168.206.112;branch=z9hG4bKPjrCrWt6rvZ37QxAdh5x0y-vaCx.y1HGpr Via: SIP/2.0/TCP 192.168.206.159:43498;rport=59677;received=192.168.206.159;branch=z9hG4bK-d8754z-884c23056ad58d7b-1---d8754z- To: <sip:[email protected]>;tag=5bef756d From: <sip:[email protected]>;tag=1114ab1f Call-ID: MzhlMDdjNjQ3MzdhNTRiZmNiZTlhNDJjMWIwNGQ1OGU CSeq: 1 INVITE User-Agent: X-Lite release 4.5.5 stamp 71236 Content-Length: 0 --end msg-- 04-06-2014 10:38:14.971 Debug stack.cpp:410: Queuing cloned received message 0x7fcacc0c0af8 for worker threads 04-06-2014 10:38:14.971 Debug stack.cpp:189: Worker thread dequeue message 0x7fcacc0c0af8 04-06-2014 10:38:14.971 Debug pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 487/INVITE/cseq=1 (rdata0x7fcacc0c0af8) 04-06-2014 10:38:14.971 Debug pjsip: tsx0x7fcaac072 Incoming Response msg 487/INVITE/cseq=1 (rdata0x7fcacc0c0af8) in state Calling 04-06-2014 10:38:14.971 Debug pjsip: endpoint Request msg ACK/cseq=1 (tdta0x7fcab0000bf0) created. 04-06-2014 10:38:14.971 Verbose stack.cpp:242: TX 458 bytes Request msg ACK/cseq=1 (tdta0x7fcab0000bf0) to TCP 192.168.206.112:5058: --start msg-- ACK sip:[email protected]:50030;transport=tcp;rinstance=215393d055505407 SIP/2.0 Via: SIP/2.0/TCP 192.168.206.112:36494;rport;branch=z9hG4bKPjSVMVYWOim2pe.3ly3eSAkpDmC4hJm2ZV Max-Forwards: 70 From: <sip:[email protected]>;tag=1114ab1f To: <sip:[email protected]>;tag=5bef756d Call-ID: MzhlMDdjNjQ3MzdhNTRiZmNiZTlhNDJjMWIwNGQ1OGU CSeq: 1 ACK Route: <sip:CpSQZ/[email protected]:5058;transport=TCP;lr;ob> Content-Length: 0 --end msg-- 04-06-2014 10:38:14.971 Debug pjsip: tsx0x7fcaac072 State changed from Calling to Completed, event=RX_MSG 04-06-2014 10:38:14.971 Debug stateful_proxy.cpp:365: tsx0x7fcaac072368 - tu_on_tsx_state UAC, TSX_STATE RX_MSG state=Completed 04-06-2014 10:38:14.971 Debug stateful_proxy.cpp:4055: tsx0x7fcaac072368 - uac_data = 0x7fcaac06f1b0, uas_data = 0x7fcaac0067e0 04-06-2014 10:38:14.971 Debug stateful_proxy.cpp:4094: tsx0x7fcaac072368 - RX_MSG on active UAC transaction 04-06-2014 10:38:14.971 Debug stateful_proxy.cpp:3055: tsx0x7fcaac072368 - Final response, so disconnect UAS and UAC transactions 04-06-2014 10:38:14.971 Debug pjsip: tdta0x7fcaac00 Destroying txdata Response msg 408/INVITE/cseq=1 (tdta0x7fcaac006990) 04-06-2014 10:38:14.971 Debug stateful_proxy.cpp:3574: Dissociate UAC transaction 0x7fcaac06f1b0 (0) 04-06-2014 10:38:14.971 Debug pjsip: tsx0x7fcaac006 Sending Response msg 487/INVITE/cseq=1 (tdta0x7fcab0005aa0) in state Proceeding 04-06-2014 10:38:14.971 Debug pjsip: tdta0x7fcaac00 Destroying txdata Response msg 100/INVITE/cseq=1 (tdta0x7fcaac008b60) 04-06-2014 10:38:14.971 Verbose stack.cpp:242: TX 523 bytes Response msg 487/INVITE/cseq=1 (tdta0x7fcab0005aa0) to TCP 192.168.206.112:33070: --start msg-- SIP/2.0 487 Request Terminated Via: SIP/2.0/TCP 192.168.206.112:33070;rport=33070;received=192.168.206.112;branch=z9hG4bKPjrCrWt6rvZ37QxAdh5x0y-vaCx.y1HGpr Via: SIP/2.0/TCP 192.168.206.159:43498;rport=59677;received=192.168.206.159;branch=z9hG4bK-d8754z-884c23056ad58d7b-1---d8754z- To: <sip:[email protected]>;tag=5bef756d From: <sip:[email protected]>;tag=1114ab1f Call-ID: MzhlMDdjNjQ3MzdhNTRiZmNiZTlhNDJjMWIwNGQ1OGU CSeq: 1 INVITE User-Agent: X-Lite release 4.5.5 stamp 71236 Content-Length: 0 --end msg-- 04-06-2014 10:38:14.972 Debug pjsip: tsx0x7fcaac006 State changed from Proceeding to Completed, event=TX_MSG 04-06-2014 10:38:14.972 Debug stateful_proxy.cpp:365: tsx0x7fcaac006078 - tu_on_tsx_state UAS, TSX_STATE TX_MSG state=Completed 04-06-2014 10:38:14.972 Debug stateful_proxy.cpp:3379: Report SAS end marker - trail (25) 04-06-2014 10:38:14.972 Debug stack.cpp:191: Worker thread completed processing message 0x7fcacc0c0af8 04-06-2014 10:38:14.972 Debug stack.cpp:197: Request latency = 793us 04-06-2014 10:38:14.972 Debug load_monitor.cpp:175: Accepted 100.000000% of requests, latency error = -0.994482, overload responses = 0 04-06-2014 10:38:14.972 Debug load_monitor.cpp:197: Increase rate to 119.692879 04-06-2014 10:38:14.972 Debug pjsip: tsx0x7fcaac072 Timeout timer event 04-06-2014 10:38:14.972 Debug pjsip: tsx0x7fcaac072 State changed from Completed to Terminated, event=TIMER 04-06-2014 10:38:14.972 Debug stateful_proxy.cpp:365: tsx0x7fcaac072368 - tu_on_tsx_state UAC, TSX_STATE TIMER state=Terminated 04-06-2014 10:38:14.972 Debug stateful_proxy.cpp:4055: tsx0x7fcaac072368 - uac_data = 0x7fcaac06f1b0, uas_data = (nil) 04-06-2014 10:38:14.972 Debug pjsip: tsx0x7fcaac072 Timeout timer event 04-06-2014 10:38:14.972 Debug pjsip: tsx0x7fcaac072 State changed from Terminated to Destroyed, event=TIMER 04-06-2014 10:38:14.972 Debug stateful_proxy.cpp:365: tsx0x7fcaac072368 - tu_on_tsx_state UAC, TSX_STATE TIMER state=Destroyed 04-06-2014 10:38:14.972 Debug stateful_proxy.cpp:4055: tsx0x7fcaac072368 - uac_data = 0x7fcaac06f1b0, uas_data = (nil) 04-06-2014 10:38:14.972 Debug stateful_proxy.cpp:4132: tsx0x7fcaac072368 - UAC tsx destroyed 04-06-2014 10:38:14.972 Debug pjsip: tdta0x7fcaac06 Destroying txdata Request msg INVITE/cseq=1 (tdta0x7fcaac06f350) 04-06-2014 10:38:14.972 Debug pjsip: tdta0x7fcab000 Destroying txdata Request msg ACK/cseq=1 (tdta0x7fcab0000bf0) 04-06-2014 10:38:14.990 Debug pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=1 (rdata0x7fcacc026928) 04-06-2014 10:38:14.991 Verbose stack.cpp:226: RX 412 bytes Request msg ACK/cseq=1 (rdata0x7fcacc026928) from TCP 192.168.206.112:33070: --start msg-- ACK sip:[email protected];transport=tcp SIP/2.0 Via: SIP/2.0/TCP 192.168.206.112:33070;rport;branch=z9hG4bKPjrCrWt6rvZ37QxAdh5x0y-vaCx.y1HGpr Max-Forwards: 70 From: <sip:[email protected]>;tag=1114ab1f To: <sip:[email protected]>;tag=5bef756d Call-ID: MzhlMDdjNjQ3MzdhNTRiZmNiZTlhNDJjMWIwNGQ1OGU CSeq: 1 ACK Route: <sip:192.168.206.112:5054;transport=TCP;lr;orig> Content-Length: 0 --end msg-- 04-06-2014 10:38:14.991 Debug stack.cpp:410: Queuing cloned received message 0x7fcacc0c0af8 for worker threads 04-06-2014 10:38:14.991 Debug stack.cpp:189: Worker thread dequeue message 0x7fcacc0c0af8 04-06-2014 10:38:14.991 Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=1 (rdata0x7fcacc0c0af8) 04-06-2014 10:38:14.991 Debug pjsip: tsx0x7fcaac006 Incoming Request msg ACK/cseq=1 (rdata0x7fcacc0c0af8) in state Completed 04-06-2014 10:38:14.991 Debug pjsip: tsx0x7fcaac006 State changed from Completed to Confirmed, event=RX_MSG 04-06-2014 10:38:14.991 Debug stateful_proxy.cpp:365: tsx0x7fcaac006078 - tu_on_tsx_state UAS, TSX_STATE RX_MSG state=Confirmed 04-06-2014 10:38:14.991 Debug stack.cpp:191: Worker thread completed processing message 0x7fcacc0c0af8 04-06-2014 10:38:14.991 Debug stack.cpp:197: Request latency = 296us 04-06-2014 10:38:19.333 Verbose pjsip: tcplis:5054 TCP listener 192.168.206.112:5054: got incoming TCP connection from 192.168.206.112:42513, sock=152 04-06-2014 10:38:19.333 Verbose pjsip: tcps0x7fcacc0c TCP server transport created 04-06-2014 10:38:19.334 Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=2939 (rdata0x7fcacc0c0de8) 04-06-2014 10:38:19.334 Verbose stack.cpp:226: RX 358 bytes Request msg OPTIONS/cseq=2939 (rdata0x7fcacc0c0de8) from TCP 192.168.206.112:42513: --start msg-- OPTIONS sip:[email protected]:5054 SIP/2.0 Via: SIP/2.0/TCP 192.168.206.112;rport;branch=z9hG4bK-2939 Max-Forwards: 2 To: <sip:[email protected]:5054> From: poll-sip <sip:[email protected]>;tag=2939 Call-ID: poll-sip-2939 CSeq: 2939 OPTIONS Contact: <sip:192.168.206.112> Accept: application/sdp Content-Length: 0 User-Agent: poll-sip --end msg-- 04-06-2014 10:38:19.334 Debug stack.cpp:410: Queuing cloned received message 0x7fcacc13d388 for worker threads 04-06-2014 10:38:19.334 Debug stack.cpp:189: Worker thread dequeue message 0x7fcacc13d388 04-06-2014 10:38:19.334 Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=2939 (rdata0x7fcacc13d388) 04-06-2014 10:38:19.334 Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=2939 (tdta0x7fcab8000c70) created 04-06-2014 10:38:19.334 Verbose stack.cpp:242: TX 284 bytes Response msg 200/OPTIONS/cseq=2939 (tdta0x7fcab8000c70) to TCP 192.168.206.112:42513: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP 192.168.206.112;rport=42513;received=192.168.206.112;branch=z9hG4bK-2939 Call-ID: poll-sip-2939 From: "poll-sip" <sip:[email protected]>;tag=2939 To: <sip:[email protected]>;tag=z9hG4bK-2939 CSeq: 2939 OPTIONS Content-Length: 0 --end msg-- 04-06-2014 10:38:19.334 Debug pjsip: tdta0x7fcab800 Destroying txdata Response msg 200/OPTIONS/cseq=2939 (tdta0x7fcab8000c70) 04-06-2014 10:38:19.334 Debug stack.cpp:191: Worker thread completed processing message 0x7fcacc13d388 04-06-2014 10:38:19.334 Debug stack.cpp:197: Request latency = 272us 04-06-2014 10:38:19.992 Debug pjsip: tsx0x7fcaac006 Timeout timer event 04-06-2014 10:38:19.992 Debug pjsip: tsx0x7fcaac006 State changed from Confirmed to Terminated, event=TIMER 04-06-2014 10:38:19.992 Debug stateful_proxy.cpp:365: tsx0x7fcaac006078 - tu_on_tsx_state UAS, TSX_STATE TIMER state=Terminated 04-06-2014 10:38:19.993 Debug pjsip: tsx0x7fcaac006 Timeout timer event 04-06-2014 10:38:19.993 Debug pjsip: tsx0x7fcaac006 State changed from Terminated to Destroyed, event=TIMER 04-06-2014 10:38:19.993 Debug stateful_proxy.cpp:365: tsx0x7fcaac006078 - tu_on_tsx_state UAS, TSX_STATE TIMER state=Destroyed 04-06-2014 10:38:19.993 Debug stateful_proxy.cpp:3146: tsx0x7fcaac006078 - UAS tsx destroyed 04-06-2014 10:38:19.993 Debug stateful_proxy.cpp:3536: tsx0x7fcaac006078 - Cancel 0 pending UAC transactions 04-06-2014 10:38:19.993 Debug stateful_proxy.cpp:3545: tsx0x7fcaac006078 - Check target 0, UAC data = (nil), UAC tsx = (nil) 04-06-2014 10:38:19.993 Debug stateful_proxy.cpp:2063: UASTransaction destructor (0x7fcaac0067e0) 04-06-2014 10:38:19.993 Debug stateful_proxy.cpp:2083: Disconnect UAC transactions from UAS transaction 04-06-2014 10:38:19.993 Debug stateful_proxy.cpp:2154: Free original request (0x7fcaac002c08) 04-06-2014 10:38:19.993 Debug pjsip: tdta0x7fcaac00 Destroying txdata Request msg INVITE/cseq=1 (tdta0x7fcaac002b60) 04-06-2014 10:38:19.993 Debug aschain.h:130: AsChain dec ref 0x7fcaac0461e0 -> 1 04-06-2014 10:38:19.993 Debug aschain.cpp:109: Removing AsChain 0x7fcaac046750 from map 04-06-2014 10:38:19.993 Debug aschain.h:130: AsChain dec ref 0x7fcaac046750 -> 0 04-06-2014 10:38:19.993 Debug aschain.cpp:81: Destroying AsChain 0x7fcaac046750 04-06-2014 10:38:19.993 Debug aschain.cpp:99: Sending ACR (0x7fcaac005b20) from AS chain 04-06-2014 10:38:19.993 Debug acr.cpp:82: Sending Null ACR (0x7fcaac005b20) 04-06-2014 10:38:19.993 Debug acr.cpp:53: Destroyed ACR (0x7fcaac005b20) 04-06-2014 10:38:19.993 Debug aschain.cpp:109: Removing AsChain 0x7fcaac0461e0 from map 04-06-2014 10:38:19.993 Debug aschain.h:130: AsChain dec ref 0x7fcaac0461e0 -> 0 04-06-2014 10:38:19.993 Debug aschain.cpp:81: Destroying AsChain 0x7fcaac0461e0 04-06-2014 10:38:19.993 Debug aschain.cpp:99: Sending ACR (0x7fcaac00dad0) from AS chain 04-06-2014 10:38:19.993 Debug acr.cpp:82: Sending Null ACR (0x7fcaac00dad0) 04-06-2014 10:38:19.993 Debug acr.cpp:53: Destroyed ACR (0x7fcaac00dad0) 04-06-2014 10:38:19.993 Debug stateful_proxy.cpp:2194: UASTransaction destructor completed 04-06-2014 10:38:19.994 Debug pjsip: tdta0x7fcab000 Destroying txdata Response msg 487/INVITE/cseq=1 (tdta0x7fcab0005aa0) 04-06-2014 10:38:19.994 Debug pjsip: tsx0x7fcaac006 Transaction destroyed! 04-06-2014 10:38:19.994 Debug pjsip: tsx0x7fcaac072 Transaction destroyed! 04-06-2014 10:38:20.334 Verbose pjsip: tcps0x7fcacc0c TCP connection closed 04-06-2014 10:38:20.334 Debug connection_tracker.cpp:91: Connection 0x7fcacc0c0af8 has been destroyed 04-06-2014 10:38:20.334 Verbose pjsip: tcps0x7fcacc0c TCP transport destroyed with reason 70016: End of file (PJ_EEOF) -----Original Message----- From: Eleanor Merry [mailto:[email protected]] Sent: Wednesday, June 04, 2014 6:34 PM To: PS; [email protected] Subject: RE: [Clearwater] Question on creating SIP call Hi Paul, I'm going to need to see some logs to debug this. Can you please turn on debug logging for your Clearwater server and make a call? You will need to: - Create/edit the file /etc/clearwater/user_settings and add log_level=5. - For bono, sprout and homestead run "service <service> stop" to restart the component (it's automatically restarted by monit). The debug logs are created in /var/log/<sprout/bono/homestead>. Ellie -----Original Message----- From: [email protected] [mailto:[email protected]] On Behalf Of Paul Sun Sent: 04 June 2014 11:33 To: [email protected] Subject: Re: [Clearwater] Question on creating SIP call Any idea why 192.168.0.159 send CANCEL on packet #4? o. Time Source Sport Destination Dport RawProto Protocol Length VlanId Dscp Info 1 2014-06-04 16:24:03.038997 192.168.0.159 64038 192.168.0.112 5060 TCP SIP/SDP 1020 0 Request: INVITE sip:[email protected];transport=tcp | 2 2014-06-04 16:24:03.039049 192.168.0.112 5060 192.168.0.159 64038 TCP TCP 56 0 sip > 64038 [ACK] Seq=1 Ack=965 Win=114 Len=0 3 2014-06-04 16:24:03.041056 192.168.0.112 5060 192.168.0.159 64038 TCP SIP 510 0 Status: 100 Trying | 4 2014-06-04 16:24:03.049601 192.168.0.159 64038 192.168.0.112 5060 TCP SIP 509 0 Request: CANCEL sip:[email protected];transport=tcp | 5 2014-06-04 16:24:03.050163 192.168.0.112 5060 192.168.0.158 49896 TCP TCP 1316 0 [TCP segment of a reassembled PDU] 6 2014-06-04 16:24:03.050195 192.168.0.112 5060 192.168.0.158 49896 TCP SIP/SDP 560 0 Request: INVITE sip:[email protected]:49896;transport=tcp;rinstance=427b47a968808703 | 7 2014-06-04 16:24:03.050493 192.168.0.112 5060 192.168.0.159 64038 TCP SIP 425 0 Status: 200 OK | 8 2014-06-04 16:24:03.051171 192.168.0.158 49896 192.168.0.112 5060 TCP TCP 62 0 49896 > sip [ACK] Seq=1 Ack=1765 Win=16695 Len=0 9 2014-06-04 16:24:03.051729 192.168.0.112 5060 192.168.0.158 49896 TCP SIP 440 0 Request: CANCEL sip:[email protected]:49896;transport=tcp;rinstance=427b47a968808703 | 10 2014-06-04 16:24:03.064229 192.168.0.158 49896 192.168.0.112 5060 TCP SIP 471 0 Status: 200 OK | 11 2014-06-04 16:24:03.064266 192.168.0.112 5060 192.168.0.158 49896 TCP TCP 56 0 sip > 49896 [ACK] Seq=2149 Ack=416 Win=89 Len=0 12 2014-06-04 16:24:03.066223 192.168.0.158 49896 192.168.0.112 5060 TCP SIP 803 0 Status: 487 Request Terminated | 13 2014-06-04 16:24:03.066248 192.168.0.112 5060 192.168.0.158 49896 TCP TCP 56 0 sip > 49896 [ACK] Seq=2149 Ack=1163 Win=88 Len=0 14 2014-06-04 16:24:03.066608 192.168.0.112 5060 192.168.0.158 49896 TCP SIP 447 0 Request: ACK sip:[email protected]:49896;transport=tcp;rinstance=427b47a968808703 | 15 2014-06-04 16:24:03.259855 192.168.0.159 64038 192.168.0.112 5060 TCP TCP 62 0 64038 > sip [ACK] Seq=1418 Ack=824 Win=16120 Len=0 16 2014-06-04 16:24:03.259894 192.168.0.112 5060 192.168.0.159 64038 TCP SIP 453 0 Status: 487 Request Terminated | 17 2014-06-04 16:24:03.262852 192.168.0.159 64038 192.168.0.112 5060 TCP SIP 469 0 Request: ACK sip:[email protected];transport=tcp | 18 2014-06-04 16:24:03.270988 192.168.0.158 49896 192.168.0.112 5060 TCP TCP 62 0 49896 > sip [ACK] Seq=1163 Ack=2540 Win=16501 Len=0 19 2014-06-04 16:24:03.300786 192.168.0.112 5060 192.168.0.159 64038 TCP TCP 56 0 sip > 64038 [ACK] Seq=1221 Ack=1831 Win=115 Len=0 -----Original Message----- From: PS Sent: Wednesday, June 04, 2014 6:00 PM To: [email protected] Subject: Question on creating SIP call Hi I faced a problem on creating a SIP call between two X-Lite client. I observed that Client A send SIP REQUEST CANCEL after 100 Trying. Is there any reason on this? - PS _______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/listinfo/clearwater _______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/listinfo/clearwater
